All of lore.kernel.org
 help / color / mirror / Atom feed
* [Qemu-devel] [PATCH v2 0/6] nbd refactoring part 2
@ 2017-06-21 15:34 Vladimir Sementsov-Ogievskiy
  2017-06-21 15:34 ` [Qemu-devel] [PATCH v2 1/6] nbd/server: nbd_negotiate: return 1 on NBD_OPT_ABORT Vladimir Sementsov-Ogievskiy
                   ` (5 more replies)
  0 siblings, 6 replies; 28+ messages in thread
From: Vladimir Sementsov-Ogievskiy @ 2017-06-21 15:34 UTC (permalink / raw)
  To: qemu-devel; +Cc: stefanha, eblake, pbonzini, den, vsementsov

This is last part of "nbd errors and traces refactoring".

Patches 01-10 from "nbd errors and traces refactoring" are already merged.
Patches 11-13 from it are rejected - do not regret them.
So, these series is update of 14-19 patches from "nbd errors and traces
refactoring"

v2:
01: EPIPE not handled
    imporve comments
02: rebased on absence of old patch 13, errors are not saved into
    separate ret variable
    TRACE on fail of sending NBD_REP_ACK reply to NBD_OPT_ABORT
    instead of error propagating and EPIPE handling
03: fix error_prepend
04: just remove this TRACE
05: just trace nbd magic as 64bit number
06: improve commit message
    simplify trace_nbd_receive_negotiate_server_flags - do not trace
    separate flags
    add trace_nbd_opt_abort_reply_failed
    remove tail periods from traces


Vladimir Sementsov-Ogievskiy (6):
  nbd/server: nbd_negotiate: return 1 on NBD_OPT_ABORT
  nbd/server: use errp instead of LOG
  nbd/server: add errp to nbd_send_reply()
  nbd/common: nbd_tls_handshake: remove extra TRACE
  nbd/client: refactor TRACE of NBD_MAGIC
  nbd: use generic trace subsystem instead of TRACE macro

 Makefile.objs      |   1 +
 nbd/client.c       |  87 +++++--------
 nbd/common.c       |   4 +-
 nbd/nbd-internal.h |  19 ---
 nbd/server.c       | 368 +++++++++++++++++++++++++++++++----------------------
 nbd/trace-events   |  68 ++++++++++
 6 files changed, 320 insertions(+), 227 deletions(-)
 create mode 100644 nbd/trace-events

-- 
2.11.1

^ permalink raw reply	[flat|nested] 28+ messages in thread

* [Qemu-devel] [PATCH v2 1/6] nbd/server: nbd_negotiate: return 1 on NBD_OPT_ABORT
  2017-06-21 15:34 [Qemu-devel] [PATCH v2 0/6] nbd refactoring part 2 Vladimir Sementsov-Ogievskiy
@ 2017-06-21 15:34 ` Vladimir Sementsov-Ogievskiy
  2017-06-29 18:46   ` Eric Blake
  2017-06-21 15:34 ` [Qemu-devel] [PATCH v2 2/6] nbd/server: use errp instead of LOG Vladimir Sementsov-Ogievskiy
                   ` (4 subsequent siblings)
  5 siblings, 1 reply; 28+ messages in thread
From: Vladimir Sementsov-Ogievskiy @ 2017-06-21 15:34 UTC (permalink / raw)
  To: qemu-devel; +Cc: stefanha, eblake, pbonzini, den, vsementsov

Separate case when client sent NBD_OPT_ABORT from other errors.
It will be needed for the following patch, where errors will be
reported.
Considered case is not actually the error - it honestly follows NBD
protocol. Therefore it should not be reported like an error.

Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
---
 nbd/server.c | 20 +++++++++++++++-----
 1 file changed, 15 insertions(+), 5 deletions(-)

diff --git a/nbd/server.c b/nbd/server.c
index 8a70c054a6..f0bff23b8b 100644
--- a/nbd/server.c
+++ b/nbd/server.c
@@ -349,9 +349,13 @@ static QIOChannel *nbd_negotiate_handle_starttls(NBDClient *client,
     return QIO_CHANNEL(tioc);
 }
 
-
-/* Process all NBD_OPT_* client option commands.
- * Return -errno on error, 0 on success. */
+/* nbd_negotiate_options
+ * Process all NBD_OPT_* client option commands.
+ * Return:
+ * -errno  on error
+ * 0       on successful negotiation
+ * 1       if client sent NBD_OPT_ABORT, i.e. on legal disconnect
+ */
 static int nbd_negotiate_options(NBDClient *client)
 {
     uint32_t flags;
@@ -459,7 +463,7 @@ static int nbd_negotiate_options(NBDClient *client)
                 }
                 /* Let the client keep trying, unless they asked to quit */
                 if (clientflags == NBD_OPT_ABORT) {
-                    return -EINVAL;
+                    return 1;
                 }
                 break;
             }
@@ -477,7 +481,7 @@ static int nbd_negotiate_options(NBDClient *client)
                  * disconnecting, but that we must also tolerate
                  * guests that don't wait for our reply. */
                 nbd_negotiate_send_rep(client->ioc, NBD_REP_ACK, clientflags);
-                return -EINVAL;
+                return 1;
 
             case NBD_OPT_EXPORT_NAME:
                 return nbd_negotiate_handle_export_name(client, length);
@@ -533,6 +537,12 @@ static int nbd_negotiate_options(NBDClient *client)
     }
 }
 
+/* nbd_negotiate
+ * Return:
+ * -errno  on error
+ * 0       on successful negotiation
+ * 1       if client sent NBD_OPT_ABORT, i.e. on legal disconnect
+ */
 static coroutine_fn int nbd_negotiate(NBDClient *client)
 {
     char buf[8 + 8 + 8 + 128];
-- 
2.11.1

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* [Qemu-devel] [PATCH v2 2/6] nbd/server: use errp instead of LOG
  2017-06-21 15:34 [Qemu-devel] [PATCH v2 0/6] nbd refactoring part 2 Vladimir Sementsov-Ogievskiy
  2017-06-21 15:34 ` [Qemu-devel] [PATCH v2 1/6] nbd/server: nbd_negotiate: return 1 on NBD_OPT_ABORT Vladimir Sementsov-Ogievskiy
@ 2017-06-21 15:34 ` Vladimir Sementsov-Ogievskiy
  2017-06-29 19:27   ` Eric Blake
  2017-07-07 14:40   ` Eric Blake
  2017-06-21 15:34 ` [Qemu-devel] [PATCH v2 3/6] nbd/server: add errp to nbd_send_reply() Vladimir Sementsov-Ogievskiy
                   ` (3 subsequent siblings)
  5 siblings, 2 replies; 28+ messages in thread
From: Vladimir Sementsov-Ogievskiy @ 2017-06-21 15:34 UTC (permalink / raw)
  To: qemu-devel; +Cc: stefanha, eblake, pbonzini, den, vsementsov

Move to modern errp scheme from just LOGging errors.

Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
---
 nbd/server.c | 268 +++++++++++++++++++++++++++++++++++------------------------
 1 file changed, 161 insertions(+), 107 deletions(-)

diff --git a/nbd/server.c b/nbd/server.c
index f0bff23b8b..fa493602dd 100644
--- a/nbd/server.c
+++ b/nbd/server.c
@@ -134,7 +134,7 @@ static void nbd_client_receive_next_request(NBDClient *client);
 /* Send a reply header, including length, but no payload.
  * Return -errno on error, 0 on success. */
 static int nbd_negotiate_send_rep_len(QIOChannel *ioc, uint32_t type,
-                                      uint32_t opt, uint32_t len)
+                                      uint32_t opt, uint32_t len, Error **errp)
 {
     uint64_t magic;
 
@@ -142,23 +142,26 @@ static int nbd_negotiate_send_rep_len(QIOChannel *ioc, uint32_t type,
           type, opt, len);
 
     magic = cpu_to_be64(NBD_REP_MAGIC);
-    if (nbd_write(ioc, &magic, sizeof(magic), NULL) < 0) {
-        LOG("write failed (rep magic)");
+    if (nbd_write(ioc, &magic, sizeof(magic), errp) < 0) {
+        error_prepend(errp, "write failed (rep magic): ");
         return -EINVAL;
     }
+
     opt = cpu_to_be32(opt);
-    if (nbd_write(ioc, &opt, sizeof(opt), NULL) < 0) {
-        LOG("write failed (rep opt)");
+    if (nbd_write(ioc, &opt, sizeof(opt), errp) < 0) {
+        error_prepend(errp, "write failed (rep opt): ");
         return -EINVAL;
     }
+
     type = cpu_to_be32(type);
-    if (nbd_write(ioc, &type, sizeof(type), NULL) < 0) {
-        LOG("write failed (rep type)");
+    if (nbd_write(ioc, &type, sizeof(type), errp) < 0) {
+        error_prepend(errp, "write failed (rep type): ");
         return -EINVAL;
     }
+
     len = cpu_to_be32(len);
-    if (nbd_write(ioc, &len, sizeof(len), NULL) < 0) {
-        LOG("write failed (rep data length)");
+    if (nbd_write(ioc, &len, sizeof(len), errp) < 0) {
+        error_prepend(errp, "write failed (rep data length): ");
         return -EINVAL;
     }
     return 0;
@@ -166,16 +169,17 @@ static int nbd_negotiate_send_rep_len(QIOChannel *ioc, uint32_t type,
 
 /* Send a reply header with default 0 length.
  * Return -errno on error, 0 on success. */
-static int nbd_negotiate_send_rep(QIOChannel *ioc, uint32_t type, uint32_t opt)
+static int nbd_negotiate_send_rep(QIOChannel *ioc, uint32_t type, uint32_t opt,
+                                  Error **errp)
 {
-    return nbd_negotiate_send_rep_len(ioc, type, opt, 0);
+    return nbd_negotiate_send_rep_len(ioc, type, opt, 0, errp);
 }
 
 /* Send an error reply.
  * Return -errno on error, 0 on success. */
-static int GCC_FMT_ATTR(4, 5)
+static int GCC_FMT_ATTR(5, 6)
 nbd_negotiate_send_rep_err(QIOChannel *ioc, uint32_t type,
-                           uint32_t opt, const char *fmt, ...)
+                           uint32_t opt, Error **errp, const char *fmt, ...)
 {
     va_list va;
     char *msg;
@@ -188,16 +192,17 @@ nbd_negotiate_send_rep_err(QIOChannel *ioc, uint32_t type,
     len = strlen(msg);
     assert(len < 4096);
     TRACE("sending error message \"%s\"", msg);
-    ret = nbd_negotiate_send_rep_len(ioc, type, opt, len);
+    ret = nbd_negotiate_send_rep_len(ioc, type, opt, len, errp);
     if (ret < 0) {
         goto out;
     }
-    if (nbd_write(ioc, msg, len, NULL) < 0) {
-        LOG("write failed (error message)");
+    if (nbd_write(ioc, msg, len, errp) < 0) {
+        error_prepend(errp, "write failed (error message): ");
         ret = -EIO;
     } else {
         ret = 0;
     }
+
 out:
     g_free(msg);
     return ret;
@@ -205,7 +210,8 @@ out:
 
 /* Send a single NBD_REP_SERVER reply to NBD_OPT_LIST, including payload.
  * Return -errno on error, 0 on success. */
-static int nbd_negotiate_send_rep_list(QIOChannel *ioc, NBDExport *exp)
+static int nbd_negotiate_send_rep_list(QIOChannel *ioc, NBDExport *exp,
+                                       Error **errp)
 {
     size_t name_len, desc_len;
     uint32_t len;
@@ -217,53 +223,60 @@ static int nbd_negotiate_send_rep_list(QIOChannel *ioc, NBDExport *exp)
     name_len = strlen(name);
     desc_len = strlen(desc);
     len = name_len + desc_len + sizeof(len);
-    ret = nbd_negotiate_send_rep_len(ioc, NBD_REP_SERVER, NBD_OPT_LIST, len);
+    ret = nbd_negotiate_send_rep_len(ioc, NBD_REP_SERVER, NBD_OPT_LIST, len,
+                                     errp);
     if (ret < 0) {
         return ret;
     }
 
     len = cpu_to_be32(name_len);
-    if (nbd_write(ioc, &len, sizeof(len), NULL) < 0) {
-        LOG("write failed (name length)");
+    if (nbd_write(ioc, &len, sizeof(len), errp) < 0) {
+        error_prepend(errp, "write failed (name length): ");
         return -EINVAL;
     }
-    if (nbd_write(ioc, name, name_len, NULL) < 0) {
-        LOG("write failed (name buffer)");
+
+    if (nbd_write(ioc, name, name_len, errp) < 0) {
+        error_prepend(errp, "write failed (name buffer): ");
         return -EINVAL;
     }
-    if (nbd_write(ioc, desc, desc_len, NULL) < 0) {
-        LOG("write failed (description buffer)");
+
+    if (nbd_write(ioc, desc, desc_len, errp) < 0) {
+        error_prepend(errp, "write failed (description buffer): ");
         return -EINVAL;
     }
+
     return 0;
 }
 
 /* Process the NBD_OPT_LIST command, with a potential series of replies.
  * Return -errno on error, 0 on success. */
-static int nbd_negotiate_handle_list(NBDClient *client, uint32_t length)
+static int nbd_negotiate_handle_list(NBDClient *client, uint32_t length,
+                                     Error **errp)
 {
     NBDExport *exp;
 
     if (length) {
-        if (nbd_drop(client->ioc, length, NULL) < 0) {
+        if (nbd_drop(client->ioc, length, errp) < 0) {
             return -EIO;
         }
         return nbd_negotiate_send_rep_err(client->ioc,
                                           NBD_REP_ERR_INVALID, NBD_OPT_LIST,
+                                          errp,
                                           "OPT_LIST should not have length");
     }
 
     /* For each export, send a NBD_REP_SERVER reply. */
     QTAILQ_FOREACH(exp, &exports, next) {
-        if (nbd_negotiate_send_rep_list(client->ioc, exp)) {
+        if (nbd_negotiate_send_rep_list(client->ioc, exp, errp)) {
             return -EINVAL;
         }
     }
     /* Finish with a NBD_REP_ACK. */
-    return nbd_negotiate_send_rep(client->ioc, NBD_REP_ACK, NBD_OPT_LIST);
+    return nbd_negotiate_send_rep(client->ioc, NBD_REP_ACK, NBD_OPT_LIST, errp);
 }
 
-static int nbd_negotiate_handle_export_name(NBDClient *client, uint32_t length)
+static int nbd_negotiate_handle_export_name(NBDClient *client, uint32_t length,
+                                            Error **errp)
 {
     char name[NBD_MAX_NAME_SIZE + 1];
 
@@ -272,11 +285,11 @@ static int nbd_negotiate_handle_export_name(NBDClient *client, uint32_t length)
      */
     TRACE("Checking length");
     if (length >= sizeof(name)) {
-        LOG("Bad length received");
+        error_setg(errp, "Bad length received");
         return -EINVAL;
     }
-    if (nbd_read(client->ioc, name, length, NULL) < 0) {
-        LOG("read failed");
+    if (nbd_read(client->ioc, name, length, errp) < 0) {
+        error_prepend(errp, "read failed: ");
         return -EINVAL;
     }
     name[length] = '\0';
@@ -285,7 +298,7 @@ static int nbd_negotiate_handle_export_name(NBDClient *client, uint32_t length)
 
     client->exp = nbd_export_find(name);
     if (!client->exp) {
-        LOG("export not found");
+        error_setg(errp, "export not found");
         return -EINVAL;
     }
 
@@ -298,7 +311,8 @@ static int nbd_negotiate_handle_export_name(NBDClient *client, uint32_t length)
 /* Handle NBD_OPT_STARTTLS. Return NULL to drop connection, or else the
  * new channel for all further (now-encrypted) communication. */
 static QIOChannel *nbd_negotiate_handle_starttls(NBDClient *client,
-                                                 uint32_t length)
+                                                 uint32_t length,
+                                                 Error **errp)
 {
     QIOChannel *ioc;
     QIOChannelTLS *tioc;
@@ -307,23 +321,24 @@ static QIOChannel *nbd_negotiate_handle_starttls(NBDClient *client,
     TRACE("Setting up TLS");
     ioc = client->ioc;
     if (length) {
-        if (nbd_drop(ioc, length, NULL) < 0) {
+        if (nbd_drop(ioc, length, errp) < 0) {
             return NULL;
         }
         nbd_negotiate_send_rep_err(ioc, NBD_REP_ERR_INVALID, NBD_OPT_STARTTLS,
+                                   errp,
                                    "OPT_STARTTLS should not have length");
         return NULL;
     }
 
     if (nbd_negotiate_send_rep(client->ioc, NBD_REP_ACK,
-                               NBD_OPT_STARTTLS) < 0) {
+                               NBD_OPT_STARTTLS, errp) < 0) {
         return NULL;
     }
 
     tioc = qio_channel_tls_new_server(ioc,
                                       client->tlscreds,
                                       client->tlsaclname,
-                                      NULL);
+                                      errp);
     if (!tioc) {
         return NULL;
     }
@@ -342,7 +357,7 @@ static QIOChannel *nbd_negotiate_handle_starttls(NBDClient *client,
     g_main_loop_unref(data.loop);
     if (data.error) {
         object_unref(OBJECT(tioc));
-        error_free(data.error);
+        error_propagate(errp, data.error);
         return NULL;
     }
 
@@ -352,14 +367,16 @@ static QIOChannel *nbd_negotiate_handle_starttls(NBDClient *client,
 /* nbd_negotiate_options
  * Process all NBD_OPT_* client option commands.
  * Return:
- * -errno  on error
- * 0       on successful negotiation
- * 1       if client sent NBD_OPT_ABORT, i.e. on legal disconnect
+ * -errno  on error, errp is set
+ * 0       on successful negotiation, errp is not set
+ * 1       if client sent NBD_OPT_ABORT, i.e. on legal disconnect,
+ *         errp is not set
  */
-static int nbd_negotiate_options(NBDClient *client)
+static int nbd_negotiate_options(NBDClient *client, Error **errp)
 {
     uint32_t flags;
     bool fixedNewstyle = false;
+    Error *local_err = NULL;
 
     /* Client sends:
         [ 0 ..   3]   client flags
@@ -375,8 +392,8 @@ static int nbd_negotiate_options(NBDClient *client)
         ...           Rest of request
     */
 
-    if (nbd_read(client->ioc, &flags, sizeof(flags), NULL) < 0) {
-        LOG("read failed");
+    if (nbd_read(client->ioc, &flags, sizeof(flags), errp) < 0) {
+        error_prepend(errp, "read failed: ");
         return -EIO;
     }
     TRACE("Checking client flags");
@@ -392,7 +409,7 @@ static int nbd_negotiate_options(NBDClient *client)
         flags &= ~NBD_FLAG_C_NO_ZEROES;
     }
     if (flags != 0) {
-        TRACE("Unknown client flags 0x%" PRIx32 " received", flags);
+        error_setg(errp, "Unknown client flags 0x%" PRIx32 " received", flags);
         return -EIO;
     }
 
@@ -401,26 +418,25 @@ static int nbd_negotiate_options(NBDClient *client)
         uint32_t clientflags, length;
         uint64_t magic;
 
-        if (nbd_read(client->ioc, &magic, sizeof(magic), NULL) < 0) {
-            LOG("read failed");
+        if (nbd_read(client->ioc, &magic, sizeof(magic), errp) < 0) {
+            error_prepend(errp, "read failed: ");
             return -EINVAL;
         }
         TRACE("Checking opts magic");
         if (magic != be64_to_cpu(NBD_OPTS_MAGIC)) {
-            LOG("Bad magic received");
+            error_setg(errp, "Bad magic received");
             return -EINVAL;
         }
 
         if (nbd_read(client->ioc, &clientflags,
-                      sizeof(clientflags), NULL) < 0)
-        {
-            LOG("read failed");
+                     sizeof(clientflags), errp) < 0) {
+            error_prepend(errp, "read failed: ");
             return -EINVAL;
         }
         clientflags = be32_to_cpu(clientflags);
 
-        if (nbd_read(client->ioc, &length, sizeof(length), NULL) < 0) {
-            LOG("read failed");
+        if (nbd_read(client->ioc, &length, sizeof(length), errp) < 0) {
+            error_prepend(errp, "read failed: ");
             return -EINVAL;
         }
         length = be32_to_cpu(length);
@@ -430,12 +446,12 @@ static int nbd_negotiate_options(NBDClient *client)
             client->ioc == (QIOChannel *)client->sioc) {
             QIOChannel *tioc;
             if (!fixedNewstyle) {
-                TRACE("Unsupported option 0x%" PRIx32, clientflags);
+                error_setg(errp, "Unsupported option 0x%" PRIx32, clientflags);
                 return -EINVAL;
             }
             switch (clientflags) {
             case NBD_OPT_STARTTLS:
-                tioc = nbd_negotiate_handle_starttls(client, length);
+                tioc = nbd_negotiate_handle_starttls(client, length, errp);
                 if (!tioc) {
                     return -EIO;
                 }
@@ -445,16 +461,17 @@ static int nbd_negotiate_options(NBDClient *client)
 
             case NBD_OPT_EXPORT_NAME:
                 /* No way to return an error to client, so drop connection */
-                TRACE("Option 0x%x not permitted before TLS", clientflags);
+                error_setg(errp, "Option 0x%x not permitted before TLS",
+                           clientflags);
                 return -EINVAL;
 
             default:
-                if (nbd_drop(client->ioc, length, NULL) < 0) {
+                if (nbd_drop(client->ioc, length, errp) < 0) {
                     return -EIO;
                 }
                 ret = nbd_negotiate_send_rep_err(client->ioc,
                                                  NBD_REP_ERR_TLS_REQD,
-                                                 clientflags,
+                                                 clientflags, errp,
                                                  "Option 0x%" PRIx32
                                                  "not permitted before TLS",
                                                  clientflags);
@@ -470,7 +487,7 @@ static int nbd_negotiate_options(NBDClient *client)
         } else if (fixedNewstyle) {
             switch (clientflags) {
             case NBD_OPT_LIST:
-                ret = nbd_negotiate_handle_list(client, length);
+                ret = nbd_negotiate_handle_list(client, length, errp);
                 if (ret < 0) {
                     return ret;
                 }
@@ -480,25 +497,33 @@ static int nbd_negotiate_options(NBDClient *client)
                 /* NBD spec says we must try to reply before
                  * disconnecting, but that we must also tolerate
                  * guests that don't wait for our reply. */
-                nbd_negotiate_send_rep(client->ioc, NBD_REP_ACK, clientflags);
+                nbd_negotiate_send_rep(client->ioc, NBD_REP_ACK, clientflags,
+                                       &local_err);
+
+                if (local_err != NULL) {
+                    TRACE("Reply to NBD_OPT_ABORT request failed: %s",
+                          error_get_pretty(local_err));
+                    error_free(local_err);
+                }
+
                 return 1;
 
             case NBD_OPT_EXPORT_NAME:
-                return nbd_negotiate_handle_export_name(client, length);
+                return nbd_negotiate_handle_export_name(client, length, errp);
 
             case NBD_OPT_STARTTLS:
-                if (nbd_drop(client->ioc, length, NULL) < 0) {
+                if (nbd_drop(client->ioc, length, errp) < 0) {
                     return -EIO;
                 }
                 if (client->tlscreds) {
                     ret = nbd_negotiate_send_rep_err(client->ioc,
                                                      NBD_REP_ERR_INVALID,
-                                                     clientflags,
+                                                     clientflags, errp,
                                                      "TLS already enabled");
                 } else {
                     ret = nbd_negotiate_send_rep_err(client->ioc,
                                                      NBD_REP_ERR_POLICY,
-                                                     clientflags,
+                                                     clientflags, errp,
                                                      "TLS not configured");
                 }
                 if (ret < 0) {
@@ -506,12 +531,12 @@ static int nbd_negotiate_options(NBDClient *client)
                 }
                 break;
             default:
-                if (nbd_drop(client->ioc, length, NULL) < 0) {
+                if (nbd_drop(client->ioc, length, errp) < 0) {
                     return -EIO;
                 }
                 ret = nbd_negotiate_send_rep_err(client->ioc,
                                                  NBD_REP_ERR_UNSUP,
-                                                 clientflags,
+                                                 clientflags, errp,
                                                  "Unsupported option 0x%"
                                                  PRIx32,
                                                  clientflags);
@@ -527,10 +552,10 @@ static int nbd_negotiate_options(NBDClient *client)
              */
             switch (clientflags) {
             case NBD_OPT_EXPORT_NAME:
-                return nbd_negotiate_handle_export_name(client, length);
+                return nbd_negotiate_handle_export_name(client, length, errp);
 
             default:
-                TRACE("Unsupported option 0x%" PRIx32, clientflags);
+                error_setg(errp, "Unsupported option 0x%" PRIx32, clientflags);
                 return -EINVAL;
             }
         }
@@ -539,11 +564,12 @@ static int nbd_negotiate_options(NBDClient *client)
 
 /* nbd_negotiate
  * Return:
- * -errno  on error
- * 0       on successful negotiation
- * 1       if client sent NBD_OPT_ABORT, i.e. on legal disconnect
+ * -errno  on error, errp is set
+ * 0       on successful negotiation, errp is not set
+ * 1       if client sent NBD_OPT_ABORT, i.e. on legal disconnect,
+ *         errp is not set
  */
-static coroutine_fn int nbd_negotiate(NBDClient *client)
+static coroutine_fn int nbd_negotiate(NBDClient *client, Error **errp)
 {
     char buf[8 + 8 + 8 + 128];
     int ret;
@@ -591,21 +617,23 @@ static coroutine_fn int nbd_negotiate(NBDClient *client)
 
     if (oldStyle) {
         if (client->tlscreds) {
-            TRACE("TLS cannot be enabled with oldstyle protocol");
+            error_setg(errp, "TLS cannot be enabled with oldstyle protocol");
             return -EINVAL;
         }
-        if (nbd_write(client->ioc, buf, sizeof(buf), NULL) < 0) {
-            LOG("write failed");
+        if (nbd_write(client->ioc, buf, sizeof(buf), errp) < 0) {
+            error_prepend(errp, "write failed: ");
             return -EINVAL;
         }
     } else {
-        if (nbd_write(client->ioc, buf, 18, NULL) < 0) {
-            LOG("write failed");
+        if (nbd_write(client->ioc, buf, 18, errp) < 0) {
+            error_prepend(errp, "write failed: ");
             return -EINVAL;
         }
-        ret = nbd_negotiate_options(client);
+        ret = nbd_negotiate_options(client, errp);
         if (ret != 0) {
-            LOG("option negotiation failed");
+            if (ret < 0) {
+                error_prepend(errp, "option negotiation failed: ");
+            }
             return ret;
         }
 
@@ -614,9 +642,9 @@ static coroutine_fn int nbd_negotiate(NBDClient *client)
         stq_be_p(buf + 18, client->exp->size);
         stw_be_p(buf + 26, client->exp->nbdflags | myflags);
         len = client->no_zeroes ? 10 : sizeof(buf) - 18;
-        ret = nbd_write(client->ioc, buf + 18, len, NULL);
+        ret = nbd_write(client->ioc, buf + 18, len, errp);
         if (ret < 0) {
-            LOG("write failed");
+            error_prepend(errp, "write failed: ");
             return ret;
         }
     }
@@ -626,13 +654,14 @@ static coroutine_fn int nbd_negotiate(NBDClient *client)
     return 0;
 }
 
-static int nbd_receive_request(QIOChannel *ioc, NBDRequest *request)
+static int nbd_receive_request(QIOChannel *ioc, NBDRequest *request,
+                               Error **errp)
 {
     uint8_t buf[NBD_REQUEST_SIZE];
     uint32_t magic;
     int ret;
 
-    ret = nbd_read(ioc, buf, sizeof(buf), NULL);
+    ret = nbd_read(ioc, buf, sizeof(buf), errp);
     if (ret < 0) {
         return ret;
     }
@@ -658,7 +687,7 @@ static int nbd_receive_request(QIOChannel *ioc, NBDRequest *request)
           magic, request->flags, request->type, request->from, request->len);
 
     if (magic != NBD_REQUEST_MAGIC) {
-        LOG("invalid magic (got 0x%" PRIx32 ")", magic);
+        error_setg(errp, "invalid magic (got 0x%" PRIx32 ")", magic);
         return -EINVAL;
     }
     return 0;
@@ -1004,13 +1033,14 @@ static int nbd_co_send_reply(NBDRequestData *req, NBDReply *reply, int len)
  * the client (although the caller may still need to disconnect after reporting
  * the error).
  */
-static int nbd_co_receive_request(NBDRequestData *req, NBDRequest *request)
+static int nbd_co_receive_request(NBDRequestData *req, NBDRequest *request,
+                                  Error **errp)
 {
     NBDClient *client = req->client;
 
     g_assert(qemu_in_coroutine());
     assert(client->recv_coroutine == qemu_coroutine_self());
-    if (nbd_receive_request(client->ioc, request) < 0) {
+    if (nbd_receive_request(client->ioc, request, errp) < 0) {
         return -EIO;
     }
 
@@ -1032,27 +1062,29 @@ static int nbd_co_receive_request(NBDRequestData *req, NBDRequest *request)
      * checks as possible until after reading any NBD_CMD_WRITE
      * payload, so we can try and keep the connection alive.  */
     if ((request->from + request->len) < request->from) {
-        LOG("integer overflow detected, you're probably being attacked");
+        error_setg(errp,
+                   "integer overflow detected, you're probably being attacked");
         return -EINVAL;
     }
 
     if (request->type == NBD_CMD_READ || request->type == NBD_CMD_WRITE) {
         if (request->len > NBD_MAX_BUFFER_SIZE) {
-            LOG("len (%" PRIu32" ) is larger than max len (%u)",
-                request->len, NBD_MAX_BUFFER_SIZE);
+            error_setg(errp, "len (%" PRIu32" ) is larger than max len (%u)",
+                       request->len, NBD_MAX_BUFFER_SIZE);
             return -EINVAL;
         }
 
         req->data = blk_try_blockalign(client->exp->blk, request->len);
         if (req->data == NULL) {
+            error_setg(errp, "No memory");
             return -ENOMEM;
         }
     }
     if (request->type == NBD_CMD_WRITE) {
         TRACE("Reading %" PRIu32 " byte(s)", request->len);
 
-        if (nbd_read(client->ioc, req->data, request->len, NULL) < 0) {
-            LOG("reading from socket failed");
+        if (nbd_read(client->ioc, req->data, request->len, errp) < 0) {
+            error_prepend(errp, "reading from socket failed: ");
             return -EIO;
         }
         req->complete = true;
@@ -1060,18 +1092,18 @@ static int nbd_co_receive_request(NBDRequestData *req, NBDRequest *request)
 
     /* Sanity checks, part 2. */
     if (request->from + request->len > client->exp->size) {
-        LOG("operation past EOF; From: %" PRIu64 ", Len: %" PRIu32
-            ", Size: %" PRIu64, request->from, request->len,
-            (uint64_t)client->exp->size);
+        error_setg(errp, "operation past EOF; From: %" PRIu64 ", Len: %" PRIu32
+                   ", Size: %" PRIu64, request->from, request->len,
+                   (uint64_t)client->exp->size);
         return request->type == NBD_CMD_WRITE ? -ENOSPC : -EINVAL;
     }
     if (request->flags & ~(NBD_CMD_FLAG_FUA | NBD_CMD_FLAG_NO_HOLE)) {
-        LOG("unsupported flags (got 0x%x)", request->flags);
+        error_setg(errp, "unsupported flags (got 0x%x)", request->flags);
         return -EINVAL;
     }
     if (request->type != NBD_CMD_WRITE_ZEROES &&
         (request->flags & NBD_CMD_FLAG_NO_HOLE)) {
-        LOG("unexpected flags (got 0x%x)", request->flags);
+        error_setg(errp, "unexpected flags (got 0x%x)", request->flags);
         return -EINVAL;
     }
 
@@ -1089,6 +1121,7 @@ static coroutine_fn void nbd_trip(void *opaque)
     int ret;
     int flags;
     int reply_data_len = 0;
+    Error *local_err = NULL;
 
     TRACE("Reading request.");
     if (client->closing) {
@@ -1097,7 +1130,7 @@ static coroutine_fn void nbd_trip(void *opaque)
     }
 
     req = nbd_request_get(client);
-    ret = nbd_co_receive_request(req, &request);
+    ret = nbd_co_receive_request(req, &request, &local_err);
     client->recv_coroutine = NULL;
     nbd_client_receive_next_request(client);
     if (ret == -EIO) {
@@ -1128,7 +1161,7 @@ static coroutine_fn void nbd_trip(void *opaque)
         if (request.flags & NBD_CMD_FLAG_FUA) {
             ret = blk_co_flush(exp->blk);
             if (ret < 0) {
-                LOG("flush failed");
+                error_setg_errno(&local_err, -ret, "flush failed");
                 reply.error = -ret;
                 break;
             }
@@ -1137,7 +1170,7 @@ static coroutine_fn void nbd_trip(void *opaque)
         ret = blk_pread(exp->blk, request.from + exp->dev_offset,
                         req->data, request.len);
         if (ret < 0) {
-            LOG("reading from file failed");
+            error_setg_errno(&local_err, -ret, "reading from file failed");
             reply.error = -ret;
             break;
         }
@@ -1164,7 +1197,7 @@ static coroutine_fn void nbd_trip(void *opaque)
         ret = blk_pwrite(exp->blk, request.from + exp->dev_offset,
                          req->data, request.len, flags);
         if (ret < 0) {
-            LOG("writing to file failed");
+            error_setg_errno(&local_err, -ret, "writing to file failed");
             reply.error = -ret;
         }
 
@@ -1173,7 +1206,7 @@ static coroutine_fn void nbd_trip(void *opaque)
         TRACE("Request type is WRITE_ZEROES");
 
         if (exp->nbdflags & NBD_FLAG_READ_ONLY) {
-            TRACE("Server is read-only, return error");
+            error_setg(&local_err, "Server is read-only, return error");
             reply.error = EROFS;
             break;
         }
@@ -1190,7 +1223,7 @@ static coroutine_fn void nbd_trip(void *opaque)
         ret = blk_pwrite_zeroes(exp->blk, request.from + exp->dev_offset,
                                 request.len, flags);
         if (ret < 0) {
-            LOG("writing to file failed");
+            error_setg_errno(&local_err, -ret, "writing to file failed");
             reply.error = -ret;
         }
 
@@ -1204,7 +1237,7 @@ static coroutine_fn void nbd_trip(void *opaque)
 
         ret = blk_co_flush(exp->blk);
         if (ret < 0) {
-            LOG("flush failed");
+            error_setg_errno(&local_err, -ret, "flush failed");
             reply.error = -ret;
         }
 
@@ -1214,21 +1247,35 @@ static coroutine_fn void nbd_trip(void *opaque)
         ret = blk_co_pdiscard(exp->blk, request.from + exp->dev_offset,
                               request.len);
         if (ret < 0) {
-            LOG("discard failed");
+            error_setg_errno(&local_err, -ret, "discard failed");
             reply.error = -ret;
         }
 
         break;
     default:
-        LOG("invalid request type (%" PRIu32 ") received", request.type);
+        error_setg(&local_err, "invalid request type (%" PRIu32 ") received",
+                   request.type);
         reply.error = EINVAL;
     }
 
 reply:
+    if (local_err) {
+        /* If we are here local_err is not fatal error, already stored in
+         * reply.error */
+        error_report_err(local_err);
+        local_err = NULL;
+    }
+
+    if (nbd_co_send_reply(req, &reply, reply_data_len) < 0) {
+        error_setg(&local_err, "Failed to send reply");
+        goto disconnect;
+    }
+
     /* We must disconnect after NBD_CMD_WRITE if we did not
      * read the payload.
      */
-    if (nbd_co_send_reply(req, &reply, reply_data_len) < 0 || !req->complete) {
+    if (!req->complete) {
+        error_setg(&local_err, "Request handling failed in intermediate state");
         goto disconnect;
     }
 
@@ -1240,6 +1287,9 @@ done:
     return;
 
 disconnect:
+    if (local_err) {
+        error_reportf_err(local_err, "Disconnect client, due to: ");
+    }
     nbd_request_put(req);
     client_close(client, true);
     nbd_client_put(client);
@@ -1258,6 +1308,7 @@ static coroutine_fn void nbd_co_client_start(void *opaque)
 {
     NBDClient *client = opaque;
     NBDExport *exp = client->exp;
+    Error *local_err = NULL;
 
     if (exp) {
         nbd_export_get(exp);
@@ -1265,7 +1316,10 @@ static coroutine_fn void nbd_co_client_start(void *opaque)
     }
     qemu_co_mutex_init(&client->send_lock);
 
-    if (nbd_negotiate(client)) {
+    if (nbd_negotiate(client, &local_err)) {
+        if (local_err) {
+            error_report_err(local_err);
+        }
         client_close(client, false);
         return;
     }
-- 
2.11.1

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* [Qemu-devel] [PATCH v2 3/6] nbd/server: add errp to nbd_send_reply()
  2017-06-21 15:34 [Qemu-devel] [PATCH v2 0/6] nbd refactoring part 2 Vladimir Sementsov-Ogievskiy
  2017-06-21 15:34 ` [Qemu-devel] [PATCH v2 1/6] nbd/server: nbd_negotiate: return 1 on NBD_OPT_ABORT Vladimir Sementsov-Ogievskiy
  2017-06-21 15:34 ` [Qemu-devel] [PATCH v2 2/6] nbd/server: use errp instead of LOG Vladimir Sementsov-Ogievskiy
@ 2017-06-21 15:34 ` Vladimir Sementsov-Ogievskiy
  2017-06-29 19:31   ` Eric Blake
  2017-06-21 15:34 ` [Qemu-devel] [PATCH v2 4/6] nbd/common: nbd_tls_handshake: remove extra TRACE Vladimir Sementsov-Ogievskiy
                   ` (2 subsequent siblings)
  5 siblings, 1 reply; 28+ messages in thread
From: Vladimir Sementsov-Ogievskiy @ 2017-06-21 15:34 UTC (permalink / raw)
  To: qemu-devel; +Cc: stefanha, eblake, pbonzini, den, vsementsov

Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
---
 nbd/server.c | 17 +++++++++--------
 1 file changed, 9 insertions(+), 8 deletions(-)

diff --git a/nbd/server.c b/nbd/server.c
index fa493602dd..0671ebc50a 100644
--- a/nbd/server.c
+++ b/nbd/server.c
@@ -693,7 +693,7 @@ static int nbd_receive_request(QIOChannel *ioc, NBDRequest *request,
     return 0;
 }
 
-static int nbd_send_reply(QIOChannel *ioc, NBDReply *reply)
+static int nbd_send_reply(QIOChannel *ioc, NBDReply *reply, Error **errp)
 {
     uint8_t buf[NBD_REPLY_SIZE];
 
@@ -712,7 +712,7 @@ static int nbd_send_reply(QIOChannel *ioc, NBDReply *reply)
     stl_be_p(buf + 4, reply->error);
     stq_be_p(buf + 8, reply->handle);
 
-    return nbd_write(ioc, buf, sizeof(buf), NULL);
+    return nbd_write(ioc, buf, sizeof(buf), errp);
 }
 
 #define MAX_NBD_REQUESTS 16
@@ -999,7 +999,8 @@ void nbd_export_close_all(void)
     }
 }
 
-static int nbd_co_send_reply(NBDRequestData *req, NBDReply *reply, int len)
+static int nbd_co_send_reply(NBDRequestData *req, NBDReply *reply, int len,
+                             Error **errp)
 {
     NBDClient *client = req->client;
     int ret;
@@ -1009,12 +1010,12 @@ static int nbd_co_send_reply(NBDRequestData *req, NBDReply *reply, int len)
     client->send_coroutine = qemu_coroutine_self();
 
     if (!len) {
-        ret = nbd_send_reply(client->ioc, reply);
+        ret = nbd_send_reply(client->ioc, reply, errp);
     } else {
         qio_channel_set_cork(client->ioc, true);
-        ret = nbd_send_reply(client->ioc, reply);
+        ret = nbd_send_reply(client->ioc, reply, errp);
         if (ret == 0) {
-            ret = nbd_write(client->ioc, req->data, len, NULL);
+            ret = nbd_write(client->ioc, req->data, len, errp);
             if (ret < 0) {
                 ret = -EIO;
             }
@@ -1266,8 +1267,8 @@ reply:
         local_err = NULL;
     }
 
-    if (nbd_co_send_reply(req, &reply, reply_data_len) < 0) {
-        error_setg(&local_err, "Failed to send reply");
+    if (nbd_co_send_reply(req, &reply, reply_data_len, &local_err) < 0) {
+        error_prepend(&local_err, "Failed to send reply: ");
         goto disconnect;
     }
 
-- 
2.11.1

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* [Qemu-devel] [PATCH v2 4/6] nbd/common: nbd_tls_handshake: remove extra TRACE
  2017-06-21 15:34 [Qemu-devel] [PATCH v2 0/6] nbd refactoring part 2 Vladimir Sementsov-Ogievskiy
                   ` (2 preceding siblings ...)
  2017-06-21 15:34 ` [Qemu-devel] [PATCH v2 3/6] nbd/server: add errp to nbd_send_reply() Vladimir Sementsov-Ogievskiy
@ 2017-06-21 15:34 ` Vladimir Sementsov-Ogievskiy
  2017-06-29 19:32   ` Eric Blake
  2017-06-21 15:34 ` [Qemu-devel] [PATCH v2 5/6] nbd/client: refactor TRACE of NBD_MAGIC Vladimir Sementsov-Ogievskiy
  2017-06-21 15:34 ` [Qemu-devel] [PATCH v2 6/6] nbd: use generic trace subsystem instead of TRACE macro Vladimir Sementsov-Ogievskiy
  5 siblings, 1 reply; 28+ messages in thread
From: Vladimir Sementsov-Ogievskiy @ 2017-06-21 15:34 UTC (permalink / raw)
  To: qemu-devel; +Cc: stefanha, eblake, pbonzini, den, vsementsov

Error is propagated to the caller, TRACE is not needed.

Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
---
 nbd/common.c | 4 +---
 1 file changed, 1 insertion(+), 3 deletions(-)

diff --git a/nbd/common.c b/nbd/common.c
index 6b5c1b7b02..4dab41e2c0 100644
--- a/nbd/common.c
+++ b/nbd/common.c
@@ -97,9 +97,7 @@ void nbd_tls_handshake(QIOTask *task,
 {
     struct NBDTLSHandshakeData *data = opaque;
 
-    if (qio_task_propagate_error(task, &data->error)) {
-        TRACE("TLS failed %s", error_get_pretty(data->error));
-    }
+    qio_task_propagate_error(task, &data->error);
     data->complete = true;
     g_main_loop_quit(data->loop);
 }
-- 
2.11.1

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* [Qemu-devel] [PATCH v2 5/6] nbd/client: refactor TRACE of NBD_MAGIC
  2017-06-21 15:34 [Qemu-devel] [PATCH v2 0/6] nbd refactoring part 2 Vladimir Sementsov-Ogievskiy
                   ` (3 preceding siblings ...)
  2017-06-21 15:34 ` [Qemu-devel] [PATCH v2 4/6] nbd/common: nbd_tls_handshake: remove extra TRACE Vladimir Sementsov-Ogievskiy
@ 2017-06-21 15:34 ` Vladimir Sementsov-Ogievskiy
  2017-06-29 19:36   ` Eric Blake
  2017-06-21 15:34 ` [Qemu-devel] [PATCH v2 6/6] nbd: use generic trace subsystem instead of TRACE macro Vladimir Sementsov-Ogievskiy
  5 siblings, 1 reply; 28+ messages in thread
From: Vladimir Sementsov-Ogievskiy @ 2017-06-21 15:34 UTC (permalink / raw)
  To: qemu-devel; +Cc: stefanha, eblake, pbonzini, den, vsementsov

We are going to switch from TRACE macro to trace points,
this TRACE complicates things, this patch simplifies it.

Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
---
 nbd/client.c | 15 ++++-----------
 1 file changed, 4 insertions(+), 11 deletions(-)

diff --git a/nbd/client.c b/nbd/client.c
index b97143fa60..5a4825ebe0 100644
--- a/nbd/client.c
+++ b/nbd/client.c
@@ -426,14 +426,13 @@ static QIOChannel *nbd_receive_starttls(QIOChannel *ioc,
     return QIO_CHANNEL(tioc);
 }
 
-
 int nbd_receive_negotiate(QIOChannel *ioc, const char *name, uint16_t *flags,
                           QCryptoTLSCreds *tlscreds, const char *hostname,
                           QIOChannel **outioc,
                           off_t *size, Error **errp)
 {
     char buf[256];
-    uint64_t magic, s;
+    uint64_t nbd_magic, magic, s;
     int rc;
     bool zeroes = true;
 
@@ -461,15 +460,9 @@ int nbd_receive_negotiate(QIOChannel *ioc, const char *name, uint16_t *flags,
         goto fail;
     }
 
-    TRACE("Magic is %c%c%c%c%c%c%c%c",
-          qemu_isprint(buf[0]) ? buf[0] : '.',
-          qemu_isprint(buf[1]) ? buf[1] : '.',
-          qemu_isprint(buf[2]) ? buf[2] : '.',
-          qemu_isprint(buf[3]) ? buf[3] : '.',
-          qemu_isprint(buf[4]) ? buf[4] : '.',
-          qemu_isprint(buf[5]) ? buf[5] : '.',
-          qemu_isprint(buf[6]) ? buf[6] : '.',
-          qemu_isprint(buf[7]) ? buf[7] : '.');
+    memcpy(&nbd_magic, buf, 8);
+    nbd_magic = be64_to_cpu(nbd_magic);
+    TRACE("Magic is 0x%" PRIx64, nbd_magic);
 
     if (memcmp(buf, "NBDMAGIC", 8) != 0) {
         error_setg(errp, "Invalid magic received");
-- 
2.11.1

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* [Qemu-devel] [PATCH v2 6/6] nbd: use generic trace subsystem instead of TRACE macro
  2017-06-21 15:34 [Qemu-devel] [PATCH v2 0/6] nbd refactoring part 2 Vladimir Sementsov-Ogievskiy
                   ` (4 preceding siblings ...)
  2017-06-21 15:34 ` [Qemu-devel] [PATCH v2 5/6] nbd/client: refactor TRACE of NBD_MAGIC Vladimir Sementsov-Ogievskiy
@ 2017-06-21 15:34 ` Vladimir Sementsov-Ogievskiy
  2017-06-29 20:12   ` Eric Blake
                     ` (4 more replies)
  5 siblings, 5 replies; 28+ messages in thread
From: Vladimir Sementsov-Ogievskiy @ 2017-06-21 15:34 UTC (permalink / raw)
  To: qemu-devel; +Cc: stefanha, eblake, pbonzini, den, vsementsov

Starting from this patch to enable traces use -trace option of qemu or
-T, --trace option of qemu-img, qemu-io and qemu-nbd. For qemu traces
also can be managed by qmp commands trace-event-{get,set}-state.

Recompilation with CFLAGS=-DDEBUG_NBD is no more needed, furthermore,
DEBUG_NBD macro is removed from the code.

Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
---
 Makefile.objs      |  1 +
 nbd/client.c       | 74 +++++++++++++++++++++---------------------------
 nbd/nbd-internal.h | 19 -------------
 nbd/server.c       | 83 ++++++++++++++++++++++++++----------------------------
 nbd/trace-events   | 68 ++++++++++++++++++++++++++++++++++++++++++++
 5 files changed, 141 insertions(+), 104 deletions(-)
 create mode 100644 nbd/trace-events

diff --git a/Makefile.objs b/Makefile.objs
index b2e6322ef0..a66ea34cc4 100644
--- a/Makefile.objs
+++ b/Makefile.objs
@@ -168,6 +168,7 @@ trace-events-subdirs += linux-user
 trace-events-subdirs += qapi
 trace-events-subdirs += accel/tcg
 trace-events-subdirs += accel/kvm
+trace-events-subdirs += nbd
 
 trace-events-files = $(SRC_PATH)/trace-events $(trace-events-subdirs:%=$(SRC_PATH)/%/trace-events)
 
diff --git a/nbd/client.c b/nbd/client.c
index 5a4825ebe0..75b28f4ccf 100644
--- a/nbd/client.c
+++ b/nbd/client.c
@@ -19,6 +19,7 @@
 
 #include "qemu/osdep.h"
 #include "qapi/error.h"
+#include "trace.h"
 #include "nbd-internal.h"
 
 static int nbd_errno_to_system_errno(int err)
@@ -44,7 +45,7 @@ static int nbd_errno_to_system_errno(int err)
         ret = ESHUTDOWN;
         break;
     default:
-        TRACE("Squashing unexpected error %d to EINVAL", err);
+        trace_nbd_unknown_error(err);
         /* fallthrough */
     case NBD_EINVAL:
         ret = EINVAL;
@@ -103,7 +104,7 @@ static int nbd_send_option_request(QIOChannel *ioc, uint32_t opt,
     if (len == -1) {
         req.length = len = strlen(data);
     }
-    TRACE("Sending option request %" PRIu32", len %" PRIu32, opt, len);
+    trace_nbd_send_option_request(opt, len);
 
     stq_be_p(&req.magic, NBD_OPTS_MAGIC);
     stl_be_p(&req.option, opt);
@@ -153,8 +154,7 @@ static int nbd_receive_option_reply(QIOChannel *ioc, uint32_t opt,
     be32_to_cpus(&reply->type);
     be32_to_cpus(&reply->length);
 
-    TRACE("Received option reply %" PRIx32", type %" PRIx32", len %" PRIu32,
-          reply->option, reply->type, reply->length);
+    trace_nbd_receive_option_reply(reply->option, reply->type, reply->length);
 
     if (reply->magic != NBD_REP_MAGIC) {
         error_setg(errp, "Unexpected option reply magic");
@@ -201,8 +201,7 @@ static int nbd_handle_reply_err(QIOChannel *ioc, nbd_opt_reply *reply,
 
     switch (reply->type) {
     case NBD_REP_ERR_UNSUP:
-        TRACE("server doesn't understand request %" PRIx32
-              ", attempting fallback", reply->option);
+        trace_nbd_reply_err_unsup(reply->option);
         result = 0;
         goto cleanup;
 
@@ -342,12 +341,12 @@ static int nbd_receive_query_exports(QIOChannel *ioc,
 {
     bool foundExport = false;
 
-    TRACE("Querying export list for '%s'", wantname);
+    trace_nbd_receive_query_exports_start(wantname);
     if (nbd_send_option_request(ioc, NBD_OPT_LIST, 0, NULL, errp) < 0) {
         return -1;
     }
 
-    TRACE("Reading available export names");
+    trace_nbd_receive_query_exports_loop();
     while (1) {
         int ret = nbd_receive_list(ioc, wantname, &foundExport, errp);
 
@@ -362,7 +361,7 @@ static int nbd_receive_query_exports(QIOChannel *ioc,
                 nbd_send_opt_abort(ioc);
                 return -1;
             }
-            TRACE("Found desired export name '%s'", wantname);
+            trace_nbd_receive_query_exports_success(wantname);
             return 0;
         }
     }
@@ -376,12 +375,12 @@ static QIOChannel *nbd_receive_starttls(QIOChannel *ioc,
     QIOChannelTLS *tioc;
     struct NBDTLSHandshakeData data = { 0 };
 
-    TRACE("Requesting TLS from server");
+    trace_nbd_receive_starttls_request();
     if (nbd_send_option_request(ioc, NBD_OPT_STARTTLS, 0, NULL, errp) < 0) {
         return NULL;
     }
 
-    TRACE("Getting TLS reply from server");
+    trace_nbd_receive_starttls_reply();
     if (nbd_receive_option_reply(ioc, NBD_OPT_STARTTLS, &reply, errp) < 0) {
         return NULL;
     }
@@ -400,14 +399,14 @@ static QIOChannel *nbd_receive_starttls(QIOChannel *ioc,
         return NULL;
     }
 
-    TRACE("TLS request approved, setting up TLS");
+    trace_nbd_receive_starttls_new_client();
     tioc = qio_channel_tls_new_client(ioc, tlscreds, hostname, errp);
     if (!tioc) {
         return NULL;
     }
     qio_channel_set_name(QIO_CHANNEL(tioc), "nbd-client-tls");
     data.loop = g_main_loop_new(g_main_context_default(), FALSE);
-    TRACE("Starting TLS handshake");
+    trace_nbd_receive_starttls_tls_handshake();
     qio_channel_tls_handshake(tioc,
                               nbd_tls_handshake,
                               &data,
@@ -436,8 +435,7 @@ int nbd_receive_negotiate(QIOChannel *ioc, const char *name, uint16_t *flags,
     int rc;
     bool zeroes = true;
 
-    TRACE("Receiving negotiation tlscreds=%p hostname=%s.",
-          tlscreds, hostname ? hostname : "<null>");
+    trace_nbd_receive_negotiate(tlscreds, hostname ? hostname : "<null>");
 
     rc = -EINVAL;
 
@@ -462,7 +460,7 @@ int nbd_receive_negotiate(QIOChannel *ioc, const char *name, uint16_t *flags,
 
     memcpy(&nbd_magic, buf, 8);
     nbd_magic = be64_to_cpu(nbd_magic);
-    TRACE("Magic is 0x%" PRIx64, nbd_magic);
+    trace_nbd_receive_negotiate_magic(nbd_magic);
 
     if (memcmp(buf, "NBDMAGIC", 8) != 0) {
         error_setg(errp, "Invalid magic received");
@@ -474,7 +472,7 @@ int nbd_receive_negotiate(QIOChannel *ioc, const char *name, uint16_t *flags,
         goto fail;
     }
     magic = be64_to_cpu(magic);
-    TRACE("Magic is 0x%" PRIx64, magic);
+    trace_nbd_receive_negotiate_magic2(magic);
 
     if (magic == NBD_OPTS_MAGIC) {
         uint32_t clientflags = 0;
@@ -486,15 +484,13 @@ int nbd_receive_negotiate(QIOChannel *ioc, const char *name, uint16_t *flags,
             goto fail;
         }
         globalflags = be16_to_cpu(globalflags);
-        TRACE("Global flags are %" PRIx32, globalflags);
+        trace_nbd_receive_negotiate_server_flags(globalflags);
         if (globalflags & NBD_FLAG_FIXED_NEWSTYLE) {
             fixedNewStyle = true;
-            TRACE("Server supports fixed new style");
             clientflags |= NBD_FLAG_C_FIXED_NEWSTYLE;
         }
         if (globalflags & NBD_FLAG_NO_ZEROES) {
             zeroes = false;
-            TRACE("Server supports no zeroes");
             clientflags |= NBD_FLAG_C_NO_ZEROES;
         }
         /* client requested flags */
@@ -516,7 +512,7 @@ int nbd_receive_negotiate(QIOChannel *ioc, const char *name, uint16_t *flags,
             }
         }
         if (!name) {
-            TRACE("Using default NBD export name \"\"");
+            trace_nbd_receive_negotiate_default_name();
             name = "";
         }
         if (fixedNewStyle) {
@@ -565,7 +561,7 @@ int nbd_receive_negotiate(QIOChannel *ioc, const char *name, uint16_t *flags,
             goto fail;
         }
         *size = be64_to_cpu(s);
-        TRACE("Size is %" PRIu64, *size);
+        trace_nbd_receive_negotiate_export_size(*size);
 
         if (nbd_read(ioc, &oldflags, sizeof(oldflags), errp) < 0) {
             error_prepend(errp, "Failed to read export flags");
@@ -582,7 +578,7 @@ int nbd_receive_negotiate(QIOChannel *ioc, const char *name, uint16_t *flags,
         goto fail;
     }
 
-    TRACE("Size is %" PRIu64 ", export flags %" PRIx16, *size, *flags);
+    trace_nbd_receive_negotiate_size_flags(*size, *flags);
     if (zeroes && nbd_drop(ioc, 124, errp) < 0) {
         error_prepend(errp, "Failed to read reserved block");
         goto fail;
@@ -604,7 +600,7 @@ int nbd_init(int fd, QIOChannelSocket *sioc, uint16_t flags, off_t size,
         return -E2BIG;
     }
 
-    TRACE("Setting NBD socket");
+    trace_nbd_init_set_socket();
 
     if (ioctl(fd, NBD_SET_SOCK, (unsigned long) sioc->fd) < 0) {
         int serrno = errno;
@@ -612,7 +608,7 @@ int nbd_init(int fd, QIOChannelSocket *sioc, uint16_t flags, off_t size,
         return -serrno;
     }
 
-    TRACE("Setting block size to %lu", (unsigned long)BDRV_SECTOR_SIZE);
+    trace_nbd_init_set_block_size(BDRV_SECTOR_SIZE);
 
     if (ioctl(fd, NBD_SET_BLKSIZE, (unsigned long)BDRV_SECTOR_SIZE) < 0) {
         int serrno = errno;
@@ -620,10 +616,9 @@ int nbd_init(int fd, QIOChannelSocket *sioc, uint16_t flags, off_t size,
         return -serrno;
     }
 
-    TRACE("Setting size to %lu block(s)", sectors);
+    trace_nbd_init_set_size(sectors);
     if (size % BDRV_SECTOR_SIZE) {
-        TRACE("Ignoring trailing %d bytes of export",
-              (int) (size % BDRV_SECTOR_SIZE));
+        trace_nbd_init_trailing_bytes(size % BDRV_SECTOR_SIZE);
     }
 
     if (ioctl(fd, NBD_SET_SIZE_BLOCKS, sectors) < 0) {
@@ -635,7 +630,7 @@ int nbd_init(int fd, QIOChannelSocket *sioc, uint16_t flags, off_t size,
     if (ioctl(fd, NBD_SET_FLAGS, (unsigned long) flags) < 0) {
         if (errno == ENOTTY) {
             int read_only = (flags & NBD_FLAG_READ_ONLY) != 0;
-            TRACE("Setting readonly attribute");
+            trace_nbd_init_set_readonly();
 
             if (ioctl(fd, BLKROSET, (unsigned long) &read_only) < 0) {
                 int serrno = errno;
@@ -649,7 +644,7 @@ int nbd_init(int fd, QIOChannelSocket *sioc, uint16_t flags, off_t size,
         }
     }
 
-    TRACE("Negotiation ended");
+    trace_nbd_init_finish();
 
     return 0;
 }
@@ -659,7 +654,7 @@ int nbd_client(int fd)
     int ret;
     int serrno;
 
-    TRACE("Doing NBD loop");
+    trace_nbd_client_loop();
 
     ret = ioctl(fd, NBD_DO_IT);
     if (ret < 0 && errno == EPIPE) {
@@ -671,12 +666,12 @@ int nbd_client(int fd)
     }
     serrno = errno;
 
-    TRACE("NBD loop returned %d: %s", ret, strerror(serrno));
+    trace_nbd_client_loop_ret(ret, strerror(serrno));
 
-    TRACE("Clearing NBD queue");
+    trace_nbd_client_clear_queue();
     ioctl(fd, NBD_CLEAR_QUE);
 
-    TRACE("Clearing NBD socket");
+    trace_nbd_client_clear_socket();
     ioctl(fd, NBD_CLEAR_SOCK);
 
     errno = serrno;
@@ -713,11 +708,8 @@ ssize_t nbd_send_request(QIOChannel *ioc, NBDRequest *request)
 {
     uint8_t buf[NBD_REQUEST_SIZE];
 
-    TRACE("Sending request to server: "
-          "{ .from = %" PRIu64", .len = %" PRIu32 ", .handle = %" PRIu64
-          ", .flags = %" PRIx16 ", .type = %" PRIu16 " }",
-          request->from, request->len, request->handle,
-          request->flags, request->type);
+    trace_nbd_send_request(request->from, request->len, request->handle,
+                           request->flags, request->type);
 
     stl_be_p(buf, NBD_REQUEST_MAGIC);
     stw_be_p(buf + 4, request->flags);
@@ -762,9 +754,7 @@ ssize_t nbd_receive_reply(QIOChannel *ioc, NBDReply *reply, Error **errp)
         error_setg(errp, "server shutting down");
         return -EINVAL;
     }
-    TRACE("Got reply: { magic = 0x%" PRIx32 ", .error = % " PRId32
-          ", handle = %" PRIu64" }",
-          magic, reply->error, reply->handle);
+    trace_nbd_receive_reply(magic, reply->error, reply->handle);
 
     if (magic != NBD_REPLY_MAGIC) {
         error_setg(errp, "invalid magic (got 0x%" PRIx32 ")", magic);
diff --git a/nbd/nbd-internal.h b/nbd/nbd-internal.h
index 39bfed177c..cf6ecbf358 100644
--- a/nbd/nbd-internal.h
+++ b/nbd/nbd-internal.h
@@ -31,25 +31,6 @@
 #include "qemu/queue.h"
 #include "qemu/main-loop.h"
 
-/* #define DEBUG_NBD */
-
-#ifdef DEBUG_NBD
-#define DEBUG_NBD_PRINT 1
-#else
-#define DEBUG_NBD_PRINT 0
-#endif
-
-#define TRACE(msg, ...) do { \
-    if (DEBUG_NBD_PRINT) { \
-        LOG(msg, ## __VA_ARGS__); \
-    } \
-} while (0)
-
-#define LOG(msg, ...) do { \
-    fprintf(stderr, "%s:%s():L%d: " msg "\n", \
-            __FILE__, __FUNCTION__, __LINE__, ## __VA_ARGS__); \
-} while (0)
-
 /* This is all part of the "official" NBD API.
  *
  * The most up-to-date documentation is available at:
diff --git a/nbd/server.c b/nbd/server.c
index 0671ebc50a..52ed9625fd 100644
--- a/nbd/server.c
+++ b/nbd/server.c
@@ -19,6 +19,7 @@
 
 #include "qemu/osdep.h"
 #include "qapi/error.h"
+#include "trace.h"
 #include "nbd-internal.h"
 
 static int system_errno_to_nbd_errno(int err)
@@ -138,8 +139,7 @@ static int nbd_negotiate_send_rep_len(QIOChannel *ioc, uint32_t type,
 {
     uint64_t magic;
 
-    TRACE("Reply opt=%" PRIx32 " type=%" PRIx32 " len=%" PRIu32,
-          type, opt, len);
+    trace_nbd_negotiate_send_rep_len(type, opt, len);
 
     magic = cpu_to_be64(NBD_REP_MAGIC);
     if (nbd_write(ioc, &magic, sizeof(magic), errp) < 0) {
@@ -191,7 +191,7 @@ nbd_negotiate_send_rep_err(QIOChannel *ioc, uint32_t type,
     va_end(va);
     len = strlen(msg);
     assert(len < 4096);
-    TRACE("sending error message \"%s\"", msg);
+    trace_nbd_negotiate_send_rep_err(msg);
     ret = nbd_negotiate_send_rep_len(ioc, type, opt, len, errp);
     if (ret < 0) {
         goto out;
@@ -219,7 +219,7 @@ static int nbd_negotiate_send_rep_list(QIOChannel *ioc, NBDExport *exp,
     const char *desc = exp->description ? exp->description : "";
     int ret;
 
-    TRACE("Advertising export name '%s' description '%s'", name, desc);
+    trace_nbd_negotiate_send_rep_list(name, desc);
     name_len = strlen(name);
     desc_len = strlen(desc);
     len = name_len + desc_len + sizeof(len);
@@ -283,7 +283,7 @@ static int nbd_negotiate_handle_export_name(NBDClient *client, uint32_t length,
     /* Client sends:
         [20 ..  xx]   export name (length bytes)
      */
-    TRACE("Checking length");
+    trace_nbd_negotiate_handle_export_name();
     if (length >= sizeof(name)) {
         error_setg(errp, "Bad length received");
         return -EINVAL;
@@ -294,7 +294,7 @@ static int nbd_negotiate_handle_export_name(NBDClient *client, uint32_t length,
     }
     name[length] = '\0';
 
-    TRACE("Client requested export '%s'", name);
+    trace_nbd_negotiate_handle_export_name_request(name);
 
     client->exp = nbd_export_find(name);
     if (!client->exp) {
@@ -318,7 +318,7 @@ static QIOChannel *nbd_negotiate_handle_starttls(NBDClient *client,
     QIOChannelTLS *tioc;
     struct NBDTLSHandshakeData data = { 0 };
 
-    TRACE("Setting up TLS");
+    trace_nbd_negotiate_handle_starttls();
     ioc = client->ioc;
     if (length) {
         if (nbd_drop(ioc, length, errp) < 0) {
@@ -344,7 +344,7 @@ static QIOChannel *nbd_negotiate_handle_starttls(NBDClient *client,
     }
 
     qio_channel_set_name(QIO_CHANNEL(tioc), "nbd-server-tls");
-    TRACE("Starting TLS handshake");
+    trace_nbd_negotiate_handle_starttls_handshake();
     data.loop = g_main_loop_new(g_main_context_default(), FALSE);
     qio_channel_tls_handshake(tioc,
                               nbd_tls_handshake,
@@ -396,15 +396,15 @@ static int nbd_negotiate_options(NBDClient *client, Error **errp)
         error_prepend(errp, "read failed: ");
         return -EIO;
     }
-    TRACE("Checking client flags");
+    trace_nbd_negotiate_options_flags();
     be32_to_cpus(&flags);
     if (flags & NBD_FLAG_C_FIXED_NEWSTYLE) {
-        TRACE("Client supports fixed newstyle handshake");
+        trace_nbd_negotiate_options_newstyle();
         fixedNewstyle = true;
         flags &= ~NBD_FLAG_C_FIXED_NEWSTYLE;
     }
     if (flags & NBD_FLAG_C_NO_ZEROES) {
-        TRACE("Client supports no zeroes at handshake end");
+        trace_nbd_negotiate_options_no_zeroes();
         client->no_zeroes = true;
         flags &= ~NBD_FLAG_C_NO_ZEROES;
     }
@@ -422,7 +422,7 @@ static int nbd_negotiate_options(NBDClient *client, Error **errp)
             error_prepend(errp, "read failed: ");
             return -EINVAL;
         }
-        TRACE("Checking opts magic");
+        trace_nbd_negotiate_options_check_magic();
         if (magic != be64_to_cpu(NBD_OPTS_MAGIC)) {
             error_setg(errp, "Bad magic received");
             return -EINVAL;
@@ -441,7 +441,7 @@ static int nbd_negotiate_options(NBDClient *client, Error **errp)
         }
         length = be32_to_cpu(length);
 
-        TRACE("Checking option 0x%" PRIx32, clientflags);
+        trace_nbd_negotiate_options_check_option(clientflags);
         if (client->tlscreds &&
             client->ioc == (QIOChannel *)client->sioc) {
             QIOChannel *tioc;
@@ -501,8 +501,8 @@ static int nbd_negotiate_options(NBDClient *client, Error **errp)
                                        &local_err);
 
                 if (local_err != NULL) {
-                    TRACE("Reply to NBD_OPT_ABORT request failed: %s",
-                          error_get_pretty(local_err));
+                    const char *error = error_get_pretty(local_err);
+                    trace_nbd_opt_abort_reply_failed(error);
                     error_free(local_err);
                 }
 
@@ -599,14 +599,14 @@ static coroutine_fn int nbd_negotiate(NBDClient *client, Error **errp)
 
     qio_channel_set_blocking(client->ioc, false, NULL);
 
-    TRACE("Beginning negotiation.");
+    trace_nbd_negotiate_begin();
     memset(buf, 0, sizeof(buf));
     memcpy(buf, "NBDMAGIC", 8);
 
     oldStyle = client->exp != NULL && !client->tlscreds;
     if (oldStyle) {
-        TRACE("advertising size %" PRIu64 " and flags %x",
-              client->exp->size, client->exp->nbdflags | myflags);
+        trace_nbd_negotiate_old_style(client->exp->size,
+                                      client->exp->nbdflags | myflags);
         stq_be_p(buf + 8, NBD_CLIENT_MAGIC);
         stq_be_p(buf + 16, client->exp->size);
         stw_be_p(buf + 26, client->exp->nbdflags | myflags);
@@ -637,8 +637,8 @@ static coroutine_fn int nbd_negotiate(NBDClient *client, Error **errp)
             return ret;
         }
 
-        TRACE("advertising size %" PRIu64 " and flags %x",
-              client->exp->size, client->exp->nbdflags | myflags);
+        trace_nbd_negotiate_new_style_size_flags(
+            client->exp->size, client->exp->nbdflags | myflags);
         stq_be_p(buf + 18, client->exp->size);
         stw_be_p(buf + 26, client->exp->nbdflags | myflags);
         len = client->no_zeroes ? 10 : sizeof(buf) - 18;
@@ -649,7 +649,7 @@ static coroutine_fn int nbd_negotiate(NBDClient *client, Error **errp)
         }
     }
 
-    TRACE("Negotiation succeeded.");
+    trace_nbd_negotiate_success();
 
     return 0;
 }
@@ -682,9 +682,8 @@ static int nbd_receive_request(QIOChannel *ioc, NBDRequest *request,
     request->from   = ldq_be_p(buf + 16);
     request->len    = ldl_be_p(buf + 24);
 
-    TRACE("Got request: { magic = 0x%" PRIx32 ", .flags = %" PRIx16
-          ", .type = %" PRIx16 ", from = %" PRIu64 ", len = %" PRIu32 " }",
-          magic, request->flags, request->type, request->from, request->len);
+    trace_nbd_receive_request(magic, request->flags, request->type,
+                              request->from, request->len);
 
     if (magic != NBD_REQUEST_MAGIC) {
         error_setg(errp, "invalid magic (got 0x%" PRIx32 ")", magic);
@@ -699,9 +698,7 @@ static int nbd_send_reply(QIOChannel *ioc, NBDReply *reply, Error **errp)
 
     reply->error = system_errno_to_nbd_errno(reply->error);
 
-    TRACE("Sending response to client: { .error = %" PRId32
-          ", handle = %" PRIu64 " }",
-          reply->error, reply->handle);
+    trace_nbd_send_reply(reply->error, reply->handle);
 
     /* Reply
        [ 0 ..  3]    magic   (NBD_REPLY_MAGIC)
@@ -798,7 +795,7 @@ static void blk_aio_attached(AioContext *ctx, void *opaque)
     NBDExport *exp = opaque;
     NBDClient *client;
 
-    TRACE("Export %s: Attaching clients to AIO context %p\n", exp->name, ctx);
+    trace_blk_aio_attached(exp->name, ctx);
 
     exp->ctx = ctx;
 
@@ -818,7 +815,7 @@ static void blk_aio_detach(void *opaque)
     NBDExport *exp = opaque;
     NBDClient *client;
 
-    TRACE("Export %s: Detaching clients from AIO context %p\n", exp->name, exp->ctx);
+    trace_blk_aio_detach(exp->name, exp->ctx);
 
     QTAILQ_FOREACH(client, &exp->clients, next) {
         qio_channel_detach_aio_context(client->ioc);
@@ -1045,7 +1042,7 @@ static int nbd_co_receive_request(NBDRequestData *req, NBDRequest *request,
         return -EIO;
     }
 
-    TRACE("Decoding type");
+    trace_nbd_co_receive_request_decode_type();
 
     if (request->type != NBD_CMD_WRITE) {
         /* No payload, we are ready to read the next request.  */
@@ -1055,7 +1052,7 @@ static int nbd_co_receive_request(NBDRequestData *req, NBDRequest *request,
     if (request->type == NBD_CMD_DISC) {
         /* Special case: we're going to disconnect without a reply,
          * whether or not flags, from, or len are bogus */
-        TRACE("Request type is DISCONNECT");
+        trace_nbd_co_receive_request_disconnect();
         return -EIO;
     }
 
@@ -1082,7 +1079,7 @@ static int nbd_co_receive_request(NBDRequestData *req, NBDRequest *request,
         }
     }
     if (request->type == NBD_CMD_WRITE) {
-        TRACE("Reading %" PRIu32 " byte(s)", request->len);
+        trace_nbd_co_receive_request_cmd_write(request->len);
 
         if (nbd_read(client->ioc, req->data, request->len, errp) < 0) {
             error_prepend(errp, "reading from socket failed: ");
@@ -1124,7 +1121,7 @@ static coroutine_fn void nbd_trip(void *opaque)
     int reply_data_len = 0;
     Error *local_err = NULL;
 
-    TRACE("Reading request.");
+    trace_do_nbd_trip();
     if (client->closing) {
         nbd_client_put(client);
         return;
@@ -1156,7 +1153,7 @@ static coroutine_fn void nbd_trip(void *opaque)
 
     switch (request.type) {
     case NBD_CMD_READ:
-        TRACE("Request type is READ");
+        trace_do_nbd_trip_cmd_read();
 
         /* XXX: NBD Protocol only documents use of FUA with WRITE */
         if (request.flags & NBD_CMD_FLAG_FUA) {
@@ -1177,19 +1174,19 @@ static coroutine_fn void nbd_trip(void *opaque)
         }
 
         reply_data_len = request.len;
-        TRACE("Read %" PRIu32" byte(s)", request.len);
+        trace_do_nbd_trip_read(request.len);
 
         break;
     case NBD_CMD_WRITE:
-        TRACE("Request type is WRITE");
+        trace_do_nbd_trip_cmd_write();
 
         if (exp->nbdflags & NBD_FLAG_READ_ONLY) {
-            TRACE("Server is read-only, return error");
+            trace_do_nbd_trip_cmd_write_readonly();
             reply.error = EROFS;
             break;
         }
 
-        TRACE("Writing to device");
+        trace_do_nbd_trip_write();
 
         flags = 0;
         if (request.flags & NBD_CMD_FLAG_FUA) {
@@ -1204,7 +1201,7 @@ static coroutine_fn void nbd_trip(void *opaque)
 
         break;
     case NBD_CMD_WRITE_ZEROES:
-        TRACE("Request type is WRITE_ZEROES");
+        trace_do_nbd_trip_cmd_write_zeroes();
 
         if (exp->nbdflags & NBD_FLAG_READ_ONLY) {
             error_setg(&local_err, "Server is read-only, return error");
@@ -1212,7 +1209,7 @@ static coroutine_fn void nbd_trip(void *opaque)
             break;
         }
 
-        TRACE("Writing to device");
+        trace_do_nbd_trip_write_zeroes();
 
         flags = 0;
         if (request.flags & NBD_CMD_FLAG_FUA) {
@@ -1234,7 +1231,7 @@ static coroutine_fn void nbd_trip(void *opaque)
         abort();
 
     case NBD_CMD_FLUSH:
-        TRACE("Request type is FLUSH");
+        trace_do_nbd_trip_cmd_flush();
 
         ret = blk_co_flush(exp->blk);
         if (ret < 0) {
@@ -1244,7 +1241,7 @@ static coroutine_fn void nbd_trip(void *opaque)
 
         break;
     case NBD_CMD_TRIM:
-        TRACE("Request type is TRIM");
+        trace_do_nbd_trip_cmd_trim();
         ret = blk_co_pdiscard(exp->blk, request.from + exp->dev_offset,
                               request.len);
         if (ret < 0) {
@@ -1280,7 +1277,7 @@ reply:
         goto disconnect;
     }
 
-    TRACE("Request/Reply complete");
+    trace_do_nbd_trip_complete();
 
 done:
     nbd_request_put(req);
diff --git a/nbd/trace-events b/nbd/trace-events
new file mode 100644
index 0000000000..46e4d110bd
--- /dev/null
+++ b/nbd/trace-events
@@ -0,0 +1,68 @@
+# nbd/client.c
+nbd_unknown_error(int err) "Squashing unexpected error %d to EINVAL"
+nbd_send_option_request(uint32_t opt, uint32_t len) "Sending option request %" PRIu32", len %" PRIu32
+nbd_receive_option_reply(uint32_t option, uint32_t type, uint32_t length) "Received option reply %" PRIx32", type %" PRIx32", len %" PRIu32
+nbd_reply_err_unsup(uint32_t option) "server doesn't understand request %" PRIx32 ", attempting fallback"
+nbd_receive_query_exports_start(const char *wantname) "Querying export list for '%s'"
+nbd_receive_query_exports_loop(void) "Reading available export names"
+nbd_receive_query_exports_success(const char *wantname) "Found desired export name '%s'"
+nbd_receive_starttls_request(void) "Requesting TLS from server"
+nbd_receive_starttls_reply(void) "Getting TLS reply from server"
+nbd_receive_starttls_new_client(void) "TLS request approved, setting up TLS"
+nbd_receive_starttls_tls_handshake(void) "Starting TLS handshake"
+nbd_receive_negotiate(void *tlscreds, const char *hostname) "Receiving negotiation tlscreds=%p hostname=%s"
+nbd_receive_negotiate_magic(uint64_t magic) "Magic is 0x%" PRIx64
+nbd_receive_negotiate_magic2(uint64_t magic) "Magic is 0x%" PRIx64
+nbd_receive_negotiate_server_flags(uint32_t globalflags) "Global flags are %" PRIx32
+nbd_receive_negotiate_default_name(void) "Using default NBD export name \"\""
+nbd_receive_negotiate_export_size(uint64_t size) "Size is %" PRIu64
+nbd_receive_negotiate_size_flags(uint64_t size, uint16_t flags) "Size is %" PRIu64 ", export flags %" PRIx16
+nbd_init_set_socket(void) "Setting NBD socket"
+nbd_init_set_block_size(unsigned long block_size) "Setting block size to %lu"
+nbd_init_set_size(unsigned long sectors) "Setting size to %lu block(s)"
+nbd_init_trailing_bytes(int ignored_bytes) "Ignoring trailing %d bytes of export"
+nbd_init_set_readonly(void) "Setting readonly attribute"
+nbd_init_finish(void) "Negotiation ended"
+nbd_client_loop(void) "Doing NBD loop"
+nbd_client_loop_ret(int ret, const char *error) "NBD loop returned %d: %s"
+nbd_client_clear_queue(void) "Clearing NBD queue"
+nbd_client_clear_socket(void) "Clearing NBD socket"
+nbd_send_request(uint64_t from, uint32_t len, uint64_t handle, uint16_t flags, uint16_t type) "Sending request to server: { .from = %" PRIu64", .len = %" PRIu32 ", .handle = %" PRIu64 ", .flags = %" PRIx16 ", .type = %" PRIu16 " }"
+nbd_receive_reply(uint32_t magic, int32_t error, uint64_t handle) "Got reply: { magic = 0x%" PRIx32 ", .error = % " PRId32 ", handle = %" PRIu64" }"
+
+# nbd/server.c
+nbd_negotiate_send_rep_len(uint32_t type, uint32_t opt, uint32_t len) "Reply opt=%" PRIx32 " type=%" PRIx32 " len=%" PRIu32
+nbd_negotiate_send_rep_err(const char *msg) "sending error message \"%s\""
+nbd_negotiate_send_rep_list(const char *name, const char *desc) "Advertising export name '%s' description '%s'"
+nbd_negotiate_handle_export_name(void) "Checking length"
+nbd_negotiate_handle_export_name_request(const char *name) "Client requested export '%s'"
+nbd_negotiate_handle_starttls(void) "Setting up TLS"
+nbd_negotiate_handle_starttls_handshake(void) "Starting TLS handshake"
+nbd_negotiate_options_flags(void) "Checking client flags"
+nbd_negotiate_options_newstyle(void) "Client supports fixed newstyle handshake"
+nbd_negotiate_options_no_zeroes(void) "Client supports no zeroes at handshake end"
+nbd_negotiate_options_check_magic(void) "Checking opts magic"
+nbd_negotiate_options_check_option(uint32_t clientflags) "Checking option 0x%" PRIx32
+nbd_opt_abort_reply_failed(const char *error) "Reply to NBD_OPT_ABORT request failed: %s"
+nbd_negotiate_begin(void) "Beginning negotiation"
+nbd_negotiate_old_style(uint64_t size, unsigned flags) "advertising size %" PRIu64 " and flags %x"
+nbd_negotiate_new_style_size_flags(uint64_t size, unsigned flags) "advertising size %" PRIu64 " and flags %x"
+nbd_negotiate_success(void) "Negotiation succeeded"
+nbd_receive_request(uint32_t magic, uint16_t flags, uint16_t type, uint64_t from, uint32_t len) "Got request: { magic = 0x%" PRIx32 ", .flags = %" PRIx16 ", .type = %" PRIx16 ", from = %" PRIu64 ", len = %" PRIu32 " }"
+nbd_send_reply(int32_t error, uint64_t handle) "Sending response to client: { .error = %" PRId32 ", handle = %" PRIu64 " }"
+blk_aio_attached(const char *name, void *ctx) "Export %s: Attaching clients to AIO context %p\n"
+blk_aio_detach(const char *name, void *ctx) "Export %s: Detaching clients from AIO context %p\n"
+nbd_co_receive_request_decode_type(void) "Decoding type"
+nbd_co_receive_request_disconnect(void) "Request type is DISCONNECT"
+nbd_co_receive_request_cmd_write(uint32_t len) "Reading %" PRIu32 " byte(s)"
+do_nbd_trip(void) "Reading request"
+do_nbd_trip_cmd_read(void) "Request type is READ"
+do_nbd_trip_read(uint32_t len) "Read %" PRIu32" byte(s)"
+do_nbd_trip_cmd_write(void) "Request type is WRITE"
+do_nbd_trip_cmd_write_readonly(void) "Server is read-only, return error"
+do_nbd_trip_write(void) "Writing to device"
+do_nbd_trip_cmd_write_zeroes(void) "Request type is WRITE_ZEROES"
+do_nbd_trip_write_zeroes(void) "Writing to device"
+do_nbd_trip_cmd_flush(void) "Request type is FLUSH"
+do_nbd_trip_cmd_trim(void) "Request type is TRIM"
+do_nbd_trip_complete(void) "Request/Reply complete"
-- 
2.11.1

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* Re: [Qemu-devel] [PATCH v2 1/6] nbd/server: nbd_negotiate: return 1 on NBD_OPT_ABORT
  2017-06-21 15:34 ` [Qemu-devel] [PATCH v2 1/6] nbd/server: nbd_negotiate: return 1 on NBD_OPT_ABORT Vladimir Sementsov-Ogievskiy
@ 2017-06-29 18:46   ` Eric Blake
  2017-07-06 16:07     ` Eric Blake
  0 siblings, 1 reply; 28+ messages in thread
From: Eric Blake @ 2017-06-29 18:46 UTC (permalink / raw)
  To: Vladimir Sementsov-Ogievskiy, qemu-devel; +Cc: stefanha, pbonzini, den

[-- Attachment #1: Type: text/plain, Size: 3410 bytes --]

On 06/21/2017 10:34 AM, Vladimir Sementsov-Ogievskiy wrote:
> Separate case when client sent NBD_OPT_ABORT from other errors.

Commit messages are best written in imperative tense (you can supply an
implicit "apply this patch in order to" prefix in front of the message,
and it should still generally read well); and that doesn't mix well with
past-tense descriptions.  I might have written:

Separate the case when a client sends NBD_OPT_ABORT from all other errors.

> It will be needed for the following patch, where errors will be
> reported.
> Considered case is not actually the error - it honestly follows NBD
> protocol. Therefore it should not be reported like an error.

This particular case is not actually an error - it honestly follows the
NBD protocol.

> 
> Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
> ---
>  nbd/server.c | 20 +++++++++++++++-----
>  1 file changed, 15 insertions(+), 5 deletions(-)
> 

> -
> -/* Process all NBD_OPT_* client option commands.
> - * Return -errno on error, 0 on success. */
> +/* nbd_negotiate_options
> + * Process all NBD_OPT_* client option commands.
> + * Return:
> + * -errno  on error
> + * 0       on successful negotiation
> + * 1       if client sent NBD_OPT_ABORT, i.e. on legal disconnect

"legal" often comes with connotations about law (and I don't want to get
mired in an open-source law discussion); I'd stick with "valid".

> + */
>  static int nbd_negotiate_options(NBDClient *client)
>  {
>      uint32_t flags;
> @@ -459,7 +463,7 @@ static int nbd_negotiate_options(NBDClient *client)
>                  }
>                  /* Let the client keep trying, unless they asked to quit */
>                  if (clientflags == NBD_OPT_ABORT) {
> -                    return -EINVAL;
> +                    return 1;

Note: the reason we don't try to send an NBD_REP_ACK here (a guest that
forgot to start the TLS handshake) is because we don't want to ever
return NBD_REP_ACK when we are going to require TLS.  It's a bit odd
that we don't reply here, but DO reply to all other NBD_OPT_ABORT, but I
don't think it makes us any less compliant to the spec.

>                  }
>                  break;
>              }
> @@ -477,7 +481,7 @@ static int nbd_negotiate_options(NBDClient *client)
>                   * disconnecting, but that we must also tolerate
>                   * guests that don't wait for our reply. */
>                  nbd_negotiate_send_rep(client->ioc, NBD_REP_ACK, clientflags);
> -                return -EINVAL;
> +                return 1;

If anything, we may want (as a separate patch) to add a comment to our
TLS behavior as to why we don't reply with NBD_REP_ACK.  But doesn't
affect this patch.

>  
>              case NBD_OPT_EXPORT_NAME:
>                  return nbd_negotiate_handle_export_name(client, length);
> @@ -533,6 +537,12 @@ static int nbd_negotiate_options(NBDClient *client)
>      }
>  }
>  
> +/* nbd_negotiate
> + * Return:
> + * -errno  on error
> + * 0       on successful negotiation
> + * 1       if client sent NBD_OPT_ABORT, i.e. on legal disconnect

Again on the wording.  With that touched up,
Reviewed-by: Eric Blake <eblake@redhat.com>

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3266
Virtualization:  qemu.org | libvirt.org


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 604 bytes --]

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [Qemu-devel] [PATCH v2 2/6] nbd/server: use errp instead of LOG
  2017-06-21 15:34 ` [Qemu-devel] [PATCH v2 2/6] nbd/server: use errp instead of LOG Vladimir Sementsov-Ogievskiy
@ 2017-06-29 19:27   ` Eric Blake
  2017-07-05 12:33     ` Vladimir Sementsov-Ogievskiy
  2017-07-05 17:38     ` Markus Armbruster
  2017-07-07 14:40   ` Eric Blake
  1 sibling, 2 replies; 28+ messages in thread
From: Eric Blake @ 2017-06-29 19:27 UTC (permalink / raw)
  To: Vladimir Sementsov-Ogievskiy, qemu-devel
  Cc: stefanha, pbonzini, den, Markus Armbruster

[-- Attachment #1: Type: text/plain, Size: 5434 bytes --]

On 06/21/2017 10:34 AM, Vladimir Sementsov-Ogievskiy wrote:
> Move to modern errp scheme from just LOGging errors.
> 
> Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
> ---
>  nbd/server.c | 268 +++++++++++++++++++++++++++++++++++------------------------
>  1 file changed, 161 insertions(+), 107 deletions(-)

Unfortunately longer, but I'm okay with that (and we already did it
client-side, so this is just a case of a patch series being spread out
over time).


>  
>  /* Send an error reply.
>   * Return -errno on error, 0 on success. */
> -static int GCC_FMT_ATTR(4, 5)
> +static int GCC_FMT_ATTR(5, 6)
>  nbd_negotiate_send_rep_err(QIOChannel *ioc, uint32_t type,
> -                           uint32_t opt, const char *fmt, ...)
> +                           uint32_t opt, Error **errp, const char *fmt, ...)
>  {

Markus, this violates our usual idiom of errp last in code that is not
directly operating on an Error (the actual Error implementation in
error.c being the main obvious exception that lists errp first), but I
don't see any better approach. Do you have any thoughts on it?

> -    if (nbd_read(client->ioc, name, length, NULL) < 0) {
> -        LOG("read failed");
> +    if (nbd_read(client->ioc, name, length, errp) < 0) {
> +        error_prepend(errp, "read failed: ");
>          return -EINVAL;
>      }

I'm still not convinced we need quite as many error_prepend() calls (it
may be simpler to just use the underlying error message as-is, without
trying to prepend) - but deciding where it is fluff is a cleanup while
this patch is all about a mechanical conversion, so I'm not going to
hold up this patch while we solve that debate.


>      tioc = qio_channel_tls_new_server(ioc,
>                                        client->tlscreds,
>                                        client->tlsaclname,
> -                                      NULL);
> +                                      errp);

Yay for wiring things up to no longer ignore original error messages.

> @@ -352,14 +367,16 @@ static QIOChannel *nbd_negotiate_handle_starttls(NBDClient *client,
>  /* nbd_negotiate_options
>   * Process all NBD_OPT_* client option commands.
>   * Return:
> - * -errno  on error
> - * 0       on successful negotiation
> - * 1       if client sent NBD_OPT_ABORT, i.e. on legal disconnect
> + * -errno  on error, errp is set
> + * 0       on successful negotiation, errp is not set
> + * 1       if client sent NBD_OPT_ABORT, i.e. on legal disconnect,
> + *         errp is not set

You'll have some rebase churn based on my comments on 1/6 (where I
suggested s/legal/valid/).  I'm not sure the change about documenting
whether errp is set is even necessary (we have enough common usage of
errp, that it is kind of easy to just assume that everyone knows errp is
set only on negative return); but it doesn't hurt to keep it.

> @@ -480,25 +497,33 @@ static int nbd_negotiate_options(NBDClient *client)
>                  /* NBD spec says we must try to reply before
>                   * disconnecting, but that we must also tolerate
>                   * guests that don't wait for our reply. */
> -                nbd_negotiate_send_rep(client->ioc, NBD_REP_ACK, clientflags);
> +                nbd_negotiate_send_rep(client->ioc, NBD_REP_ACK, clientflags,
> +                                       &local_err);
> +
> +                if (local_err != NULL) {
> +                    TRACE("Reply to NBD_OPT_ABORT request failed: %s",
> +                          error_get_pretty(local_err));
> +                    error_free(local_err);
> +                }
> +

Not sure this is necessary.  I would have just used:

nbd_negotiate_send_rep(client->ioc, NBD_REP_ACK, clientflags, NULL);

and then you don't even need a local_err variable.


> @@ -1089,6 +1121,7 @@ static coroutine_fn void nbd_trip(void *opaque)
>      int ret;
>      int flags;
>      int reply_data_len = 0;
> +    Error *local_err = NULL;
>  
>      TRACE("Reading request.");
>      if (client->closing) {
> @@ -1097,7 +1130,7 @@ static coroutine_fn void nbd_trip(void *opaque)

> @@ -1128,7 +1161,7 @@ static coroutine_fn void nbd_trip(void *opaque)
>          if (request.flags & NBD_CMD_FLAG_FUA) {
>              ret = blk_co_flush(exp->blk);
>              if (ret < 0) {
> -                LOG("flush failed");
> +                error_setg_errno(&local_err, -ret, "flush failed");
>                  reply.error = -ret;
>                  break;
>              }

>  reply:
> +    if (local_err) {
> +        /* If we are here local_err is not fatal error, already stored in
> +         * reply.error */
> +        error_report_err(local_err);
> +        local_err = NULL;
> +    }

So we still end up printing the error directly to stderr, the way LOG()
used to do; but in light of the recent CVEs on 'qemu-nbd -t' not being
robust to misbehaved clients, it does feel like the right thing (the
server detecting an error does not mean that the server should quit,
merely that it should log that a client is no longer connected).

Overall the change looks good to me, but I'll wait to see if Markus has
any design advice before giving my R-b.

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3266
Virtualization:  qemu.org | libvirt.org


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 604 bytes --]

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [Qemu-devel] [PATCH v2 3/6] nbd/server: add errp to nbd_send_reply()
  2017-06-21 15:34 ` [Qemu-devel] [PATCH v2 3/6] nbd/server: add errp to nbd_send_reply() Vladimir Sementsov-Ogievskiy
@ 2017-06-29 19:31   ` Eric Blake
  0 siblings, 0 replies; 28+ messages in thread
From: Eric Blake @ 2017-06-29 19:31 UTC (permalink / raw)
  To: Vladimir Sementsov-Ogievskiy, qemu-devel; +Cc: stefanha, pbonzini, den

[-- Attachment #1: Type: text/plain, Size: 961 bytes --]

On 06/21/2017 10:34 AM, Vladimir Sementsov-Ogievskiy wrote:
> Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
> ---
>  nbd/server.c | 17 +++++++++--------
>  1 file changed, 9 insertions(+), 8 deletions(-)
> 

> @@ -1266,8 +1267,8 @@ reply:
>          local_err = NULL;
>      }
>  
> -    if (nbd_co_send_reply(req, &reply, reply_data_len) < 0) {
> -        error_setg(&local_err, "Failed to send reply");
> +    if (nbd_co_send_reply(req, &reply, reply_data_len, &local_err) < 0) {
> +        error_prepend(&local_err, "Failed to send reply: ");
>          goto disconnect;

Again, I'm not sure if the error_prepend is necessary vs. just directly
reusing the error from earlier in the stack.  But it's not enough to
stop me from giving:

Reviewed-by: Eric Blake <eblake@redhat.com>

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3266
Virtualization:  qemu.org | libvirt.org


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 604 bytes --]

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [Qemu-devel] [PATCH v2 4/6] nbd/common: nbd_tls_handshake: remove extra TRACE
  2017-06-21 15:34 ` [Qemu-devel] [PATCH v2 4/6] nbd/common: nbd_tls_handshake: remove extra TRACE Vladimir Sementsov-Ogievskiy
@ 2017-06-29 19:32   ` Eric Blake
  0 siblings, 0 replies; 28+ messages in thread
From: Eric Blake @ 2017-06-29 19:32 UTC (permalink / raw)
  To: Vladimir Sementsov-Ogievskiy, qemu-devel; +Cc: stefanha, pbonzini, den

[-- Attachment #1: Type: text/plain, Size: 985 bytes --]

On 06/21/2017 10:34 AM, Vladimir Sementsov-Ogievskiy wrote:
> Error is propagated to the caller, TRACE is not needed.
> 
> Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
> ---
>  nbd/common.c | 4 +---
>  1 file changed, 1 insertion(+), 3 deletions(-)

Reviewed-by: Eric Blake <eblake@redhat.com>

> 
> diff --git a/nbd/common.c b/nbd/common.c
> index 6b5c1b7b02..4dab41e2c0 100644
> --- a/nbd/common.c
> +++ b/nbd/common.c
> @@ -97,9 +97,7 @@ void nbd_tls_handshake(QIOTask *task,
>  {
>      struct NBDTLSHandshakeData *data = opaque;
>  
> -    if (qio_task_propagate_error(task, &data->error)) {
> -        TRACE("TLS failed %s", error_get_pretty(data->error));
> -    }
> +    qio_task_propagate_error(task, &data->error);
>      data->complete = true;
>      g_main_loop_quit(data->loop);
>  }
> 

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3266
Virtualization:  qemu.org | libvirt.org


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 604 bytes --]

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [Qemu-devel] [PATCH v2 5/6] nbd/client: refactor TRACE of NBD_MAGIC
  2017-06-21 15:34 ` [Qemu-devel] [PATCH v2 5/6] nbd/client: refactor TRACE of NBD_MAGIC Vladimir Sementsov-Ogievskiy
@ 2017-06-29 19:36   ` Eric Blake
  2017-07-05 15:21     ` Paolo Bonzini
  0 siblings, 1 reply; 28+ messages in thread
From: Eric Blake @ 2017-06-29 19:36 UTC (permalink / raw)
  To: Vladimir Sementsov-Ogievskiy, qemu-devel; +Cc: stefanha, pbonzini, den

[-- Attachment #1: Type: text/plain, Size: 2224 bytes --]

On 06/21/2017 10:34 AM, Vladimir Sementsov-Ogievskiy wrote:
> We are going to switch from TRACE macro to trace points,
> this TRACE complicates things, this patch simplifies it.
> 
> Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
> ---
>  nbd/client.c | 15 ++++-----------
>  1 file changed, 4 insertions(+), 11 deletions(-)
> 
> diff --git a/nbd/client.c b/nbd/client.c
> index b97143fa60..5a4825ebe0 100644
> --- a/nbd/client.c
> +++ b/nbd/client.c
> @@ -426,14 +426,13 @@ static QIOChannel *nbd_receive_starttls(QIOChannel *ioc,
>      return QIO_CHANNEL(tioc);
>  }
>  
> -
>  int nbd_receive_negotiate(QIOChannel *ioc, const char *name, uint16_t *flags,

Spurious whitespace change?

>                            QCryptoTLSCreds *tlscreds, const char *hostname,
>                            QIOChannel **outioc,
>                            off_t *size, Error **errp)
>  {
>      char buf[256];
> -    uint64_t magic, s;
> +    uint64_t nbd_magic, magic, s;

Why do we need two separate variables? Can't you just reuse 'magic'?

>      int rc;
>      bool zeroes = true;
>  
> @@ -461,15 +460,9 @@ int nbd_receive_negotiate(QIOChannel *ioc, const char *name, uint16_t *flags,
>          goto fail;
>      }
>  
> -    TRACE("Magic is %c%c%c%c%c%c%c%c",
> -          qemu_isprint(buf[0]) ? buf[0] : '.',
> -          qemu_isprint(buf[1]) ? buf[1] : '.',
> -          qemu_isprint(buf[2]) ? buf[2] : '.',
> -          qemu_isprint(buf[3]) ? buf[3] : '.',
> -          qemu_isprint(buf[4]) ? buf[4] : '.',
> -          qemu_isprint(buf[5]) ? buf[5] : '.',
> -          qemu_isprint(buf[6]) ? buf[6] : '.',
> -          qemu_isprint(buf[7]) ? buf[7] : '.');
> +    memcpy(&nbd_magic, buf, 8);
> +    nbd_magic = be64_to_cpu(nbd_magic);

Do we really need to copy the memory around twice?  Can't we just use:
 magic = ldq_be_p(buf);
and call it good?

> +    TRACE("Magic is 0x%" PRIx64, nbd_magic);
>  
>      if (memcmp(buf, "NBDMAGIC", 8) != 0) {
>          error_setg(errp, "Invalid magic received");
> 

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3266
Virtualization:  qemu.org | libvirt.org


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 604 bytes --]

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [Qemu-devel] [PATCH v2 6/6] nbd: use generic trace subsystem instead of TRACE macro
  2017-06-21 15:34 ` [Qemu-devel] [PATCH v2 6/6] nbd: use generic trace subsystem instead of TRACE macro Vladimir Sementsov-Ogievskiy
@ 2017-06-29 20:12   ` Eric Blake
  2017-07-06 14:49     ` Eric Blake
  2017-07-05 15:29   ` Paolo Bonzini
                     ` (3 subsequent siblings)
  4 siblings, 1 reply; 28+ messages in thread
From: Eric Blake @ 2017-06-29 20:12 UTC (permalink / raw)
  To: Vladimir Sementsov-Ogievskiy, qemu-devel; +Cc: stefanha, pbonzini, den

[-- Attachment #1: Type: text/plain, Size: 2070 bytes --]

On 06/21/2017 10:34 AM, Vladimir Sementsov-Ogievskiy wrote:
> Starting from this patch to enable traces use -trace option of qemu or
> -T, --trace option of qemu-img, qemu-io and qemu-nbd. For qemu traces
> also can be managed by qmp commands trace-event-{get,set}-state.

Maybe:

Let NBD use the trace mechanisms already present in qemu. Now you can
use the -trace optino of qemu, or the -T/--trace option of qemu-img,
qemu-io, and qemu-nbd, to select nbd traces.  For qemu, the QMP commands
trace-event-{get,set}-state can also toggle tracing on the fly.

I also mentioned in v1 that an actual command line example might be
helpful (for example, is it qemu-nbd --trace "nbd_*" to get ALL nbd
traces enabled?)

> 
> Recompilation with CFLAGS=-DDEBUG_NBD is no more needed, furthermore,
> DEBUG_NBD macro is removed from the code.

Yay!

> 
> Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>


> @@ -462,7 +460,7 @@ int nbd_receive_negotiate(QIOChannel *ioc, const char *name, uint16_t *flags,
>  
>      memcpy(&nbd_magic, buf, 8);
>      nbd_magic = be64_to_cpu(nbd_magic);
> -    TRACE("Magic is 0x%" PRIx64, nbd_magic);
> +    trace_nbd_receive_negotiate_magic(nbd_magic);

Might be some churn based on the resolution to 5/6.

>  
>      if (memcmp(buf, "NBDMAGIC", 8) != 0) {
>          error_setg(errp, "Invalid magic received");
> @@ -474,7 +472,7 @@ int nbd_receive_negotiate(QIOChannel *ioc, const char *name, uint16_t *flags,
>          goto fail;
>      }
>      magic = be64_to_cpu(magic);
> -    TRACE("Magic is 0x%" PRIx64, magic);
> +    trace_nbd_receive_negotiate_magic2(magic);

I'm not sure you need two different trace functions, since the message
is identical.  I'd just have trace_nbd_receive_magic(magic) and use that
at both call sites.

But overall worth having, even if we fine-tune it later.

Reviewed-by: Eric Blake <eblake@redhat.com>

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3266
Virtualization:  qemu.org | libvirt.org


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 604 bytes --]

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [Qemu-devel] [PATCH v2 2/6] nbd/server: use errp instead of LOG
  2017-06-29 19:27   ` Eric Blake
@ 2017-07-05 12:33     ` Vladimir Sementsov-Ogievskiy
  2017-07-05 15:21       ` Paolo Bonzini
  2017-07-05 17:38     ` Markus Armbruster
  1 sibling, 1 reply; 28+ messages in thread
From: Vladimir Sementsov-Ogievskiy @ 2017-07-05 12:33 UTC (permalink / raw)
  To: Eric Blake, qemu-devel; +Cc: stefanha, pbonzini, den, Markus Armbruster

Markus, what do you think? I'll resend tomorrow with Eric's comments 
applied, should I change something with this errp?

29.06.2017 22:27, Eric Blake wrote:
> On 06/21/2017 10:34 AM, Vladimir Sementsov-Ogievskiy wrote:

[...]

>> -static int GCC_FMT_ATTR(4, 5)
>> +static int GCC_FMT_ATTR(5, 6)
>>   nbd_negotiate_send_rep_err(QIOChannel *ioc, uint32_t type,
>> -                           uint32_t opt, const char *fmt, ...)
>> +                           uint32_t opt, Error **errp, const char *fmt, ...)
>>   {
> Markus, this violates our usual idiom of errp last in code that is not
> directly operating on an Error (the actual Error implementation in
> error.c being the main obvious exception that lists errp first), but I
> don't see any better approach. Do you have any thoughts on it?
>
>> -    if (nbd_read(client->ioc, name, length, NULL) < 0) {
>> -        LOG("read failed");
>> +    if (nbd_read(client->ioc, name, length, errp) < 0) {
>> +        error_prepend(errp, "read failed: ");
>>           return -EINVAL;
>>       }

[...]

>
> Overall the change looks good to me, but I'll wait to see if Markus has
> any design advice before giving my R-b.
>

-- 
Best regards,
Vladimir

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [Qemu-devel] [PATCH v2 2/6] nbd/server: use errp instead of LOG
  2017-07-05 12:33     ` Vladimir Sementsov-Ogievskiy
@ 2017-07-05 15:21       ` Paolo Bonzini
  0 siblings, 0 replies; 28+ messages in thread
From: Paolo Bonzini @ 2017-07-05 15:21 UTC (permalink / raw)
  To: Vladimir Sementsov-Ogievskiy, Eric Blake, qemu-devel
  Cc: stefanha, den, Markus Armbruster



On 05/07/2017 14:33, Vladimir Sementsov-Ogievskiy wrote:
> 
> 
>>> -static int GCC_FMT_ATTR(4, 5)
>>> +static int GCC_FMT_ATTR(5, 6)
>>>   nbd_negotiate_send_rep_err(QIOChannel *ioc, uint32_t type,
>>> -                           uint32_t opt, const char *fmt, ...)
>>> +                           uint32_t opt, Error **errp, const char
>>> *fmt, ...)
>>>   {
>> Markus, this violates our usual idiom of errp last in code that is not
>> directly operating on an Error (the actual Error implementation in
>> error.c being the main obvious exception that lists errp first), but I
>> don't see any better approach. Do you have any thoughts on it?

I think it's okay as it matches functions like vfprintf.

Paolo

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [Qemu-devel] [PATCH v2 5/6] nbd/client: refactor TRACE of NBD_MAGIC
  2017-06-29 19:36   ` Eric Blake
@ 2017-07-05 15:21     ` Paolo Bonzini
  0 siblings, 0 replies; 28+ messages in thread
From: Paolo Bonzini @ 2017-07-05 15:21 UTC (permalink / raw)
  To: Eric Blake, Vladimir Sementsov-Ogievskiy, qemu-devel; +Cc: stefanha, den

[-- Attachment #1: Type: text/plain, Size: 267 bytes --]



On 29/06/2017 21:36, Eric Blake wrote:
>> +    memcpy(&nbd_magic, buf, 8);
>> +    nbd_magic = be64_to_cpu(nbd_magic);
> Do we really need to copy the memory around twice?  Can't we just use:
>  magic = ldq_be_p(buf);
> and call it good?

Yes.

Paolo


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [Qemu-devel] [PATCH v2 6/6] nbd: use generic trace subsystem instead of TRACE macro
  2017-06-21 15:34 ` [Qemu-devel] [PATCH v2 6/6] nbd: use generic trace subsystem instead of TRACE macro Vladimir Sementsov-Ogievskiy
  2017-06-29 20:12   ` Eric Blake
@ 2017-07-05 15:29   ` Paolo Bonzini
  2017-07-06  8:45     ` Vladimir Sementsov-Ogievskiy
  2017-07-06 15:01   ` Eric Blake
                     ` (2 subsequent siblings)
  4 siblings, 1 reply; 28+ messages in thread
From: Paolo Bonzini @ 2017-07-05 15:29 UTC (permalink / raw)
  To: Vladimir Sementsov-Ogievskiy, qemu-devel; +Cc: stefanha, eblake, den



On 21/06/2017 17:34, Vladimir Sementsov-Ogievskiy wrote:
> Starting from this patch to enable traces use -trace option of qemu or
> -T, --trace option of qemu-img, qemu-io and qemu-nbd. For qemu traces
> also can be managed by qmp commands trace-event-{get,set}-state.
> 
> Recompilation with CFLAGS=-DDEBUG_NBD is no more needed, furthermore,
> DEBUG_NBD macro is removed from the code.
> 
> Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
> ---
>  Makefile.objs      |  1 +
>  nbd/client.c       | 74 +++++++++++++++++++++---------------------------
>  nbd/nbd-internal.h | 19 -------------
>  nbd/server.c       | 83 ++++++++++++++++++++++++++----------------------------
>  nbd/trace-events   | 68 ++++++++++++++++++++++++++++++++++++++++++++
>  5 files changed, 141 insertions(+), 104 deletions(-)
>  create mode 100644 nbd/trace-events
> 
> diff --git a/Makefile.objs b/Makefile.objs
> index b2e6322ef0..a66ea34cc4 100644
> --- a/Makefile.objs
> +++ b/Makefile.objs
> @@ -168,6 +168,7 @@ trace-events-subdirs += linux-user
>  trace-events-subdirs += qapi
>  trace-events-subdirs += accel/tcg
>  trace-events-subdirs += accel/kvm
> +trace-events-subdirs += nbd
>  
>  trace-events-files = $(SRC_PATH)/trace-events $(trace-events-subdirs:%=$(SRC_PATH)/%/trace-events)
>  
> diff --git a/nbd/client.c b/nbd/client.c
> index 5a4825ebe0..75b28f4ccf 100644
> --- a/nbd/client.c
> +++ b/nbd/client.c
> @@ -19,6 +19,7 @@
>  
>  #include "qemu/osdep.h"
>  #include "qapi/error.h"
> +#include "trace.h"
>  #include "nbd-internal.h"
>  
>  static int nbd_errno_to_system_errno(int err)
> @@ -44,7 +45,7 @@ static int nbd_errno_to_system_errno(int err)
>          ret = ESHUTDOWN;
>          break;
>      default:
> -        TRACE("Squashing unexpected error %d to EINVAL", err);
> +        trace_nbd_unknown_error(err);
>          /* fallthrough */
>      case NBD_EINVAL:
>          ret = EINVAL;
> @@ -103,7 +104,7 @@ static int nbd_send_option_request(QIOChannel *ioc, uint32_t opt,
>      if (len == -1) {
>          req.length = len = strlen(data);
>      }
> -    TRACE("Sending option request %" PRIu32", len %" PRIu32, opt, len);
> +    trace_nbd_send_option_request(opt, len);
>  
>      stq_be_p(&req.magic, NBD_OPTS_MAGIC);
>      stl_be_p(&req.option, opt);
> @@ -153,8 +154,7 @@ static int nbd_receive_option_reply(QIOChannel *ioc, uint32_t opt,
>      be32_to_cpus(&reply->type);
>      be32_to_cpus(&reply->length);
>  
> -    TRACE("Received option reply %" PRIx32", type %" PRIx32", len %" PRIu32,
> -          reply->option, reply->type, reply->length);
> +    trace_nbd_receive_option_reply(reply->option, reply->type, reply->length);
>  
>      if (reply->magic != NBD_REP_MAGIC) {
>          error_setg(errp, "Unexpected option reply magic");
> @@ -201,8 +201,7 @@ static int nbd_handle_reply_err(QIOChannel *ioc, nbd_opt_reply *reply,
>  
>      switch (reply->type) {
>      case NBD_REP_ERR_UNSUP:
> -        TRACE("server doesn't understand request %" PRIx32
> -              ", attempting fallback", reply->option);
> +        trace_nbd_reply_err_unsup(reply->option);
>          result = 0;
>          goto cleanup;
>  
> @@ -342,12 +341,12 @@ static int nbd_receive_query_exports(QIOChannel *ioc,
>  {
>      bool foundExport = false;
>  
> -    TRACE("Querying export list for '%s'", wantname);
> +    trace_nbd_receive_query_exports_start(wantname);
>      if (nbd_send_option_request(ioc, NBD_OPT_LIST, 0, NULL, errp) < 0) {
>          return -1;
>      }
>  
> -    TRACE("Reading available export names");
> +    trace_nbd_receive_query_exports_loop();
>      while (1) {
>          int ret = nbd_receive_list(ioc, wantname, &foundExport, errp);
>  
> @@ -362,7 +361,7 @@ static int nbd_receive_query_exports(QIOChannel *ioc,
>                  nbd_send_opt_abort(ioc);
>                  return -1;
>              }
> -            TRACE("Found desired export name '%s'", wantname);
> +            trace_nbd_receive_query_exports_success(wantname);
>              return 0;
>          }
>      }
> @@ -376,12 +375,12 @@ static QIOChannel *nbd_receive_starttls(QIOChannel *ioc,
>      QIOChannelTLS *tioc;
>      struct NBDTLSHandshakeData data = { 0 };
>  
> -    TRACE("Requesting TLS from server");
> +    trace_nbd_receive_starttls_request();
>      if (nbd_send_option_request(ioc, NBD_OPT_STARTTLS, 0, NULL, errp) < 0) {
>          return NULL;
>      }
>  
> -    TRACE("Getting TLS reply from server");
> +    trace_nbd_receive_starttls_reply();
>      if (nbd_receive_option_reply(ioc, NBD_OPT_STARTTLS, &reply, errp) < 0) {
>          return NULL;
>      }
> @@ -400,14 +399,14 @@ static QIOChannel *nbd_receive_starttls(QIOChannel *ioc,
>          return NULL;
>      }
>  
> -    TRACE("TLS request approved, setting up TLS");
> +    trace_nbd_receive_starttls_new_client();
>      tioc = qio_channel_tls_new_client(ioc, tlscreds, hostname, errp);
>      if (!tioc) {
>          return NULL;
>      }
>      qio_channel_set_name(QIO_CHANNEL(tioc), "nbd-client-tls");
>      data.loop = g_main_loop_new(g_main_context_default(), FALSE);
> -    TRACE("Starting TLS handshake");
> +    trace_nbd_receive_starttls_tls_handshake();
>      qio_channel_tls_handshake(tioc,
>                                nbd_tls_handshake,
>                                &data,
> @@ -436,8 +435,7 @@ int nbd_receive_negotiate(QIOChannel *ioc, const char *name, uint16_t *flags,
>      int rc;
>      bool zeroes = true;
>  
> -    TRACE("Receiving negotiation tlscreds=%p hostname=%s.",
> -          tlscreds, hostname ? hostname : "<null>");
> +    trace_nbd_receive_negotiate(tlscreds, hostname ? hostname : "<null>");
>  
>      rc = -EINVAL;
>  
> @@ -462,7 +460,7 @@ int nbd_receive_negotiate(QIOChannel *ioc, const char *name, uint16_t *flags,
>  
>      memcpy(&nbd_magic, buf, 8);
>      nbd_magic = be64_to_cpu(nbd_magic);
> -    TRACE("Magic is 0x%" PRIx64, nbd_magic);
> +    trace_nbd_receive_negotiate_magic(nbd_magic);
>  
>      if (memcmp(buf, "NBDMAGIC", 8) != 0) {
>          error_setg(errp, "Invalid magic received");
> @@ -474,7 +472,7 @@ int nbd_receive_negotiate(QIOChannel *ioc, const char *name, uint16_t *flags,
>          goto fail;
>      }
>      magic = be64_to_cpu(magic);
> -    TRACE("Magic is 0x%" PRIx64, magic);
> +    trace_nbd_receive_negotiate_magic2(magic);
>  
>      if (magic == NBD_OPTS_MAGIC) {
>          uint32_t clientflags = 0;
> @@ -486,15 +484,13 @@ int nbd_receive_negotiate(QIOChannel *ioc, const char *name, uint16_t *flags,
>              goto fail;
>          }
>          globalflags = be16_to_cpu(globalflags);
> -        TRACE("Global flags are %" PRIx32, globalflags);
> +        trace_nbd_receive_negotiate_server_flags(globalflags);
>          if (globalflags & NBD_FLAG_FIXED_NEWSTYLE) {
>              fixedNewStyle = true;
> -            TRACE("Server supports fixed new style");
>              clientflags |= NBD_FLAG_C_FIXED_NEWSTYLE;
>          }
>          if (globalflags & NBD_FLAG_NO_ZEROES) {
>              zeroes = false;
> -            TRACE("Server supports no zeroes");
>              clientflags |= NBD_FLAG_C_NO_ZEROES;
>          }
>          /* client requested flags */
> @@ -516,7 +512,7 @@ int nbd_receive_negotiate(QIOChannel *ioc, const char *name, uint16_t *flags,
>              }
>          }
>          if (!name) {
> -            TRACE("Using default NBD export name \"\"");
> +            trace_nbd_receive_negotiate_default_name();
>              name = "";
>          }
>          if (fixedNewStyle) {
> @@ -565,7 +561,7 @@ int nbd_receive_negotiate(QIOChannel *ioc, const char *name, uint16_t *flags,
>              goto fail;
>          }
>          *size = be64_to_cpu(s);
> -        TRACE("Size is %" PRIu64, *size);
> +        trace_nbd_receive_negotiate_export_size(*size);
>  
>          if (nbd_read(ioc, &oldflags, sizeof(oldflags), errp) < 0) {
>              error_prepend(errp, "Failed to read export flags");
> @@ -582,7 +578,7 @@ int nbd_receive_negotiate(QIOChannel *ioc, const char *name, uint16_t *flags,
>          goto fail;
>      }
>  
> -    TRACE("Size is %" PRIu64 ", export flags %" PRIx16, *size, *flags);
> +    trace_nbd_receive_negotiate_size_flags(*size, *flags);
>      if (zeroes && nbd_drop(ioc, 124, errp) < 0) {
>          error_prepend(errp, "Failed to read reserved block");
>          goto fail;
> @@ -604,7 +600,7 @@ int nbd_init(int fd, QIOChannelSocket *sioc, uint16_t flags, off_t size,
>          return -E2BIG;
>      }
>  
> -    TRACE("Setting NBD socket");
> +    trace_nbd_init_set_socket();
>  
>      if (ioctl(fd, NBD_SET_SOCK, (unsigned long) sioc->fd) < 0) {
>          int serrno = errno;
> @@ -612,7 +608,7 @@ int nbd_init(int fd, QIOChannelSocket *sioc, uint16_t flags, off_t size,
>          return -serrno;
>      }
>  
> -    TRACE("Setting block size to %lu", (unsigned long)BDRV_SECTOR_SIZE);
> +    trace_nbd_init_set_block_size(BDRV_SECTOR_SIZE);
>  
>      if (ioctl(fd, NBD_SET_BLKSIZE, (unsigned long)BDRV_SECTOR_SIZE) < 0) {
>          int serrno = errno;
> @@ -620,10 +616,9 @@ int nbd_init(int fd, QIOChannelSocket *sioc, uint16_t flags, off_t size,
>          return -serrno;
>      }
>  
> -    TRACE("Setting size to %lu block(s)", sectors);
> +    trace_nbd_init_set_size(sectors);
>      if (size % BDRV_SECTOR_SIZE) {
> -        TRACE("Ignoring trailing %d bytes of export",
> -              (int) (size % BDRV_SECTOR_SIZE));
> +        trace_nbd_init_trailing_bytes(size % BDRV_SECTOR_SIZE);
>      }
>  
>      if (ioctl(fd, NBD_SET_SIZE_BLOCKS, sectors) < 0) {
> @@ -635,7 +630,7 @@ int nbd_init(int fd, QIOChannelSocket *sioc, uint16_t flags, off_t size,
>      if (ioctl(fd, NBD_SET_FLAGS, (unsigned long) flags) < 0) {
>          if (errno == ENOTTY) {
>              int read_only = (flags & NBD_FLAG_READ_ONLY) != 0;
> -            TRACE("Setting readonly attribute");
> +            trace_nbd_init_set_readonly();
>  
>              if (ioctl(fd, BLKROSET, (unsigned long) &read_only) < 0) {
>                  int serrno = errno;
> @@ -649,7 +644,7 @@ int nbd_init(int fd, QIOChannelSocket *sioc, uint16_t flags, off_t size,
>          }
>      }
>  
> -    TRACE("Negotiation ended");
> +    trace_nbd_init_finish();
>  
>      return 0;
>  }
> @@ -659,7 +654,7 @@ int nbd_client(int fd)
>      int ret;
>      int serrno;
>  
> -    TRACE("Doing NBD loop");
> +    trace_nbd_client_loop();
>  
>      ret = ioctl(fd, NBD_DO_IT);
>      if (ret < 0 && errno == EPIPE) {
> @@ -671,12 +666,12 @@ int nbd_client(int fd)
>      }
>      serrno = errno;
>  
> -    TRACE("NBD loop returned %d: %s", ret, strerror(serrno));
> +    trace_nbd_client_loop_ret(ret, strerror(serrno));
>  
> -    TRACE("Clearing NBD queue");
> +    trace_nbd_client_clear_queue();
>      ioctl(fd, NBD_CLEAR_QUE);
>  
> -    TRACE("Clearing NBD socket");
> +    trace_nbd_client_clear_socket();
>      ioctl(fd, NBD_CLEAR_SOCK);
>  
>      errno = serrno;
> @@ -713,11 +708,8 @@ ssize_t nbd_send_request(QIOChannel *ioc, NBDRequest *request)
>  {
>      uint8_t buf[NBD_REQUEST_SIZE];
>  
> -    TRACE("Sending request to server: "
> -          "{ .from = %" PRIu64", .len = %" PRIu32 ", .handle = %" PRIu64
> -          ", .flags = %" PRIx16 ", .type = %" PRIu16 " }",
> -          request->from, request->len, request->handle,
> -          request->flags, request->type);
> +    trace_nbd_send_request(request->from, request->len, request->handle,
> +                           request->flags, request->type);
>  
>      stl_be_p(buf, NBD_REQUEST_MAGIC);
>      stw_be_p(buf + 4, request->flags);
> @@ -762,9 +754,7 @@ ssize_t nbd_receive_reply(QIOChannel *ioc, NBDReply *reply, Error **errp)
>          error_setg(errp, "server shutting down");
>          return -EINVAL;
>      }
> -    TRACE("Got reply: { magic = 0x%" PRIx32 ", .error = % " PRId32
> -          ", handle = %" PRIu64" }",
> -          magic, reply->error, reply->handle);
> +    trace_nbd_receive_reply(magic, reply->error, reply->handle);
>  
>      if (magic != NBD_REPLY_MAGIC) {
>          error_setg(errp, "invalid magic (got 0x%" PRIx32 ")", magic);
> diff --git a/nbd/nbd-internal.h b/nbd/nbd-internal.h
> index 39bfed177c..cf6ecbf358 100644
> --- a/nbd/nbd-internal.h
> +++ b/nbd/nbd-internal.h
> @@ -31,25 +31,6 @@
>  #include "qemu/queue.h"
>  #include "qemu/main-loop.h"
>  
> -/* #define DEBUG_NBD */
> -
> -#ifdef DEBUG_NBD
> -#define DEBUG_NBD_PRINT 1
> -#else
> -#define DEBUG_NBD_PRINT 0
> -#endif
> -
> -#define TRACE(msg, ...) do { \
> -    if (DEBUG_NBD_PRINT) { \
> -        LOG(msg, ## __VA_ARGS__); \
> -    } \
> -} while (0)
> -
> -#define LOG(msg, ...) do { \
> -    fprintf(stderr, "%s:%s():L%d: " msg "\n", \
> -            __FILE__, __FUNCTION__, __LINE__, ## __VA_ARGS__); \
> -} while (0)
> -
>  /* This is all part of the "official" NBD API.
>   *
>   * The most up-to-date documentation is available at:
> diff --git a/nbd/server.c b/nbd/server.c
> index 0671ebc50a..52ed9625fd 100644
> --- a/nbd/server.c
> +++ b/nbd/server.c
> @@ -19,6 +19,7 @@
>  
>  #include "qemu/osdep.h"
>  #include "qapi/error.h"
> +#include "trace.h"
>  #include "nbd-internal.h"
>  
>  static int system_errno_to_nbd_errno(int err)
> @@ -138,8 +139,7 @@ static int nbd_negotiate_send_rep_len(QIOChannel *ioc, uint32_t type,
>  {
>      uint64_t magic;
>  
> -    TRACE("Reply opt=%" PRIx32 " type=%" PRIx32 " len=%" PRIu32,
> -          type, opt, len);
> +    trace_nbd_negotiate_send_rep_len(type, opt, len);
>  
>      magic = cpu_to_be64(NBD_REP_MAGIC);
>      if (nbd_write(ioc, &magic, sizeof(magic), errp) < 0) {
> @@ -191,7 +191,7 @@ nbd_negotiate_send_rep_err(QIOChannel *ioc, uint32_t type,
>      va_end(va);
>      len = strlen(msg);
>      assert(len < 4096);
> -    TRACE("sending error message \"%s\"", msg);
> +    trace_nbd_negotiate_send_rep_err(msg);
>      ret = nbd_negotiate_send_rep_len(ioc, type, opt, len, errp);
>      if (ret < 0) {
>          goto out;
> @@ -219,7 +219,7 @@ static int nbd_negotiate_send_rep_list(QIOChannel *ioc, NBDExport *exp,
>      const char *desc = exp->description ? exp->description : "";
>      int ret;
>  
> -    TRACE("Advertising export name '%s' description '%s'", name, desc);
> +    trace_nbd_negotiate_send_rep_list(name, desc);
>      name_len = strlen(name);
>      desc_len = strlen(desc);
>      len = name_len + desc_len + sizeof(len);
> @@ -283,7 +283,7 @@ static int nbd_negotiate_handle_export_name(NBDClient *client, uint32_t length,
>      /* Client sends:
>          [20 ..  xx]   export name (length bytes)
>       */
> -    TRACE("Checking length");
> +    trace_nbd_negotiate_handle_export_name();
>      if (length >= sizeof(name)) {
>          error_setg(errp, "Bad length received");
>          return -EINVAL;
> @@ -294,7 +294,7 @@ static int nbd_negotiate_handle_export_name(NBDClient *client, uint32_t length,
>      }
>      name[length] = '\0';
>  
> -    TRACE("Client requested export '%s'", name);
> +    trace_nbd_negotiate_handle_export_name_request(name);
>  
>      client->exp = nbd_export_find(name);
>      if (!client->exp) {
> @@ -318,7 +318,7 @@ static QIOChannel *nbd_negotiate_handle_starttls(NBDClient *client,
>      QIOChannelTLS *tioc;
>      struct NBDTLSHandshakeData data = { 0 };
>  
> -    TRACE("Setting up TLS");
> +    trace_nbd_negotiate_handle_starttls();
>      ioc = client->ioc;
>      if (length) {
>          if (nbd_drop(ioc, length, errp) < 0) {
> @@ -344,7 +344,7 @@ static QIOChannel *nbd_negotiate_handle_starttls(NBDClient *client,
>      }
>  
>      qio_channel_set_name(QIO_CHANNEL(tioc), "nbd-server-tls");
> -    TRACE("Starting TLS handshake");
> +    trace_nbd_negotiate_handle_starttls_handshake();
>      data.loop = g_main_loop_new(g_main_context_default(), FALSE);
>      qio_channel_tls_handshake(tioc,
>                                nbd_tls_handshake,
> @@ -396,15 +396,15 @@ static int nbd_negotiate_options(NBDClient *client, Error **errp)
>          error_prepend(errp, "read failed: ");
>          return -EIO;
>      }
> -    TRACE("Checking client flags");
> +    trace_nbd_negotiate_options_flags();
>      be32_to_cpus(&flags);
>      if (flags & NBD_FLAG_C_FIXED_NEWSTYLE) {
> -        TRACE("Client supports fixed newstyle handshake");
> +        trace_nbd_negotiate_options_newstyle();
>          fixedNewstyle = true;
>          flags &= ~NBD_FLAG_C_FIXED_NEWSTYLE;
>      }
>      if (flags & NBD_FLAG_C_NO_ZEROES) {
> -        TRACE("Client supports no zeroes at handshake end");
> +        trace_nbd_negotiate_options_no_zeroes();
>          client->no_zeroes = true;
>          flags &= ~NBD_FLAG_C_NO_ZEROES;
>      }
> @@ -422,7 +422,7 @@ static int nbd_negotiate_options(NBDClient *client, Error **errp)
>              error_prepend(errp, "read failed: ");
>              return -EINVAL;
>          }
> -        TRACE("Checking opts magic");
> +        trace_nbd_negotiate_options_check_magic();
>          if (magic != be64_to_cpu(NBD_OPTS_MAGIC)) {
>              error_setg(errp, "Bad magic received");
>              return -EINVAL;
> @@ -441,7 +441,7 @@ static int nbd_negotiate_options(NBDClient *client, Error **errp)
>          }
>          length = be32_to_cpu(length);
>  
> -        TRACE("Checking option 0x%" PRIx32, clientflags);
> +        trace_nbd_negotiate_options_check_option(clientflags);
>          if (client->tlscreds &&
>              client->ioc == (QIOChannel *)client->sioc) {
>              QIOChannel *tioc;
> @@ -501,8 +501,8 @@ static int nbd_negotiate_options(NBDClient *client, Error **errp)
>                                         &local_err);
>  
>                  if (local_err != NULL) {
> -                    TRACE("Reply to NBD_OPT_ABORT request failed: %s",
> -                          error_get_pretty(local_err));
> +                    const char *error = error_get_pretty(local_err);
> +                    trace_nbd_opt_abort_reply_failed(error);
>                      error_free(local_err);
>                  }
>  
> @@ -599,14 +599,14 @@ static coroutine_fn int nbd_negotiate(NBDClient *client, Error **errp)
>  
>      qio_channel_set_blocking(client->ioc, false, NULL);
>  
> -    TRACE("Beginning negotiation.");
> +    trace_nbd_negotiate_begin();
>      memset(buf, 0, sizeof(buf));
>      memcpy(buf, "NBDMAGIC", 8);
>  
>      oldStyle = client->exp != NULL && !client->tlscreds;
>      if (oldStyle) {
> -        TRACE("advertising size %" PRIu64 " and flags %x",
> -              client->exp->size, client->exp->nbdflags | myflags);
> +        trace_nbd_negotiate_old_style(client->exp->size,
> +                                      client->exp->nbdflags | myflags);
>          stq_be_p(buf + 8, NBD_CLIENT_MAGIC);
>          stq_be_p(buf + 16, client->exp->size);
>          stw_be_p(buf + 26, client->exp->nbdflags | myflags);
> @@ -637,8 +637,8 @@ static coroutine_fn int nbd_negotiate(NBDClient *client, Error **errp)
>              return ret;
>          }
>  
> -        TRACE("advertising size %" PRIu64 " and flags %x",
> -              client->exp->size, client->exp->nbdflags | myflags);
> +        trace_nbd_negotiate_new_style_size_flags(
> +            client->exp->size, client->exp->nbdflags | myflags);
>          stq_be_p(buf + 18, client->exp->size);
>          stw_be_p(buf + 26, client->exp->nbdflags | myflags);
>          len = client->no_zeroes ? 10 : sizeof(buf) - 18;
> @@ -649,7 +649,7 @@ static coroutine_fn int nbd_negotiate(NBDClient *client, Error **errp)
>          }
>      }
>  
> -    TRACE("Negotiation succeeded.");
> +    trace_nbd_negotiate_success();
>  
>      return 0;
>  }
> @@ -682,9 +682,8 @@ static int nbd_receive_request(QIOChannel *ioc, NBDRequest *request,
>      request->from   = ldq_be_p(buf + 16);
>      request->len    = ldl_be_p(buf + 24);
>  
> -    TRACE("Got request: { magic = 0x%" PRIx32 ", .flags = %" PRIx16
> -          ", .type = %" PRIx16 ", from = %" PRIu64 ", len = %" PRIu32 " }",
> -          magic, request->flags, request->type, request->from, request->len);
> +    trace_nbd_receive_request(magic, request->flags, request->type,
> +                              request->from, request->len);
>  
>      if (magic != NBD_REQUEST_MAGIC) {
>          error_setg(errp, "invalid magic (got 0x%" PRIx32 ")", magic);
> @@ -699,9 +698,7 @@ static int nbd_send_reply(QIOChannel *ioc, NBDReply *reply, Error **errp)
>  
>      reply->error = system_errno_to_nbd_errno(reply->error);
>  
> -    TRACE("Sending response to client: { .error = %" PRId32
> -          ", handle = %" PRIu64 " }",
> -          reply->error, reply->handle);
> +    trace_nbd_send_reply(reply->error, reply->handle);
>  
>      /* Reply
>         [ 0 ..  3]    magic   (NBD_REPLY_MAGIC)
> @@ -798,7 +795,7 @@ static void blk_aio_attached(AioContext *ctx, void *opaque)
>      NBDExport *exp = opaque;
>      NBDClient *client;
>  
> -    TRACE("Export %s: Attaching clients to AIO context %p\n", exp->name, ctx);
> +    trace_blk_aio_attached(exp->name, ctx);
>  
>      exp->ctx = ctx;
>  
> @@ -818,7 +815,7 @@ static void blk_aio_detach(void *opaque)
>      NBDExport *exp = opaque;
>      NBDClient *client;
>  
> -    TRACE("Export %s: Detaching clients from AIO context %p\n", exp->name, exp->ctx);
> +    trace_blk_aio_detach(exp->name, exp->ctx);
>  
>      QTAILQ_FOREACH(client, &exp->clients, next) {
>          qio_channel_detach_aio_context(client->ioc);
> @@ -1045,7 +1042,7 @@ static int nbd_co_receive_request(NBDRequestData *req, NBDRequest *request,
>          return -EIO;
>      }
>  
> -    TRACE("Decoding type");
> +    trace_nbd_co_receive_request_decode_type();
>  
>      if (request->type != NBD_CMD_WRITE) {
>          /* No payload, we are ready to read the next request.  */
> @@ -1055,7 +1052,7 @@ static int nbd_co_receive_request(NBDRequestData *req, NBDRequest *request,
>      if (request->type == NBD_CMD_DISC) {
>          /* Special case: we're going to disconnect without a reply,
>           * whether or not flags, from, or len are bogus */
> -        TRACE("Request type is DISCONNECT");
> +        trace_nbd_co_receive_request_disconnect();
>          return -EIO;
>      }
>  
> @@ -1082,7 +1079,7 @@ static int nbd_co_receive_request(NBDRequestData *req, NBDRequest *request,
>          }
>      }
>      if (request->type == NBD_CMD_WRITE) {
> -        TRACE("Reading %" PRIu32 " byte(s)", request->len);
> +        trace_nbd_co_receive_request_cmd_write(request->len);
>  
>          if (nbd_read(client->ioc, req->data, request->len, errp) < 0) {
>              error_prepend(errp, "reading from socket failed: ");
> @@ -1124,7 +1121,7 @@ static coroutine_fn void nbd_trip(void *opaque)
>      int reply_data_len = 0;
>      Error *local_err = NULL;
>  
> -    TRACE("Reading request.");
> +    trace_do_nbd_trip();
>      if (client->closing) {
>          nbd_client_put(client);
>          return;
> @@ -1156,7 +1153,7 @@ static coroutine_fn void nbd_trip(void *opaque)
>  
>      switch (request.type) {
>      case NBD_CMD_READ:
> -        TRACE("Request type is READ");
> +        trace_do_nbd_trip_cmd_read();
>  
>          /* XXX: NBD Protocol only documents use of FUA with WRITE */
>          if (request.flags & NBD_CMD_FLAG_FUA) {
> @@ -1177,19 +1174,19 @@ static coroutine_fn void nbd_trip(void *opaque)
>          }
>  
>          reply_data_len = request.len;
> -        TRACE("Read %" PRIu32" byte(s)", request.len);
> +        trace_do_nbd_trip_read(request.len);
>  
>          break;
>      case NBD_CMD_WRITE:
> -        TRACE("Request type is WRITE");
> +        trace_do_nbd_trip_cmd_write();
>  
>          if (exp->nbdflags & NBD_FLAG_READ_ONLY) {
> -            TRACE("Server is read-only, return error");
> +            trace_do_nbd_trip_cmd_write_readonly();
>              reply.error = EROFS;
>              break;
>          }
>  
> -        TRACE("Writing to device");
> +        trace_do_nbd_trip_write();
>  
>          flags = 0;
>          if (request.flags & NBD_CMD_FLAG_FUA) {
> @@ -1204,7 +1201,7 @@ static coroutine_fn void nbd_trip(void *opaque)
>  
>          break;
>      case NBD_CMD_WRITE_ZEROES:
> -        TRACE("Request type is WRITE_ZEROES");
> +        trace_do_nbd_trip_cmd_write_zeroes();
>  
>          if (exp->nbdflags & NBD_FLAG_READ_ONLY) {
>              error_setg(&local_err, "Server is read-only, return error");
> @@ -1212,7 +1209,7 @@ static coroutine_fn void nbd_trip(void *opaque)
>              break;
>          }
>  
> -        TRACE("Writing to device");
> +        trace_do_nbd_trip_write_zeroes();
>  
>          flags = 0;
>          if (request.flags & NBD_CMD_FLAG_FUA) {
> @@ -1234,7 +1231,7 @@ static coroutine_fn void nbd_trip(void *opaque)
>          abort();
>  
>      case NBD_CMD_FLUSH:
> -        TRACE("Request type is FLUSH");
> +        trace_do_nbd_trip_cmd_flush();
>  
>          ret = blk_co_flush(exp->blk);
>          if (ret < 0) {
> @@ -1244,7 +1241,7 @@ static coroutine_fn void nbd_trip(void *opaque)
>  
>          break;
>      case NBD_CMD_TRIM:
> -        TRACE("Request type is TRIM");
> +        trace_do_nbd_trip_cmd_trim();
>          ret = blk_co_pdiscard(exp->blk, request.from + exp->dev_offset,
>                                request.len);
>          if (ret < 0) {
> @@ -1280,7 +1277,7 @@ reply:
>          goto disconnect;
>      }
>  
> -    TRACE("Request/Reply complete");
> +    trace_do_nbd_trip_complete();
>  
>  done:
>      nbd_request_put(req);
> diff --git a/nbd/trace-events b/nbd/trace-events
> new file mode 100644
> index 0000000000..46e4d110bd
> --- /dev/null
> +++ b/nbd/trace-events
> @@ -0,0 +1,68 @@
> +# nbd/client.c
> +nbd_unknown_error(int err) "Squashing unexpected error %d to EINVAL"
> +nbd_send_option_request(uint32_t opt, uint32_t len) "Sending option request %" PRIu32", len %" PRIu32
> +nbd_receive_option_reply(uint32_t option, uint32_t type, uint32_t length) "Received option reply %" PRIx32", type %" PRIx32", len %" PRIu32
> +nbd_reply_err_unsup(uint32_t option) "server doesn't understand request %" PRIx32 ", attempting fallback"
> +nbd_receive_query_exports_start(const char *wantname) "Querying export list for '%s'"
> +nbd_receive_query_exports_loop(void) "Reading available export names"
> +nbd_receive_query_exports_success(const char *wantname) "Found desired export name '%s'"
> +nbd_receive_starttls_request(void) "Requesting TLS from server"
> +nbd_receive_starttls_reply(void) "Getting TLS reply from server"
> +nbd_receive_starttls_new_client(void) "TLS request approved, setting up TLS"
> +nbd_receive_starttls_tls_handshake(void) "Starting TLS handshake"
> +nbd_receive_negotiate(void *tlscreds, const char *hostname) "Receiving negotiation tlscreds=%p hostname=%s"
> +nbd_receive_negotiate_magic(uint64_t magic) "Magic is 0x%" PRIx64
> +nbd_receive_negotiate_magic2(uint64_t magic) "Magic is 0x%" PRIx64
> +nbd_receive_negotiate_server_flags(uint32_t globalflags) "Global flags are %" PRIx32
> +nbd_receive_negotiate_default_name(void) "Using default NBD export name \"\""
> +nbd_receive_negotiate_export_size(uint64_t size) "Size is %" PRIu64
> +nbd_receive_negotiate_size_flags(uint64_t size, uint16_t flags) "Size is %" PRIu64 ", export flags %" PRIx16
> +nbd_init_set_socket(void) "Setting NBD socket"
> +nbd_init_set_block_size(unsigned long block_size) "Setting block size to %lu"
> +nbd_init_set_size(unsigned long sectors) "Setting size to %lu block(s)"
> +nbd_init_trailing_bytes(int ignored_bytes) "Ignoring trailing %d bytes of export"
> +nbd_init_set_readonly(void) "Setting readonly attribute"
> +nbd_init_finish(void) "Negotiation ended"
> +nbd_client_loop(void) "Doing NBD loop"
> +nbd_client_loop_ret(int ret, const char *error) "NBD loop returned %d: %s"
> +nbd_client_clear_queue(void) "Clearing NBD queue"
> +nbd_client_clear_socket(void) "Clearing NBD socket"
> +nbd_send_request(uint64_t from, uint32_t len, uint64_t handle, uint16_t flags, uint16_t type) "Sending request to server: { .from = %" PRIu64", .len = %" PRIu32 ", .handle = %" PRIu64 ", .flags = %" PRIx16 ", .type = %" PRIu16 " }"
> +nbd_receive_reply(uint32_t magic, int32_t error, uint64_t handle) "Got reply: { magic = 0x%" PRIx32 ", .error = % " PRId32 ", handle = %" PRIu64" }"
> +
> +# nbd/server.c
> +nbd_negotiate_send_rep_len(uint32_t type, uint32_t opt, uint32_t len) "Reply opt=%" PRIx32 " type=%" PRIx32 " len=%" PRIu32
> +nbd_negotiate_send_rep_err(const char *msg) "sending error message \"%s\""
> +nbd_negotiate_send_rep_list(const char *name, const char *desc) "Advertising export name '%s' description '%s'"
> +nbd_negotiate_handle_export_name(void) "Checking length"
> +nbd_negotiate_handle_export_name_request(const char *name) "Client requested export '%s'"
> +nbd_negotiate_handle_starttls(void) "Setting up TLS"
> +nbd_negotiate_handle_starttls_handshake(void) "Starting TLS handshake"
> +nbd_negotiate_options_flags(void) "Checking client flags"
> +nbd_negotiate_options_newstyle(void) "Client supports fixed newstyle handshake"
> +nbd_negotiate_options_no_zeroes(void) "Client supports no zeroes at handshake end"
> +nbd_negotiate_options_check_magic(void) "Checking opts magic"
> +nbd_negotiate_options_check_option(uint32_t clientflags) "Checking option 0x%" PRIx32
> +nbd_opt_abort_reply_failed(const char *error) "Reply to NBD_OPT_ABORT request failed: %s"
> +nbd_negotiate_begin(void) "Beginning negotiation"
> +nbd_negotiate_old_style(uint64_t size, unsigned flags) "advertising size %" PRIu64 " and flags %x"
> +nbd_negotiate_new_style_size_flags(uint64_t size, unsigned flags) "advertising size %" PRIu64 " and flags %x"
> +nbd_negotiate_success(void) "Negotiation succeeded"
> +nbd_receive_request(uint32_t magic, uint16_t flags, uint16_t type, uint64_t from, uint32_t len) "Got request: { magic = 0x%" PRIx32 ", .flags = %" PRIx16 ", .type = %" PRIx16 ", from = %" PRIu64 ", len = %" PRIu32 " }"
> +nbd_send_reply(int32_t error, uint64_t handle) "Sending response to client: { .error = %" PRId32 ", handle = %" PRIu64 " }"
> +blk_aio_attached(const char *name, void *ctx) "Export %s: Attaching clients to AIO context %p\n"
> +blk_aio_detach(const char *name, void *ctx) "Export %s: Detaching clients from AIO context %p\n"
> +nbd_co_receive_request_decode_type(void) "Decoding type"

Please add the request->handle and request->type as an argument...

> +nbd_co_receive_request_disconnect(void) "Request type is DISCONNECT"

... and remove this one, which is now unnecessary.

> +nbd_co_receive_request_cmd_write(uint32_t len) "Reading %" PRIu32 " byte(s)"
> +do_nbd_trip(void) "Reading request"

Please remove do_ from all these tracepoints, in addition:

> +do_nbd_trip_cmd_read(void) "Request type is READ"

This can be removed if nbd_co_receive_request_decode_type gets
request.type as an argument.

> +do_nbd_trip_read(uint32_t len) "Read %" PRIu32" byte(s)"

This one is good.

> +do_nbd_trip_cmd_write(void) "Request type is WRITE"
> +do_nbd_trip_cmd_write_readonly(void) "Server is read-only, return error"

These can be removed.

> +do_nbd_trip_write(void) "Writing to device"

Please add the handle here.

> +do_nbd_trip_cmd_write_zeroes(void) "Request type is WRITE_ZEROES"
> +do_nbd_trip_write_zeroes(void) "Writing to device"
> +do_nbd_trip_cmd_flush(void) "Request type is FLUSH"
> +do_nbd_trip_cmd_trim(void) "Request type is TRIM"

Can all be removed.

> +do_nbd_trip_complete(void) "Request/Reply complete"

This one is good, but please add the handle here too.

Thanks,

Paolo

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [Qemu-devel] [PATCH v2 2/6] nbd/server: use errp instead of LOG
  2017-06-29 19:27   ` Eric Blake
  2017-07-05 12:33     ` Vladimir Sementsov-Ogievskiy
@ 2017-07-05 17:38     ` Markus Armbruster
  1 sibling, 0 replies; 28+ messages in thread
From: Markus Armbruster @ 2017-07-05 17:38 UTC (permalink / raw)
  To: Eric Blake
  Cc: Vladimir Sementsov-Ogievskiy, qemu-devel, pbonzini, stefanha, den

Eric Blake <eblake@redhat.com> writes:

> On 06/21/2017 10:34 AM, Vladimir Sementsov-Ogievskiy wrote:
>> Move to modern errp scheme from just LOGging errors.
>> 
>> Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
>> ---
>>  nbd/server.c | 268 +++++++++++++++++++++++++++++++++++------------------------
>>  1 file changed, 161 insertions(+), 107 deletions(-)
>
> Unfortunately longer, but I'm okay with that (and we already did it
> client-side, so this is just a case of a patch series being spread out
> over time).
>
>
>>  
>>  /* Send an error reply.
>>   * Return -errno on error, 0 on success. */
>> -static int GCC_FMT_ATTR(4, 5)
>> +static int GCC_FMT_ATTR(5, 6)
>>  nbd_negotiate_send_rep_err(QIOChannel *ioc, uint32_t type,
>> -                           uint32_t opt, const char *fmt, ...)
>> +                           uint32_t opt, Error **errp, const char *fmt, ...)
>>  {
>
> Markus, this violates our usual idiom of errp last in code that is not
> directly operating on an Error (the actual Error implementation in
> error.c being the main obvious exception that lists errp first), but I
> don't see any better approach. Do you have any thoughts on it?

The convention to put Error **errp last comes from GLib's GError.
Here's what it has to say about combining GError with variable
arguments:

    The last argument of a function that returns an error should be a
    location where a GError can be placed (i.e. "GError** error"). If
    GError is used with varargs, the GError** should be the last
    argument before the "...".

https://developer.gnome.org/glib/unstable/glib-Error-Reporting.html

Separating the format string from the variable arguments is ugly,
though.  I can't find examples of this ugliness in /usr/include/glib.  I
can find a few for Vladimir's solution:

* g_output_stream_printf() in gio/goutputstream.h: format string
  followed by arguments

* g_initable_new() in gio/ginitable.h: key name followed by key value,
  ..., NULL

* g_subprocess_new() in gio/gsubprocess.h: argv0, ..., NULL

* g_subprocess_launcher_spawn() in gio/gsubprocesslauncher.h: argv0,
  ..., NULL

* g_markup_collect_attributes() in gmarkup.h: attribute name followed by
  attribute value, ..., NULL

Let's follow this precedence.  In short, Vladimir's patch is okay as is.

[...]

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [Qemu-devel] [PATCH v2 6/6] nbd: use generic trace subsystem instead of TRACE macro
  2017-07-05 15:29   ` Paolo Bonzini
@ 2017-07-06  8:45     ` Vladimir Sementsov-Ogievskiy
  2017-07-06  8:57       ` Paolo Bonzini
  0 siblings, 1 reply; 28+ messages in thread
From: Vladimir Sementsov-Ogievskiy @ 2017-07-06  8:45 UTC (permalink / raw)
  To: Paolo Bonzini, qemu-devel; +Cc: stefanha, eblake, den

05.07.2017 18:29, Paolo Bonzini wrote:
>
> On 21/06/2017 17:34, Vladimir Sementsov-Ogievskiy wrote:
>> Starting from this patch to enable traces use -trace option of qemu or
>> -T, --trace option of qemu-img, qemu-io and qemu-nbd. For qemu traces
>> also can be managed by qmp commands trace-event-{get,set}-state.
>>
>> Recompilation with CFLAGS=-DDEBUG_NBD is no more needed, furthermore,
>> DEBUG_NBD macro is removed from the code.
>>
>> Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
>> ---
>>   Makefile.objs      |  1 +
>>   nbd/client.c       | 74 +++++++++++++++++++++---------------------------
>>   nbd/nbd-internal.h | 19 -------------
>>   nbd/server.c       | 83 ++++++++++++++++++++++++++----------------------------
>>   nbd/trace-events   | 68 ++++++++++++++++++++++++++++++++++++++++++++
>>   5 files changed, 141 insertions(+), 104 deletions(-)
>>   create mode 100644 nbd/trace-events
>>
>> diff --git a/Makefile.objs b/Makefile.objs
>> index b2e6322ef0..a66ea34cc4 100644
>> --- a/Makefile.objs
>> +++ b/Makefile.objs
>> @@ -168,6 +168,7 @@ trace-events-subdirs += linux-user
>>   trace-events-subdirs += qapi
>>   trace-events-subdirs += accel/tcg
>>   trace-events-subdirs += accel/kvm
>> +trace-events-subdirs += nbd
>>   
>>   trace-events-files = $(SRC_PATH)/trace-events $(trace-events-subdirs:%=$(SRC_PATH)/%/trace-events)
>>   
>> diff --git a/nbd/client.c b/nbd/client.c
>> index 5a4825ebe0..75b28f4ccf 100644
>> --- a/nbd/client.c
>> +++ b/nbd/client.c
>> @@ -19,6 +19,7 @@
>>   
>>   #include "qemu/osdep.h"
>>   #include "qapi/error.h"
>> +#include "trace.h"
>>   #include "nbd-internal.h"
>>   
>>   static int nbd_errno_to_system_errno(int err)
>> @@ -44,7 +45,7 @@ static int nbd_errno_to_system_errno(int err)
>>           ret = ESHUTDOWN;
>>           break;
>>       default:
>> -        TRACE("Squashing unexpected error %d to EINVAL", err);
>> +        trace_nbd_unknown_error(err);
>>           /* fallthrough */
>>       case NBD_EINVAL:
>>           ret = EINVAL;
>> @@ -103,7 +104,7 @@ static int nbd_send_option_request(QIOChannel *ioc, uint32_t opt,
>>       if (len == -1) {
>>           req.length = len = strlen(data);
>>       }
>> -    TRACE("Sending option request %" PRIu32", len %" PRIu32, opt, len);
>> +    trace_nbd_send_option_request(opt, len);
>>   
>>       stq_be_p(&req.magic, NBD_OPTS_MAGIC);
>>       stl_be_p(&req.option, opt);
>> @@ -153,8 +154,7 @@ static int nbd_receive_option_reply(QIOChannel *ioc, uint32_t opt,
>>       be32_to_cpus(&reply->type);
>>       be32_to_cpus(&reply->length);
>>   
>> -    TRACE("Received option reply %" PRIx32", type %" PRIx32", len %" PRIu32,
>> -          reply->option, reply->type, reply->length);
>> +    trace_nbd_receive_option_reply(reply->option, reply->type, reply->length);
>>   
>>       if (reply->magic != NBD_REP_MAGIC) {
>>           error_setg(errp, "Unexpected option reply magic");
>> @@ -201,8 +201,7 @@ static int nbd_handle_reply_err(QIOChannel *ioc, nbd_opt_reply *reply,
>>   
>>       switch (reply->type) {
>>       case NBD_REP_ERR_UNSUP:
>> -        TRACE("server doesn't understand request %" PRIx32
>> -              ", attempting fallback", reply->option);
>> +        trace_nbd_reply_err_unsup(reply->option);
>>           result = 0;
>>           goto cleanup;
>>   
>> @@ -342,12 +341,12 @@ static int nbd_receive_query_exports(QIOChannel *ioc,
>>   {
>>       bool foundExport = false;
>>   
>> -    TRACE("Querying export list for '%s'", wantname);
>> +    trace_nbd_receive_query_exports_start(wantname);
>>       if (nbd_send_option_request(ioc, NBD_OPT_LIST, 0, NULL, errp) < 0) {
>>           return -1;
>>       }
>>   
>> -    TRACE("Reading available export names");
>> +    trace_nbd_receive_query_exports_loop();
>>       while (1) {
>>           int ret = nbd_receive_list(ioc, wantname, &foundExport, errp);
>>   
>> @@ -362,7 +361,7 @@ static int nbd_receive_query_exports(QIOChannel *ioc,
>>                   nbd_send_opt_abort(ioc);
>>                   return -1;
>>               }
>> -            TRACE("Found desired export name '%s'", wantname);
>> +            trace_nbd_receive_query_exports_success(wantname);
>>               return 0;
>>           }
>>       }
>> @@ -376,12 +375,12 @@ static QIOChannel *nbd_receive_starttls(QIOChannel *ioc,
>>       QIOChannelTLS *tioc;
>>       struct NBDTLSHandshakeData data = { 0 };
>>   
>> -    TRACE("Requesting TLS from server");
>> +    trace_nbd_receive_starttls_request();
>>       if (nbd_send_option_request(ioc, NBD_OPT_STARTTLS, 0, NULL, errp) < 0) {
>>           return NULL;
>>       }
>>   
>> -    TRACE("Getting TLS reply from server");
>> +    trace_nbd_receive_starttls_reply();
>>       if (nbd_receive_option_reply(ioc, NBD_OPT_STARTTLS, &reply, errp) < 0) {
>>           return NULL;
>>       }
>> @@ -400,14 +399,14 @@ static QIOChannel *nbd_receive_starttls(QIOChannel *ioc,
>>           return NULL;
>>       }
>>   
>> -    TRACE("TLS request approved, setting up TLS");
>> +    trace_nbd_receive_starttls_new_client();
>>       tioc = qio_channel_tls_new_client(ioc, tlscreds, hostname, errp);
>>       if (!tioc) {
>>           return NULL;
>>       }
>>       qio_channel_set_name(QIO_CHANNEL(tioc), "nbd-client-tls");
>>       data.loop = g_main_loop_new(g_main_context_default(), FALSE);
>> -    TRACE("Starting TLS handshake");
>> +    trace_nbd_receive_starttls_tls_handshake();
>>       qio_channel_tls_handshake(tioc,
>>                                 nbd_tls_handshake,
>>                                 &data,
>> @@ -436,8 +435,7 @@ int nbd_receive_negotiate(QIOChannel *ioc, const char *name, uint16_t *flags,
>>       int rc;
>>       bool zeroes = true;
>>   
>> -    TRACE("Receiving negotiation tlscreds=%p hostname=%s.",
>> -          tlscreds, hostname ? hostname : "<null>");
>> +    trace_nbd_receive_negotiate(tlscreds, hostname ? hostname : "<null>");
>>   
>>       rc = -EINVAL;
>>   
>> @@ -462,7 +460,7 @@ int nbd_receive_negotiate(QIOChannel *ioc, const char *name, uint16_t *flags,
>>   
>>       memcpy(&nbd_magic, buf, 8);
>>       nbd_magic = be64_to_cpu(nbd_magic);
>> -    TRACE("Magic is 0x%" PRIx64, nbd_magic);
>> +    trace_nbd_receive_negotiate_magic(nbd_magic);
>>   
>>       if (memcmp(buf, "NBDMAGIC", 8) != 0) {
>>           error_setg(errp, "Invalid magic received");
>> @@ -474,7 +472,7 @@ int nbd_receive_negotiate(QIOChannel *ioc, const char *name, uint16_t *flags,
>>           goto fail;
>>       }
>>       magic = be64_to_cpu(magic);
>> -    TRACE("Magic is 0x%" PRIx64, magic);
>> +    trace_nbd_receive_negotiate_magic2(magic);
>>   
>>       if (magic == NBD_OPTS_MAGIC) {
>>           uint32_t clientflags = 0;
>> @@ -486,15 +484,13 @@ int nbd_receive_negotiate(QIOChannel *ioc, const char *name, uint16_t *flags,
>>               goto fail;
>>           }
>>           globalflags = be16_to_cpu(globalflags);
>> -        TRACE("Global flags are %" PRIx32, globalflags);
>> +        trace_nbd_receive_negotiate_server_flags(globalflags);
>>           if (globalflags & NBD_FLAG_FIXED_NEWSTYLE) {
>>               fixedNewStyle = true;
>> -            TRACE("Server supports fixed new style");
>>               clientflags |= NBD_FLAG_C_FIXED_NEWSTYLE;
>>           }
>>           if (globalflags & NBD_FLAG_NO_ZEROES) {
>>               zeroes = false;
>> -            TRACE("Server supports no zeroes");
>>               clientflags |= NBD_FLAG_C_NO_ZEROES;
>>           }
>>           /* client requested flags */
>> @@ -516,7 +512,7 @@ int nbd_receive_negotiate(QIOChannel *ioc, const char *name, uint16_t *flags,
>>               }
>>           }
>>           if (!name) {
>> -            TRACE("Using default NBD export name \"\"");
>> +            trace_nbd_receive_negotiate_default_name();
>>               name = "";
>>           }
>>           if (fixedNewStyle) {
>> @@ -565,7 +561,7 @@ int nbd_receive_negotiate(QIOChannel *ioc, const char *name, uint16_t *flags,
>>               goto fail;
>>           }
>>           *size = be64_to_cpu(s);
>> -        TRACE("Size is %" PRIu64, *size);
>> +        trace_nbd_receive_negotiate_export_size(*size);
>>   
>>           if (nbd_read(ioc, &oldflags, sizeof(oldflags), errp) < 0) {
>>               error_prepend(errp, "Failed to read export flags");
>> @@ -582,7 +578,7 @@ int nbd_receive_negotiate(QIOChannel *ioc, const char *name, uint16_t *flags,
>>           goto fail;
>>       }
>>   
>> -    TRACE("Size is %" PRIu64 ", export flags %" PRIx16, *size, *flags);
>> +    trace_nbd_receive_negotiate_size_flags(*size, *flags);
>>       if (zeroes && nbd_drop(ioc, 124, errp) < 0) {
>>           error_prepend(errp, "Failed to read reserved block");
>>           goto fail;
>> @@ -604,7 +600,7 @@ int nbd_init(int fd, QIOChannelSocket *sioc, uint16_t flags, off_t size,
>>           return -E2BIG;
>>       }
>>   
>> -    TRACE("Setting NBD socket");
>> +    trace_nbd_init_set_socket();
>>   
>>       if (ioctl(fd, NBD_SET_SOCK, (unsigned long) sioc->fd) < 0) {
>>           int serrno = errno;
>> @@ -612,7 +608,7 @@ int nbd_init(int fd, QIOChannelSocket *sioc, uint16_t flags, off_t size,
>>           return -serrno;
>>       }
>>   
>> -    TRACE("Setting block size to %lu", (unsigned long)BDRV_SECTOR_SIZE);
>> +    trace_nbd_init_set_block_size(BDRV_SECTOR_SIZE);
>>   
>>       if (ioctl(fd, NBD_SET_BLKSIZE, (unsigned long)BDRV_SECTOR_SIZE) < 0) {
>>           int serrno = errno;
>> @@ -620,10 +616,9 @@ int nbd_init(int fd, QIOChannelSocket *sioc, uint16_t flags, off_t size,
>>           return -serrno;
>>       }
>>   
>> -    TRACE("Setting size to %lu block(s)", sectors);
>> +    trace_nbd_init_set_size(sectors);
>>       if (size % BDRV_SECTOR_SIZE) {
>> -        TRACE("Ignoring trailing %d bytes of export",
>> -              (int) (size % BDRV_SECTOR_SIZE));
>> +        trace_nbd_init_trailing_bytes(size % BDRV_SECTOR_SIZE);
>>       }
>>   
>>       if (ioctl(fd, NBD_SET_SIZE_BLOCKS, sectors) < 0) {
>> @@ -635,7 +630,7 @@ int nbd_init(int fd, QIOChannelSocket *sioc, uint16_t flags, off_t size,
>>       if (ioctl(fd, NBD_SET_FLAGS, (unsigned long) flags) < 0) {
>>           if (errno == ENOTTY) {
>>               int read_only = (flags & NBD_FLAG_READ_ONLY) != 0;
>> -            TRACE("Setting readonly attribute");
>> +            trace_nbd_init_set_readonly();
>>   
>>               if (ioctl(fd, BLKROSET, (unsigned long) &read_only) < 0) {
>>                   int serrno = errno;
>> @@ -649,7 +644,7 @@ int nbd_init(int fd, QIOChannelSocket *sioc, uint16_t flags, off_t size,
>>           }
>>       }
>>   
>> -    TRACE("Negotiation ended");
>> +    trace_nbd_init_finish();
>>   
>>       return 0;
>>   }
>> @@ -659,7 +654,7 @@ int nbd_client(int fd)
>>       int ret;
>>       int serrno;
>>   
>> -    TRACE("Doing NBD loop");
>> +    trace_nbd_client_loop();
>>   
>>       ret = ioctl(fd, NBD_DO_IT);
>>       if (ret < 0 && errno == EPIPE) {
>> @@ -671,12 +666,12 @@ int nbd_client(int fd)
>>       }
>>       serrno = errno;
>>   
>> -    TRACE("NBD loop returned %d: %s", ret, strerror(serrno));
>> +    trace_nbd_client_loop_ret(ret, strerror(serrno));
>>   
>> -    TRACE("Clearing NBD queue");
>> +    trace_nbd_client_clear_queue();
>>       ioctl(fd, NBD_CLEAR_QUE);
>>   
>> -    TRACE("Clearing NBD socket");
>> +    trace_nbd_client_clear_socket();
>>       ioctl(fd, NBD_CLEAR_SOCK);
>>   
>>       errno = serrno;
>> @@ -713,11 +708,8 @@ ssize_t nbd_send_request(QIOChannel *ioc, NBDRequest *request)
>>   {
>>       uint8_t buf[NBD_REQUEST_SIZE];
>>   
>> -    TRACE("Sending request to server: "
>> -          "{ .from = %" PRIu64", .len = %" PRIu32 ", .handle = %" PRIu64
>> -          ", .flags = %" PRIx16 ", .type = %" PRIu16 " }",
>> -          request->from, request->len, request->handle,
>> -          request->flags, request->type);
>> +    trace_nbd_send_request(request->from, request->len, request->handle,
>> +                           request->flags, request->type);
>>   
>>       stl_be_p(buf, NBD_REQUEST_MAGIC);
>>       stw_be_p(buf + 4, request->flags);
>> @@ -762,9 +754,7 @@ ssize_t nbd_receive_reply(QIOChannel *ioc, NBDReply *reply, Error **errp)
>>           error_setg(errp, "server shutting down");
>>           return -EINVAL;
>>       }
>> -    TRACE("Got reply: { magic = 0x%" PRIx32 ", .error = % " PRId32
>> -          ", handle = %" PRIu64" }",
>> -          magic, reply->error, reply->handle);
>> +    trace_nbd_receive_reply(magic, reply->error, reply->handle);
>>   
>>       if (magic != NBD_REPLY_MAGIC) {
>>           error_setg(errp, "invalid magic (got 0x%" PRIx32 ")", magic);
>> diff --git a/nbd/nbd-internal.h b/nbd/nbd-internal.h
>> index 39bfed177c..cf6ecbf358 100644
>> --- a/nbd/nbd-internal.h
>> +++ b/nbd/nbd-internal.h
>> @@ -31,25 +31,6 @@
>>   #include "qemu/queue.h"
>>   #include "qemu/main-loop.h"
>>   
>> -/* #define DEBUG_NBD */
>> -
>> -#ifdef DEBUG_NBD
>> -#define DEBUG_NBD_PRINT 1
>> -#else
>> -#define DEBUG_NBD_PRINT 0
>> -#endif
>> -
>> -#define TRACE(msg, ...) do { \
>> -    if (DEBUG_NBD_PRINT) { \
>> -        LOG(msg, ## __VA_ARGS__); \
>> -    } \
>> -} while (0)
>> -
>> -#define LOG(msg, ...) do { \
>> -    fprintf(stderr, "%s:%s():L%d: " msg "\n", \
>> -            __FILE__, __FUNCTION__, __LINE__, ## __VA_ARGS__); \
>> -} while (0)
>> -
>>   /* This is all part of the "official" NBD API.
>>    *
>>    * The most up-to-date documentation is available at:
>> diff --git a/nbd/server.c b/nbd/server.c
>> index 0671ebc50a..52ed9625fd 100644
>> --- a/nbd/server.c
>> +++ b/nbd/server.c
>> @@ -19,6 +19,7 @@
>>   
>>   #include "qemu/osdep.h"
>>   #include "qapi/error.h"
>> +#include "trace.h"
>>   #include "nbd-internal.h"
>>   
>>   static int system_errno_to_nbd_errno(int err)
>> @@ -138,8 +139,7 @@ static int nbd_negotiate_send_rep_len(QIOChannel *ioc, uint32_t type,
>>   {
>>       uint64_t magic;
>>   
>> -    TRACE("Reply opt=%" PRIx32 " type=%" PRIx32 " len=%" PRIu32,
>> -          type, opt, len);
>> +    trace_nbd_negotiate_send_rep_len(type, opt, len);
>>   
>>       magic = cpu_to_be64(NBD_REP_MAGIC);
>>       if (nbd_write(ioc, &magic, sizeof(magic), errp) < 0) {
>> @@ -191,7 +191,7 @@ nbd_negotiate_send_rep_err(QIOChannel *ioc, uint32_t type,
>>       va_end(va);
>>       len = strlen(msg);
>>       assert(len < 4096);
>> -    TRACE("sending error message \"%s\"", msg);
>> +    trace_nbd_negotiate_send_rep_err(msg);
>>       ret = nbd_negotiate_send_rep_len(ioc, type, opt, len, errp);
>>       if (ret < 0) {
>>           goto out;
>> @@ -219,7 +219,7 @@ static int nbd_negotiate_send_rep_list(QIOChannel *ioc, NBDExport *exp,
>>       const char *desc = exp->description ? exp->description : "";
>>       int ret;
>>   
>> -    TRACE("Advertising export name '%s' description '%s'", name, desc);
>> +    trace_nbd_negotiate_send_rep_list(name, desc);
>>       name_len = strlen(name);
>>       desc_len = strlen(desc);
>>       len = name_len + desc_len + sizeof(len);
>> @@ -283,7 +283,7 @@ static int nbd_negotiate_handle_export_name(NBDClient *client, uint32_t length,
>>       /* Client sends:
>>           [20 ..  xx]   export name (length bytes)
>>        */
>> -    TRACE("Checking length");
>> +    trace_nbd_negotiate_handle_export_name();
>>       if (length >= sizeof(name)) {
>>           error_setg(errp, "Bad length received");
>>           return -EINVAL;
>> @@ -294,7 +294,7 @@ static int nbd_negotiate_handle_export_name(NBDClient *client, uint32_t length,
>>       }
>>       name[length] = '\0';
>>   
>> -    TRACE("Client requested export '%s'", name);
>> +    trace_nbd_negotiate_handle_export_name_request(name);
>>   
>>       client->exp = nbd_export_find(name);
>>       if (!client->exp) {
>> @@ -318,7 +318,7 @@ static QIOChannel *nbd_negotiate_handle_starttls(NBDClient *client,
>>       QIOChannelTLS *tioc;
>>       struct NBDTLSHandshakeData data = { 0 };
>>   
>> -    TRACE("Setting up TLS");
>> +    trace_nbd_negotiate_handle_starttls();
>>       ioc = client->ioc;
>>       if (length) {
>>           if (nbd_drop(ioc, length, errp) < 0) {
>> @@ -344,7 +344,7 @@ static QIOChannel *nbd_negotiate_handle_starttls(NBDClient *client,
>>       }
>>   
>>       qio_channel_set_name(QIO_CHANNEL(tioc), "nbd-server-tls");
>> -    TRACE("Starting TLS handshake");
>> +    trace_nbd_negotiate_handle_starttls_handshake();
>>       data.loop = g_main_loop_new(g_main_context_default(), FALSE);
>>       qio_channel_tls_handshake(tioc,
>>                                 nbd_tls_handshake,
>> @@ -396,15 +396,15 @@ static int nbd_negotiate_options(NBDClient *client, Error **errp)
>>           error_prepend(errp, "read failed: ");
>>           return -EIO;
>>       }
>> -    TRACE("Checking client flags");
>> +    trace_nbd_negotiate_options_flags();
>>       be32_to_cpus(&flags);
>>       if (flags & NBD_FLAG_C_FIXED_NEWSTYLE) {
>> -        TRACE("Client supports fixed newstyle handshake");
>> +        trace_nbd_negotiate_options_newstyle();
>>           fixedNewstyle = true;
>>           flags &= ~NBD_FLAG_C_FIXED_NEWSTYLE;
>>       }
>>       if (flags & NBD_FLAG_C_NO_ZEROES) {
>> -        TRACE("Client supports no zeroes at handshake end");
>> +        trace_nbd_negotiate_options_no_zeroes();
>>           client->no_zeroes = true;
>>           flags &= ~NBD_FLAG_C_NO_ZEROES;
>>       }
>> @@ -422,7 +422,7 @@ static int nbd_negotiate_options(NBDClient *client, Error **errp)
>>               error_prepend(errp, "read failed: ");
>>               return -EINVAL;
>>           }
>> -        TRACE("Checking opts magic");
>> +        trace_nbd_negotiate_options_check_magic();
>>           if (magic != be64_to_cpu(NBD_OPTS_MAGIC)) {
>>               error_setg(errp, "Bad magic received");
>>               return -EINVAL;
>> @@ -441,7 +441,7 @@ static int nbd_negotiate_options(NBDClient *client, Error **errp)
>>           }
>>           length = be32_to_cpu(length);
>>   
>> -        TRACE("Checking option 0x%" PRIx32, clientflags);
>> +        trace_nbd_negotiate_options_check_option(clientflags);
>>           if (client->tlscreds &&
>>               client->ioc == (QIOChannel *)client->sioc) {
>>               QIOChannel *tioc;
>> @@ -501,8 +501,8 @@ static int nbd_negotiate_options(NBDClient *client, Error **errp)
>>                                          &local_err);
>>   
>>                   if (local_err != NULL) {
>> -                    TRACE("Reply to NBD_OPT_ABORT request failed: %s",
>> -                          error_get_pretty(local_err));
>> +                    const char *error = error_get_pretty(local_err);
>> +                    trace_nbd_opt_abort_reply_failed(error);
>>                       error_free(local_err);
>>                   }
>>   
>> @@ -599,14 +599,14 @@ static coroutine_fn int nbd_negotiate(NBDClient *client, Error **errp)
>>   
>>       qio_channel_set_blocking(client->ioc, false, NULL);
>>   
>> -    TRACE("Beginning negotiation.");
>> +    trace_nbd_negotiate_begin();
>>       memset(buf, 0, sizeof(buf));
>>       memcpy(buf, "NBDMAGIC", 8);
>>   
>>       oldStyle = client->exp != NULL && !client->tlscreds;
>>       if (oldStyle) {
>> -        TRACE("advertising size %" PRIu64 " and flags %x",
>> -              client->exp->size, client->exp->nbdflags | myflags);
>> +        trace_nbd_negotiate_old_style(client->exp->size,
>> +                                      client->exp->nbdflags | myflags);
>>           stq_be_p(buf + 8, NBD_CLIENT_MAGIC);
>>           stq_be_p(buf + 16, client->exp->size);
>>           stw_be_p(buf + 26, client->exp->nbdflags | myflags);
>> @@ -637,8 +637,8 @@ static coroutine_fn int nbd_negotiate(NBDClient *client, Error **errp)
>>               return ret;
>>           }
>>   
>> -        TRACE("advertising size %" PRIu64 " and flags %x",
>> -              client->exp->size, client->exp->nbdflags | myflags);
>> +        trace_nbd_negotiate_new_style_size_flags(
>> +            client->exp->size, client->exp->nbdflags | myflags);
>>           stq_be_p(buf + 18, client->exp->size);
>>           stw_be_p(buf + 26, client->exp->nbdflags | myflags);
>>           len = client->no_zeroes ? 10 : sizeof(buf) - 18;
>> @@ -649,7 +649,7 @@ static coroutine_fn int nbd_negotiate(NBDClient *client, Error **errp)
>>           }
>>       }
>>   
>> -    TRACE("Negotiation succeeded.");
>> +    trace_nbd_negotiate_success();
>>   
>>       return 0;
>>   }
>> @@ -682,9 +682,8 @@ static int nbd_receive_request(QIOChannel *ioc, NBDRequest *request,
>>       request->from   = ldq_be_p(buf + 16);
>>       request->len    = ldl_be_p(buf + 24);
>>   
>> -    TRACE("Got request: { magic = 0x%" PRIx32 ", .flags = %" PRIx16
>> -          ", .type = %" PRIx16 ", from = %" PRIu64 ", len = %" PRIu32 " }",
>> -          magic, request->flags, request->type, request->from, request->len);
>> +    trace_nbd_receive_request(magic, request->flags, request->type,
>> +                              request->from, request->len);
>>   
>>       if (magic != NBD_REQUEST_MAGIC) {
>>           error_setg(errp, "invalid magic (got 0x%" PRIx32 ")", magic);
>> @@ -699,9 +698,7 @@ static int nbd_send_reply(QIOChannel *ioc, NBDReply *reply, Error **errp)
>>   
>>       reply->error = system_errno_to_nbd_errno(reply->error);
>>   
>> -    TRACE("Sending response to client: { .error = %" PRId32
>> -          ", handle = %" PRIu64 " }",
>> -          reply->error, reply->handle);
>> +    trace_nbd_send_reply(reply->error, reply->handle);
>>   
>>       /* Reply
>>          [ 0 ..  3]    magic   (NBD_REPLY_MAGIC)
>> @@ -798,7 +795,7 @@ static void blk_aio_attached(AioContext *ctx, void *opaque)
>>       NBDExport *exp = opaque;
>>       NBDClient *client;
>>   
>> -    TRACE("Export %s: Attaching clients to AIO context %p\n", exp->name, ctx);
>> +    trace_blk_aio_attached(exp->name, ctx);
>>   
>>       exp->ctx = ctx;
>>   
>> @@ -818,7 +815,7 @@ static void blk_aio_detach(void *opaque)
>>       NBDExport *exp = opaque;
>>       NBDClient *client;
>>   
>> -    TRACE("Export %s: Detaching clients from AIO context %p\n", exp->name, exp->ctx);
>> +    trace_blk_aio_detach(exp->name, exp->ctx);
>>   
>>       QTAILQ_FOREACH(client, &exp->clients, next) {
>>           qio_channel_detach_aio_context(client->ioc);
>> @@ -1045,7 +1042,7 @@ static int nbd_co_receive_request(NBDRequestData *req, NBDRequest *request,
>>           return -EIO;
>>       }
>>   
>> -    TRACE("Decoding type");
>> +    trace_nbd_co_receive_request_decode_type();
>>   
>>       if (request->type != NBD_CMD_WRITE) {
>>           /* No payload, we are ready to read the next request.  */
>> @@ -1055,7 +1052,7 @@ static int nbd_co_receive_request(NBDRequestData *req, NBDRequest *request,
>>       if (request->type == NBD_CMD_DISC) {
>>           /* Special case: we're going to disconnect without a reply,
>>            * whether or not flags, from, or len are bogus */
>> -        TRACE("Request type is DISCONNECT");
>> +        trace_nbd_co_receive_request_disconnect();
>>           return -EIO;
>>       }
>>   
>> @@ -1082,7 +1079,7 @@ static int nbd_co_receive_request(NBDRequestData *req, NBDRequest *request,
>>           }
>>       }
>>       if (request->type == NBD_CMD_WRITE) {
>> -        TRACE("Reading %" PRIu32 " byte(s)", request->len);
>> +        trace_nbd_co_receive_request_cmd_write(request->len);
>>   
>>           if (nbd_read(client->ioc, req->data, request->len, errp) < 0) {
>>               error_prepend(errp, "reading from socket failed: ");
>> @@ -1124,7 +1121,7 @@ static coroutine_fn void nbd_trip(void *opaque)
>>       int reply_data_len = 0;
>>       Error *local_err = NULL;
>>   
>> -    TRACE("Reading request.");
>> +    trace_do_nbd_trip();
>>       if (client->closing) {
>>           nbd_client_put(client);
>>           return;
>> @@ -1156,7 +1153,7 @@ static coroutine_fn void nbd_trip(void *opaque)
>>   
>>       switch (request.type) {
>>       case NBD_CMD_READ:
>> -        TRACE("Request type is READ");
>> +        trace_do_nbd_trip_cmd_read();
>>   
>>           /* XXX: NBD Protocol only documents use of FUA with WRITE */
>>           if (request.flags & NBD_CMD_FLAG_FUA) {
>> @@ -1177,19 +1174,19 @@ static coroutine_fn void nbd_trip(void *opaque)
>>           }
>>   
>>           reply_data_len = request.len;
>> -        TRACE("Read %" PRIu32" byte(s)", request.len);
>> +        trace_do_nbd_trip_read(request.len);
>>   
>>           break;
>>       case NBD_CMD_WRITE:
>> -        TRACE("Request type is WRITE");
>> +        trace_do_nbd_trip_cmd_write();
>>   
>>           if (exp->nbdflags & NBD_FLAG_READ_ONLY) {
>> -            TRACE("Server is read-only, return error");
>> +            trace_do_nbd_trip_cmd_write_readonly();
>>               reply.error = EROFS;
>>               break;
>>           }
>>   
>> -        TRACE("Writing to device");
>> +        trace_do_nbd_trip_write();
>>   
>>           flags = 0;
>>           if (request.flags & NBD_CMD_FLAG_FUA) {
>> @@ -1204,7 +1201,7 @@ static coroutine_fn void nbd_trip(void *opaque)
>>   
>>           break;
>>       case NBD_CMD_WRITE_ZEROES:
>> -        TRACE("Request type is WRITE_ZEROES");
>> +        trace_do_nbd_trip_cmd_write_zeroes();
>>   
>>           if (exp->nbdflags & NBD_FLAG_READ_ONLY) {
>>               error_setg(&local_err, "Server is read-only, return error");
>> @@ -1212,7 +1209,7 @@ static coroutine_fn void nbd_trip(void *opaque)
>>               break;
>>           }
>>   
>> -        TRACE("Writing to device");
>> +        trace_do_nbd_trip_write_zeroes();
>>   
>>           flags = 0;
>>           if (request.flags & NBD_CMD_FLAG_FUA) {
>> @@ -1234,7 +1231,7 @@ static coroutine_fn void nbd_trip(void *opaque)
>>           abort();
>>   
>>       case NBD_CMD_FLUSH:
>> -        TRACE("Request type is FLUSH");
>> +        trace_do_nbd_trip_cmd_flush();
>>   
>>           ret = blk_co_flush(exp->blk);
>>           if (ret < 0) {
>> @@ -1244,7 +1241,7 @@ static coroutine_fn void nbd_trip(void *opaque)
>>   
>>           break;
>>       case NBD_CMD_TRIM:
>> -        TRACE("Request type is TRIM");
>> +        trace_do_nbd_trip_cmd_trim();
>>           ret = blk_co_pdiscard(exp->blk, request.from + exp->dev_offset,
>>                                 request.len);
>>           if (ret < 0) {
>> @@ -1280,7 +1277,7 @@ reply:
>>           goto disconnect;
>>       }
>>   
>> -    TRACE("Request/Reply complete");
>> +    trace_do_nbd_trip_complete();
>>   
>>   done:
>>       nbd_request_put(req);
>> diff --git a/nbd/trace-events b/nbd/trace-events
>> new file mode 100644
>> index 0000000000..46e4d110bd
>> --- /dev/null
>> +++ b/nbd/trace-events
>> @@ -0,0 +1,68 @@
>> +# nbd/client.c
>> +nbd_unknown_error(int err) "Squashing unexpected error %d to EINVAL"
>> +nbd_send_option_request(uint32_t opt, uint32_t len) "Sending option request %" PRIu32", len %" PRIu32
>> +nbd_receive_option_reply(uint32_t option, uint32_t type, uint32_t length) "Received option reply %" PRIx32", type %" PRIx32", len %" PRIu32
>> +nbd_reply_err_unsup(uint32_t option) "server doesn't understand request %" PRIx32 ", attempting fallback"
>> +nbd_receive_query_exports_start(const char *wantname) "Querying export list for '%s'"
>> +nbd_receive_query_exports_loop(void) "Reading available export names"
>> +nbd_receive_query_exports_success(const char *wantname) "Found desired export name '%s'"
>> +nbd_receive_starttls_request(void) "Requesting TLS from server"
>> +nbd_receive_starttls_reply(void) "Getting TLS reply from server"
>> +nbd_receive_starttls_new_client(void) "TLS request approved, setting up TLS"
>> +nbd_receive_starttls_tls_handshake(void) "Starting TLS handshake"
>> +nbd_receive_negotiate(void *tlscreds, const char *hostname) "Receiving negotiation tlscreds=%p hostname=%s"
>> +nbd_receive_negotiate_magic(uint64_t magic) "Magic is 0x%" PRIx64
>> +nbd_receive_negotiate_magic2(uint64_t magic) "Magic is 0x%" PRIx64
>> +nbd_receive_negotiate_server_flags(uint32_t globalflags) "Global flags are %" PRIx32
>> +nbd_receive_negotiate_default_name(void) "Using default NBD export name \"\""
>> +nbd_receive_negotiate_export_size(uint64_t size) "Size is %" PRIu64
>> +nbd_receive_negotiate_size_flags(uint64_t size, uint16_t flags) "Size is %" PRIu64 ", export flags %" PRIx16
>> +nbd_init_set_socket(void) "Setting NBD socket"
>> +nbd_init_set_block_size(unsigned long block_size) "Setting block size to %lu"
>> +nbd_init_set_size(unsigned long sectors) "Setting size to %lu block(s)"
>> +nbd_init_trailing_bytes(int ignored_bytes) "Ignoring trailing %d bytes of export"
>> +nbd_init_set_readonly(void) "Setting readonly attribute"
>> +nbd_init_finish(void) "Negotiation ended"
>> +nbd_client_loop(void) "Doing NBD loop"
>> +nbd_client_loop_ret(int ret, const char *error) "NBD loop returned %d: %s"
>> +nbd_client_clear_queue(void) "Clearing NBD queue"
>> +nbd_client_clear_socket(void) "Clearing NBD socket"
>> +nbd_send_request(uint64_t from, uint32_t len, uint64_t handle, uint16_t flags, uint16_t type) "Sending request to server: { .from = %" PRIu64", .len = %" PRIu32 ", .handle = %" PRIu64 ", .flags = %" PRIx16 ", .type = %" PRIu16 " }"
>> +nbd_receive_reply(uint32_t magic, int32_t error, uint64_t handle) "Got reply: { magic = 0x%" PRIx32 ", .error = % " PRId32 ", handle = %" PRIu64" }"
>> +
>> +# nbd/server.c
>> +nbd_negotiate_send_rep_len(uint32_t type, uint32_t opt, uint32_t len) "Reply opt=%" PRIx32 " type=%" PRIx32 " len=%" PRIu32
>> +nbd_negotiate_send_rep_err(const char *msg) "sending error message \"%s\""
>> +nbd_negotiate_send_rep_list(const char *name, const char *desc) "Advertising export name '%s' description '%s'"
>> +nbd_negotiate_handle_export_name(void) "Checking length"
>> +nbd_negotiate_handle_export_name_request(const char *name) "Client requested export '%s'"
>> +nbd_negotiate_handle_starttls(void) "Setting up TLS"
>> +nbd_negotiate_handle_starttls_handshake(void) "Starting TLS handshake"
>> +nbd_negotiate_options_flags(void) "Checking client flags"
>> +nbd_negotiate_options_newstyle(void) "Client supports fixed newstyle handshake"
>> +nbd_negotiate_options_no_zeroes(void) "Client supports no zeroes at handshake end"
>> +nbd_negotiate_options_check_magic(void) "Checking opts magic"
>> +nbd_negotiate_options_check_option(uint32_t clientflags) "Checking option 0x%" PRIx32
>> +nbd_opt_abort_reply_failed(const char *error) "Reply to NBD_OPT_ABORT request failed: %s"
>> +nbd_negotiate_begin(void) "Beginning negotiation"
>> +nbd_negotiate_old_style(uint64_t size, unsigned flags) "advertising size %" PRIu64 " and flags %x"
>> +nbd_negotiate_new_style_size_flags(uint64_t size, unsigned flags) "advertising size %" PRIu64 " and flags %x"
>> +nbd_negotiate_success(void) "Negotiation succeeded"
>> +nbd_receive_request(uint32_t magic, uint16_t flags, uint16_t type, uint64_t from, uint32_t len) "Got request: { magic = 0x%" PRIx32 ", .flags = %" PRIx16 ", .type = %" PRIx16 ", from = %" PRIu64 ", len = %" PRIu32 " }"
>> +nbd_send_reply(int32_t error, uint64_t handle) "Sending response to client: { .error = %" PRId32 ", handle = %" PRIu64 " }"
>> +blk_aio_attached(const char *name, void *ctx) "Export %s: Attaching clients to AIO context %p\n"
>> +blk_aio_detach(const char *name, void *ctx) "Export %s: Detaching clients from AIO context %p\n"
>> +nbd_co_receive_request_decode_type(void) "Decoding type"
> Please add the request->handle and request->type as an argument...
>
>> +nbd_co_receive_request_disconnect(void) "Request type is DISCONNECT"
> ... and remove this one, which is now unnecessary.
>
>> +nbd_co_receive_request_cmd_write(uint32_t len) "Reading %" PRIu32 " byte(s)"
>> +do_nbd_trip(void) "Reading request"
> Please remove do_ from all these tracepoints, in addition:
>
>> +do_nbd_trip_cmd_read(void) "Request type is READ"
> This can be removed if nbd_co_receive_request_decode_type gets
> request.type as an argument.
>
>> +do_nbd_trip_read(uint32_t len) "Read %" PRIu32" byte(s)"
> This one is good.

why do you like this and do not like nbd_trip_write_zeros?

>
>> +do_nbd_trip_cmd_write(void) "Request type is WRITE"
>> +do_nbd_trip_cmd_write_readonly(void) "Server is read-only, return error"
> These can be removed.

I think the second is informative, isn't it?

>
>> +do_nbd_trip_write(void) "Writing to device"
> Please add the handle here.

handle will be printed in nbd_co_receive_request_decode_type..

remove nbd_trip_write? or add length like with nbd_trip_read?

>
>> +do_nbd_trip_cmd_write_zeroes(void) "Request type is WRITE_ZEROES"
>> +do_nbd_trip_write_zeroes(void) "Writing to device"
>> +do_nbd_trip_cmd_flush(void) "Request type is FLUSH"
>> +do_nbd_trip_cmd_trim(void) "Request type is TRIM"
> Can all be removed.

then, remove nbd_trip_write too ?

>
>> +do_nbd_trip_complete(void) "Request/Reply complete"
> This one is good, but please add the handle here too.
>
> Thanks,
>
> Paolo


-- 
Best regards,
Vladimir

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [Qemu-devel] [PATCH v2 6/6] nbd: use generic trace subsystem instead of TRACE macro
  2017-07-06  8:45     ` Vladimir Sementsov-Ogievskiy
@ 2017-07-06  8:57       ` Paolo Bonzini
  0 siblings, 0 replies; 28+ messages in thread
From: Paolo Bonzini @ 2017-07-06  8:57 UTC (permalink / raw)
  To: Vladimir Sementsov-Ogievskiy, qemu-devel; +Cc: stefanha, eblake, den



On 06/07/2017 10:45, Vladimir Sementsov-Ogievskiy wrote:
>>> +do_nbd_trip_read(uint32_t len) "Read %" PRIu32" byte(s)"
>> This one is good.
> 
> why do you like this and do not like nbd_trip_write_zeros?

I'm not sure I understand: this one is after blk_pread returns.  It
tells you that the socket is about to receive the payload.

For write, nothing special happened since do_nbd_trip_cmd_write.

For write zeroes, nothing special happened since
nbd_co_receive_request_decode_type.

>>
>>> +do_nbd_trip_cmd_write(void) "Request type is WRITE"
>>> +do_nbd_trip_cmd_write_readonly(void) "Server is read-only, return
>>> error"
>> These can be removed.
> 
> I think the second is informative, isn't it?

Can you instead add a trace point at the beginning of nbd_co_send_reply,
with handle/error/len?  Then you can remove do_nbd_trip_read and
do_nbd_trip_complete, too.

>>> +do_nbd_trip_write(void) "Writing to device"
>> Please add the handle here.
> 
> handle will be printed in nbd_co_receive_request_decode_type..

You need it in case there are multiple requests in flight.

>>> +do_nbd_trip_cmd_write_zeroes(void) "Request type is WRITE_ZEROES"
>>> +do_nbd_trip_write_zeroes(void) "Writing to device"
>>> +do_nbd_trip_cmd_flush(void) "Request type is FLUSH"
>>> +do_nbd_trip_cmd_trim(void) "Request type is TRIM"
>> Can all be removed.
> 
> then, remove nbd_trip_write too ?

Write is different because it happens after nbd_read(client->ioc,
req->data, request->len, NULL) has completed.  You can add a tracepoint
to nbd_co_receive_request instead.

Paolo

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [Qemu-devel] [PATCH v2 6/6] nbd: use generic trace subsystem instead of TRACE macro
  2017-06-29 20:12   ` Eric Blake
@ 2017-07-06 14:49     ` Eric Blake
  0 siblings, 0 replies; 28+ messages in thread
From: Eric Blake @ 2017-07-06 14:49 UTC (permalink / raw)
  To: Vladimir Sementsov-Ogievskiy, qemu-devel; +Cc: pbonzini, stefanha, den

[-- Attachment #1: Type: text/plain, Size: 1100 bytes --]

On 06/29/2017 03:12 PM, Eric Blake wrote:
> On 06/21/2017 10:34 AM, Vladimir Sementsov-Ogievskiy wrote:
>> Starting from this patch to enable traces use -trace option of qemu or
>> -T, --trace option of qemu-img, qemu-io and qemu-nbd. For qemu traces
>> also can be managed by qmp commands trace-event-{get,set}-state.
> 
> Maybe:
> 
> Let NBD use the trace mechanisms already present in qemu. Now you can
> use the -trace optino of qemu, or the -T/--trace option of qemu-img,
> qemu-io, and qemu-nbd, to select nbd traces.  For qemu, the QMP commands
> trace-event-{get,set}-state can also toggle tracing on the fly.
> 
> I also mentioned in v1 that an actual command line example might be
> helpful (for example, is it qemu-nbd --trace "nbd_*" to get ALL nbd
> traces enabled?)

Answering myself: almost.  Either you have to use the pattern --trace
"*nbd_*", or better, you follow Paolo's advice to rename any 'do_nbd_'
traces to be just 'nbd_'.

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3266
Virtualization:  qemu.org | libvirt.org


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 604 bytes --]

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [Qemu-devel] [PATCH v2 6/6] nbd: use generic trace subsystem instead of TRACE macro
  2017-06-21 15:34 ` [Qemu-devel] [PATCH v2 6/6] nbd: use generic trace subsystem instead of TRACE macro Vladimir Sementsov-Ogievskiy
  2017-06-29 20:12   ` Eric Blake
  2017-07-05 15:29   ` Paolo Bonzini
@ 2017-07-06 15:01   ` Eric Blake
  2017-07-06 15:28   ` Eric Blake
  2017-07-06 15:44   ` Eric Blake
  4 siblings, 0 replies; 28+ messages in thread
From: Eric Blake @ 2017-07-06 15:01 UTC (permalink / raw)
  To: Vladimir Sementsov-Ogievskiy, qemu-devel; +Cc: stefanha, pbonzini, den

[-- Attachment #1: Type: text/plain, Size: 1399 bytes --]

On 06/21/2017 10:34 AM, Vladimir Sementsov-Ogievskiy wrote:
> Starting from this patch to enable traces use -trace option of qemu or
> -T, --trace option of qemu-img, qemu-io and qemu-nbd. For qemu traces
> also can be managed by qmp commands trace-event-{get,set}-state.
> 
> Recompilation with CFLAGS=-DDEBUG_NBD is no more needed, furthermore,
> DEBUG_NBD macro is removed from the code.
> 
> Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
> ---

> +++ b/nbd/client.c

> @@ -565,7 +561,7 @@ int nbd_receive_negotiate(QIOChannel *ioc, const char *name, uint16_t *flags,
>              goto fail;
>          }
>          *size = be64_to_cpu(s);
> -        TRACE("Size is %" PRIu64, *size);
> +        trace_nbd_receive_negotiate_export_size(*size);
>  

This one is redundant...

>          if (nbd_read(ioc, &oldflags, sizeof(oldflags), errp) < 0) {
>              error_prepend(errp, "Failed to read export flags");
> @@ -582,7 +578,7 @@ int nbd_receive_negotiate(QIOChannel *ioc, const char *name, uint16_t *flags,
>          goto fail;
>      }
>  
> -    TRACE("Size is %" PRIu64 ", export flags %" PRIx16, *size, *flags);
> +    trace_nbd_receive_negotiate_size_flags(*size, *flags);

...with this one.

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3266
Virtualization:  qemu.org | libvirt.org


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 604 bytes --]

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [Qemu-devel] [PATCH v2 6/6] nbd: use generic trace subsystem instead of TRACE macro
  2017-06-21 15:34 ` [Qemu-devel] [PATCH v2 6/6] nbd: use generic trace subsystem instead of TRACE macro Vladimir Sementsov-Ogievskiy
                     ` (2 preceding siblings ...)
  2017-07-06 15:01   ` Eric Blake
@ 2017-07-06 15:28   ` Eric Blake
  2017-07-06 15:44   ` Eric Blake
  4 siblings, 0 replies; 28+ messages in thread
From: Eric Blake @ 2017-07-06 15:28 UTC (permalink / raw)
  To: Vladimir Sementsov-Ogievskiy, qemu-devel; +Cc: stefanha, pbonzini, den

[-- Attachment #1: Type: text/plain, Size: 1449 bytes --]

On 06/21/2017 10:34 AM, Vladimir Sementsov-Ogievskiy wrote:
> Starting from this patch to enable traces use -trace option of qemu or
> -T, --trace option of qemu-img, qemu-io and qemu-nbd. For qemu traces
> also can be managed by qmp commands trace-event-{get,set}-state.
> 
> Recompilation with CFLAGS=-DDEBUG_NBD is no more needed, furthermore,
> DEBUG_NBD macro is removed from the code.
> 

> +++ b/nbd/server.c
> @@ -19,6 +19,7 @@
>  
>  #include "qemu/osdep.h"
>  #include "qapi/error.h"
> +#include "trace.h"
>  #include "nbd-internal.h"
>  
>  static int system_errno_to_nbd_errno(int err)
> @@ -138,8 +139,7 @@ static int nbd_negotiate_send_rep_len(QIOChannel *ioc, uint32_t type,
>  {
>      uint64_t magic;
>  
> -    TRACE("Reply opt=%" PRIx32 " type=%" PRIx32 " len=%" PRIu32,
> -          type, opt, len);
> +    trace_nbd_negotiate_send_rep_len(type, opt, len);

Eww. The old code is backwards (prints "opt=<type>, type=<opt>").  It
makes sense to print opt first.

> +# nbd/server.c
> +nbd_negotiate_send_rep_len(uint32_t type, uint32_t opt, uint32_t len) "Reply opt=%" PRIx32 " type=%" PRIx32 " len=%" PRIu32

It may also make sense to split the fixup of the backwards printout as a
separate patch, so that it doesn't get lost in the noisse of the bulk
conversion.

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3266
Virtualization:  qemu.org | libvirt.org


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 604 bytes --]

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [Qemu-devel] [PATCH v2 6/6] nbd: use generic trace subsystem instead of TRACE macro
  2017-06-21 15:34 ` [Qemu-devel] [PATCH v2 6/6] nbd: use generic trace subsystem instead of TRACE macro Vladimir Sementsov-Ogievskiy
                     ` (3 preceding siblings ...)
  2017-07-06 15:28   ` Eric Blake
@ 2017-07-06 15:44   ` Eric Blake
  2017-07-07 14:02     ` Vladimir Sementsov-Ogievskiy
  4 siblings, 1 reply; 28+ messages in thread
From: Eric Blake @ 2017-07-06 15:44 UTC (permalink / raw)
  To: Vladimir Sementsov-Ogievskiy, qemu-devel; +Cc: stefanha, pbonzini, den

[-- Attachment #1: Type: text/plain, Size: 1331 bytes --]

On 06/21/2017 10:34 AM, Vladimir Sementsov-Ogievskiy wrote:
> Starting from this patch to enable traces use -trace option of qemu or
> -T, --trace option of qemu-img, qemu-io and qemu-nbd. For qemu traces
> also can be managed by qmp commands trace-event-{get,set}-state.
> 
> Recompilation with CFLAGS=-DDEBUG_NBD is no more needed, furthermore,
> DEBUG_NBD macro is removed from the code.
> 
> Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
> ---

> +++ b/nbd/server.c

> @@ -441,7 +441,7 @@ static int nbd_negotiate_options(NBDClient *client, Error **errp)
>          }
>          length = be32_to_cpu(length);
>  
> -        TRACE("Checking option 0x%" PRIx32, clientflags);
> +        trace_nbd_negotiate_options_check_option(clientflags);

This variable is a stupid name (it has nothing to do with flags, but is
a single integer representing the option requested by the client). Now's
as good as any to rename it to something that makes sense (maybe 'option').

> +nbd_negotiate_options_check_option(uint32_t clientflags) "Checking option 0x%" PRIx32

and likewise use the saner name in the trace file.  Perhaps as a
separate cleanup patch.

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3266
Virtualization:  qemu.org | libvirt.org


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 604 bytes --]

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [Qemu-devel] [PATCH v2 1/6] nbd/server: nbd_negotiate: return 1 on NBD_OPT_ABORT
  2017-06-29 18:46   ` Eric Blake
@ 2017-07-06 16:07     ` Eric Blake
  0 siblings, 0 replies; 28+ messages in thread
From: Eric Blake @ 2017-07-06 16:07 UTC (permalink / raw)
  To: Vladimir Sementsov-Ogievskiy, qemu-devel; +Cc: pbonzini, stefanha, den

[-- Attachment #1: Type: text/plain, Size: 2449 bytes --]

On 06/29/2017 01:46 PM, Eric Blake wrote:
> On 06/21/2017 10:34 AM, Vladimir Sementsov-Ogievskiy wrote:
>> Separate case when client sent NBD_OPT_ABORT from other errors.
> 
> Commit messages are best written in imperative tense (you can supply an
> implicit "apply this patch in order to" prefix in front of the message,
> and it should still generally read well); and that doesn't mix well with
> past-tense descriptions.  I might have written:
> 
> Separate the case when a client sends NBD_OPT_ABORT from all other errors.
> 
>> It will be needed for the following patch, where errors will be
>> reported.
>> Considered case is not actually the error - it honestly follows NBD
>> protocol. Therefore it should not be reported like an error.
> 
> This particular case is not actually an error - it honestly follows the
> NBD protocol.
> 
>>
>> Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
>> ---
>>  nbd/server.c | 20 +++++++++++++++-----
>>  1 file changed, 15 insertions(+), 5 deletions(-)
>>
> 
>> -
>> -/* Process all NBD_OPT_* client option commands.
>> - * Return -errno on error, 0 on success. */
>> +/* nbd_negotiate_options
>> + * Process all NBD_OPT_* client option commands.
>> + * Return:
>> + * -errno  on error
>> + * 0       on successful negotiation
>> + * 1       if client sent NBD_OPT_ABORT, i.e. on legal disconnect
> 

Phooey, I'm just now noticing (while trying to rebase my existing
patches on top of yours) that we have a conflict in semantics.  For
reference, my patch was posted here:

https://lists.gnu.org/archive/html/qemu-devel/2017-02/msg04535.html

where I picked the semantics:

+/* Process all NBD_OPT_* client option commands, during fixed newstyle
+ * negotiation. Return -errno on error, 0 on successful
NBD_OPT_EXPORT_NAME,
+ * and 1 on successful NBD_OPT_GO. */
+static int nbd_negotiate_options(NBDClient *client, uint16_t myflags)

But since I'm rebasing my stuff anyways, I'll come up with some other
way to combine the two semantics (perhaps by refactoring the response to
NBD_OPT_EXPORT_NAME to occur in nbd_negotiate_options() instead of in
the caller, so that returning 0 is always sufficient to mark that
newstyle negotiation is complete and the server is now in transmission
phase).

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3266
Virtualization:  qemu.org | libvirt.org


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 604 bytes --]

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [Qemu-devel] [PATCH v2 6/6] nbd: use generic trace subsystem instead of TRACE macro
  2017-07-06 15:44   ` Eric Blake
@ 2017-07-07 14:02     ` Vladimir Sementsov-Ogievskiy
  0 siblings, 0 replies; 28+ messages in thread
From: Vladimir Sementsov-Ogievskiy @ 2017-07-07 14:02 UTC (permalink / raw)
  To: Eric Blake, qemu-devel; +Cc: stefanha, pbonzini, den

06.07.2017 18:44, Eric Blake wrote:
> On 06/21/2017 10:34 AM, Vladimir Sementsov-Ogievskiy wrote:
>> Starting from this patch to enable traces use -trace option of qemu or
>> -T, --trace option of qemu-img, qemu-io and qemu-nbd. For qemu traces
>> also can be managed by qmp commands trace-event-{get,set}-state.
>>
>> Recompilation with CFLAGS=-DDEBUG_NBD is no more needed, furthermore,
>> DEBUG_NBD macro is removed from the code.
>>
>> Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
>> ---
>> +++ b/nbd/server.c
>> @@ -441,7 +441,7 @@ static int nbd_negotiate_options(NBDClient *client, Error **errp)
>>           }
>>           length = be32_to_cpu(length);
>>   
>> -        TRACE("Checking option 0x%" PRIx32, clientflags);
>> +        trace_nbd_negotiate_options_check_option(clientflags);
> This variable is a stupid name (it has nothing to do with flags, but is
> a single integer representing the option requested by the client). Now's

will use your wording for commit message)

> as good as any to rename it to something that makes sense (maybe 'option').
>
>> +nbd_negotiate_options_check_option(uint32_t clientflags) "Checking option 0x%" PRIx32
> and likewise use the saner name in the trace file.  Perhaps as a
> separate cleanup patch.
>

-- 
Best regards,
Vladimir

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [Qemu-devel] [PATCH v2 2/6] nbd/server: use errp instead of LOG
  2017-06-21 15:34 ` [Qemu-devel] [PATCH v2 2/6] nbd/server: use errp instead of LOG Vladimir Sementsov-Ogievskiy
  2017-06-29 19:27   ` Eric Blake
@ 2017-07-07 14:40   ` Eric Blake
  2017-07-07 15:10     ` Vladimir Sementsov-Ogievskiy
  1 sibling, 1 reply; 28+ messages in thread
From: Eric Blake @ 2017-07-07 14:40 UTC (permalink / raw)
  To: Vladimir Sementsov-Ogievskiy, qemu-devel
  Cc: stefanha, pbonzini, den, Daniel P. Berrange

[-- Attachment #1: Type: text/plain, Size: 1756 bytes --]

On 06/21/2017 10:34 AM, Vladimir Sementsov-Ogievskiy wrote:
> Move to modern errp scheme from just LOGging errors.
> 
> Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
> ---
>  nbd/server.c | 268 +++++++++++++++++++++++++++++++++++------------------------
>  1 file changed, 161 insertions(+), 107 deletions(-)

> -static coroutine_fn int nbd_negotiate(NBDClient *client)
> +static coroutine_fn int nbd_negotiate(NBDClient *client, Error **errp)
>  {
>      char buf[8 + 8 + 8 + 128];
>      int ret;

Now that you have this,

>     qio_channel_set_blocking(client->ioc, false, NULL);
> 

you should probably pass errp through to qio_channel_set_blocking and
return early if that fails (either here or in one of the followup
patches) [hmm, I note that most callers of qio_channel_set_blocking()
ignore errors - outside of NBD, so that's a separate cleanup series]


> @@ -591,21 +617,23 @@ static coroutine_fn int nbd_negotiate(NBDClient *client)
>  
>      if (oldStyle) {
>          if (client->tlscreds) {
> -            TRACE("TLS cannot be enabled with oldstyle protocol");
> +            error_setg(errp, "TLS cannot be enabled with oldstyle protocol");
>              return -EINVAL;

This code is unreachable, since earlier we have:

>     oldStyle = client->exp != NULL && !client->tlscreds;

You could just as easily delete the conditional.  In fact, our code has:

if (oldStyle) {
    do stuff
} else {
    do stuff
}

if (oldStyle) {
    do stuff
} else {
    do stuff
}

and it would be simple to merge that into a single if statement.

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3266
Virtualization:  qemu.org | libvirt.org


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 604 bytes --]

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [Qemu-devel] [PATCH v2 2/6] nbd/server: use errp instead of LOG
  2017-07-07 14:40   ` Eric Blake
@ 2017-07-07 15:10     ` Vladimir Sementsov-Ogievskiy
  0 siblings, 0 replies; 28+ messages in thread
From: Vladimir Sementsov-Ogievskiy @ 2017-07-07 15:10 UTC (permalink / raw)
  To: Eric Blake, qemu-devel; +Cc: stefanha, pbonzini, den, Daniel P. Berrange

07.07.2017 17:40, Eric Blake wrote:
> On 06/21/2017 10:34 AM, Vladimir Sementsov-Ogievskiy wrote:
>> Move to modern errp scheme from just LOGging errors.
>>
>> Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
>> ---
>>   nbd/server.c | 268 +++++++++++++++++++++++++++++++++++------------------------
>>   1 file changed, 161 insertions(+), 107 deletions(-)
>> -static coroutine_fn int nbd_negotiate(NBDClient *client)
>> +static coroutine_fn int nbd_negotiate(NBDClient *client, Error **errp)
>>   {
>>       char buf[8 + 8 + 8 + 128];
>>       int ret;
> Now that you have this,
>
>>      qio_channel_set_blocking(client->ioc, false, NULL);
>>
> you should probably pass errp through to qio_channel_set_blocking and
> return early if that fails (either here or in one of the followup
> patches) [hmm, I note that most callers of qio_channel_set_blocking()
> ignore errors - outside of NBD, so that's a separate cleanup series]

I've looked through realizations of ioc_klass->io_set_blocking - looks 
like they all are returning zero always.

>
>
>> @@ -591,21 +617,23 @@ static coroutine_fn int nbd_negotiate(NBDClient *client)
>>   
>>       if (oldStyle) {
>>           if (client->tlscreds) {
>> -            TRACE("TLS cannot be enabled with oldstyle protocol");
>> +            error_setg(errp, "TLS cannot be enabled with oldstyle protocol");
>>               return -EINVAL;
> This code is unreachable, since earlier we have:
>
>>      oldStyle = client->exp != NULL && !client->tlscreds;
> You could just as easily delete the conditional.  In fact, our code has:
>
> if (oldStyle) {
>      do stuff
> } else {
>      do stuff
> }
>
> if (oldStyle) {
>      do stuff
> } else {
>      do stuff
> }
>
> and it would be simple to merge that into a single if statement.
>

-- 
Best regards,
Vladimir

^ permalink raw reply	[flat|nested] 28+ messages in thread

end of thread, other threads:[~2017-07-07 15:10 UTC | newest]

Thread overview: 28+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2017-06-21 15:34 [Qemu-devel] [PATCH v2 0/6] nbd refactoring part 2 Vladimir Sementsov-Ogievskiy
2017-06-21 15:34 ` [Qemu-devel] [PATCH v2 1/6] nbd/server: nbd_negotiate: return 1 on NBD_OPT_ABORT Vladimir Sementsov-Ogievskiy
2017-06-29 18:46   ` Eric Blake
2017-07-06 16:07     ` Eric Blake
2017-06-21 15:34 ` [Qemu-devel] [PATCH v2 2/6] nbd/server: use errp instead of LOG Vladimir Sementsov-Ogievskiy
2017-06-29 19:27   ` Eric Blake
2017-07-05 12:33     ` Vladimir Sementsov-Ogievskiy
2017-07-05 15:21       ` Paolo Bonzini
2017-07-05 17:38     ` Markus Armbruster
2017-07-07 14:40   ` Eric Blake
2017-07-07 15:10     ` Vladimir Sementsov-Ogievskiy
2017-06-21 15:34 ` [Qemu-devel] [PATCH v2 3/6] nbd/server: add errp to nbd_send_reply() Vladimir Sementsov-Ogievskiy
2017-06-29 19:31   ` Eric Blake
2017-06-21 15:34 ` [Qemu-devel] [PATCH v2 4/6] nbd/common: nbd_tls_handshake: remove extra TRACE Vladimir Sementsov-Ogievskiy
2017-06-29 19:32   ` Eric Blake
2017-06-21 15:34 ` [Qemu-devel] [PATCH v2 5/6] nbd/client: refactor TRACE of NBD_MAGIC Vladimir Sementsov-Ogievskiy
2017-06-29 19:36   ` Eric Blake
2017-07-05 15:21     ` Paolo Bonzini
2017-06-21 15:34 ` [Qemu-devel] [PATCH v2 6/6] nbd: use generic trace subsystem instead of TRACE macro Vladimir Sementsov-Ogievskiy
2017-06-29 20:12   ` Eric Blake
2017-07-06 14:49     ` Eric Blake
2017-07-05 15:29   ` Paolo Bonzini
2017-07-06  8:45     ` Vladimir Sementsov-Ogievskiy
2017-07-06  8:57       ` Paolo Bonzini
2017-07-06 15:01   ` Eric Blake
2017-07-06 15:28   ` Eric Blake
2017-07-06 15:44   ` Eric Blake
2017-07-07 14:02     ` Vladimir Sementsov-Ogievskiy

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.