From cb5303927188de9504a6e18aedec299956a22b6f Mon Sep 17 00:00:00 2001 From: Ondrej Zajicek Date: Thu, 26 Feb 2009 14:23:54 +0100 Subject: [PATCH] Rate limit for most abundant log messages --- filter/filter.c | 4 +++- lib/birdlib.h | 8 ++++++++ proto/bgp/bgp.h | 4 ++++ proto/bgp/packets.c | 9 ++++++--- sysdep/linux/netlink/netlink.c | 4 +++- sysdep/unix/krt.c | 26 ++++++++++++++------------ sysdep/unix/log.c | 32 ++++++++++++++++++++++++++++++++ 7 files changed, 70 insertions(+), 17 deletions(-) diff --git a/filter/filter.c b/filter/filter.c index 9e75f174..785a0876 100644 --- a/filter/filter.c +++ b/filter/filter.c @@ -281,8 +281,10 @@ rta_cow(void) } } +static struct rate_limit rl_runtime_err; + #define runtime(x) do { \ - log( L_ERR "filters, line %d: %s", what->lineno, x); \ + log_rl(&rl_runtime_err, L_ERR "filters, line %d: %s", what->lineno, x); \ res.type = T_RETURN; \ res.val.i = F_ERROR; \ return res; \ diff --git a/lib/birdlib.h b/lib/birdlib.h index 93f25fb8..b7cd6b43 100644 --- a/lib/birdlib.h +++ b/lib/birdlib.h @@ -9,6 +9,8 @@ #ifndef _BIRD_BIRDLIB_H_ #define _BIRD_BIRDLIB_H_ +#include "timer.h" + /* Ugly structure offset handling macros */ #define OFFSETOF(s, i) ((unsigned int)&((s *)0)->i) @@ -33,8 +35,14 @@ /* Logging and dying */ +struct rate_limit { + bird_clock_t timestamp; + int count; +}; + #define log log_msg void log_msg(char *msg, ...); +void log_rl(struct rate_limit *rl, char *msg, ...); void die(char *msg, ...) NORET; void bug(char *msg, ...) NORET; diff --git a/proto/bgp/bgp.h b/proto/bgp/bgp.h index b706caf1..b0ead9d3 100644 --- a/proto/bgp/bgp.h +++ b/proto/bgp/bgp.h @@ -139,6 +139,10 @@ void bgp_store_error(struct bgp_proto *p, struct bgp_conn *c, u8 class, u32 code #define BGP_TRACE(flags, msg, args...) do { if ((p->p.debug & flags) || BGP_FORCE_DEBUG) \ log(L_TRACE "%s: " msg, p->p.name , ## args ); } while(0) +#define BGP_TRACE_RL(rl, flags, msg, args...) do { if ((p->p.debug & flags) || BGP_FORCE_DEBUG) \ + log_rl(rl, L_TRACE "%s: " msg, p->p.name , ## args ); } while(0) + + /* attrs.c */ void bgp_attach_attr(struct ea_list **to, struct linpool *pool, unsigned attr, uintptr_t val); diff --git a/proto/bgp/packets.c b/proto/bgp/packets.c index 27c0755e..fe7472bd 100644 --- a/proto/bgp/packets.c +++ b/proto/bgp/packets.c @@ -21,6 +21,8 @@ #include "bgp.h" +static struct rate_limit rl_rcv_update, rl_snd_update; + static byte * bgp_create_notification(struct bgp_conn *conn, byte *buf) { @@ -175,7 +177,7 @@ bgp_create_update(struct bgp_conn *conn, byte *buf) } if (wd_size || r_size) { - BGP_TRACE(D_PACKETS, "Sending UPDATE"); + BGP_TRACE_RL(&rl_snd_update, D_PACKETS, "Sending UPDATE"); return w; } else @@ -282,7 +284,7 @@ bgp_create_update(struct bgp_conn *conn, byte *buf) lp_flush(bgp_linpool); if (size) { - BGP_TRACE(D_PACKETS, "Sending UPDATE"); + BGP_TRACE_RL(&rl_snd_update, D_PACKETS, "Sending UPDATE"); return w; } else @@ -762,7 +764,8 @@ bgp_rx_update(struct bgp_conn *conn, byte *pkt, int len) byte *withdrawn, *attrs, *nlri; int withdrawn_len, attr_len, nlri_len; - BGP_TRACE(D_PACKETS, "Got UPDATE"); + BGP_TRACE_RL(&rl_rcv_update, D_PACKETS, "Got UPDATE"); + if (conn->state != BS_ESTABLISHED) { bgp_error(conn, 5, 0, NULL, 0); return; } bgp_start_timer(conn->hold_timer, conn->hold_time); diff --git a/sysdep/linux/netlink/netlink.c b/sysdep/linux/netlink/netlink.c index 08817ca4..734247ec 100644 --- a/sysdep/linux/netlink/netlink.c +++ b/sysdep/linux/netlink/netlink.c @@ -129,6 +129,8 @@ nl_get_reply(void) } } +static struct rate_limit rl_netlink_err; + static int nl_error(struct nlmsghdr *h) { @@ -143,7 +145,7 @@ nl_error(struct nlmsghdr *h) e = (struct nlmsgerr *) NLMSG_DATA(h); ec = -e->error; if (ec) - log(L_WARN "Netlink: %s", strerror(ec)); + log_rl(&rl_netlink_err, L_WARN "Netlink: %s", strerror(ec)); return ec; } diff --git a/sysdep/unix/krt.c b/sysdep/unix/krt.c index fded9abe..816eb444 100644 --- a/sysdep/unix/krt.c +++ b/sysdep/unix/krt.c @@ -183,18 +183,18 @@ struct protocol proto_unix_iface = { * Tracing of routes */ -static void -krt_trace_in_print(struct krt_proto *p, rte *e, char *msg) -{ - DBG("KRT: %I/%d: %s\n", e->net->n.prefix, e->net->n.pxlen, msg); - log(L_TRACE "%s: %I/%d: %s", p->p.name, e->net->n.prefix, e->net->n.pxlen, msg); -} - static inline void krt_trace_in(struct krt_proto *p, rte *e, char *msg) { if (p->p.debug & D_PACKETS) - krt_trace_in_print(p, e, msg); + log(L_TRACE "%s: %I/%d: %s", p->p.name, e->net->n.prefix, e->net->n.pxlen, msg); +} + +static inline void +krt_trace_in_rl(struct rate_limit *rl, struct krt_proto *p, rte *e, char *msg) +{ + if (p->p.debug & D_PACKETS) + log_rl(rl, L_TRACE "%s: %I/%d: %s", p->p.name, e->net->n.prefix, e->net->n.pxlen, msg); } /* @@ -203,6 +203,8 @@ krt_trace_in(struct krt_proto *p, rte *e, char *msg) #ifdef KRT_ALLOW_LEARN +static struct rate_limit rl_alien_seen, rl_alien_updated, rl_alien_created, rl_alien_ignored; + static inline int krt_same_key(rte *a, rte *b) { @@ -249,20 +251,20 @@ krt_learn_scan(struct krt_proto *p, rte *e) { if (krt_uptodate(m, e)) { - krt_trace_in(p, e, "[alien] seen"); + krt_trace_in_rl(&rl_alien_seen, p, e, "[alien] seen"); rte_free(e); m->u.krt.seen = 1; } else { - krt_trace_in(p, e, "[alien] updated"); + krt_trace_in_rl(&rl_alien_updated, p, e, "[alien] updated"); *mm = m->next; rte_free(m); m = NULL; } } else - krt_trace_in(p, e, "[alien] created"); + krt_trace_in_rl(&rl_alien_created, p, e, "[alien] created"); if (!m) { e->attrs = rta_lookup(e->attrs); @@ -516,7 +518,7 @@ krt_got_route(struct krt_proto *p, rte *e) krt_learn_scan(p, e); else { - krt_trace_in(p, e, "alien route, ignored"); + krt_trace_in_rl(&rl_alien_ignored, p, e, "alien route, ignored"); rte_free(e); } return; diff --git a/sysdep/unix/log.c b/sysdep/unix/log.c index 08711e17..eb083099 100644 --- a/sysdep/unix/log.c +++ b/sysdep/unix/log.c @@ -30,6 +30,9 @@ static FILE *dbgf = NULL; static list *current_log_list; static list init_log_list; +bird_clock_t rate_limit_time = 5; +int rate_limit_count = 5; + #ifdef HAVE_SYSLOG #include @@ -126,6 +129,35 @@ log_msg(char *msg, ...) va_end(args); } +void +log_rl(struct rate_limit *rl, char *msg, ...) +{ + int class = 1; + va_list args; + + bird_clock_t delta = now - rl->timestamp; + if ((0 <= delta) && (delta < rate_limit_time)) + { + rl->count++; + } + else + { + rl->timestamp = now; + rl->count = 1; + } + + if (rl->count > rate_limit_count) + return; + + va_start(args, msg); + if (*msg >= 1 && *msg <= 8) + class = *msg++; + vlog(class, msg, args); + if (rl->count == rate_limit_count) + vlog(class, "...", args); + va_end(args); +} + /** * bug - report an internal error * @msg: a printf-like error message