netlink-socket: Reduce nl_sock_recv() from 2 (or more) system calls to 1.
[sliver-openvswitch.git] / lib / netlink-socket.c
index 9e3dd97..719f658 100644 (file)
@@ -24,6 +24,8 @@
 #include <unistd.h>
 #include "coverage.h"
 #include "dynamic-string.h"
+#include "hash.h"
+#include "hmap.h"
 #include "netlink.h"
 #include "netlink-protocol.h"
 #include "ofpbuf.h"
@@ -36,7 +38,7 @@ VLOG_DEFINE_THIS_MODULE(netlink_socket);
 
 COVERAGE_DEFINE(netlink_overflow);
 COVERAGE_DEFINE(netlink_received);
-COVERAGE_DEFINE(netlink_recv_retry);
+COVERAGE_DEFINE(netlink_recv_jumbo);
 COVERAGE_DEFINE(netlink_send);
 COVERAGE_DEFINE(netlink_sent);
 
@@ -51,7 +53,7 @@ COVERAGE_DEFINE(netlink_sent);
 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);
+                      const void *message, size_t size, int protocol);
 \f
 /* Netlink sockets. */
 
@@ -59,10 +61,14 @@ struct nl_sock
 {
     int fd;
     uint32_t pid;
+    int protocol;
+    bool any_groups;
+    struct nl_dump *dump;
 };
 
 static int alloc_pid(uint32_t *);
 static void free_pid(uint32_t);
+static int nl_sock_cow__(struct nl_sock *);
 
 /* Creates a new netlink socket for the given netlink 'protocol'
  * (NETLINK_ROUTE, NETLINK_GENERIC, ...).  Returns 0 and sets '*sockp' to the
@@ -85,6 +91,9 @@ nl_sock_create(int protocol, struct nl_sock **sockp)
         VLOG_ERR("fcntl: %s", strerror(errno));
         goto error;
     }
+    sock->protocol = protocol;
+    sock->any_groups = false;
+    sock->dump = NULL;
 
     retval = alloc_pid(&sock->pid);
     if (retval) {
@@ -128,14 +137,27 @@ error:
     return retval;
 }
 
+/* Creates a new netlink socket for the same protocol as 'src'.  Returns 0 and
+ * sets '*sockp' to the new socket if successful, otherwise returns a positive
+ * errno value.  */
+int
+nl_sock_clone(const struct nl_sock *src, struct nl_sock **sockp)
+{
+    return nl_sock_create(src->protocol, sockp);
+}
+
 /* Destroys netlink socket 'sock'. */
 void
 nl_sock_destroy(struct nl_sock *sock)
 {
     if (sock) {
-        close(sock->fd);
-        free_pid(sock->pid);
-        free(sock);
+        if (sock->dump) {
+            sock->dump = NULL;
+        } else {
+            close(sock->fd);
+            free_pid(sock->pid);
+            free(sock);
+        }
     }
 }
 
@@ -149,12 +171,17 @@ nl_sock_destroy(struct nl_sock *sock)
 int
 nl_sock_join_mcgroup(struct nl_sock *sock, unsigned int multicast_group)
 {
+    int error = nl_sock_cow__(sock);
+    if (error) {
+        return error;
+    }
     if (setsockopt(sock->fd, SOL_NETLINK, NETLINK_ADD_MEMBERSHIP,
                    &multicast_group, sizeof multicast_group) < 0) {
         VLOG_WARN("could not join multicast group %u (%s)",
                   multicast_group, strerror(errno));
         return errno;
     }
+    sock->any_groups = true;
     return 0;
 }
 
@@ -171,6 +198,7 @@ nl_sock_join_mcgroup(struct nl_sock *sock, unsigned int multicast_group)
 int
 nl_sock_leave_mcgroup(struct nl_sock *sock, unsigned int multicast_group)
 {
+    assert(!sock->dump);
     if (setsockopt(sock->fd, SOL_NETLINK, NETLINK_DROP_MEMBERSHIP,
                    &multicast_group, sizeof multicast_group) < 0) {
         VLOG_WARN("could not leave multicast group %u (%s)",
@@ -180,15 +208,8 @@ nl_sock_leave_mcgroup(struct nl_sock *sock, unsigned int multicast_group)
     return 0;
 }
 
-/* Tries to send 'msg', which must contain a Netlink message, to the kernel on
- * 'sock'.  nlmsg_len in 'msg' will be finalized to match msg->size, and
- * nlmsg_pid will be set to 'sock''s pid, before the message is sent.
- *
- * Returns 0 if successful, otherwise a positive errno value.  If
- * 'wait' is true, then the send will wait until buffer space is ready;
- * otherwise, returns EAGAIN if the 'sock' send buffer is full. */
-int
-nl_sock_send(struct nl_sock *sock, const struct ofpbuf *msg, bool wait)
+static int
+nl_sock_send__(struct nl_sock *sock, const struct ofpbuf *msg, bool wait)
 {
     struct nlmsghdr *nlmsg = nl_msg_nlmsghdr(msg);
     int error;
@@ -200,43 +221,28 @@ nl_sock_send(struct nl_sock *sock, const struct ofpbuf *msg, bool wait)
         retval = send(sock->fd, msg->data, msg->size, wait ? 0 : MSG_DONTWAIT);
         error = retval < 0 ? errno : 0;
     } while (error == EINTR);
-    log_nlmsg(__func__, error, msg->data, msg->size);
+    log_nlmsg(__func__, error, msg->data, msg->size, sock->protocol);
     if (!error) {
         COVERAGE_INC(netlink_sent);
     }
     return error;
 }
 
-/* Tries to send the 'n_iov' chunks of data in 'iov' to the kernel on 'sock' as
- * a single Netlink message.  (The message must be fully formed and not require
- * finalization of its nlmsg_len or nlmsg_pid fields.)
+/* Tries to send 'msg', which must contain a Netlink message, to the kernel on
+ * 'sock'.  nlmsg_len in 'msg' will be finalized to match msg->size, and
+ * nlmsg_pid will be set to 'sock''s pid, before the message is sent.
  *
- * Returns 0 if successful, otherwise a positive errno value.  If 'wait' is
- * true, then the send will wait until buffer space is ready; otherwise,
- * returns EAGAIN if the 'sock' send buffer is full. */
+ * Returns 0 if successful, otherwise a positive errno value.  If
+ * 'wait' is true, then the send will wait until buffer space is ready;
+ * otherwise, returns EAGAIN if the 'sock' send buffer is full. */
 int
-nl_sock_sendv(struct nl_sock *sock, const struct iovec iov[], size_t n_iov,
-              bool wait)
+nl_sock_send(struct nl_sock *sock, const struct ofpbuf *msg, bool wait)
 {
-    struct msghdr msg;
-    int error;
-
-    COVERAGE_INC(netlink_send);
-    memset(&msg, 0, sizeof msg);
-    msg.msg_iov = (struct iovec *) iov;
-    msg.msg_iovlen = n_iov;
-    do {
-        int retval;
-        retval = sendmsg(sock->fd, &msg, wait ? 0 : MSG_DONTWAIT);
-        error = retval < 0 ? errno : 0;
-    } while (error == EINTR);
-    if (error != EAGAIN) {
-        log_nlmsg(__func__, error, iov[0].iov_base, iov[0].iov_len);
-        if (!error) {
-            COVERAGE_INC(netlink_sent);
-        }
+    int error = nl_sock_cow__(sock);
+    if (error) {
+        return error;
     }
-    return error;
+    return nl_sock_send__(sock, msg, wait);
 }
 
 /* This stress option is useful for testing that OVS properly tolerates
@@ -248,84 +254,71 @@ STRESS_OPTION(
     netlink_overflow, "simulate netlink socket receive buffer overflow",
     5, 1, -1, 100);
 
-/* Tries to receive a netlink message from the kernel on 'sock'.  If
- * successful, stores the received message into '*bufp' and returns 0.  The
- * caller is responsible for destroying the message with ofpbuf_delete().  On
- * failure, returns a positive errno value and stores a null pointer into
- * '*bufp'.
- *
- * If 'wait' is true, nl_sock_recv waits for a message to be ready; otherwise,
- * returns EAGAIN if the 'sock' receive buffer is empty. */
-int
-nl_sock_recv(struct nl_sock *sock, struct ofpbuf **bufp, bool wait)
+static int
+nl_sock_recv__(struct nl_sock *sock, struct ofpbuf **bufp, bool wait)
 {
-    uint8_t tmp;
-    ssize_t bufsize = 2048;
-    ssize_t nbytes, nbytes2;
-    struct ofpbuf *buf;
+    /* We can't accurately predict the size of the data to be received.  Most
+     * received data will fit in a 2 kB buffer, so we allocate that much space.
+     * In case the data is actually bigger than that, we make available enough
+     * additional space to allow Netlink messages to be up to 64 kB long (a
+     * reasonable figure since that's the maximum length of a Netlink
+     * attribute). */
+    enum { MAX_SIZE = 65536 };
+    enum { HEAD_SIZE = 2048 };
+    enum { TAIL_SIZE = MAX_SIZE - HEAD_SIZE };
+
     struct nlmsghdr *nlmsghdr;
-    struct iovec iov;
-    struct msghdr msg = {
-        .msg_name = NULL,
-        .msg_namelen = 0,
-        .msg_iov = &iov,
-        .msg_iovlen = 1,
-        .msg_control = NULL,
-        .msg_controllen = 0,
-        .msg_flags = 0
-    };
+    uint8_t tail[TAIL_SIZE];
+    struct iovec iov[2];
+    struct ofpbuf *buf;
+    struct msghdr msg;
+    ssize_t retval;
 
-    buf = ofpbuf_new(bufsize);
     *bufp = NULL;
 
-try_again:
-    /* Attempt to read the message.  We don't know the size of the data
-     * yet, so we take a guess at 2048.  If we're wrong, we keep trying
-     * and doubling the buffer size each time.
-     */
-    nlmsghdr = ofpbuf_put_uninit(buf, bufsize);
-    iov.iov_base = nlmsghdr;
-    iov.iov_len = bufsize;
+    buf = ofpbuf_new(HEAD_SIZE);
+    iov[0].iov_base = buf->data;
+    iov[0].iov_len = HEAD_SIZE;
+    iov[1].iov_base = tail;
+    iov[1].iov_len = TAIL_SIZE;
+
+    memset(&msg, 0, sizeof msg);
+    msg.msg_iov = iov;
+    msg.msg_iovlen = 2;
+
     do {
-        nbytes = recvmsg(sock->fd, &msg, (wait ? 0 : MSG_DONTWAIT) | MSG_PEEK);
-    } while (nbytes < 0 && errno == EINTR);
-    if (nbytes < 0) {
+        retval = recvmsg(sock->fd, &msg, wait ? 0 : MSG_DONTWAIT);
+    } while (retval < 0 && errno == EINTR);
+
+    if (retval < 0) {
+        int error = errno;
+        if (error == ENOBUFS) {
+            /* Socket receive buffer overflow dropped one or more messages that
+             * the kernel tried to send to us. */
+            COVERAGE_INC(netlink_overflow);
+        }
         ofpbuf_delete(buf);
-        return errno;
+        return error;
     }
+
     if (msg.msg_flags & MSG_TRUNC) {
-        COVERAGE_INC(netlink_recv_retry);
-        bufsize *= 2;
-        ofpbuf_reinit(buf, bufsize);
-        goto try_again;
+        VLOG_ERR_RL(&rl, "truncated message (longer than %d bytes)", MAX_SIZE);
+        ofpbuf_delete(buf);
+        return E2BIG;
     }
-    buf->size = nbytes;
 
-    /* We successfully read the message, so recv again to clear the queue */
-    iov.iov_base = &tmp;
-    iov.iov_len = 1;
-    do {
-        nbytes2 = recvmsg(sock->fd, &msg, MSG_DONTWAIT);
-    } while (nbytes2 < 0 && errno == EINTR);
-    if (nbytes2 < 0) {
-        if (errno == ENOBUFS) {
-            /* The kernel is notifying us that a message it tried to send to us
-             * was dropped.  We have to pass this along to the caller in case
-             * it wants to retry a request.  So kill the buffer, which we can
-             * re-read next time. */
-            COVERAGE_INC(netlink_overflow);
-            ofpbuf_delete(buf);
-            return ENOBUFS;
-        } else {
-            VLOG_ERR_RL(&rl, "failed to remove nlmsg from socket: %s\n",
-                        strerror(errno));
-        }
+    ofpbuf_put_uninit(buf, MIN(retval, HEAD_SIZE));
+    if (retval > HEAD_SIZE) {
+        COVERAGE_INC(netlink_recv_jumbo);
+        ofpbuf_put(buf, tail, retval - HEAD_SIZE);
     }
-    if (nbytes < sizeof *nlmsghdr
+
+    nlmsghdr = buf->data;
+    if (retval < sizeof *nlmsghdr
         || nlmsghdr->nlmsg_len < sizeof *nlmsghdr
-        || nlmsghdr->nlmsg_len > nbytes) {
+        || nlmsghdr->nlmsg_len > retval) {
         VLOG_ERR_RL(&rl, "received invalid nlmsg (%zd bytes < %d)",
-                    bufsize, NLMSG_HDRLEN);
+                    retval, NLMSG_HDRLEN);
         ofpbuf_delete(buf);
         return EPROTO;
     }
@@ -336,12 +329,30 @@ try_again:
     }
 
     *bufp = buf;
-    log_nlmsg(__func__, 0, buf->data, buf->size);
+    log_nlmsg(__func__, 0, buf->data, buf->size, sock->protocol);
     COVERAGE_INC(netlink_received);
 
     return 0;
 }
 
+/* Tries to receive a netlink message from the kernel on 'sock'.  If
+ * successful, stores the received message into '*bufp' and returns 0.  The
+ * caller is responsible for destroying the message with ofpbuf_delete().  On
+ * failure, returns a positive errno value and stores a null pointer into
+ * '*bufp'.
+ *
+ * If 'wait' is true, nl_sock_recv waits for a message to be ready; otherwise,
+ * returns EAGAIN if the 'sock' receive buffer is empty. */
+int
+nl_sock_recv(struct nl_sock *sock, struct ofpbuf **bufp, bool wait)
+{
+    int error = nl_sock_cow__(sock);
+    if (error) {
+        return error;
+    }
+    return nl_sock_recv__(sock, bufp, wait);
+}
+
 /* Sends 'request' to the kernel via 'sock' and waits for a response.  If
  * successful, returns 0.  On failure, returns a positive errno value.
  *
@@ -418,7 +429,7 @@ recv:
     }
     nlmsghdr = nl_msg_nlmsghdr(reply);
     if (seq != nlmsghdr->nlmsg_seq) {
-        VLOG_DBG_RL(&rl, "ignoring seq %"PRIu32" != expected %"PRIu32,
+        VLOG_DBG_RL(&rl, "ignoring seq %#"PRIx32" != expected %#"PRIx32,
                     nl_msg_nlmsghdr(reply)->nlmsg_seq, seq);
         ofpbuf_delete(reply);
         goto recv;
@@ -451,9 +462,47 @@ recv:
 int
 nl_sock_drain(struct nl_sock *sock)
 {
+    int error = nl_sock_cow__(sock);
+    if (error) {
+        return error;
+    }
     return drain_rcvbuf(sock->fd);
 }
 
+/* The client is attempting some operation on 'sock'.  If 'sock' has an ongoing
+ * dump operation, then replace 'sock''s fd with a new socket and hand 'sock''s
+ * old fd over to the dump. */
+static int
+nl_sock_cow__(struct nl_sock *sock)
+{
+    struct nl_sock *copy;
+    uint32_t tmp_pid;
+    int tmp_fd;
+    int error;
+
+    if (!sock->dump) {
+        return 0;
+    }
+
+    error = nl_sock_clone(sock, &copy);
+    if (error) {
+        return error;
+    }
+
+    tmp_fd = sock->fd;
+    sock->fd = copy->fd;
+    copy->fd = tmp_fd;
+
+    tmp_pid = sock->pid;
+    sock->pid = copy->pid;
+    copy->pid = tmp_pid;
+
+    sock->dump->sock = copy;
+    sock->dump = NULL;
+
+    return 0;
+}
+
 /* Starts a Netlink "dump" operation, by sending 'request' to the kernel via
  * 'sock', and initializes 'dump' to reflect the state of the operation.
  *
@@ -461,22 +510,23 @@ nl_sock_drain(struct nl_sock *sock)
  * be set to 'sock''s pid, before the message is sent.  NLM_F_DUMP and
  * NLM_F_ACK will be set in nlmsg_flags.
  *
- * The properties of Netlink make dump operations reliable as long as all of
- * the following are true:
- *
- *   - At most a single dump is in progress at a time on a given nl_sock.
+ * This Netlink socket library is designed to ensure that the dump is reliable
+ * and that it will not interfere with other operations on 'sock', including
+ * destroying or sending and receiving messages on 'sock'.  One corner case is
+ * not handled:
  *
- *   - The nl_sock is not subscribed to any multicast groups.
- *
- *   - The nl_sock is not used to send any other messages before the dump
- *     operation is complete.
+ *   - If 'sock' has been used to send a request (e.g. with nl_sock_send())
+ *     whose response has not yet been received (e.g. with nl_sock_recv()).
+ *     This is unusual: usually nl_sock_transact() is used to send a message
+ *     and receive its reply all in one go.
  *
  * This function provides no status indication.  An error status for the entire
  * dump operation is provided when it is completed by calling nl_dump_done().
  *
- * The caller is responsible for destroying 'request'.  The caller must not
- * close 'sock' before it completes the dump operation (by calling
- * nl_dump_done()).
+ * The caller is responsible for destroying 'request'.
+ *
+ * The new 'dump' is independent of 'sock'.  'sock' and 'dump' may be destroyed
+ * in either order.
  */
 void
 nl_dump_start(struct nl_dump *dump,
@@ -485,9 +535,21 @@ nl_dump_start(struct nl_dump *dump,
     struct nlmsghdr *nlmsghdr = nl_msg_nlmsghdr(request);
     nlmsghdr->nlmsg_flags |= NLM_F_DUMP | NLM_F_ACK;
     dump->seq = nlmsghdr->nlmsg_seq;
-    dump->sock = sock;
-    dump->status = nl_sock_send(sock, request, true);
     dump->buffer = NULL;
+    if (sock->any_groups || sock->dump) {
+        /* 'sock' might belong to some multicast group, or it already has an
+         * onoging dump.  Clone the socket to avoid possibly intermixing
+         * multicast messages or previous dump results with our results. */
+        dump->status = nl_sock_clone(sock, &dump->sock);
+        if (dump->status) {
+            return;
+        }
+    } else {
+        sock->dump = dump;
+        dump->sock = sock;
+        dump->status = 0;
+    }
+    dump->status = nl_sock_send__(sock, request, true);
 }
 
 /* Helper function for nl_dump_next(). */
@@ -498,7 +560,7 @@ nl_dump_recv(struct nl_dump *dump, struct ofpbuf **bufferp)
     struct ofpbuf *buffer;
     int retval;
 
-    retval = nl_sock_recv(dump->sock, bufferp, true);
+    retval = nl_sock_recv__(dump->sock, bufferp, true);
     if (retval) {
         return retval == EINTR ? EAGAIN : retval;
     }
@@ -506,7 +568,7 @@ nl_dump_recv(struct nl_dump *dump, struct ofpbuf **bufferp)
 
     nlmsghdr = nl_msg_nlmsghdr(buffer);
     if (dump->seq != nlmsghdr->nlmsg_seq) {
-        VLOG_DBG_RL(&rl, "ignoring seq %"PRIu32" != expected %"PRIu32,
+        VLOG_DBG_RL(&rl, "ignoring seq %#"PRIx32" != expected %#"PRIx32,
                     nlmsghdr->nlmsg_seq, dump->seq);
         return EAGAIN;
     }
@@ -587,6 +649,13 @@ nl_dump_done(struct nl_dump *dump)
         }
     }
 
+    if (dump->sock) {
+        if (dump->sock->dump) {
+            dump->sock->dump = NULL;
+        } else {
+            nl_sock_destroy(dump->sock);
+        }
+    }
     ofpbuf_delete(dump->buffer);
     return dump->status == EOF ? 0 : dump->status;
 }
@@ -601,10 +670,61 @@ nl_sock_wait(const struct nl_sock *sock, short int events)
 \f
 /* Miscellaneous.  */
 
+struct genl_family {
+    struct hmap_node hmap_node;
+    uint16_t id;
+    char *name;
+};
+
+static struct hmap genl_families = HMAP_INITIALIZER(&genl_families);
+
 static const struct nl_policy family_policy[CTRL_ATTR_MAX + 1] = {
     [CTRL_ATTR_FAMILY_ID] = {.type = NL_A_U16},
 };
 
+static struct genl_family *
+find_genl_family_by_id(uint16_t id)
+{
+    struct genl_family *family;
+
+    HMAP_FOR_EACH_IN_BUCKET (family, hmap_node, hash_int(id, 0),
+                             &genl_families) {
+        if (family->id == id) {
+            return family;
+        }
+    }
+    return NULL;
+}
+
+static void
+define_genl_family(uint16_t id, const char *name)
+{
+    struct genl_family *family = find_genl_family_by_id(id);
+
+    if (family) {
+        if (!strcmp(family->name, name)) {
+            return;
+        }
+        free(family->name);
+    } else {
+        family = xmalloc(sizeof *family);
+        family->id = id;
+        hmap_insert(&genl_families, &family->hmap_node, hash_int(id, 0));
+    }
+    family->name = xstrdup(name);
+}
+
+static const char *
+genl_family_to_name(uint16_t id)
+{
+    if (id == GENL_ID_CTRL) {
+        return "control";
+    } else {
+        struct genl_family *family = find_genl_family_by_id(id);
+        return family ? family->name : "unknown";
+    }
+}
+
 static int do_lookup_genl_family(const char *name)
 {
     struct nl_sock *sock;
@@ -638,9 +758,12 @@ static int do_lookup_genl_family(const char *name)
     retval = nl_attr_get_u16(attrs[CTRL_ATTR_FAMILY_ID]);
     if (retval == 0) {
         retval = -EPROTO;
+    } else {
+        define_genl_family(retval, name);
     }
     nl_sock_destroy(sock);
     ofpbuf_delete(reply);
+
     return retval;
 }
 
@@ -707,7 +830,7 @@ free_pid(uint32_t pid)
 }
 \f
 static void
-nlmsghdr_to_string(const struct nlmsghdr *h, struct ds *ds)
+nlmsghdr_to_string(const struct nlmsghdr *h, int protocol, struct ds *ds)
 {
     struct nlmsg_flag {
         unsigned int bits;
@@ -738,6 +861,8 @@ nlmsghdr_to_string(const struct nlmsghdr *h, struct ds *ds)
         ds_put_cstr(ds, "(overrun)");
     } else if (h->nlmsg_type < NLMSG_MIN_TYPE) {
         ds_put_cstr(ds, "(reserved)");
+    } else if (protocol == NETLINK_GENERIC) {
+        ds_put_format(ds, "(%s)", genl_family_to_name(h->nlmsg_type));
     } else {
         ds_put_cstr(ds, "(family-defined)");
     }
@@ -759,12 +884,12 @@ nlmsghdr_to_string(const struct nlmsghdr *h, struct ds *ds)
 }
 
 static char *
-nlmsg_to_string(const struct ofpbuf *buffer)
+nlmsg_to_string(const struct ofpbuf *buffer, int protocol)
 {
     struct ds ds = DS_EMPTY_INITIALIZER;
     const struct nlmsghdr *h = ofpbuf_at(buffer, 0, NLMSG_HDRLEN);
     if (h) {
-        nlmsghdr_to_string(h, &ds);
+        nlmsghdr_to_string(h, protocol, &ds);
         if (h->nlmsg_type == NLMSG_ERROR) {
             const struct nlmsgerr *e;
             e = ofpbuf_at(buffer, NLMSG_HDRLEN,
@@ -775,7 +900,7 @@ nlmsg_to_string(const struct ofpbuf *buffer)
                     ds_put_format(&ds, "(%s)", strerror(-e->error));
                 }
                 ds_put_cstr(&ds, ", in-reply-to(");
-                nlmsghdr_to_string(&e->msg, &ds);
+                nlmsghdr_to_string(&e->msg, protocol, &ds);
                 ds_put_cstr(&ds, "))");
             } else {
                 ds_put_cstr(&ds, " error(truncated)");
@@ -791,6 +916,12 @@ nlmsg_to_string(const struct ofpbuf *buffer)
             } else {
                 ds_put_cstr(&ds, " done(truncated)");
             }
+        } else if (protocol == NETLINK_GENERIC) {
+            struct genlmsghdr *genl = nl_msg_genlmsghdr(buffer);
+            if (genl) {
+                ds_put_format(&ds, ",genl(cmd=%"PRIu8",version=%"PRIu8")",
+                              genl->cmd, genl->version);
+            }
         }
     } else {
         ds_put_cstr(&ds, "nl(truncated)");
@@ -800,7 +931,7 @@ nlmsg_to_string(const struct ofpbuf *buffer)
 
 static void
 log_nlmsg(const char *function, int error,
-          const void *message, size_t size)
+          const void *message, size_t size, int protocol)
 {
     struct ofpbuf buffer;
     char *nlmsg;
@@ -810,7 +941,7 @@ log_nlmsg(const char *function, int error,
     }
 
     ofpbuf_use_const(&buffer, message, size);
-    nlmsg = nlmsg_to_string(&buffer);
+    nlmsg = nlmsg_to_string(&buffer, protocol);
     VLOG_DBG_RL(&rl, "%s (%s): %s", function, strerror(error), nlmsg);
     free(nlmsg);
 }