vlog: Apply rate-limiting everywhere it seems warranted.
[sliver-openvswitch.git] / lib / dhcp.c
index 9ab9cc6..2e9f3df 100644 (file)
@@ -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 *
@@ -374,6 +379,31 @@ dhcp_msg_get_uint16(const struct dhcp_msg *msg, int code,
     }
 }
 
+/* Appends a string representing 'duration' seconds to 'ds'. */
+static void
+put_duration(struct ds *ds, unsigned int duration)
+{
+    if (duration) {
+        if (duration >= 86400) {
+            ds_put_format(ds, "%ud", duration / 86400);
+            duration %= 86400;
+        }
+        if (duration >= 3600) {
+            ds_put_format(ds, "%uh", duration / 3600);
+            duration %= 3600;
+        }
+        if (duration >= 60) {
+            ds_put_format(ds, "%umin", duration / 60);
+            duration %= 60;
+        }
+        if (duration > 0) {
+            ds_put_format(ds, "%us", duration);
+        }
+    } else {
+        ds_put_cstr(ds, "0s");
+    }
+}
+
 /* Appends a string representation of 'opt', which has the given 'code', to
  * 'ds'. */
 const char *
@@ -394,17 +424,22 @@ dhcp_option_to_string(const struct dhcp_option *opt, int code, struct ds *ds)
     }
     ds_put_char(ds, '=');
 
+    if (!opt->data || !opt->n) {
+        ds_put_cstr(ds, opt->data ? "empty" : "null");
+        return ds_cstr(ds);
+    }
+
     if (class->type == DHCP_ARG_STRING) {
         ds_put_char(ds, '"');
+        ds_put_printable(ds, opt->data, opt->n);
+        ds_put_char(ds, '"');
+        return ds_cstr(ds);
     }
     for (offset = 0; offset + type->size <= opt->n; offset += type->size) {
         const void *p = (const char *) opt->data + offset;
         const uint8_t *uint8 = p;
         const uint32_t *uint32 = p;
         const uint16_t *uint16 = p;
-        const char *cp = p;
-        unsigned char c;
-        unsigned int secs;
 
         if (offset && class->type != DHCP_ARG_STRING) {
             ds_put_cstr(ds, class->type == DHCP_ARG_UINT8 ? ":" : ", ");
@@ -425,31 +460,10 @@ dhcp_option_to_string(const struct dhcp_option *opt, int code, struct ds *ds)
             ds_put_format(ds, "%"PRIu32, ntohl(*uint32));
             break;
         case DHCP_ARG_SECS:
-            secs = ntohl(*uint32);
-            if (secs >= 86400) {
-                ds_put_format(ds, "%ud", secs / 86400);
-                secs %= 86400;
-            }
-            if (secs >= 3600) {
-                ds_put_format(ds, "%uh", secs / 3600);
-                secs %= 3600;
-            }
-            if (secs >= 60) {
-                ds_put_format(ds, "%umin", secs / 60);
-                secs %= 60;
-            }
-            if (secs > 0 || *uint32 == 0) {
-                ds_put_format(ds, "%us", secs);
-            }
+            put_duration(ds, ntohl(*uint32));
             break;
         case DHCP_ARG_STRING:
-            c = *cp;
-            if (isprint(c) && (!isspace(c) || c == ' ') && c != '\\') {
-                ds_put_char(ds, *cp);
-            } else {
-                ds_put_format(ds, "\\%03o", (int) c);
-            }
-            break;
+            NOT_REACHED();
         case DHCP_ARG_BOOLEAN:
             if (*uint8 == 0) {
                 ds_put_cstr(ds, "false");
@@ -461,9 +475,6 @@ dhcp_option_to_string(const struct dhcp_option *opt, int code, struct ds *ds)
             break;
         }
     }
-    if (class->type == DHCP_ARG_STRING) {
-        ds_put_char(ds, '"');
-    }
     if (offset != opt->n) {
         if (offset) {
             ds_put_cstr(ds, ", ");
@@ -479,6 +490,15 @@ dhcp_option_to_string(const struct dhcp_option *opt, int code, struct ds *ds)
     return ds_cstr(ds);
 }
 
+/* Returns true if 'a' and 'b' have the same content, false otherwise. */
+bool
+dhcp_option_equals(const struct dhcp_option *a, const struct dhcp_option *b)
+{
+    return ((a->data != NULL) == (b->data != NULL)
+            && a->n == b->n
+            && !memcmp(a->data, b->data, a->n));
+}
+
 /* Replaces 'ds' by a string representation of 'msg'.  If 'multiline' is
  * false, 'ds' receives a single-line representation of 'msg', otherwise a
  * multiline representation. */
@@ -489,13 +509,14 @@ dhcp_msg_to_string(const struct dhcp_msg *msg, bool multiline, struct ds *ds)
     int code;
 
     ds_clear(ds);
-    ds_put_format(ds, "%s%c%s%cxid=%08"PRIx32"%csecs=%"PRIu16,
-                  (msg->op == DHCP_BOOTREQUEST ? "BOOTREQUEST"
-                   : msg->op == DHCP_BOOTREPLY ? "BOOTREPLY"
-                   : "<<bad DHCP op>>"),
-                  separator, dhcp_type_name(msg->type),
-                  separator, msg->xid,
-                  separator, msg->secs);
+    ds_put_format(ds, "op=%s",
+                  (msg->op == DHCP_BOOTREQUEST ? "request"
+                   : msg->op == DHCP_BOOTREPLY ? "reply"
+                   : "error"));
+    ds_put_format(ds, "%ctype=%s", separator, dhcp_type_name(msg->type));
+    ds_put_format(ds, "%cxid=0x%08"PRIx32, separator, msg->xid);
+    ds_put_format(ds, "%csecs=", separator);
+    put_duration(ds, msg->secs);
     if (msg->flags) {
         ds_put_format(ds, "%cflags=", separator);
         if (msg->flags & DHCP_FLAGS_BROADCAST) {
@@ -554,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);
@@ -583,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;
@@ -623,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;
     }
 
@@ -669,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);
@@ -686,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;
     }
@@ -699,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);
     }