vconn: Distinguish between parse errors and other messages in rate-limiting.

The vconn code wants to rate-limit errors, which there's not too much
point in reporting a lot of, from the log of all OpenFlow messages, which
are very important if we really want to log them at all.  So use a
different rate-limiter for each category.

diff --git a/lib/vconn.c b/lib/vconn.c
index 043312ce86a1e2f648368668ff35237908bcf4ea..1dec3073e162f4f03e05ce9673ce12bd9d8a1b75 100644 (file)
--- a/lib/vconn.c
+++ b/lib/vconn.c
@@ -85,10 +85,14 @@ static struct pvconn_class *pvconn_classes[] = {
 #endif
 };
 
-/* 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);
+/* Rate limit for individual OpenFlow messages going over the vconn, output at
+ * DBG level.  This is very high because, if these are enabled, it is because
+ * we really need to see them. */
+static struct vlog_rate_limit ofmsg_rl = VLOG_RATE_LIMIT_INIT(600, 600);
+
+/* Rate limit for OpenFlow message parse errors.  These always indicate a bug
+ * in the peer and so there's not much point in showing a lot of them. */
+static struct vlog_rate_limit bad_ofmsg_rl = VLOG_RATE_LIMIT_INIT(1, 5);
 
 static int do_recv(struct vconn *, struct ofpbuf **);
 static int do_send(struct vconn *, struct ofpbuf *);
@@ -334,13 +338,14 @@ vcs_recv_hello(struct vconn *vconn)
                 struct ds msg = DS_EMPTY_INITIALIZER;
                 ds_put_format(&msg, "%s: extra-long hello:\n", vconn->name);
                 ds_put_hex_dump(&msg, b->data, b->size, 0, true);
-                VLOG_WARN_RL(&rl, "%s", ds_cstr(&msg));
+                VLOG_WARN_RL(&bad_ofmsg_rl, "%s", ds_cstr(&msg));
                 ds_destroy(&msg);
             }
 
             vconn->version = MIN(OFP_VERSION, oh->version);
             if (vconn->version < vconn->min_version) {
-                VLOG_WARN_RL(&rl, "%s: version negotiation failed: we support "
+                VLOG_WARN_RL(&bad_ofmsg_rl,
+                             "%s: version negotiation failed: we support "
                              "versions 0x%02x to 0x%02x inclusive but peer "
                              "supports no later than version 0x%02"PRIx8,
                              vconn->name, vconn->min_version, OFP_VERSION,
@@ -358,7 +363,8 @@ vcs_recv_hello(struct vconn *vconn)
             return;
         } else {
             char *s = ofp_to_string(b->data, b->size, 1);
-            VLOG_WARN_RL(&rl, "%s: received message while expecting hello: %s",
+            VLOG_WARN_RL(&bad_ofmsg_rl,
+                         "%s: received message while expecting hello: %s",
                          vconn->name, s);
             free(s);
             retval = EPROTO;
@@ -471,7 +477,7 @@ again:
 
         if (VLOG_IS_DBG_ENABLED()) {
             char *s = ofp_to_string((*msgp)->data, (*msgp)->size, 1);
-            VLOG_DBG_RL(&rl, "%s: received: %s", vconn->name, s);
+            VLOG_DBG_RL(&ofmsg_rl, "%s: received: %s", vconn->name, s);
             free(s);
         }
 
@@ -498,11 +504,13 @@ again:
                     ofpbuf_delete(*msgp);
                     goto again;
                 }
-                VLOG_ERR_RL(&rl, "%s: received OpenFlow message type %"PRIu8" "
+                VLOG_ERR_RL(&bad_ofmsg_rl,
+                            "%s: received OpenFlow message type %"PRIu8" "
                             "before version negotiation complete",
                             vconn->name, oh->type);
             } else {
-                VLOG_ERR_RL(&rl, "%s: received OpenFlow version 0x%02"PRIx8" "
+                VLOG_ERR_RL(&bad_ofmsg_rl,
+                            "%s: received OpenFlow version 0x%02"PRIx8" "
                             "!= expected %02x",
                             vconn->name, oh->version, vconn->version);
             }
@@ -550,7 +558,7 @@ do_send(struct vconn *vconn, struct ofpbuf *msg)
         char *s = ofp_to_string(msg->data, msg->size, 1);
         retval = (vconn->class->send)(vconn, msg);
         if (retval != EAGAIN) {
-            VLOG_DBG_RL(&rl, "%s: sent (%s): %s",
+            VLOG_DBG_RL(&ofmsg_rl, "%s: sent (%s): %s",
                         vconn->name, strerror(retval), s);
         }
         free(s);
@@ -607,8 +615,8 @@ vconn_recv_xid(struct vconn *vconn, uint32_t xid, struct ofpbuf **replyp)
             return 0;
         }
 
-        VLOG_DBG_RL(&rl, "%s: received reply with xid %08"PRIx32" != expected "
-                    "%08"PRIx32, vconn->name, recv_xid, xid);
+        VLOG_DBG_RL(&bad_ofmsg_rl, "%s: received reply with xid %08"PRIx32
+                    " != expected %08"PRIx32, vconn->name, recv_xid, xid);
         ofpbuf_delete(reply);
     }
 }
@@ -1000,8 +1008,9 @@ check_message_type(uint8_t got_type, uint8_t want_type)
     if (got_type != want_type) {
         char *want_type_name = ofp_message_type_to_string(want_type);
         char *got_type_name = ofp_message_type_to_string(got_type);
-        VLOG_WARN("received bad message type %s (expected %s)",
-                  got_type_name, want_type_name);
+        VLOG_WARN_RL(&bad_ofmsg_rl,
+                     "received bad message type %s (expected %s)",
+                     got_type_name, want_type_name);
         free(want_type_name);
         free(got_type_name);
         return false;
@@ -1023,8 +1032,9 @@ check_ofp_message(const struct ofp_header *msg, uint8_t type, size_t size)
     got_size = ntohs(msg->length);
     if (got_size != size) {
         char *type_name = ofp_message_type_to_string(type);
-        VLOG_WARN("received %s message of length %"PRIu16" (expected %zu)",
-                  type_name, got_size, size);
+        VLOG_WARN_RL(&bad_ofmsg_rl,
+                     "received %s message of length %"PRIu16" (expected %zu)",
+                     type_name, got_size, size);
         free(type_name);
         return EINVAL;
     }
@@ -1055,19 +1065,20 @@ check_ofp_message_array(const struct ofp_header *msg, uint8_t type,
     got_size = ntohs(msg->length);
     if (got_size < min_size) {
         char *type_name = ofp_message_type_to_string(type);
-        VLOG_WARN("received %s message of length %"PRIu16" "
-                  "(expected at least %zu)",
-                  type_name, got_size, min_size);
+        VLOG_WARN_RL(&bad_ofmsg_rl, "received %s message of length %"PRIu16" "
+                     "(expected at least %zu)",
+                     type_name, got_size, min_size);
         free(type_name);
         return EINVAL;
     }
     if ((got_size - min_size) % array_elt_size) {
         char *type_name = ofp_message_type_to_string(type);
-        VLOG_WARN("received %s message of bad length %"PRIu16": the "
-                  "excess over %zu (%zu) is not evenly divisible by %zu "
-                  "(remainder is %zu)",
-                  type_name, got_size, min_size, got_size - min_size,
-                  array_elt_size, (got_size - min_size) % array_elt_size);
+        VLOG_WARN_RL(&bad_ofmsg_rl,
+                     "received %s message of bad length %"PRIu16": the "
+                     "excess over %zu (%zu) is not evenly divisible by %zu "
+                     "(remainder is %zu)",
+                     type_name, got_size, min_size, got_size - min_size,
+                     array_elt_size, (got_size - min_size) % array_elt_size);
         free(type_name);
         return EINVAL;
     }
@@ -1090,15 +1101,14 @@ flow_stats_first(struct flow_stats_iterator *iter,
 const struct ofp_flow_stats *
 flow_stats_next(struct flow_stats_iterator *iter)
 {
-    static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(1, 5);
     ptrdiff_t bytes_left = iter->end - iter->pos;
     const struct ofp_flow_stats *fs;
     size_t length;
 
     if (bytes_left < sizeof *fs) {
         if (bytes_left != 0) {
-            VLOG_WARN_RL(&rl, "%td leftover bytes in flow stats reply",
-                         bytes_left);
+            VLOG_WARN_RL(&bad_ofmsg_rl,
+                         "%td leftover bytes in flow stats reply", bytes_left);
         }
         return NULL;
     }
@@ -1106,15 +1116,15 @@ flow_stats_next(struct flow_stats_iterator *iter)
     fs = (const void *) iter->pos;
     length = ntohs(fs->length);
     if (length < sizeof *fs) {
-        VLOG_WARN_RL(&rl, "flow stats length %zu is shorter than min %zu",
-                     length, sizeof *fs);
+        VLOG_WARN_RL(&bad_ofmsg_rl, "flow stats length %zu is shorter than "
+                     "min %zu", length, sizeof *fs);
         return NULL;
     } else if (length > bytes_left) {
-        VLOG_WARN_RL(&rl, "flow stats length %zu but only %td bytes left",
-                     length, bytes_left);
+        VLOG_WARN_RL(&bad_ofmsg_rl, "flow stats length %zu but only %td "
+                     "bytes left", length, bytes_left);
         return NULL;
     } else if ((length - sizeof *fs) % sizeof fs->actions[0]) {
-        VLOG_WARN_RL(&rl, "flow stats length %zu has %zu bytes "
+        VLOG_WARN_RL(&bad_ofmsg_rl, "flow stats length %zu has %zu bytes "
                      "left over in final action", length,
                      (length - sizeof *fs) % sizeof fs->actions[0]);
         return NULL;