Libguestfs - Dec 2019 - [PATCH nbdkit 0/7] server: Allow datapath debug messages to be suppressed.

The immediate reason for this patch is to reduce the amount of
debugging in virt-v2v with using the virt-v2v -v option (because this
implies running nbdkit in verbose mode too).  Most of the messages are
datapath ones about pread/pwrite requests, and in fact as we've added
more filters on top of nbdkit these messages have got more and more
verbose.  However they are not particularly interesting so by using
-D nbdkit.backend.datapath=0 we could suppress all these messages,
reducing the size of the log files by over 2/3rds.

Rich.

Just refactoring, no effect.
---
 server/Makefile.am   |  1 +
 server/backend.c     | 40 +------------------
 server/debug-flags.c | 95 ++++++++++++++++++++++++++++++++++++++++++++
 server/internal.h    |  4 ++
 server/main.c        | 14 +------
 5 files changed, 103 insertions(+), 51 deletions(-)

diff --git a/server/Makefile.am b/server/Makefile.am
index 24a66c8..465d5aa 100644
--- a/server/Makefile.am
+++ b/server/Makefile.am
@@ -42,6 +42,7 @@ nbdkit_SOURCES = \
 	connections.c \
 	crypto.c \
 	debug.c \
+	debug-flags.c \
 	extents.c \
 	filters.c \
 	internal.h \
diff --git a/server/backend.c b/server/backend.c
index 23a99f7..b9fe2a2 100644
--- a/server/backend.c
+++ b/server/backend.c
@@ -46,42 +46,6 @@
 
 /* Helpers for registering a new backend. */
 
-/* Set all debug flags which apply to this backend. */
-static void
-set_debug_flags (void *dl, const char *name)
-{
-  struct debug_flag *flag;
-
-  for (flag = debug_flags; flag != NULL; flag = flag->next) {
-    if (!flag->used && strcmp (name, flag->name) == 0) {
-      CLEANUP_FREE char *var = NULL;
-      int *sym;
-
-      /* Synthesize the name of the variable. */
-      if (asprintf (&var, "%s_debug_%s", name, flag->flag) ==
-1) {
-        perror ("asprintf");
-        exit (EXIT_FAILURE);
-      }
-
-      /* Find the symbol. */
-      sym = dlsym (dl, var);
-      if (sym == NULL) {
-        fprintf (stderr,
-                 "%s: -D %s.%s: %s does not contain a "
-                 "global variable called %s\n",
-                 program_name, name, flag->flag, name, var);
-        exit (EXIT_FAILURE);
-      }
-
-      /* Set the flag. */
-      *sym = flag->value;
-
-      /* Mark this flag as used. */
-      flag->used = true;
-    }
-  }
-}
-
 void
 backend_init (struct backend *b, struct backend *next, size_t index,
               const char *filename, void *dl, const char *type)
@@ -140,8 +104,8 @@ backend_load (struct backend *b, const char *name, void
(*load) (void))
 
   debug ("registered %s %s (name %s)", b->type, b->filename,
b->name);
 
-  /* Set debug flags before calling load. */
-  set_debug_flags (b->dl, name);
+  /* Apply debug flags before calling load. */
+  apply_debug_flags (b->dl, name);
 
   /* Call the on-load callback if it exists. */
   debug ("%s: load", name);
diff --git a/server/debug-flags.c b/server/debug-flags.c
new file mode 100644
index 0000000..c73e1b9
--- /dev/null
+++ b/server/debug-flags.c
@@ -0,0 +1,95 @@
+/* nbdkit
+ * Copyright (C) 2013-2019 Red Hat Inc.
+ *
+ * Redistribution and use in source and binary forms, with or without
+ * modification, are permitted provided that the following conditions are
+ * met:
+ *
+ * * Redistributions of source code must retain the above copyright
+ * notice, this list of conditions and the following disclaimer.
+ *
+ * * Redistributions in binary form must reproduce the above copyright
+ * notice, this list of conditions and the following disclaimer in the
+ * documentation and/or other materials provided with the distribution.
+ *
+ * * Neither the name of Red Hat nor the names of its contributors may be
+ * used to endorse or promote products derived from this software without
+ * specific prior written permission.
+ *
+ * THIS SOFTWARE IS PROVIDED BY RED HAT AND CONTRIBUTORS ''AS
IS'' AND
+ * ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO,
+ * THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A
+ * PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL RED HAT OR
+ * CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
+ * SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
+ * LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF
+ * USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND
+ * ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY,
+ * OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT
+ * OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
+ * SUCH DAMAGE.
+ */
+
+#include <config.h>
+
+#include <stdio.h>
+#include <stdlib.h>
+#include <string.h>
+
+#include <dlfcn.h>
+
+#include "internal.h"
+
+/* Apply all debug flags applicable to this backend. */
+void
+apply_debug_flags (void *dl, const char *name)
+{
+  struct debug_flag *flag;
+
+  for (flag = debug_flags; flag != NULL; flag = flag->next) {
+    if (!flag->used && strcmp (name, flag->name) == 0) {
+      CLEANUP_FREE char *var = NULL;
+      int *sym;
+
+      /* Synthesize the name of the variable. */
+      if (asprintf (&var, "%s_debug_%s", name, flag->flag) ==
-1) {
+        perror ("asprintf");
+        exit (EXIT_FAILURE);
+      }
+
+      /* Find the symbol. */
+      sym = dlsym (dl, var);
+      if (sym == NULL) {
+        fprintf (stderr,
+                 "%s: -D %s.%s: %s does not contain a "
+                 "global variable called %s\n",
+                 program_name, name, flag->flag, name, var);
+        exit (EXIT_FAILURE);
+      }
+
+      /* Set the flag. */
+      *sym = flag->value;
+
+      /* Mark this flag as used. */
+      flag->used = true;
+    }
+  }
+}
+
+void
+free_debug_flags (void)
+{
+  while (debug_flags != NULL) {
+    struct debug_flag *next = debug_flags->next;
+
+    if (!debug_flags->used) {
+      fprintf (stderr, "%s: warning: debug flag -D %s.%s was not
used\n",
+               program_name, debug_flags->name, debug_flags->flag);
+      exit (EXIT_FAILURE);
+    }
+    free (debug_flags->name);
+    free (debug_flags->flag);
+    free (debug_flags);
+    debug_flags = next;
+  }
+}
diff --git a/server/internal.h b/server/internal.h
index 95f24c5..c4d1344 100644
--- a/server/internal.h
+++ b/server/internal.h
@@ -287,6 +287,10 @@ extern int crypto_negotiate_tls (struct connection *conn,
       nbdkit_debug ((fs), ##__VA_ARGS__);                \
   } while (0)
 
+/* debug-flags.c */
+extern void apply_debug_flags (void *dl, const char *name);
+extern void free_debug_flags (void);
+
 /* log-*.c */
 #if !HAVE_VFPRINTF_PERCENT_M
 #include <stdio.h>
diff --git a/server/main.c b/server/main.c
index 8cc7a89..486ff35 100644
--- a/server/main.c
+++ b/server/main.c
@@ -614,19 +614,7 @@ main (int argc, char *argv[])
   }
 
   /* Check all debug flags were used, and free them. */
-  while (debug_flags != NULL) {
-    struct debug_flag *next = debug_flags->next;
-
-    if (!debug_flags->used) {
-      fprintf (stderr, "%s: debug flag -D %s.%s was not used\n",
-               program_name, debug_flags->name, debug_flags->flag);
-      exit (EXIT_FAILURE);
-    }
-    free (debug_flags->name);
-    free (debug_flags->flag);
-    free (debug_flags);
-    debug_flags = next;
-  }
+  free_debug_flags ();
 
   if (help) {
     struct backend *b;
-- 
2.23.0

Useful to print the error displayed by nbdkit in all cases, not
just when the test fails.

Also fix the error message if the test does fail (unexpected -> expected).
---
 tests/test-debug-flags.sh | 5 ++---
 1 file changed, 2 insertions(+), 3 deletions(-)

diff --git a/tests/test-debug-flags.sh b/tests/test-debug-flags.sh
index 10e916c..88f5a22 100755
--- a/tests/test-debug-flags.sh
+++ b/tests/test-debug-flags.sh
@@ -49,10 +49,9 @@ expected_failure ()
 
 check_error ()
 {
+    cat debug-flags.out
     if ! grep -sq "$1" debug-flags.out; then
-        echo "unexpected error message containing: $1"
-        echo "actual output:"
-        cat debug-flags.out
+        echo "expected error message containing: $1"
         exit 1
     fi
 }
-- 
2.23.0

This was a hard error before, but that's not very useful.  It's best
to ignore -D options that we don't understand (but we still warn about
them).
---
 server/debug-flags.c      | 16 +++++++---------
 tests/test-debug-flags.sh | 22 +++++++++++++++++-----
 2 files changed, 24 insertions(+), 14 deletions(-)

diff --git a/server/debug-flags.c b/server/debug-flags.c
index c73e1b9..53adc21 100644
--- a/server/debug-flags.c
+++ b/server/debug-flags.c
@@ -59,17 +59,17 @@ apply_debug_flags (void *dl, const char *name)
 
       /* Find the symbol. */
       sym = dlsym (dl, var);
-      if (sym == NULL) {
+      if (sym) {
+        /* Set the flag. */
+        *sym = flag->value;
+      }
+      else {
         fprintf (stderr,
-                 "%s: -D %s.%s: %s does not contain a "
+                 "%s: warning: -D %s.%s: %s does not contain a "
                  "global variable called %s\n",
                  program_name, name, flag->flag, name, var);
-        exit (EXIT_FAILURE);
       }
 
-      /* Set the flag. */
-      *sym = flag->value;
-
       /* Mark this flag as used. */
       flag->used = true;
     }
@@ -82,11 +82,9 @@ free_debug_flags (void)
   while (debug_flags != NULL) {
     struct debug_flag *next = debug_flags->next;
 
-    if (!debug_flags->used) {
+    if (!debug_flags->used)
       fprintf (stderr, "%s: warning: debug flag -D %s.%s was not
used\n",
                program_name, debug_flags->name, debug_flags->flag);
-      exit (EXIT_FAILURE);
-    }
     free (debug_flags->name);
     free (debug_flags->flag);
     free (debug_flags);
diff --git a/tests/test-debug-flags.sh b/tests/test-debug-flags.sh
index 88f5a22..9dc0a94 100755
--- a/tests/test-debug-flags.sh
+++ b/tests/test-debug-flags.sh
@@ -56,19 +56,31 @@ check_error ()
     fi
 }
 
+check_warning ()
+{
+    cat debug-flags.out
+    if ! grep -sq "warning.*$1" debug-flags.out; then
+        echo "expected warning message containing: $1"
+        exit 1
+    fi
+}
+
 # This is expected to fail because we didn't set the file= parameter,
 # but it should not fail because of the debug flag.
 nbdkit -f -D example2.extra=1 example2 2>debug-flags.out &&
expected_failure
 check_error "you must supply the file="
 
-# This should fail because the -D flag refers to an unknown global in
-# a known plugin.
+# This should fail because we didn't set the file= parameter, but it
+# should also print a warning about the unknown -D flag.
 nbdkit -f -D example2.unknown=1 example2 2>debug-flags.out &&
expected_failure
-check_error "does not contain a global variable called
example2_debug_unknown"
+check_error "you must supply the file="
+check_warning "does not contain a global variable called
example2_debug_unknown"
 
-# This should fail because the -D flag is unused.
+# This should fail because we didn't set the file= parameter, but it
+# should also print a warning because the -D flag is unused.
 nbdkit -f -D example1.foo=1 example2 2>debug-flags.out &&
expected_failure
-check_error "was not used"
+check_error "you must supply the file="
+check_warning "was not used"
 
 # These should fail because the -D flag has a bad format.
 nbdkit -f -D = example2 2>debug-flags.out && expected_failure
-- 
2.23.0

These work like plugin/filter debug flags, but apply to the internals
of the server.
---
 docs/nbdkit.pod    | 7 +++++++
 docs/synopsis.txt  | 2 +-
 server/main.c      | 3 +++
 server/nbdkit.syms | 2 ++
 4 files changed, 13 insertions(+), 1 deletion(-)

diff --git a/docs/nbdkit.pod b/docs/nbdkit.pod
index 656f330..1bacb1d 100644
--- a/docs/nbdkit.pod
+++ b/docs/nbdkit.pod
@@ -177,6 +177,13 @@ Display brief command line usage information and exit.
 Set the plugin or filter Debug Flag called C<FLAG> to the integer
 value C<N>.  See L<nbdkit-plugin(3)/Debug Flags>.
 
+=item B<-D> nbdkit.FLAG=N
+
+=item B<--debug> nbdkit.FLAG=N
+
+Set the nbdkit server Debug Flag called C<FLAG> to the integer value
+C<N>.
+
 =item B<--dump-config>
 
 Dump out the compile-time configuration values and exit.
diff --git a/docs/synopsis.txt b/docs/synopsis.txt
index 2a4adca..07b9dcf 100644
--- a/docs/synopsis.txt
+++ b/docs/synopsis.txt
@@ -1,4 +1,4 @@
-nbdkit [-D|--debug PLUGIN|FILTER.FLAG=N]
+nbdkit [-D|--debug PLUGIN|FILTER|nbdkit.FLAG=N]
        [-e|--exportname EXPORTNAME] [--exit-with-parent]
        [--filter FILTER ...] [-f|--foreground]
        [-g|--group GROUP] [-i|--ipaddr IPADDR]
diff --git a/server/main.c b/server/main.c
index 486ff35..ebac3ef 100644
--- a/server/main.c
+++ b/server/main.c
@@ -613,6 +613,9 @@ main (int argc, char *argv[])
     free (t);
   }
 
+  /* Apply nbdkit.* flags for the server. */
+  apply_debug_flags (NULL, "nbdkit");
+
   /* Check all debug flags were used, and free them. */
   free_debug_flags ();
 
diff --git a/server/nbdkit.syms b/server/nbdkit.syms
index 390972e..96c22c0 100644
--- a/server/nbdkit.syms
+++ b/server/nbdkit.syms
@@ -67,6 +67,8 @@
     nbdkit_vdebug;
     nbdkit_verror;
 
+    nbdkit_debug_*;
+
   # Everything else is hidden.
   local: *;
 };
-- 
2.23.0

Neutral refactoring.
---
 server/debug-flags.c | 24 +++++++++++++++++-------
 1 file changed, 17 insertions(+), 7 deletions(-)

diff --git a/server/debug-flags.c b/server/debug-flags.c
index 53adc21..497c2b4 100644
--- a/server/debug-flags.c
+++ b/server/debug-flags.c
@@ -40,6 +40,22 @@
 
 #include "internal.h"
 
+/* Synthesize the name of the *_debug_* variable from the plugin name
+ * and flag.
+ */
+static char *
+name_of_debug_flag (const char *name, const char *flag)
+{
+  char *var;
+
+  if (asprintf (&var, "%s_debug_%s", name, flag) == -1) {
+    perror ("asprintf");
+    exit (EXIT_FAILURE);
+  }
+
+  return var;                   /* caller frees */
+}
+
 /* Apply all debug flags applicable to this backend. */
 void
 apply_debug_flags (void *dl, const char *name)
@@ -48,14 +64,8 @@ apply_debug_flags (void *dl, const char *name)
 
   for (flag = debug_flags; flag != NULL; flag = flag->next) {
     if (!flag->used && strcmp (name, flag->name) == 0) {
-      CLEANUP_FREE char *var = NULL;
       int *sym;
-
-      /* Synthesize the name of the variable. */
-      if (asprintf (&var, "%s_debug_%s", name, flag->flag) ==
-1) {
-        perror ("asprintf");
-        exit (EXIT_FAILURE);
-      }
+      CLEANUP_FREE char *var = name_of_debug_flag (name, flag->flag);
 
       /* Find the symbol. */
       sym = dlsym (dl, var);
-- 
2.23.0

This is just a convenience.  Either of:

 -D myplugin.foo_bar=1
 -D myplugin.foo.bar=1

correspond to the same plugin variable "myplugin_debug_foo_bar".
---
 docs/nbdkit-plugin.pod |  8 ++++++++
 server/debug-flags.c   | 10 +++++++++-
 2 files changed, 17 insertions(+), 1 deletion(-)

diff --git a/docs/nbdkit-plugin.pod b/docs/nbdkit-plugin.pod
index e37fea0..0873cf6 100644
--- a/docs/nbdkit-plugin.pod
+++ b/docs/nbdkit-plugin.pod
@@ -1329,6 +1329,14 @@ You should only use this feature for debug settings.  For
general
 settings use ordinary plugin parameters.  Debug Flags can only be C
 ints.  They are not supported by non-C language plugins.
 
+For convenience C<'.'> characters are replaced with
C<'_'> characters
+in the variable name, so both of these parameters:
+
+ -D myplugin.foo_bar=1
+ -D myplugin.foo.bar=1
+
+correspond to the plugin variable C<myplugin_debug_foo_bar>.
+
 =head1 INSTALLING THE PLUGIN
 
 The plugin is a C<*.so> file and possibly a manual page.  You can of
diff --git a/server/debug-flags.c b/server/debug-flags.c
index 497c2b4..d878e96 100644
--- a/server/debug-flags.c
+++ b/server/debug-flags.c
@@ -47,12 +47,20 @@ static char *
 name_of_debug_flag (const char *name, const char *flag)
 {
   char *var;
+  size_t i;
+  int len;
 
-  if (asprintf (&var, "%s_debug_%s", name, flag) == -1) {
+  if ((len = asprintf (&var, "%s_debug_%s", name, flag)) == -1) {
     perror ("asprintf");
     exit (EXIT_FAILURE);
   }
 
+  /* If there are any '.'s remaining in the name, convert them to
'_'. */
+  for (i = 0; i < (size_t) len; ++i) {
+    if (var[i] == '.')
+      var[i] = '_';
+  }
+
   return var;                   /* caller frees */
 }
 
-- 
2.23.0

These can be used to suppress verbose debugging messages from the
backend.
---
 docs/nbdkit.pod                    | 35 ++++++++++++-
 server/backend.c                   | 83 ++++++++++++++++++------------
 tests/Makefile.am                  |  4 ++
 tests/test-nbdkit-backend-debug.sh | 81 +++++++++++++++++++++++++++++
 4 files changed, 169 insertions(+), 34 deletions(-)

diff --git a/docs/nbdkit.pod b/docs/nbdkit.pod
index 1bacb1d..19a2fd7 100644
--- a/docs/nbdkit.pod
+++ b/docs/nbdkit.pod
@@ -182,7 +182,7 @@ value C<N>.  See L<nbdkit-plugin(3)/Debug
Flags>.
 =item B<--debug> nbdkit.FLAG=N
 
 Set the nbdkit server Debug Flag called C<FLAG> to the integer value
-C<N>.
+C<N>.  See L</SERVER DEBUG FLAGS> below.
 
 =item B<--dump-config>
 
@@ -536,6 +536,39 @@ languages.  The file should be executable.  For example:
 
 (see L<nbdkit-perl-plugin(3)> for a full example).
 
+=head1 SERVER DEBUG FLAGS
+
+As well as enabling or disabling debugging in the server using
+I<--verbose> you can control extra debugging in the server using the
+C<-D nbdkit.*> flags listed in this section.  Note these flags are an
+internal implementation detail of the server and may be changed or
+removed at any time in the future.
+
+=over 4
+
+=item B<-D nbdkit.backend.controlpath=0>
+
+=item B<-D nbdkit.backend.controlpath=1>
+
+=item B<-D nbdkit.backend.datapath=0>
+
+=item B<-D nbdkit.backend.datapath=1>
+
+These flags control the verbosity of nbdkit backend debugging messages
+(the ones which show every request processed by the server).  The
+default for both settings is C<1> (normal debugging) but you can set
+them to C<0> to suppress these messages.
+
+C<-D nbdkit.backend.datapath=0> is the more useful setting which lets you
+suppress messages about pread, pwrite, zero, trim, etc. commands.
+When transferring large amounts of data these messages are numerous
+and not usually very interesting.
+
+C<-D nbdkit.backend.controlpath=0> suppresses the non-datapath
+commands (config, open, close, can_write, etc.)
+
+=back
+
 =head1 SIGNALS
 
 nbdkit responds to the following signals:
diff --git a/server/backend.c b/server/backend.c
index b9fe2a2..208c07b 100644
--- a/server/backend.c
+++ b/server/backend.c
@@ -46,6 +46,22 @@
 
 /* Helpers for registering a new backend. */
 
+/* Use:
+ * -D nbdkit.backend.controlpath=0 to suppress control path debugging.
+ * -D nbdkit.backend.datapath=0 to suppress data path debugging.
+ */
+int nbdkit_debug_backend_controlpath = 1;
+int nbdkit_debug_backend_datapath = 1;
+
+#define controlpath_debug(fs, ...)                                     \
+  do {                                                                 \
+    if (nbdkit_debug_backend_controlpath) debug ((fs), ##__VA_ARGS__); \
+  } while (0)
+#define datapath_debug(fs, ...)                                        \
+  do {                                                                 \
+    if (nbdkit_debug_backend_datapath) debug ((fs), ##__VA_ARGS__);    \
+  } while (0)
+
 void
 backend_init (struct backend *b, struct backend *next, size_t index,
               const char *filename, void *dl, const char *type)
@@ -108,7 +124,7 @@ backend_load (struct backend *b, const char *name, void
(*load) (void))
   apply_debug_flags (b->dl, name);
 
   /* Call the on-load callback if it exists. */
-  debug ("%s: load", name);
+  controlpath_debug ("%s: load", name);
   if (load)
     load ();
 }
@@ -121,7 +137,7 @@ backend_unload (struct backend *b, void (*unload) (void))
    */
   lock_unload ();
 
-  debug ("%s: unload %s", b->name, b->type);
+  controlpath_debug ("%s: unload %s", b->name, b->type);
   if (unload)
     unload ();
 
@@ -139,7 +155,7 @@ backend_open (struct backend *b, struct connection *conn,
int readonly)
 {
   struct b_conn_handle *h = &conn->handles[b->i];
 
-  debug ("%s: open readonly=%d", b->name, readonly);
+  controlpath_debug ("%s: open readonly=%d", b->name, readonly);
 
   assert (h->handle == NULL);
   assert ((h->state & HANDLE_OPEN) == 0);
@@ -151,7 +167,7 @@ backend_open (struct backend *b, struct connection *conn,
int readonly)
    * inner-to-outer ordering.
    */
   h->handle = b->open (b, conn, readonly);
-  debug ("%s: open returned handle %p", b->name, h->handle);
+  controlpath_debug ("%s: open returned handle %p", b->name,
h->handle);
 
   if (h->handle == NULL) {
     if (b->i) /* Do not strand backend if this layer failed */
@@ -179,7 +195,7 @@ backend_prepare (struct backend *b, struct connection *conn)
   if (b->i && backend_prepare (b->next, conn) == -1)
     return -1;
 
-  debug ("%s: prepare readonly=%d", b->name, h->can_write ==
0);
+  controlpath_debug ("%s: prepare readonly=%d", b->name,
h->can_write == 0);
 
   if (b->prepare (b, conn, h->handle, h->can_write == 0) == -1)
     return -1;
@@ -196,7 +212,7 @@ backend_finalize (struct backend *b, struct connection
*conn)
    * filter furthest away from the plugin, and matching .close order.
    */
 
-  debug ("%s: finalize", b->name);
+  controlpath_debug ("%s: finalize", b->name);
 
   /* Once finalize fails, we can do nothing further on this connection */
   if (h->state & HANDLE_FAILED)
@@ -223,7 +239,7 @@ backend_close (struct backend *b, struct connection *conn)
   struct b_conn_handle *h = &conn->handles[b->i];
 
   /* outer-to-inner order, opposite .open */
-  debug ("%s: close", b->name);
+  controlpath_debug ("%s: close", b->name);
 
   if (h->handle) {
     assert (h->state & HANDLE_OPEN);
@@ -252,7 +268,7 @@ backend_valid_range (struct backend *b, struct connection
*conn,
 int
 backend_reopen (struct backend *b, struct connection *conn, int readonly)
 {
-  debug ("%s: reopen readonly=%d", b->name, readonly);
+  controlpath_debug ("%s: reopen readonly=%d", b->name, readonly);
 
   if (backend_finalize (b, conn) == -1)
     return -1;
@@ -274,7 +290,7 @@ backend_get_size (struct backend *b, struct connection
*conn)
 {
   struct b_conn_handle *h = &conn->handles[b->i];
 
-  debug ("%s: get_size", b->name);
+  controlpath_debug ("%s: get_size", b->name);
 
   assert (h->handle && (h->state & HANDLE_CONNECTED));
   if (h->exportsize == -1)
@@ -287,7 +303,7 @@ backend_can_write (struct backend *b, struct connection
*conn)
 {
   struct b_conn_handle *h = &conn->handles[b->i];
 
-  debug ("%s: can_write", b->name);
+  controlpath_debug ("%s: can_write", b->name);
 
   assert (h->handle && (h->state & HANDLE_CONNECTED));
   if (h->can_write == -1)
@@ -300,7 +316,7 @@ backend_can_flush (struct backend *b, struct connection
*conn)
 {
   struct b_conn_handle *h = &conn->handles[b->i];
 
-  debug ("%s: can_flush", b->name);
+  controlpath_debug ("%s: can_flush", b->name);
 
   assert (h->handle && (h->state & HANDLE_CONNECTED));
   if (h->can_flush == -1)
@@ -313,7 +329,7 @@ backend_is_rotational (struct backend *b, struct connection
*conn)
 {
   struct b_conn_handle *h = &conn->handles[b->i];
 
-  debug ("%s: is_rotational", b->name);
+  controlpath_debug ("%s: is_rotational", b->name);
 
   assert (h->handle && (h->state & HANDLE_CONNECTED));
   if (h->is_rotational == -1)
@@ -327,7 +343,7 @@ backend_can_trim (struct backend *b, struct connection
*conn)
   struct b_conn_handle *h = &conn->handles[b->i];
   int r;
 
-  debug ("%s: can_trim", b->name);
+  controlpath_debug ("%s: can_trim", b->name);
 
   assert (h->handle && (h->state & HANDLE_CONNECTED));
   if (h->can_trim == -1) {
@@ -347,7 +363,7 @@ backend_can_zero (struct backend *b, struct connection
*conn)
   struct b_conn_handle *h = &conn->handles[b->i];
   int r;
 
-  debug ("%s: can_zero", b->name);
+  controlpath_debug ("%s: can_zero", b->name);
 
   assert (h->handle && (h->state & HANDLE_CONNECTED));
   if (h->can_zero == -1) {
@@ -367,7 +383,7 @@ backend_can_fast_zero (struct backend *b, struct connection
*conn)
   struct b_conn_handle *h = &conn->handles[b->i];
   int r;
 
-  debug ("%s: can_fast_zero", b->name);
+  controlpath_debug ("%s: can_fast_zero", b->name);
 
   assert (h->handle && (h->state & HANDLE_CONNECTED));
   if (h->can_fast_zero == -1) {
@@ -386,7 +402,7 @@ backend_can_extents (struct backend *b, struct connection
*conn)
 {
   struct b_conn_handle *h = &conn->handles[b->i];
 
-  debug ("%s: can_extents", b->name);
+  controlpath_debug ("%s: can_extents", b->name);
 
   assert (h->handle && (h->state & HANDLE_CONNECTED));
   if (h->can_extents == -1)
@@ -400,7 +416,7 @@ backend_can_fua (struct backend *b, struct connection *conn)
   struct b_conn_handle *h = &conn->handles[b->i];
   int r;
 
-  debug ("%s: can_fua", b->name);
+  controlpath_debug ("%s: can_fua", b->name);
 
   assert (h->handle && (h->state & HANDLE_CONNECTED));
   if (h->can_fua == -1) {
@@ -420,7 +436,7 @@ backend_can_multi_conn (struct backend *b, struct connection
*conn)
   struct b_conn_handle *h = &conn->handles[b->i];
 
   assert (h->handle && (h->state & HANDLE_CONNECTED));
-  debug ("%s: can_multi_conn", b->name);
+  controlpath_debug ("%s: can_multi_conn", b->name);
 
   if (h->can_multi_conn == -1)
     h->can_multi_conn = b->can_multi_conn (b, conn, h->handle);
@@ -432,7 +448,7 @@ backend_can_cache (struct backend *b, struct connection
*conn)
 {
   struct b_conn_handle *h = &conn->handles[b->i];
 
-  debug ("%s: can_cache", b->name);
+  controlpath_debug ("%s: can_cache", b->name);
 
   assert (h->handle && (h->state & HANDLE_CONNECTED));
   if (h->can_cache == -1)
@@ -451,8 +467,8 @@ backend_pread (struct backend *b, struct connection *conn,
   assert (h->handle && (h->state & HANDLE_CONNECTED));
   assert (backend_valid_range (b, conn, offset, count));
   assert (flags == 0);
-  debug ("%s: pread count=%" PRIu32 " offset=%" PRIu64,
-         b->name, count, offset);
+  datapath_debug ("%s: pread count=%" PRIu32 " offset=%"
PRIu64,
+                  b->name, count, offset);
 
   r = b->pread (b, conn, h->handle, buf, count, offset, flags, err);
   if (r == -1)
@@ -475,8 +491,8 @@ backend_pwrite (struct backend *b, struct connection *conn,
   assert (!(flags & ~NBDKIT_FLAG_FUA));
   if (fua)
     assert (h->can_fua > NBDKIT_FUA_NONE);
-  debug ("%s: pwrite count=%" PRIu32 " offset=%" PRIu64
" fua=%d",
-         b->name, count, offset, fua);
+  datapath_debug ("%s: pwrite count=%" PRIu32 " offset=%"
PRIu64 " fua=%d",
+                  b->name, count, offset, fua);
 
   r = b->pwrite (b, conn, h->handle, buf, count, offset, flags, err);
   if (r == -1)
@@ -494,7 +510,7 @@ backend_flush (struct backend *b, struct connection *conn,
   assert (h->handle && (h->state & HANDLE_CONNECTED));
   assert (h->can_flush == 1);
   assert (flags == 0);
-  debug ("%s: flush", b->name);
+  datapath_debug ("%s: flush", b->name);
 
   r = b->flush (b, conn, h->handle, flags, err);
   if (r == -1)
@@ -518,8 +534,8 @@ backend_trim (struct backend *b, struct connection *conn,
   assert (!(flags & ~NBDKIT_FLAG_FUA));
   if (fua)
     assert (h->can_fua > NBDKIT_FUA_NONE);
-  debug ("%s: trim count=%" PRIu32 " offset=%" PRIu64
" fua=%d",
-         b->name, count, offset, fua);
+  datapath_debug ("%s: trim count=%" PRIu32 " offset=%"
PRIu64 " fua=%d",
+                  b->name, count, offset, fua);
 
   r = b->trim (b, conn, h->handle, count, offset, flags, err);
   if (r == -1)
@@ -547,9 +563,10 @@ backend_zero (struct backend *b, struct connection *conn,
     assert (h->can_fua > NBDKIT_FUA_NONE);
   if (fast)
     assert (h->can_fast_zero == 1);
-  debug ("%s: zero count=%" PRIu32 " offset=%" PRIu64
-         " may_trim=%d fua=%d fast=%d",
-         b->name, count, offset, !!(flags & NBDKIT_FLAG_MAY_TRIM), fua,
fast);
+  datapath_debug ("%s: zero count=%" PRIu32 " offset=%"
PRIu64
+                  " may_trim=%d fua=%d fast=%d",
+                  b->name, count, offset,
+                  !!(flags & NBDKIT_FLAG_MAY_TRIM), fua, fast);
 
   r = b->zero (b, conn, h->handle, count, offset, flags, err);
   if (r == -1) {
@@ -572,8 +589,8 @@ backend_extents (struct backend *b, struct connection *conn,
   assert (h->can_extents >= 0);
   assert (backend_valid_range (b, conn, offset, count));
   assert (!(flags & ~NBDKIT_FLAG_REQ_ONE));
-  debug ("%s: extents count=%" PRIu32 " offset=%" PRIu64
" req_one=%d",
-         b->name, count, offset, !!(flags & NBDKIT_FLAG_REQ_ONE));
+  datapath_debug ("%s: extents count=%" PRIu32 " offset=%"
PRIu64 " req_one=%d",
+                  b->name, count, offset, !!(flags &
NBDKIT_FLAG_REQ_ONE));
 
   if (h->can_extents == 0) {
     /* By default it is safe assume that everything in the range is
@@ -602,8 +619,8 @@ backend_cache (struct backend *b, struct connection *conn,
   assert (h->can_cache > NBDKIT_CACHE_NONE);
   assert (backend_valid_range (b, conn, offset, count));
   assert (flags == 0);
-  debug ("%s: cache count=%" PRIu32 " offset=%" PRIu64,
-         b->name, count, offset);
+  datapath_debug ("%s: cache count=%" PRIu32 " offset=%"
PRIu64,
+                  b->name, count, offset);
 
   if (h->can_cache == NBDKIT_CACHE_EMULATE) {
     static char buf[MAX_REQUEST_SIZE]; /* data sink, never read */
diff --git a/tests/Makefile.am b/tests/Makefile.am
index 7a68da4..552cb5a 100644
--- a/tests/Makefile.am
+++ b/tests/Makefile.am
@@ -138,6 +138,7 @@ EXTRA_DIST = \
 	test-nbd-extents.sh \
 	test-nbd-tls.sh \
 	test-nbd-tls-psk.sh \
+	test-nbdkit-backend-debug.sh \
 	test-nozero.sh \
 	test-null-extents.sh \
 	test_ocaml_plugin.ml \
@@ -749,6 +750,9 @@ endif HAVE_VDDK
 # zero plugin test.
 TESTS += test-zero.sh
 
+# -D nbdkit.backend.* settings.
+TESTS += test-nbdkit-backend-debug.sh
+
 #----------------------------------------------------------------------
 # Tests of language plugins.
 
diff --git a/tests/test-nbdkit-backend-debug.sh
b/tests/test-nbdkit-backend-debug.sh
new file mode 100755
index 0000000..4dcc4ab
--- /dev/null
+++ b/tests/test-nbdkit-backend-debug.sh
@@ -0,0 +1,81 @@
+#!/usr/bin/env bash
+# nbdkit
+# Copyright (C) 2019 Red Hat Inc.
+#
+# Redistribution and use in source and binary forms, with or without
+# modification, are permitted provided that the following conditions are
+# met:
+#
+# * Redistributions of source code must retain the above copyright
+# notice, this list of conditions and the following disclaimer.
+#
+# * Redistributions in binary form must reproduce the above copyright
+# notice, this list of conditions and the following disclaimer in the
+# documentation and/or other materials provided with the distribution.
+#
+# * Neither the name of Red Hat nor the names of its contributors may be
+# used to endorse or promote products derived from this software without
+# specific prior written permission.
+#
+# THIS SOFTWARE IS PROVIDED BY RED HAT AND CONTRIBUTORS ''AS
IS'' AND
+# ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO,
+# THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A
+# PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL RED HAT OR
+# CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
+# SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
+# LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF
+# USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND
+# ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY,
+# OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT
+# OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
+# SUCH DAMAGE.
+
+source ./functions.sh
+set -x
+set -e
+
+requires qemu-img --version
+
+out="test-nbdkit-backend-debug.out"
+debug="test-nbdkit-backend-debug.debug"
+files="$out $debug"
+rm -f $files
+cleanup_fn rm -f $files
+
+# The error filter does nothing, it's only there to test that debug
+# messages from filters can also be suppressed.
+nbdkit -U - \
+       -v \
+       --filter=error \
+       memory 10M \
+       --run "qemu-img convert \$nbd $out" |& tee $debug
+
+# Should contain all debugging messages.
+grep '^nbdkit:.*debug: error: open' $debug
+grep '^nbdkit:.*debug: memory: open' $debug
+grep '^nbdkit:.*debug: error: pread' $debug
+grep '^nbdkit:.*debug: memory: pread' $debug
+
+nbdkit -U - \
+       -v -D nbdkit.backend.controlpath=0 \
+       --filter=error \
+       memory 10M \
+       --run "qemu-img convert \$nbd $out" |& tee $debug
+
+# Should contain only datapath messages.
+grep -v '^nbdkit:.*debug: error: open' $debug
+grep -v '^nbdkit:.*debug: memory: open' $debug
+grep '^nbdkit:.*debug: error: pread' $debug
+grep '^nbdkit:.*debug: memory: pread' $debug
+
+nbdkit -U - \
+       -v -D nbdkit.backend.datapath=0 \
+       --filter=error \
+       memory 10M \
+       --run "qemu-img convert \$nbd $out" |& tee $debug
+
+# Should contain only controlpath messages.
+grep '^nbdkit:.*debug: error: open' $debug
+grep '^nbdkit:.*debug: memory: open' $debug
+grep -v '^nbdkit:.*debug: error: pread' $debug
+grep -v '^nbdkit:.*debug: memory: pread' $debug
-- 
2.23.0

On 12/12/19 6:02 AM, Richard W.M. Jones wrote:
> Useful to print the error displayed by nbdkit in all cases, not
> just when the test fails.
> 
> Also fix the error message if the test does fail (unexpected ->
expected).
> ---
>   tests/test-debug-flags.sh | 5 ++---
>   1 file changed, 2 insertions(+), 3 deletions(-)
> 
> diff --git a/tests/test-debug-flags.sh b/tests/test-debug-flags.sh
> index 10e916c..88f5a22 100755
> --- a/tests/test-debug-flags.sh
> +++ b/tests/test-debug-flags.sh
> @@ -49,10 +49,9 @@ expected_failure ()
>   
>   check_error ()
>   {
> +    cat debug-flags.out
>       if ! grep -sq "$1" debug-flags.out; then
> -        echo "unexpected error message containing: $1"
> -        echo "actual output:"
> -        cat debug-flags.out
> +        echo "expected error message containing: $1"
Bike-shedding: my first read was more along the lines of "I've output 
the file, and found the expected error message that contains $1" when 
the point was that the expected error message was not present.

Maybe it reads better as one of:
"expected an error message that contains: $1"
"unexpected error message, expecting: $1"

But the sense change makes sense, as does the unconditional output of 
the file.

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

On 12/12/19 6:02 AM, Richard W.M. Jones wrote:
> These work like plugin/filter debug flags, but apply to the internals
> of the server.
> ---
>   docs/nbdkit.pod    | 7 +++++++
>   docs/synopsis.txt  | 2 +-
>   server/main.c      | 3 +++
>   server/nbdkit.syms | 2 ++
>   4 files changed, 13 insertions(+), 1 deletion(-)
Nice. The overall series makes sense to me.

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