nbd: trace meta context negotiation

Having a more detailed log of the interaction between client and
server is invaluable in debugging how meta context negotiation
actually works.

Signed-off-by: Eric Blake <eblake@redhat.com>
Message-Id: <20180330130950.1931229-1-eblake@redhat.com>
Reviewed-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>

3 files changed, 16 insertions, 0 deletions

diff --git a/nbd/client.c b/nbd/client.c
index dd0174b036..b9e175d1c2 100644
--- a/nbd/client.c
+++ b/nbd/client.c
@@ -623,6 +623,7 @@ static int nbd_negotiate_simple_meta_context(QIOChannel *ioc,
     char *data = g_malloc(data_len);
     char *p = data;
 
+    trace_nbd_opt_meta_request(context, export);
     stl_be_p(p, export_len);
     memcpy(p += sizeof(export_len), export, export_len);
     stl_be_p(p += export_len, 1);
@@ -680,6 +681,7 @@ static int nbd_negotiate_simple_meta_context(QIOChannel *ioc,
         }
         g_free(name);
 
+        trace_nbd_opt_meta_reply(context, received_id);
         received = true;
 
         /* receive NBD_REP_ACK */
diff --git a/nbd/server.c b/nbd/server.c
index cea158913b..9e1f227178 100644
--- a/nbd/server.c
+++ b/nbd/server.c
@@ -726,6 +726,7 @@ static int nbd_negotiate_send_meta_context(NBDClient *client,
         context_id = 0;
     }
 
+    trace_nbd_negotiate_meta_query_reply(context, context_id);
     set_be_option_rep(&opt.h, client->opt, NBD_REP_META_CONTEXT,
                       sizeof(opt) - sizeof(opt.h) + iov[1].iov_len);
     stl_be_p(&opt.context_id, context_id);
@@ -752,10 +753,12 @@ static int nbd_meta_base_query(NBDClient *client, NBDExportMetaContexts *meta,
         if (client->opt == NBD_OPT_LIST_META_CONTEXT) {
             meta->base_allocation = true;
         }
+        trace_nbd_negotiate_meta_query_parse("base:");
         return 1;
     }
 
     if (len != alen) {
+        trace_nbd_negotiate_meta_query_skip("not base:allocation");
         return nbd_opt_skip(client, len, errp);
     }
 
@@ -768,6 +771,7 @@ static int nbd_meta_base_query(NBDClient *client, NBDExportMetaContexts *meta,
         meta->base_allocation = true;
     }
 
+    trace_nbd_negotiate_meta_query_parse("base:allocation");
     return 1;
 }
 
@@ -800,6 +804,7 @@ static int nbd_negotiate_meta_query(NBDClient *client,
     /* The only supported namespace for now is 'base'. So query should start
      * with 'base:'. Otherwise, we can ignore it and skip the remainder. */
     if (len < baselen) {
+        trace_nbd_negotiate_meta_query_skip("length too short");
         return nbd_opt_skip(client, len, errp);
     }
 
@@ -809,6 +814,7 @@ static int nbd_negotiate_meta_query(NBDClient *client,
         return ret;
     }
     if (strncmp(query, "base:", baselen) != 0) {
+        trace_nbd_negotiate_meta_query_skip("not for base: namespace");
         return nbd_opt_skip(client, len, errp);
     }
 
@@ -858,6 +864,8 @@ static int nbd_negotiate_meta_queries(NBDClient *client,
         return ret;
     }
     cpu_to_be32s(&nb_queries);
+    trace_nbd_negotiate_meta_context(nbd_opt_lookup(client->opt),
+                                     meta->export_name, nb_queries);
 
     if (client->opt == NBD_OPT_LIST_META_CONTEXT && !nb_queries) {
         /* enable all known contexts */
diff --git a/nbd/trace-events b/nbd/trace-events
index 0d03edc967..dee081e775 100644
--- a/nbd/trace-events
+++ b/nbd/trace-events
@@ -10,6 +10,8 @@ nbd_receive_query_exports_start(const char *wantname) "Querying export list for
 nbd_receive_query_exports_success(const char *wantname) "Found desired export name '%s'"
 nbd_receive_starttls_new_client(void) "Setting up TLS"
 nbd_receive_starttls_tls_handshake(void) "Starting TLS handshake"
+nbd_opt_meta_request(const char *context, const char *export) "Requesting to set meta context %s for export %s"
+nbd_opt_meta_reply(const char *context, uint32_t id) "Received mapping of context %s to id %" PRIu32
 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_server_flags(uint32_t globalflags) "Global flags are 0x%" PRIx32
@@ -44,6 +46,10 @@ nbd_negotiate_handle_info_request(int request, const char *name) "Client request
 nbd_negotiate_handle_info_block_size(uint32_t minimum, uint32_t preferred, uint32_t maximum) "advertising minimum 0x%" PRIx32 ", preferred 0x%" PRIx32 ", maximum 0x%" PRIx32
 nbd_negotiate_handle_starttls(void) "Setting up TLS"
 nbd_negotiate_handle_starttls_handshake(void) "Starting TLS handshake"
+nbd_negotiate_meta_context(const char *optname, const char *export, uint32_t queries) "Client requested %s for export %s, with %" PRIu32 " queries"
+nbd_negotiate_meta_query_skip(const char *reason) "Skipping meta query: %s"
+nbd_negotiate_meta_query_parse(const char *query) "Parsed meta query '%s'"
+nbd_negotiate_meta_query_reply(const char *context, uint32_t id) "Replying with meta context '%s' id %" PRIu32
 nbd_negotiate_options_flags(uint32_t flags) "Received client flags 0x%" PRIx32
 nbd_negotiate_options_check_magic(uint64_t magic) "Checking opts magic 0x%" PRIx64
 nbd_negotiate_options_check_option(uint32_t option, const char *name) "Checking option %" PRIu32 " (%s)"