From 2b53af2523f6a3387f71372f59d3717f1f7d5fd9 Mon Sep 17 00:00:00 2001 From: Eric Blake Date: Fri, 30 Mar 2018 08:09:50 -0500 Subject: [PATCH] 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 Message-Id: <20180330130950.1931229-1-eblake@redhat.com> Reviewed-by: Vladimir Sementsov-Ogievskiy --- nbd/client.c | 2 ++ nbd/server.c | 8 ++++++++ nbd/trace-events | 6 ++++++ 3 files changed, 16 insertions(+) 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)"