vlog: Apply rate-limiting everywhere it seems warranted.

diff --git a/lib/dhcp-client.c b/lib/dhcp-client.c
index c05b614..a43c01c 100644 (file)
--- a/lib/dhcp-client.c
+++ b/lib/dhcp-client.c
@@ -73,6 +73,8 @@ enum dhclient_state {
 #undef DHCLIENT_STATE
 };
 
+static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(60, 60);
+
 static const char *
 state_name(enum dhclient_state state)
 {
@@ -541,14 +543,15 @@ dhcp_receive(struct dhclient *cli, unsigned int msgs, struct dhcp_msg *msg)
 {
     while (do_receive_msg(cli, msg)) {
         if (msg->type < 0 || msg->type > 31 || !((1u << msg->type) & msgs)) {
-            VLOG_DBG("received unexpected %s in %s state: %s",
-                     dhcp_type_name(msg->type), state_name(cli->state),
-                     dhcp_msg_to_string(msg, false, &cli->s));
+            VLOG_DBG_RL(&rl, "received unexpected %s in %s state: %s",
+                        dhcp_type_name(msg->type), state_name(cli->state),
+                        dhcp_msg_to_string(msg, false, &cli->s));
         } else if (msg->xid != cli->xid) {
-            VLOG_DBG("ignoring %s with xid != %08"PRIx32" in %s state: %s",
-                     dhcp_type_name(msg->type), msg->xid,
-                     state_name(cli->state),
-                     dhcp_msg_to_string(msg, false, &cli->s));
+            VLOG_DBG_RL(&rl,
+                        "ignoring %s with xid != %08"PRIx32" in %s state: %s",
+                        dhcp_type_name(msg->type), msg->xid,
+                        state_name(cli->state),
+                        dhcp_msg_to_string(msg, false, &cli->s));
         } else {
             return true;
         }
@@ -562,18 +565,18 @@ validate_offered_options(struct dhclient *cli, const struct dhcp_msg *msg)
 {
     uint32_t lease, netmask;
     if (!dhcp_msg_get_secs(msg, DHCP_CODE_LEASE_TIME, 0, &lease)) {
-        VLOG_WARN("%s lacks lease time: %s", dhcp_type_name(msg->type),
-                  dhcp_msg_to_string(msg, false, &cli->s));
+        VLOG_WARN_RL(&rl, "%s lacks lease time: %s", dhcp_type_name(msg->type),
+                     dhcp_msg_to_string(msg, false, &cli->s));
     } else if (!dhcp_msg_get_ip(msg, DHCP_CODE_SUBNET_MASK, 0, &netmask)) {
-        VLOG_WARN("%s lacks netmask: %s", dhcp_type_name(msg->type),
-                  dhcp_msg_to_string(msg, false, &cli->s));
+        VLOG_WARN_RL(&rl, "%s lacks netmask: %s", dhcp_type_name(msg->type),
+                     dhcp_msg_to_string(msg, false, &cli->s));
     } else if (lease < MIN_ACCEPTABLE_LEASE) {
-        VLOG_WARN("Ignoring %s with %"PRIu32"-second lease time: %s",
-                  dhcp_type_name(msg->type), lease,
-                  dhcp_msg_to_string(msg, false, &cli->s));
+        VLOG_WARN_RL(&rl, "Ignoring %s with %"PRIu32"-second lease time: %s",
+                     dhcp_type_name(msg->type), lease,
+                     dhcp_msg_to_string(msg, false, &cli->s));
     } else if (cli->validate_offer && !cli->validate_offer(msg, cli->aux)) {
-        VLOG_DBG("client validation hook refused offer: %s",
-                 dhcp_msg_to_string(msg, false, &cli->s));
+        VLOG_DBG_RL(&rl, "client validation hook refused offer: %s",
+                    dhcp_msg_to_string(msg, false, &cli->s));
     } else {
         return true;
     }
@@ -596,13 +599,13 @@ dhclient_run_SELECTING(struct dhclient *cli)
         }
         if (!dhcp_msg_get_ip(&msg, DHCP_CODE_SERVER_IDENTIFIER,
                              0, &cli->server_ip)) {
-            VLOG_WARN("DHCPOFFER lacks server identifier: %s",
-                      dhcp_msg_to_string(&msg, false, &cli->s));
+            VLOG_WARN_RL(&rl, "DHCPOFFER lacks server identifier: %s",
+                         dhcp_msg_to_string(&msg, false, &cli->s));
             continue;
         }
 
-        VLOG_DBG("accepting DHCPOFFER: %s",
-                 dhcp_msg_to_string(&msg, false, &cli->s));
+        VLOG_DBG_RL(&rl, "accepting DHCPOFFER: %s",
+                    dhcp_msg_to_string(&msg, false, &cli->s));
         cli->ipaddr = msg.yiaddr;
         state_transition(cli, S_REQUESTING);
         break;
@@ -901,20 +904,21 @@ do_receive_msg(struct dhclient *cli, struct dhcp_msg *msg)
         ip = b.l3;
         if (IP_IS_FRAGMENT(ip->ip_frag_off)) {
             /* We don't do reassembly. */
-            VLOG_WARN("ignoring fragmented DHCP datagram");
+            VLOG_WARN_RL(&rl, "ignoring fragmented DHCP datagram");
             continue;
         }
 
         dhcp = b.l7;
         if (!dhcp) {
-            VLOG_WARN("ignoring DHCP datagram with missing payload");
+            VLOG_WARN_RL(&rl, "ignoring DHCP datagram with missing payload");
             continue;
         }
 
         buffer_pull(&b, b.l7 - b.data);
         error = dhcp_parse(msg, &b);
         if (!error) {
-            VLOG_DBG("received %s", dhcp_msg_to_string(msg, false, &cli->s));
+            VLOG_DBG_RL(&rl, "received %s",
+                        dhcp_msg_to_string(msg, false, &cli->s));
             buffer_uninit(&b);
             return true;
         }

diff --git a/lib/dhcp.c b/lib/dhcp.c
index 1e6628a..2e9f3df 100644 (file)
--- a/lib/dhcp.c
+++ b/lib/dhcp.c
@@ -73,6 +73,11 @@ static struct option_class classes[DHCP_N_OPTIONS] = {
 #undef DHCP_OPT
 };
 
+/* A single (bad) DHCP message can in theory dump out many, many log messages,
+ * especially at high logging levels, so the burst size is set quite high
+ * here to avoid missing useful information. */
+struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(60, 600);
+
 static void copy_data(struct dhcp_msg *);
 
 const char *
@@ -570,15 +575,15 @@ parse_options(struct dhcp_msg *msg, const char *name, void *data, size_t size,
 
         len = buffer_try_pull(&b, 1);
         if (!len) {
-            VLOG_DBG("reached end of %s expecting length byte", name);
+            VLOG_DBG_RL(&rl, "reached end of %s expecting length byte", name);
             break;
         }
 
         payload = buffer_try_pull(&b, *len);
         if (!payload) {
-            VLOG_DBG("expected %"PRIu8" bytes of option-%"PRIu8" payload "
-                     "with only %zu bytes of %s left",
-                     *len, *code, b.size, name);
+            VLOG_DBG_RL(&rl, "expected %"PRIu8" bytes of option-%"PRIu8" "
+                        "payload with only %zu bytes of %s left",
+                        *len, *code, b.size, name);
             break;
         }
         dhcp_msg_put(msg, *code + option_offset, payload, *len);
@@ -599,23 +604,23 @@ validate_options(struct dhcp_msg *msg)
             size_t remainder = opt->n % type->size;
             bool ok = true;
             if (remainder) {
-                VLOG_DBG("%s option has %zu %zu-byte %s arguments with "
-                         "%zu bytes left over",
-                         class->name, n_elems, type->size,
-                         type->name, remainder);
+                VLOG_DBG_RL(&rl, "%s option has %zu %zu-byte %s arguments "
+                            "with %zu bytes left over",
+                            class->name, n_elems, type->size,
+                            type->name, remainder);
                 ok = false;
             }
             if (n_elems < class->min_args || n_elems > class->max_args) {
-                VLOG_DBG("%s option has %zu %zu-byte %s arguments but "
-                         "between %zu and %zu are required",
-                         class->name, n_elems, type->size, type->name,
-                         class->min_args, class->max_args);
+                VLOG_DBG_RL(&rl, "%s option has %zu %zu-byte %s arguments but "
+                            "between %zu and %zu are required",
+                            class->name, n_elems, type->size, type->name,
+                            class->min_args, class->max_args);
                 ok = false;
             }
             if (!ok) {
                 struct ds ds = DS_EMPTY_INITIALIZER;
-                VLOG_DBG("%s option contains: %s",
-                         class->name, dhcp_option_to_string(opt, code, &ds));
+                VLOG_DBG_RL(&rl, "%s option contains: %s", class->name,
+                            dhcp_option_to_string(opt, code, &ds));
                 ds_destroy(&ds);
 
                 opt->n = 0;
@@ -639,20 +644,21 @@ dhcp_parse(struct dhcp_msg *msg, const struct buffer *b_)
 
     dhcp = buffer_try_pull(&b, sizeof *dhcp);
     if (!dhcp) {
-        VLOG_DBG("buffer too small for DHCP header (%zu bytes)", b.size);
+        VLOG_DBG_RL(&rl, "buffer too small for DHCP header (%zu bytes)",
+                    b.size);
         goto error;
     }
 
     if (dhcp->op != DHCP_BOOTREPLY && dhcp->op != DHCP_BOOTREQUEST) {
-        VLOG_DBG("invalid DHCP op (%"PRIu8")", dhcp->op);
+        VLOG_DBG_RL(&rl, "invalid DHCP op (%"PRIu8")", dhcp->op);
         goto error;
     }
     if (dhcp->htype != ARP_HRD_ETHERNET) {
-        VLOG_DBG("invalid DHCP htype (%"PRIu8")", dhcp->htype);
+        VLOG_DBG_RL(&rl, "invalid DHCP htype (%"PRIu8")", dhcp->htype);
         goto error;
     }
     if (dhcp->hlen != ETH_ADDR_LEN) {
-        VLOG_DBG("invalid DHCP hlen (%"PRIu8")", dhcp->hlen);
+        VLOG_DBG_RL(&rl, "invalid DHCP hlen (%"PRIu8")", dhcp->hlen);
         goto error;
     }
 
@@ -685,10 +691,11 @@ dhcp_parse(struct dhcp_msg *msg, const struct buffer *b_)
                 }
             }
         } else {
-            VLOG_DBG("bad DHCP options cookie: %08"PRIx32, ntohl(*cookie));
+            VLOG_DBG_RL(&rl, "bad DHCP options cookie: %08"PRIx32,
+                        ntohl(*cookie));
         }
     } else {
-        VLOG_DBG("DHCP packet has no options");
+        VLOG_DBG_RL(&rl, "DHCP packet has no options");
     }
 
     vendor_class = dhcp_msg_get_string(msg, DHCP_CODE_VENDOR_CLASS);
@@ -702,7 +709,7 @@ dhcp_parse(struct dhcp_msg *msg, const struct buffer *b_)
 
     validate_options(msg);
     if (!dhcp_msg_get_uint8(msg, DHCP_CODE_DHCP_MSG_TYPE, 0, &type)) {
-        VLOG_DBG("missing DHCP message type");
+        VLOG_DBG_RL(&rl, "missing DHCP message type");
         dhcp_msg_uninit(msg);
         goto error;
     }
@@ -715,11 +722,11 @@ error:
 
         ds_init(&ds);
         ds_put_hex_dump(&ds, b_->data, b_->size, 0, true);
-        VLOG_DBG("invalid DHCP message dump:\n%s", ds_cstr(&ds));
+        VLOG_DBG_RL(&rl, "invalid DHCP message dump:\n%s", ds_cstr(&ds));
 
         ds_clear(&ds);
         dhcp_msg_to_string(msg, false, &ds);
-        VLOG_DBG("partially dissected DHCP message: %s", ds_cstr(&ds));
+        VLOG_DBG_RL(&rl, "partially dissected DHCP message: %s", ds_cstr(&ds));
 
         ds_destroy(&ds);
     }

diff --git a/lib/dpif.c b/lib/dpif.c
index 202a182..4f99312 100644 (file)
--- a/lib/dpif.c
+++ b/lib/dpif.c
@@ -54,6 +54,9 @@
 #include "vlog.h"
 #define THIS_MODULE VLM_dpif
 
+/* Not really much point in logging many dpif errors. */
+static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(5, 60);
+
 /* The Generic Netlink family number used for OpenFlow. */
 static int openflow_family;
 
@@ -142,18 +145,18 @@ dpif_recv_openflow(struct dpif *dp, struct buffer **bufferp,
                      || nl_msg_nlmsghdr(buffer)->nlmsg_type == NLMSG_DONE)));
     if (retval) {
         if (retval != EAGAIN) {
-            VLOG_WARN("dpif_recv_openflow: %s", strerror(retval)); 
+            VLOG_WARN_RL(&rl, "dpif_recv_openflow: %s", strerror(retval)); 
         }
         return retval;
     }
 
     if (nl_msg_genlmsghdr(buffer) == NULL) {
-        VLOG_DBG("received packet too short for Generic Netlink");
+        VLOG_DBG_RL(&rl, "received packet too short for Generic Netlink");
         goto error;
     }
     if (nl_msg_nlmsghdr(buffer)->nlmsg_type != openflow_family) {
-        VLOG_DBG("received type (%"PRIu16") != openflow family (%d)",
-                 nl_msg_nlmsghdr(buffer)->nlmsg_type, openflow_family);
+        VLOG_DBG_RL(&rl, "received type (%"PRIu16") != openflow family (%d)",
+                    nl_msg_nlmsghdr(buffer)->nlmsg_type, openflow_family);
         goto error;
     }
 
@@ -162,8 +165,9 @@ dpif_recv_openflow(struct dpif *dp, struct buffer **bufferp,
         goto error;
     }
     if (nl_attr_get_u32(attrs[DP_GENL_A_DP_IDX]) != dp->dp_idx) {
-        VLOG_WARN("received dp_idx (%"PRIu32") differs from expected (%d)",
-                  nl_attr_get_u32(attrs[DP_GENL_A_DP_IDX]), dp->dp_idx);
+        VLOG_WARN_RL(&rl, "received dp_idx (%"PRIu32") differs from expected "
+                     "(%d)", nl_attr_get_u32(attrs[DP_GENL_A_DP_IDX]),
+                     dp->dp_idx);
         goto error;
     }
 
@@ -171,8 +175,9 @@ dpif_recv_openflow(struct dpif *dp, struct buffer **bufferp,
     buffer->size = nl_attr_get_size(attrs[DP_GENL_A_OPENFLOW]);
     ofp_len = ntohs(oh->length);
     if (ofp_len != buffer->size) {
-        VLOG_WARN("ofp_header.length %"PRIu16" != attribute length %zu\n",
-                  ofp_len, buffer->size);
+        VLOG_WARN_RL(&rl,
+                     "ofp_header.length %"PRIu16" != attribute length %zu\n",
+                     ofp_len, buffer->size);
         buffer->size = MIN(ofp_len, buffer->size);
     }
     *bufferp = buffer;
@@ -234,7 +239,7 @@ dpif_send_openflow(struct dpif *dp, struct buffer *buffer, bool wait)
     }
     retval = nl_sock_sendv(dp->sock, iov, n_iov, false);
     if (retval && retval != EAGAIN) {
-        VLOG_WARN("dpif_send_openflow: %s", strerror(retval));
+        VLOG_WARN_RL(&rl, "dpif_send_openflow: %s", strerror(retval));
     }
     return retval;
 }

diff --git a/lib/flow.c b/lib/flow.c
index 5eea06b..795731b 100644 (file)
--- a/lib/flow.c
+++ b/lib/flow.c
@@ -101,8 +101,9 @@ flow_extract(struct buffer *packet, uint16_t in_port, struct flow *flow)
          * can end up with runt frames, e.g. frames that only ever passed
          * through virtual network devices and never touched a physical
          * Ethernet. */
-        VLOG_DBG("packet length %zu less than minimum size %d",
-                 b.size, ETH_TOTAL_MIN);
+        static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(5, 60);
+        VLOG_DBG_RL(&rl, "packet length %zu less than minimum size %d",
+                    b.size, ETH_TOTAL_MIN);
     }
 
     memset(flow, 0, sizeof *flow);

diff --git a/lib/learning-switch.c b/lib/learning-switch.c
index 27271fa..f056b91 100644 (file)
--- a/lib/learning-switch.c
+++ b/lib/learning-switch.c
@@ -68,6 +68,10 @@ struct lswitch {
     int n_queued;
 };
 
+/* The log messages here could actually be useful in debugging, so keep the
+ * rate limit relatively high. */
+static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(30, 300);
+
 static void queue_tx(struct lswitch *, struct rconn *, struct buffer *);
 static void send_features_request(struct lswitch *, struct rconn *);
 static void process_packet_in(struct lswitch *, struct rconn *,
@@ -124,9 +128,10 @@ lswitch_process_packet(struct lswitch *sw, struct rconn *rconn,
 
     oh = msg->data;
     if (msg->size < min_size[oh->type]) {
-        VLOG_WARN("%s: too short (%zu bytes) for type %"PRIu8" (min %zu)",
-                  rconn_get_name(rconn),
-                  msg->size, oh->type, min_size[oh->type]);
+        VLOG_WARN_RL(&rl,
+                     "%s: too short (%zu bytes) for type %"PRIu8" (min %zu)",
+                     rconn_get_name(rconn),
+                     msg->size, oh->type, min_size[oh->type]);
         return;
     }
 
@@ -142,7 +147,7 @@ lswitch_process_packet(struct lswitch *sw, struct rconn *rconn,
     } else {
         if (VLOG_IS_DBG_ENABLED()) {
             char *p = ofp_to_string(msg->data, msg->size, 2);
-            VLOG_DBG("OpenFlow packet ignored: %s", p);
+            VLOG_DBG_RL(&rl, "OpenFlow packet ignored: %s", p);
             free(p);
         }
     }
@@ -185,15 +190,12 @@ static void
 queue_tx(struct lswitch *sw, struct rconn *rconn, struct buffer *b)
 {
     int retval = rconn_send_with_limit(rconn, b, &sw->n_queued, 10);
-    if (retval) {
+    if (retval && retval != ENOTCONN) {
         if (retval == EAGAIN) {
-            /* FIXME: ratelimit. */
-            VLOG_WARN("%s: tx queue overflow", rconn_get_name(rconn));
-        } else if (retval == ENOTCONN) {
-            /* Ignore. */
+            VLOG_WARN_RL(&rl, "%s: tx queue overflow", rconn_get_name(rconn));
         } else {
-            /* FIXME: ratelimit. */
-            VLOG_WARN("%s: send: %s", rconn_get_name(rconn), strerror(retval));
+            VLOG_WARN_RL(&rl, "%s: send: %s",
+                         rconn_get_name(rconn), strerror(retval));
         }
     }
 }
@@ -218,9 +220,9 @@ process_packet_in(struct lswitch *sw, struct rconn *rconn,
 
     if (sw->ml) {
         if (mac_learning_learn(sw->ml, flow.dl_src, in_port)) {
-            VLOG_DBG("learned that "ETH_ADDR_FMT" is on datapath %"
-                     PRIx64" port %"PRIu16, ETH_ADDR_ARGS(flow.dl_src),
-                     ntohll(sw->datapath_id), in_port);
+            VLOG_DBG_RL(&rl, "learned that "ETH_ADDR_FMT" is on datapath %"
+                        PRIx64" port %"PRIu16, ETH_ADDR_ARGS(flow.dl_src),
+                        ntohll(sw->datapath_id), in_port);
         }
         out_port = mac_learning_lookup(sw->ml, flow.dl_dst);
     }

diff --git a/lib/mac-learning.c b/lib/mac-learning.c
index ad3a0b8..8b79dc6 100644 (file)
--- a/lib/mac-learning.c
+++ b/lib/mac-learning.c
@@ -129,8 +129,9 @@ mac_learning_learn(struct mac_learning *ml,
     struct list *bucket;
 
     if (eth_addr_is_multicast(src_mac)) {
-        VLOG_DBG("multicast packet source "ETH_ADDR_FMT,
-                 ETH_ADDR_ARGS(src_mac));
+        static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(30, 30);
+        VLOG_DBG_RL(&rl, "multicast packet source "ETH_ADDR_FMT,
+                    ETH_ADDR_ARGS(src_mac));
         return false;
     }
 

diff --git a/lib/netdev.c b/lib/netdev.c
index d9ac425..581b362 100644 (file)
--- a/lib/netdev.c
+++ b/lib/netdev.c
@@ -80,11 +80,16 @@ struct netdev {
     int changed_flags;          /* Flags that we changed. */
 };
 
+/* All open network devices. */
 static struct list netdev_list = LIST_INITIALIZER(&netdev_list);
 
 /* An AF_INET socket (used for ioctl operations). */
 static int af_inet_sock = -1;
 
+/* This is set pretty low because we probably won't learn anything from the
+ * additional log messages. */
+static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(5, 20);
+
 static void init_netdev(void);
 static int restore_flags(struct netdev *netdev);
 static int get_flags(const struct netdev *, int *flagsp);
@@ -372,8 +377,8 @@ netdev_recv(struct netdev *netdev, struct buffer *buffer)
     } while (n_bytes < 0 && errno == EINTR);
     if (n_bytes < 0) {
         if (errno != EAGAIN) {
-            VLOG_WARN("error receiving Ethernet packet on %s: %s",
-                      strerror(errno), netdev->name);
+            VLOG_WARN_RL(&rl, "error receiving Ethernet packet on %s: %s",
+                         strerror(errno), netdev->name);
         }
         return errno;
     } else {
@@ -421,8 +426,8 @@ netdev_send(struct netdev *netdev, const struct buffer *buffer)
 
     /* Pull out the Ethernet header. */
     if (buffer->size < ETH_HEADER_LEN) {
-        VLOG_WARN("cannot send %zu-byte frame on %s",
-                  buffer->size, netdev->name);
+        VLOG_WARN_RL(&rl, "cannot send %zu-byte frame on %s",
+                     buffer->size, netdev->name);
         return EMSGSIZE;
     }
     eh = buffer_at_assert(buffer, 0, sizeof *eh);
@@ -438,13 +443,14 @@ netdev_send(struct netdev *netdev, const struct buffer *buffer)
         if (errno == ENOBUFS) {
             return EAGAIN;
         } else if (errno != EAGAIN) {
-            VLOG_WARN("error sending Ethernet packet on %s: %s",
-                      netdev->name, strerror(errno));
+            VLOG_WARN_RL(&rl, "error sending Ethernet packet on %s: %s",
+                         netdev->name, strerror(errno));
         }
         return errno;
     } else if (n_bytes != buffer->size) {
-        VLOG_WARN("send partial Ethernet packet (%d bytes of %zu) on %s",
-                  (int) n_bytes, buffer->size, netdev->name);
+        VLOG_WARN_RL(&rl,
+                     "send partial Ethernet packet (%d bytes of %zu) on %s",
+                     (int) n_bytes, buffer->size, netdev->name);
         return EMSGSIZE;
     } else {
         return 0;
@@ -544,8 +550,8 @@ netdev_get_in4(const struct netdev *netdev, struct in_addr *in4)
         struct sockaddr_in *sin = (struct sockaddr_in *) &ifr.ifr_addr;
         ip = sin->sin_addr;
     } else {
-        VLOG_DBG("%s: ioctl(SIOCGIFADDR) failed: %s",
-                 netdev->name, strerror(errno));
+        VLOG_DBG_RL(&rl, "%s: ioctl(SIOCGIFADDR) failed: %s",
+                    netdev->name, strerror(errno));
     }
     if (in4) {
         *in4 = ip;
@@ -748,8 +754,8 @@ netdev_arp_lookup(const struct netdev *netdev,
     if (!retval) {
         memcpy(mac, r.arp_ha.sa_data, ETH_ADDR_LEN);
     } else if (retval != ENXIO) {
-        VLOG_WARN("%s: could not look up ARP entry for "IP_FMT": %s",
-                  netdev->name, IP_ARGS(&ip), strerror(retval));
+        VLOG_WARN_RL(&rl, "%s: could not look up ARP entry for "IP_FMT": %s",
+                     netdev->name, IP_ARGS(&ip), strerror(retval));
     }
     return retval;
 }

diff --git a/lib/netlink.c b/lib/netlink.c
index 9abe26a..1316547 100644 (file)
--- a/lib/netlink.c
+++ b/lib/netlink.c
@@ -55,6 +55,11 @@
 #define SOL_NETLINK 270
 #endif
 
+/* A single (bad) Netlink message can in theory dump out many, many log
+ * messages, so the burst size is set quite high here to avoid missing useful
+ * information.  Also, at high logging levels we log *all* Netlink messages. */
+static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(60, 600);
+
 static void log_nlmsg(const char *function, int error,
                       const void *message, size_t size);
 \f
@@ -321,15 +326,15 @@ try_again:
             buffer_delete(buf);
             return ENOBUFS;
         } else {
-            VLOG_ERR("failed to remove nlmsg from socket: %s\n",
-                     strerror(errno));
+            VLOG_ERR_RL(&rl, "failed to remove nlmsg from socket: %s\n",
+                        strerror(errno));
         }
     }
     if (nbytes < sizeof *nlmsghdr
         || nlmsghdr->nlmsg_len < sizeof *nlmsghdr
         || nlmsghdr->nlmsg_len > nbytes) {
-        VLOG_ERR("received invalid nlmsg (%zd bytes < %d)",
-                 bufsize, NLMSG_HDRLEN);
+        VLOG_ERR_RL(&rl, "received invalid nlmsg (%zd bytes < %d)",
+                    bufsize, NLMSG_HDRLEN);
         buffer_delete(buf);
         return EPROTO;
     }
@@ -394,7 +399,7 @@ recv:
     retval = nl_sock_recv(sock, &reply, true);
     if (retval) {
         if (retval == ENOBUFS) {
-            VLOG_DBG("receive buffer overflow, resending request");
+            VLOG_DBG_RL(&rl, "receive buffer overflow, resending request");
             goto send;
         } else {
             return retval;
@@ -402,14 +407,15 @@ recv:
     }
     nlmsghdr = nl_msg_nlmsghdr(reply);
     if (seq != nlmsghdr->nlmsg_seq) {
-        VLOG_DBG("ignoring seq %"PRIu32" != expected %"PRIu32,
-                 nl_msg_nlmsghdr(reply)->nlmsg_seq, seq);
+        VLOG_DBG_RL(&rl, "ignoring seq %"PRIu32" != expected %"PRIu32,
+                    nl_msg_nlmsghdr(reply)->nlmsg_seq, seq);
         buffer_delete(reply);
         goto recv;
     }
     if (nl_msg_nlmsgerr(reply, &retval)) {
         if (retval) {
-            VLOG_DBG("received NAK error=%d (%s)", retval, strerror(retval));
+            VLOG_DBG_RL(&rl, "received NAK error=%d (%s)",
+                        retval, strerror(retval));
         }
         return retval != EAGAIN ? retval : EPROTO;
     }
@@ -458,8 +464,8 @@ nl_msg_nlmsgerr(const struct buffer *msg, int *errorp)
         struct nlmsgerr *err = buffer_at(msg, NLMSG_HDRLEN, sizeof *err);
         int code = EPROTO;
         if (!err) {
-            VLOG_ERR("received invalid nlmsgerr (%zd bytes < %zd)",
-                     msg->size, NLMSG_HDRLEN + sizeof *err);
+            VLOG_ERR_RL(&rl, "received invalid nlmsgerr (%zd bytes < %zd)",
+                        msg->size, NLMSG_HDRLEN + sizeof *err);
         } else if (err->error <= 0 && err->error > INT_MIN) {
             code = -err->error;
         }
@@ -778,7 +784,7 @@ nl_policy_parse(const struct buffer *msg, const struct nl_policy policy[],
 
     p = buffer_at(msg, NLMSG_HDRLEN + GENL_HDRLEN, 0);
     if (p == NULL) {
-        VLOG_DBG("missing headers in nl_policy_parse");
+        VLOG_DBG_RL(&rl, "missing headers in nl_policy_parse");
         return false;
     }
     tail = buffer_tail(msg);
@@ -791,16 +797,16 @@ nl_policy_parse(const struct buffer *msg, const struct nl_policy policy[],
 
         /* Make sure its claimed length is plausible. */
         if (nla->nla_len < NLA_HDRLEN) {
-            VLOG_DBG("%zu: attr shorter than NLA_HDRLEN (%"PRIu16")",
-                     offset, nla->nla_len);
+            VLOG_DBG_RL(&rl, "%zu: attr shorter than NLA_HDRLEN (%"PRIu16")",
+                        offset, nla->nla_len);
             return false;
         }
         len = nla->nla_len - NLA_HDRLEN;
         aligned_len = NLA_ALIGN(len);
         if (aligned_len > tail - p) {
-            VLOG_DBG("%zu: attr %"PRIu16" aligned data len (%zu) "
-                     "> bytes left (%tu)",
-                     offset, nla->nla_type, aligned_len, tail - p);
+            VLOG_DBG_RL(&rl, "%zu: attr %"PRIu16" aligned data len (%zu) "
+                        "> bytes left (%tu)",
+                        offset, nla->nla_type, aligned_len, tail - p);
             return false;
         }
 
@@ -813,19 +819,20 @@ nl_policy_parse(const struct buffer *msg, const struct nl_policy policy[],
             min_len = p->min_len ? p->min_len : attr_len_range[p->type][0];
             max_len = p->max_len ? p->max_len : attr_len_range[p->type][1];
             if (len < min_len || len > max_len) {
-                VLOG_DBG("%zu: attr %"PRIu16" length %zu not in allowed range "
-                         "%zu...%zu", offset, type, len, min_len, max_len);
+                VLOG_DBG_RL(&rl, "%zu: attr %"PRIu16" length %zu not in "
+                            "allowed range %zu...%zu",
+                            offset, type, len, min_len, max_len);
                 return false;
             }
             if (p->type == NL_A_STRING) {
                 if (((char *) nla)[nla->nla_len - 1]) {
-                    VLOG_DBG("%zu: attr %"PRIu16" lacks null terminator",
-                             offset, type);
+                    VLOG_DBG_RL(&rl, "%zu: attr %"PRIu16" lacks null at end",
+                                offset, type);
                     return false;
                 }
                 if (memchr(nla + 1, '\0', len - 1) != NULL) {
-                    VLOG_DBG("%zu: attr %"PRIu16" lies about string length",
-                             offset, type);
+                    VLOG_DBG_RL(&rl, "%zu: attr %"PRIu16" has bad length",
+                                offset, type);
                     return false;
                 }
             }
@@ -840,7 +847,7 @@ nl_policy_parse(const struct buffer *msg, const struct nl_policy policy[],
         p += NLA_ALIGN(nla->nla_len);
     }
     if (n_required) {
-        VLOG_DBG("%zu required attrs missing", n_required);
+        VLOG_DBG_RL(&rl, "%zu required attrs missing", n_required);
         return false;
     }
     return true;
@@ -1059,7 +1066,7 @@ log_nlmsg(const char *function, int error,
     buffer.data = (void *) message;
     buffer.size = size;
     nlmsg = nlmsg_to_string(&buffer);
-    VLOG_DBG("%s (%s): %s", function, strerror(error), nlmsg);
+    VLOG_DBG_RL(&rl, "%s (%s): %s", function, strerror(error), nlmsg);
     free(nlmsg);
 }
 

diff --git a/lib/poll-loop.c b/lib/poll-loop.c
index 6bf05dd..d65c6af 100644 (file)
--- a/lib/poll-loop.c
+++ b/lib/poll-loop.c
@@ -146,7 +146,8 @@ poll_block(void)
 
     retval = time_poll(pollfds, n_pollfds, timeout);
     if (retval < 0) {
-        VLOG_ERR("poll: %s", strerror(-retval));
+        static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(1, 5);
+        VLOG_ERR_RL(&rl, "poll: %s", strerror(-retval));
     }
 
     for (node = waiters.next; node != &waiters; ) {

diff --git a/lib/socket-util.c b/lib/socket-util.c
index 35dbcd6..8fa663a 100644 (file)
--- a/lib/socket-util.c
+++ b/lib/socket-util.c
@@ -77,12 +77,13 @@ lookup_ip(const char *host_name, struct in_addr *addr)
     if (!inet_aton(host_name, addr)) {
         struct hostent *he = gethostbyname(host_name);
         if (he == NULL) {
-            VLOG_ERR("gethostbyname(%s): %s", host_name,
-                     (h_errno == HOST_NOT_FOUND ? "host not found"
-                      : h_errno == TRY_AGAIN ? "try again"
-                      : h_errno == NO_RECOVERY ? "non-recoverable error"
-                      : h_errno == NO_ADDRESS ? "no address"
-                      : "unknown error"));
+            struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(1, 5);
+            VLOG_ERR_RL(&rl, "gethostbyname(%s): %s", host_name,
+                        (h_errno == HOST_NOT_FOUND ? "host not found"
+                         : h_errno == TRY_AGAIN ? "try again"
+                         : h_errno == NO_RECOVERY ? "non-recoverable error"
+                         : h_errno == NO_ADDRESS ? "no address"
+                         : "unknown error"));
             return ENOENT;
         }
         addr->s_addr = *(uint32_t *) he->h_addr;
@@ -98,8 +99,9 @@ get_socket_error(int fd)
     int error;
     socklen_t len = sizeof(error);
     if (getsockopt(fd, SOL_SOCKET, SO_ERROR, &error, &len) < 0) {
+        struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(5, 10);
         error = errno;
-        VLOG_ERR("getsockopt(SO_ERROR): %s", strerror(error));
+        VLOG_ERR_RL(&rl, "getsockopt(SO_ERROR): %s", strerror(error));
     }
     return error;
 }
@@ -118,7 +120,8 @@ check_connection_completion(int fd)
     if (retval == 1) {
         return get_socket_error(fd);
     } else if (retval < 0) {
-        VLOG_ERR("poll: %s", strerror(errno));
+        static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(5, 10);
+        VLOG_ERR_RL(&rl, "poll: %s", strerror(errno));
         return errno;
     } else {
         return EAGAIN;
@@ -138,7 +141,8 @@ drain_rcvbuf(int fd)
 
     rcvbuf_len = sizeof rcvbuf;
     if (getsockopt(fd, SOL_SOCKET, SO_RCVBUF, &rcvbuf, &rcvbuf_len) < 0) {
-        VLOG_ERR("getsockopt(SO_RCVBUF) failed: %s", strerror(errno));
+        static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(5, 10);
+        VLOG_ERR_RL(&rl, "getsockopt(SO_RCVBUF) failed: %s", strerror(errno));
         return errno;
     }
     while (rcvbuf > 0) {

diff --git a/lib/vconn-ssl.c b/lib/vconn-ssl.c
index d109cfd..41fd1d1 100644 (file)
--- a/lib/vconn-ssl.c
+++ b/lib/vconn-ssl.c
@@ -145,6 +145,10 @@ static SSL_CTX *ctx;
 /* Required configuration. */
 static bool has_private_key, has_certificate, has_ca_cert;
 
+/* Who knows what can trigger various SSL errors, so let's throttle them down
+ * quite a bit. */
+static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(10, 25);
+
 static int ssl_init(void);
 static int do_ssl_init(void);
 static bool ssl_wants_io(int ssl_error);
@@ -368,11 +372,11 @@ interpret_ssl_error(const char *function, int ret, int error,
 
     switch (error) {
     case SSL_ERROR_NONE:
-        VLOG_ERR("%s: unexpected SSL_ERROR_NONE", function);
+        VLOG_ERR_RL(&rl, "%s: unexpected SSL_ERROR_NONE", function);
         break;
 
     case SSL_ERROR_ZERO_RETURN:
-        VLOG_ERR("%s: unexpected SSL_ERROR_ZERO_RETURN", function);
+        VLOG_ERR_RL(&rl, "%s: unexpected SSL_ERROR_ZERO_RETURN", function);
         break;
 
     case SSL_ERROR_WANT_READ:
@@ -384,15 +388,16 @@ interpret_ssl_error(const char *function, int ret, int error,
         return EAGAIN;
 
     case SSL_ERROR_WANT_CONNECT:
-        VLOG_ERR("%s: unexpected SSL_ERROR_WANT_CONNECT", function);
+        VLOG_ERR_RL(&rl, "%s: unexpected SSL_ERROR_WANT_CONNECT", function);
         break;
 
     case SSL_ERROR_WANT_ACCEPT:
-        VLOG_ERR("%s: unexpected SSL_ERROR_WANT_ACCEPT", function);
+        VLOG_ERR_RL(&rl, "%s: unexpected SSL_ERROR_WANT_ACCEPT", function);
         break;
 
     case SSL_ERROR_WANT_X509_LOOKUP:
-        VLOG_ERR("%s: unexpected SSL_ERROR_WANT_X509_LOOKUP", function);
+        VLOG_ERR_RL(&rl, "%s: unexpected SSL_ERROR_WANT_X509_LOOKUP",
+                    function);
         break;
 
     case SSL_ERROR_SYSCALL: {
@@ -400,14 +405,17 @@ interpret_ssl_error(const char *function, int ret, int error,
         if (queued_error == 0) {
             if (ret < 0) {
                 int status = errno;
-                VLOG_WARN("%s: system error (%s)", function, strerror(status));
+                VLOG_WARN_RL(&rl, "%s: system error (%s)",
+                             function, strerror(status));
                 return status;
             } else {
-                VLOG_WARN("%s: unexpected SSL connection close", function);
+                VLOG_WARN_RL(&rl, "%s: unexpected SSL connection close",
+                             function);
                 return EPROTO;
             }
         } else {
-            VLOG_DBG("%s: %s", function, ERR_error_string(queued_error, NULL));
+            VLOG_DBG_RL(&rl, "%s: %s",
+                        function, ERR_error_string(queued_error, NULL));
             break;
         }
     }
@@ -415,15 +423,17 @@ interpret_ssl_error(const char *function, int ret, int error,
     case SSL_ERROR_SSL: {
         int queued_error = ERR_get_error();
         if (queued_error != 0) {
-            VLOG_DBG("%s: %s", function, ERR_error_string(queued_error, NULL));
+            VLOG_DBG_RL(&rl, "%s: %s",
+                        function, ERR_error_string(queued_error, NULL));
         } else {
-            VLOG_ERR("%s: SSL_ERROR_SSL without queued error", function);
+            VLOG_ERR_RL(&rl, "%s: SSL_ERROR_SSL without queued error",
+                        function);
         }
         break;
     }
 
     default:
-        VLOG_ERR("%s: bad SSL error code %d", function, error);
+        VLOG_ERR_RL(&rl, "%s: bad SSL error code %d", function, error);
         break;
     }
     return EIO;
@@ -450,7 +460,8 @@ again:
         struct ofp_header *oh = rx->data;
         size_t length = ntohs(oh->length);
         if (length < sizeof(struct ofp_header)) {
-            VLOG_ERR("received too-short ofp_header (%zu bytes)", length);
+            VLOG_ERR_RL(&rl, "received too-short ofp_header (%zu bytes)",
+                        length);
             return EPROTO;
         }
         want_bytes = length - rx->size;
@@ -493,7 +504,7 @@ again:
         if (error == SSL_ERROR_ZERO_RETURN) {
             /* Connection closed (EOF). */
             if (rx->size) {
-                VLOG_WARN("SSL_read: unexpected connection close");
+                VLOG_WARN_RL(&rl, "SSL_read: unexpected connection close");
                 return EPROTO;
             } else {
                 return EOF;
@@ -541,7 +552,7 @@ ssl_do_tx(struct vconn *vconn)
         } else {
             int ssl_error = SSL_get_error(sslv->ssl, ret);
             if (ssl_error == SSL_ERROR_ZERO_RETURN) {
-                VLOG_WARN("SSL_write: connection closed");
+                VLOG_WARN_RL(&rl, "SSL_write: connection closed");
                 return EPIPE;
             } else {
                 return interpret_ssl_error("SSL_write", ret, ssl_error,
@@ -749,7 +760,7 @@ pssl_accept(struct vconn *vconn, struct vconn **new_vconnp)
     if (new_fd < 0) {
         int error = errno;
         if (error != EAGAIN) {
-            VLOG_DBG("accept: %s", strerror(error));
+            VLOG_DBG_RL(&rl, "accept: %s", strerror(error));
         }
         return error;
     }
@@ -865,7 +876,8 @@ tmp_dh_callback(SSL *ssl, int is_export UNUSED, int keylength)
             return dh->dh;
         }
     }
-    VLOG_ERR("no Diffie-Hellman parameters for key length %d", keylength);
+    VLOG_ERR_RL(&rl, "no Diffie-Hellman parameters for key length %d",
+                keylength);
     return NULL;
 }
 

diff --git a/lib/vconn-stream.c b/lib/vconn-stream.c
index 28d9635..beb239c 100644 (file)
--- a/lib/vconn-stream.c
+++ b/lib/vconn-stream.c
@@ -63,6 +63,8 @@ struct stream_vconn
 
 static struct vconn_class stream_vconn_class;
 
+static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(10, 25);
+
 int
 new_stream_vconn(const char *name, int fd, int connect_status,
                  uint32_t ip, struct vconn **vconnp)
@@ -124,7 +126,8 @@ again:
         struct ofp_header *oh = rx->data;
         size_t length = ntohs(oh->length);
         if (length < sizeof(struct ofp_header)) {
-            VLOG_ERR("received too-short ofp_header (%zu bytes)", length);
+            VLOG_ERR_RL(&rl, "received too-short ofp_header (%zu bytes)",
+                        length);
             return EPROTO;
         }
         want_bytes = length - rx->size;
@@ -151,7 +154,7 @@ again:
         return EAGAIN;
     } else if (retval == 0) {
         if (rx->size) {
-            VLOG_ERR("connection dropped mid-packet");
+            VLOG_ERR_RL(&rl, "connection dropped mid-packet");
             return EPROTO;
         } else {
             return EOF;
@@ -177,7 +180,7 @@ stream_do_tx(int fd UNUSED, short int revents UNUSED, void *vconn_)
     ssize_t n = write(s->fd, s->txbuf->data, s->txbuf->size);
     if (n < 0) {
         if (errno != EAGAIN) {
-            VLOG_ERR("send: %s", strerror(errno));
+            VLOG_ERR_RL(&rl, "send: %s", strerror(errno));
             stream_clear_txbuf(s);
             return;
         }
@@ -323,7 +326,7 @@ pstream_accept(struct vconn *vconn, struct vconn **new_vconnp)
     if (new_fd < 0) {
         int retval = errno;
         if (retval != EAGAIN) {
-            VLOG_DBG("accept: %s", strerror(retval));
+            VLOG_DBG_RL(&rl, "accept: %s", strerror(retval));
         }
         return retval;
     }

diff --git a/lib/vconn.c b/lib/vconn.c
index 7df6d27..bac38d9 100644 (file)
--- a/lib/vconn.c
+++ b/lib/vconn.c
@@ -65,6 +65,11 @@ static struct vconn_class *vconn_classes[] = {
     &punix_vconn_class,
 };
 
+/* High rate limit because most of the rate-limiting here is individual
+ * OpenFlow messages going over the vconn.  If those are enabled then we
+ * really need to see them. */
+static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(600, 600);
+
 /* Check the validity of the vconn class structures. */
 static void
 check_vconn_classes(void)
@@ -282,15 +287,15 @@ vconn_recv(struct vconn *vconn, struct buffer **msgp)
 
             if (VLOG_IS_DBG_ENABLED()) {
                 char *s = ofp_to_string((*msgp)->data, (*msgp)->size, 1);
-                VLOG_DBG("received: %s", s);
+                VLOG_DBG_RL(&rl, "received: %s", s);
                 free(s);
             }
 
             oh = buffer_at_assert(*msgp, 0, sizeof *oh);
             if (oh->version != OFP_VERSION) {
-                VLOG_ERR("received OpenFlow version %02"PRIx8" "
-                         "!= expected %02x",
-                         oh->version, OFP_VERSION);
+                VLOG_ERR_RL(&rl, "received OpenFlow version %02"PRIx8" "
+                            "!= expected %02x",
+                            oh->version, OFP_VERSION);
                 buffer_delete(*msgp);
                 *msgp = NULL;
                 return EPROTO;
@@ -327,7 +332,7 @@ vconn_send(struct vconn *vconn, struct buffer *msg)
             char *s = ofp_to_string(msg->data, msg->size, 1);
             retval = (vconn->class->send)(vconn, msg);
             if (retval != EAGAIN) {
-                VLOG_DBG("sent (%s): %s", strerror(retval), s);
+                VLOG_DBG_RL(&rl, "sent (%s): %s", strerror(retval), s);
             }
             free(s);
         }
@@ -342,7 +347,6 @@ vconn_send_block(struct vconn *vconn, struct buffer *msg)
     int retval;
     while ((retval = vconn_send(vconn, msg)) == EAGAIN) {
         vconn_send_wait(vconn);
-        VLOG_DBG("blocking on vconn send");
         poll_block();
     }
     return retval;
@@ -355,7 +359,6 @@ vconn_recv_block(struct vconn *vconn, struct buffer **msgp)
     int retval;
     while ((retval = vconn_recv(vconn, msgp)) == EAGAIN) {
         vconn_recv_wait(vconn);
-        VLOG_DBG("blocking on vconn receive");
         poll_block();
     }
     return retval;
@@ -394,8 +397,8 @@ vconn_transact(struct vconn *vconn, struct buffer *request,
             return 0;
         }
 
-        VLOG_DBG("received reply with xid %08"PRIx32" != expected %08"PRIx32,
-                 recv_xid, send_xid);
+        VLOG_DBG_RL(&rl, "received reply with xid %08"PRIx32" != expected "
+                    "%08"PRIx32, recv_xid, send_xid);
         buffer_delete(reply);
     }
 }

diff --git a/secchan/secchan.c b/secchan/secchan.c
index f3396ff..8906eb0 100644 (file)
--- a/secchan/secchan.c
+++ b/secchan/secchan.c
@@ -128,6 +128,8 @@ struct hook {
     void *aux;
 };
 
+static struct vlog_rate_limit vrl = VLOG_RATE_LIMIT_INIT(60, 60);
+
 static void parse_options(int argc, char *argv[], struct settings *);
 static void usage(void) NO_RETURN;
 
@@ -353,7 +355,7 @@ relay_accept(const struct settings *s, struct vconn *listen_vconn)
     retval = vconn_accept(listen_vconn, &new_remote);
     if (retval) {
         if (retval != EAGAIN) {
-            VLOG_WARN("accept failed (%s)", strerror(retval));
+            VLOG_WARN_RL(&vrl, "accept failed (%s)", strerror(retval));
         }
         return NULL;
     }
@@ -367,8 +369,8 @@ relay_accept(const struct settings *s, struct vconn *listen_vconn)
     nl_name_without_subscription = xasprintf("%s:0", s->nl_name);
     retval = vconn_open(nl_name_without_subscription, &new_local);
     if (retval) {
-        VLOG_ERR("could not connect to %s (%s)",
-                 nl_name_without_subscription, strerror(retval));
+        VLOG_ERR_RL(&vrl, "could not connect to %s (%s)",
+                    nl_name_without_subscription, strerror(retval));
         vconn_close(new_remote);
         free(nl_name_without_subscription);
         return NULL;
@@ -582,7 +584,8 @@ in_band_packet_cb(struct relay *r, int half, void *in_band_)
         return false;
     }
     if (msg->size < offsetof(struct ofp_packet_in, data)) {
-        VLOG_WARN("packet too short (%zu bytes) for packet_in", msg->size);
+        VLOG_WARN_RL(&vrl, "packet too short (%zu bytes) for packet_in",
+                     msg->size);
         return false;
     }
 
@@ -604,8 +607,8 @@ in_band_packet_cb(struct relay *r, int half, void *in_band_)
         /* Sent to secure channel. */
         out_port = OFPP_LOCAL;
         if (mac_learning_learn(in_band->ml, flow.dl_src, in_port)) {
-            VLOG_DBG("learned that "ETH_ADDR_FMT" is on port %"PRIu16,
-                     ETH_ADDR_ARGS(flow.dl_src), in_port);
+            VLOG_DBG_RL(&vrl, "learned that "ETH_ADDR_FMT" is on port %"PRIu16,
+                        ETH_ADDR_ARGS(flow.dl_src), in_port);
         }
     } else if (flow.dl_type == htons(ETH_TYPE_ARP)
                && eth_addr_is_broadcast(flow.dl_dst)
@@ -900,7 +903,8 @@ rate_limit_packet_cb(struct relay *r, int half, void *rl_)
         return false;
     }
     if (msg->size < offsetof(struct ofp_packet_in, data)) {
-        VLOG_WARN("packet too short (%zu bytes) for packet_in", msg->size);
+        VLOG_WARN_RL(&vrl, "packet too short (%zu bytes) for packet_in",
+                     msg->size);
         return false;
     }
 
@@ -1036,7 +1040,8 @@ switch_status_packet_cb(struct relay *r, int half, void *ss_)
         return false;
     }
     if (msg->size < sizeof(struct ofp_stats_request)) {
-        VLOG_WARN("packet too short (%zu bytes) for stats_request", msg->size);
+        VLOG_WARN_RL(&vrl, "packet too short (%zu bytes) for stats_request",
+                     msg->size);
         return false;
     }
 
@@ -1317,13 +1322,13 @@ validate_dhcp_offer(const struct dhcp_msg *msg, void *s_)
 
     vconn_name = dhcp_msg_get_string(msg, DHCP_CODE_OFP_CONTROLLER_VCONN);
     if (!vconn_name) {
-        VLOG_WARN("rejecting DHCP offer missing controller vconn");
+        VLOG_WARN_RL(&vrl, "rejecting DHCP offer missing controller vconn");
         return false;
     }
     accept = !regexec(&s->accept_controller_regex, vconn_name, 0, NULL, 0);
     if (!accept) {
-        VLOG_WARN("rejecting controller vconn that fails to match %s",
-                  s->accept_controller_re);
+        VLOG_WARN_RL(&vrl, "rejecting controller vconn that fails to match %s",
+                     s->accept_controller_re);
     }
     free(vconn_name);
     return accept;

diff --git a/switch/datapath.c b/switch/datapath.c
index 26fb06c..4776c61 100644 (file)
--- a/switch/datapath.c
+++ b/switch/datapath.c
@@ -139,6 +139,8 @@ struct datapath {
     struct list port_list; /* List of ports, for flooding. */
 };
 
+static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(60, 60);
+
 static struct remote *remote_create(struct datapath *, struct rconn *);
 static void remote_run(struct datapath *, struct remote *);
 static void remote_wait(struct remote *);
@@ -331,8 +333,8 @@ dp_run(struct datapath *dp)
             fwd_port_input(dp, buffer, port_no(dp, p));
             buffer = NULL;
         } else if (error != EAGAIN) {
-            VLOG_ERR("error receiving data from %s: %s",
-                     netdev_get_name(p->netdev), strerror(error));
+            VLOG_ERR_RL(&rl, "error receiving data from %s: %s",
+                        netdev_get_name(p->netdev), strerror(error));
         }
     }
     buffer_delete(buffer);
@@ -349,7 +351,7 @@ dp_run(struct datapath *dp)
             retval = vconn_accept(dp->listen_vconn, &new_vconn);
             if (retval) {
                 if (retval != EAGAIN) {
-                    VLOG_WARN("accept failed (%s)", strerror(retval));
+                    VLOG_WARN_RL(&rl, "accept failed (%s)", strerror(retval));
                 }
                 break;
             }
@@ -385,7 +387,7 @@ remote_run(struct datapath *dp, struct remote *r)
                 sender.xid = oh->xid;
                 fwd_control_input(dp, &sender, buffer->data, buffer->size);
             } else {
-                VLOG_WARN("received too-short OpenFlow message");
+                VLOG_WARN_RL(&rl, "received too-short OpenFlow message");
             }
             buffer_delete(buffer); 
         } else {
@@ -393,7 +395,8 @@ remote_run(struct datapath *dp, struct remote *r)
                 int error = r->cb_dump(dp, r->cb_aux);
                 if (error <= 0) {
                     if (error) {
-                        VLOG_WARN("dump callback error: %s", strerror(-error));
+                        VLOG_WARN_RL(&rl, "dump callback error: %s",
+                                     strerror(-error));
                     }
                     r->cb_done(r->cb_aux);
                     r->cb_dump = NULL;
@@ -555,8 +558,7 @@ output_packet(struct datapath *dp, struct buffer *buffer, int out_port)
     }
 
     buffer_delete(buffer);
-    /* FIXME: ratelimit */
-    VLOG_DBG("can't forward to bad port %d\n", out_port);
+    VLOG_DBG_RL(&rl, "can't forward to bad port %d\n", out_port);
 }
 
 /* Takes ownership of 'buffer' and transmits it to 'out_port' on 'dp'.
@@ -581,8 +583,7 @@ dp_output_port(struct datapath *dp, struct buffer *buffer,
         }
     } else {
         if (in_port == out_port) {
-            /* FIXME: ratelimit */
-            VLOG_DBG("can't directly forward to input port");
+            VLOG_DBG_RL(&rl, "can't directly forward to input port");
             return;
         }
         output_packet(dp, buffer, out_port);
@@ -610,8 +611,8 @@ send_openflow_buffer(struct datapath *dp, struct buffer *buffer,
               ? rconn_send(rconn, buffer, &remote->n_txq)
               : EAGAIN);
     if (retval) {
-        VLOG_WARN("send to %s failed: %s",
-                  rconn_get_name(rconn), strerror(retval));
+        VLOG_WARN_RL(&rl, "send to %s failed: %s",
+                     rconn_get_name(rconn), strerror(retval));
         buffer_delete(buffer);
     }
     return retval;
@@ -746,8 +747,8 @@ update_port_status(struct sw_port *p)
     uint32_t orig_status = p->status;
 
     if (netdev_get_flags(p->netdev, &flags) < 0) {
-        VLOG_WARN("could not get netdev flags for %s", 
-                  netdev_get_name(p->netdev));
+        VLOG_WARN_RL(&rl, "could not get netdev flags for %s", 
+                     netdev_get_name(p->netdev));
         return 0;
     } else {
         if (flags & NETDEV_UP) {
@@ -1110,7 +1111,7 @@ recv_packet_out(struct datapath *dp, const struct sender *sender UNUSED,
     int act_len = n_actions * sizeof opo->actions[0];
 
     if (act_len > (ntohs(opo->header.length) - sizeof *opo)) {
-        VLOG_DBG("message too short for number of actions");
+        VLOG_DBG_RL(&rl, "message too short for number of actions");
         return -EINVAL;
     }
 
@@ -1574,7 +1575,7 @@ recv_stats_request(struct datapath *dp, const struct sender *sender,
 
     type = ntohs(rq->type);
     if (type >= ARRAY_SIZE(stats) || !stats[type].dump) {
-        VLOG_WARN("received stats request of unknown type %d", type);
+        VLOG_WARN_RL(&rl, "received stats request of unknown type %d", type);
         return -EINVAL;
     }
 
@@ -1587,8 +1588,8 @@ recv_stats_request(struct datapath *dp, const struct sender *sender,
     
     body_len = rq_len - offsetof(struct ofp_stats_request, body);
     if (body_len < cb->s->min_body || body_len > cb->s->max_body) {
-        VLOG_WARN("stats request type %d with bad body length %d",
-                  type, body_len);
+        VLOG_WARN_RL(&rl, "stats request type %d with bad body length %d",
+                     type, body_len);
         err = -EINVAL;
         goto error;
     }
@@ -1596,8 +1597,9 @@ recv_stats_request(struct datapath *dp, const struct sender *sender,
     if (cb->s->init) {
         err = cb->s->init(dp, rq->body, body_len, &cb->state);
         if (err) {
-            VLOG_WARN("failed initialization of stats request type %d: %s",
-                      type, strerror(-err));
+            VLOG_WARN_RL(&rl,
+                         "failed initialization of stats request type %d: %s",
+                         type, strerror(-err));
             goto error;
         }
     }

diff --git a/utilities/ofp-discover.c b/utilities/ofp-discover.c
index bf5e92d..70c53ee 100644 (file)
--- a/utilities/ofp-discover.c
+++ b/utilities/ofp-discover.c
@@ -272,12 +272,13 @@ modify_dhcp_request(struct dhcp_msg *msg, void *aux)
 static bool
 validate_dhcp_offer(const struct dhcp_msg *msg, void *aux)
 {
+    static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(60, 60);
     char *vconn_name;
     bool accept;
 
     vconn_name = dhcp_msg_get_string(msg, DHCP_CODE_OFP_CONTROLLER_VCONN);
     if (!vconn_name) {
-        VLOG_WARN("rejecting DHCP offer missing controller vconn");
+        VLOG_WARN_RL(&rl, "rejecting DHCP offer missing controller vconn");
         return false;
     }
     accept = !regexec(&accept_controller_regex, vconn_name, 0, NULL, 0);