Rate limit for most abundant log messages

7 files changed, 68 insertions, 15 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)
+static inline void
+krt_trace_in(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);
+  if (p->p.debug & D_PACKETS)
+    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)
+krt_trace_in_rl(struct rate_limit *rl, struct krt_proto *p, rte *e, char *msg)
 {
   if (p->p.debug & D_PACKETS)
-    krt_trace_in_print(p, e, msg);
+    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 <sys/syslog.h>
 
@@ -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