diff mbox series

[for-2.12] nbd: trace meta context negotiation

Message ID 20180330130950.1931229-1-eblake@redhat.com
State New
Headers show
Series [for-2.12] nbd: trace meta context negotiation | expand

Commit Message

Eric Blake March 30, 2018, 1:09 p.m. UTC 
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>
---
 nbd/client.c     | 2 ++
 nbd/server.c     | 8 ++++++++
 nbd/trace-events | 6 ++++++
 3 files changed, 16 insertions(+)

Comments

Vladimir Sementsov-Ogievskiy March 30, 2018, 4:32 p.m. UTC | #1 
30.03.2018 16:09, Eric Blake wrote:
> 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>
> ---
>   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 4ee1d9a4a2c..478b6085df7 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);
> @@ -681,6 +682,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 cea158913ba..9e1f2271784 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");

Hmm, reasonable example of using same trace-point in several places in 
the code. Is it a precedent?

>           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 0d03edc967d..cfdbe04b447 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, int id) "Received mapping of context %s to id %d"

actual type is uint32_t, I'd prefer to reflect it here.

>   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, int queries) "Client requested %s for export %s, with %d queries"

and here

> +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, unsigned int id) "Replying with meta context '%s' id %d"

and here

>   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)"

Must-have trace-points, anyway:
Reviewed-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
no-reply@patchew.org March 31, 2018, 8:25 a.m. UTC | #2 
Hi,

This series failed docker-mingw@fedora build test. Please find the testing commands and
their output below. If you have Docker installed, you can probably reproduce it
locally.

Type: series
Message-id: 20180330130950.1931229-1-eblake@redhat.com
Subject: [Qemu-devel] [PATCH for-2.12] nbd: trace meta context negotiation

=== TEST SCRIPT BEGIN ===
#!/bin/bash
set -e
git submodule update --init dtc
# Let docker tests dump environment info
export SHOW_ENV=1
export J=8
time make docker-test-mingw@fedora
=== TEST SCRIPT END ===

Updating 3c8cf5a9c21ff8782164d1def7f44bd888713384
Switched to a new branch 'test'
76fbc613c7 nbd: trace meta context negotiation

=== OUTPUT BEGIN ===
Submodule 'dtc' (git://git.qemu-project.org/dtc.git) registered for path 'dtc'
Cloning into '/var/tmp/patchew-tester-tmp-vx33pf_p/src/dtc'...
Submodule path 'dtc': checked out 'e54388015af1fb4bf04d0bca99caba1074d9cc42'
  BUILD   fedora
make[1]: Entering directory '/var/tmp/patchew-tester-tmp-vx33pf_p/src'
  GEN     /var/tmp/patchew-tester-tmp-vx33pf_p/src/docker-src.2018-03-31-04.24.40.31134/qemu.tar
Cloning into '/var/tmp/patchew-tester-tmp-vx33pf_p/src/docker-src.2018-03-31-04.24.40.31134/qemu.tar.vroot'...
done.
Checking out files:  29% (1778/6066)   
Checking out files:  30% (1820/6066)   
Checking out files:  31% (1881/6066)   
Checking out files:  32% (1942/6066)   
Checking out files:  33% (2002/6066)   
Checking out files:  34% (2063/6066)   
Checking out files:  35% (2124/6066)   
Checking out files:  36% (2184/6066)   
Checking out files:  37% (2245/6066)   
Checking out files:  38% (2306/6066)   
Checking out files:  39% (2366/6066)   
Checking out files:  40% (2427/6066)   
Checking out files:  41% (2488/6066)   
Checking out files:  42% (2548/6066)   
Checking out files:  43% (2609/6066)   
Checking out files:  44% (2670/6066)   
Checking out files:  45% (2730/6066)   
Checking out files:  46% (2791/6066)   
Checking out files:  46% (2793/6066)   
Checking out files:  47% (2852/6066)   
Checking out files:  48% (2912/6066)   
Checking out files:  49% (2973/6066)   
Checking out files:  50% (3033/6066)   
Checking out files:  51% (3094/6066)   
Checking out files:  52% (3155/6066)   
Checking out files:  53% (3215/6066)   
Checking out files:  54% (3276/6066)   
Checking out files:  55% (3337/6066)   
Checking out files:  56% (3397/6066)   
Checking out files:  57% (3458/6066)   
Checking out files:  58% (3519/6066)   
Checking out files:  59% (3579/6066)   
Checking out files:  60% (3640/6066)   
Checking out files:  61% (3701/6066)   
Checking out files:  62% (3761/6066)   
Checking out files:  62% (3809/6066)   
Checking out files:  63% (3822/6066)   
Checking out files:  64% (3883/6066)   
Checking out files:  65% (3943/6066)   
Checking out files:  66% (4004/6066)   
Checking out files:  67% (4065/6066)   
Checking out files:  68% (4125/6066)   
Checking out files:  69% (4186/6066)   
Checking out files:  70% (4247/6066)   
Checking out files:  71% (4307/6066)   
Checking out files:  72% (4368/6066)   
Checking out files:  73% (4429/6066)   
Checking out files:  74% (4489/6066)   
Checking out files:  75% (4550/6066)   
Checking out files:  76% (4611/6066)   
Checking out files:  77% (4671/6066)   
Checking out files:  78% (4732/6066)   
Checking out files:  79% (4793/6066)   
Checking out files:  80% (4853/6066)   
Checking out files:  81% (4914/6066)   
Checking out files:  82% (4975/6066)   
Checking out files:  83% (5035/6066)   
Checking out files:  84% (5096/6066)   
Checking out files:  85% (5157/6066)   
Checking out files:  86% (5217/6066)   
Checking out files:  87% (5278/6066)   
Checking out files:  88% (5339/6066)   
Checking out files:  89% (5399/6066)   
Checking out files:  90% (5460/6066)   
Checking out files:  91% (5521/6066)   
Checking out files:  92% (5581/6066)   
Checking out files:  93% (5642/6066)   
Checking out files:  94% (5703/6066)   
Checking out files:  94% (5720/6066)   
Checking out files:  95% (5763/6066)   
Checking out files:  96% (5824/6066)   
Checking out files:  97% (5885/6066)   
Checking out files:  98% (5945/6066)   
Checking out files:  99% (6006/6066)   
Checking out files: 100% (6066/6066)   
Checking out files: 100% (6066/6066), done.
Your branch is up-to-date with 'origin/test'.
Submodule 'dtc' (git://git.qemu-project.org/dtc.git) registered for path 'dtc'
Cloning into '/var/tmp/patchew-tester-tmp-vx33pf_p/src/docker-src.2018-03-31-04.24.40.31134/qemu.tar.vroot/dtc'...
Submodule path 'dtc': checked out 'e54388015af1fb4bf04d0bca99caba1074d9cc42'
Submodule 'ui/keycodemapdb' (git://git.qemu.org/keycodemapdb.git) registered for path 'ui/keycodemapdb'
Cloning into '/var/tmp/patchew-tester-tmp-vx33pf_p/src/docker-src.2018-03-31-04.24.40.31134/qemu.tar.vroot/ui/keycodemapdb'...
Submodule path 'ui/keycodemapdb': checked out '6b3d716e2b6472eb7189d3220552280ef3d832ce'
tar: /var/tmp/patchew-tester-tmp-vx33pf_p/src/docker-src.2018-03-31-04.24.40.31134/qemu.tar: Wrote only 2048 of 10240 bytes
tar: Error is not recoverable: exiting now
failed to create tar file
  COPY    RUNNER
    RUN test-mingw in qemu:fedora 
tar: Unexpected EOF in archive
tar: Unexpected EOF in archive
tar: Error is not recoverable: exiting now
/var/tmp/qemu/run: line 32: prep_fail: command not found
Packages installed:
PyYAML-3.12-5.fc27.x86_64
SDL-devel-1.2.15-29.fc27.x86_64
bc-1.07.1-3.fc27.x86_64
bison-3.0.4-8.fc27.x86_64
bzip2-1.0.6-24.fc27.x86_64
ccache-3.3.6-1.fc27.x86_64
clang-5.0.1-3.fc27.x86_64
findutils-4.6.0-16.fc27.x86_64
flex-2.6.1-5.fc27.x86_64
gcc-7.3.1-5.fc27.x86_64
gcc-c++-7.3.1-5.fc27.x86_64
gettext-0.19.8.1-12.fc27.x86_64
git-2.14.3-3.fc27.x86_64
glib2-devel-2.54.3-2.fc27.x86_64
hostname-3.18-4.fc27.x86_64
libaio-devel-0.3.110-9.fc27.x86_64
libasan-7.3.1-5.fc27.x86_64
libfdt-devel-1.4.6-1.fc27.x86_64
libubsan-7.3.1-5.fc27.x86_64
llvm-5.0.1-3.fc27.x86_64
make-4.2.1-4.fc27.x86_64
mingw32-SDL-1.2.15-9.fc27.noarch
mingw32-bzip2-1.0.6-9.fc27.noarch
mingw32-curl-7.54.1-2.fc27.noarch
mingw32-glib2-2.54.1-1.fc27.noarch
mingw32-gmp-6.1.2-2.fc27.noarch
mingw32-gnutls-3.5.13-2.fc27.noarch
mingw32-gtk2-2.24.31-4.fc27.noarch
mingw32-gtk3-3.22.16-1.fc27.noarch
mingw32-libjpeg-turbo-1.5.1-3.fc27.noarch
mingw32-libpng-1.6.29-2.fc27.noarch
mingw32-libssh2-1.8.0-3.fc27.noarch
mingw32-libtasn1-4.13-1.fc27.noarch
mingw32-nettle-3.3-3.fc27.noarch
mingw32-pixman-0.34.0-3.fc27.noarch
mingw32-pkg-config-0.28-9.fc27.x86_64
mingw64-SDL-1.2.15-9.fc27.noarch
mingw64-bzip2-1.0.6-9.fc27.noarch
mingw64-curl-7.54.1-2.fc27.noarch
mingw64-glib2-2.54.1-1.fc27.noarch
mingw64-gmp-6.1.2-2.fc27.noarch
mingw64-gnutls-3.5.13-2.fc27.noarch
mingw64-gtk2-2.24.31-4.fc27.noarch
mingw64-gtk3-3.22.16-1.fc27.noarch
mingw64-libjpeg-turbo-1.5.1-3.fc27.noarch
mingw64-libpng-1.6.29-2.fc27.noarch
mingw64-libssh2-1.8.0-3.fc27.noarch
mingw64-libtasn1-4.13-1.fc27.noarch
mingw64-nettle-3.3-3.fc27.noarch
mingw64-pixman-0.34.0-3.fc27.noarch
mingw64-pkg-config-0.28-9.fc27.x86_64
nettle-devel-3.4-1.fc27.x86_64
perl-5.26.1-403.fc27.x86_64
pixman-devel-0.34.0-4.fc27.x86_64
python3-3.6.2-13.fc27.x86_64
sparse-0.5.1-2.fc27.x86_64
tar-1.29-7.fc27.x86_64
which-2.21-4.fc27.x86_64
zlib-devel-1.2.11-4.fc27.x86_64

Environment variables:
TARGET_LIST=
PACKAGES=ccache gettext git tar PyYAML sparse flex bison python3 bzip2 hostname     glib2-devel pixman-devel zlib-devel SDL-devel libfdt-devel     gcc gcc-c++ llvm clang make perl which bc findutils libaio-devel     nettle-devel libasan libubsan     mingw32-pixman mingw32-glib2 mingw32-gmp mingw32-SDL mingw32-pkg-config     mingw32-gtk2 mingw32-gtk3 mingw32-gnutls mingw32-nettle mingw32-libtasn1     mingw32-libjpeg-turbo mingw32-libpng mingw32-curl mingw32-libssh2     mingw32-bzip2     mingw64-pixman mingw64-glib2 mingw64-gmp mingw64-SDL mingw64-pkg-config     mingw64-gtk2 mingw64-gtk3 mingw64-gnutls mingw64-nettle mingw64-libtasn1     mingw64-libjpeg-turbo mingw64-libpng mingw64-curl mingw64-libssh2     mingw64-bzip2
J=8
V=
HOSTNAME=ebef5a204adf
DEBUG=
SHOW_ENV=1
PWD=/
HOME=/root
CCACHE_DIR=/var/tmp/ccache
DISTTAG=f27container
QEMU_CONFIGURE_OPTS=--python=/usr/bin/python3
FGC=f27
TEST_DIR=/tmp/qemu-test
SHLVL=1
FEATURES=mingw clang pyyaml asan dtc
PATH=/usr/lib/ccache:/usr/lib64/ccache:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
MAKEFLAGS= -j8
EXTRA_CONFIGURE_OPTS=
_=/usr/bin/env

/var/tmp/qemu/run: line 52: cd: /tmp/qemu-test/src/tests/docker: No such file or directory
/var/tmp/qemu/run: line 57: /test-mingw: No such file or directory
Traceback (most recent call last):
  File "./tests/docker/docker.py", line 407, in <module>
    sys.exit(main())
  File "./tests/docker/docker.py", line 404, in main
    return args.cmdobj.run(args, argv)
  File "./tests/docker/docker.py", line 261, in run
    return Docker().run(argv, args.keep, quiet=args.quiet)
  File "./tests/docker/docker.py", line 229, in run
    quiet=quiet)
  File "./tests/docker/docker.py", line 147, in _do_check
    return subprocess.check_call(self._command + cmd, **kwargs)
  File "/usr/lib64/python2.7/subprocess.py", line 186, in check_call
    raise CalledProcessError(retcode, cmd)
subprocess.CalledProcessError: Command '['docker', 'run', '--label', 'com.qemu.instance.uuid=ffda5c0c34bc11e8a23052540069c830', '-u', '0', '--security-opt', 'seccomp=unconfined', '--rm', '--net=none', '-e', 'TARGET_LIST=', '-e', 'EXTRA_CONFIGURE_OPTS=', '-e', 'V=', '-e', 'J=8', '-e', 'DEBUG=', '-e', 'SHOW_ENV=1', '-e', 'CCACHE_DIR=/var/tmp/ccache', '-v', '/root/.cache/qemu-docker-ccache:/var/tmp/ccache:z', '-v', '/var/tmp/patchew-tester-tmp-vx33pf_p/src/docker-src.2018-03-31-04.24.40.31134:/var/tmp/qemu:z,ro', 'qemu:fedora', '/var/tmp/qemu/run', 'test-mingw']' returned non-zero exit status 127
make[1]: *** [tests/docker/Makefile.include:129: docker-run] Error 1
make[1]: Leaving directory '/var/tmp/patchew-tester-tmp-vx33pf_p/src'
make: *** [tests/docker/Makefile.include:163: docker-run-test-mingw@fedora] Error 2

real	0m31.989s
user	0m9.321s
sys	0m6.469s
=== OUTPUT END ===

Test command exited with code: 2


---
Email generated automatically by Patchew [http://patchew.org/].
Please send your feedback to patchew-devel@redhat.com
Eric Blake April 2, 2018, 2:06 p.m. UTC | #3 
On 03/30/2018 11:32 AM, Vladimir Sementsov-Ogievskiy wrote:
> 30.03.2018 16:09, Eric Blake wrote:
>> 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>
>> ---
>>   nbd/client.c     | 2 ++
>>   nbd/server.c     | 8 ++++++++
>>   nbd/trace-events | 6 ++++++
>>   3 files changed, 16 insertions(+)
>>

>> @@ -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");
> 
> Hmm, reasonable example of using same trace-point in several places in
> the code. Is it a precedent?

Yes, trace points have been reused before; as long as the parameters are
the same and the message is reasonable, the only reason to NOT share a
trace is if you ever see yourself needing to select between the two
trace points individually. But for both of these points, it seems to me
that you'd either be tracing everything nbd_* or nothing, rather than
trying to catch just one of these points.

>> +++ 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, int id) "Received mapping of
>> context %s to id %d"
> 
> actual type is uint32_t, I'd prefer to reflect it here.
> 

It doesn't make a difference on 'unsigned int' vs. 'uint32_t' in
trace-events.  We guarantee that int is 32 bits on all platforms qemu
compiles on, and "%u" is a lot less typing than "%"PRIu32.  But you are
right that id is unsigned, and printing a negative value for an id could
be confusing, so I'll at least tweak it for that.

> 
> Must-have trace-points, anyway:
> Reviewed-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>

Thanks; I'll make those trace-events tweaks, and queue in my NBD tree
for a pull request today.
diff mbox series

Patch

diff --git a/nbd/client.c b/nbd/client.c
index 4ee1d9a4a2c..478b6085df7 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);
@@ -681,6 +682,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 cea158913ba..9e1f2271784 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 0d03edc967d..cfdbe04b447 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, int id) "Received mapping of context %s to id %d"
 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, int queries) "Client requested %s for export %s, with %d 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, unsigned int id) "Replying with meta context '%s' id %d"
 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)"