tests/test-layers.c

   1 /* nbdkit
   2  * Copyright (C) 2018-2021 Red Hat Inc.
   3  *
   4  * Redistribution and use in source and binary forms, with or without
   5  * modification, are permitted provided that the following conditions are
   6  * met:
   7  *
   8  * * Redistributions of source code must retain the above copyright
   9  * notice, this list of conditions and the following disclaimer.
  10  *
  11  * * Redistributions in binary form must reproduce the above copyright
  12  * notice, this list of conditions and the following disclaimer in the
  13  * documentation and/or other materials provided with the distribution.
  14  *
  15  * * Neither the name of Red Hat nor the names of its contributors may be
  16  * used to endorse or promote products derived from this software without
  17  * specific prior written permission.
  18  *
  19  * THIS SOFTWARE IS PROVIDED BY RED HAT AND CONTRIBUTORS ''AS IS'' AND
  20  * ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO,
  21  * THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A
  22  * PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL RED HAT OR
  23  * CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
  24  * SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
  25  * LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF
  26  * USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND
  27  * ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY,
  28  * OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT
  29  * OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
  30  * SUCH DAMAGE.
  31  */
  32
  33 /* This test constructs a plugin and 3 layers of filters:
  34  *
  35  *     NBD     ┌─────────┐    ┌─────────┐    ┌─────────┐    ┌────────┐
  36  *  client ───▶│ filter3 │───▶│ filter2 │───▶│ filter1 │───▶│ plugin │
  37  * request     └─────────┘    └─────────┘    └─────────┘    └────────┘
  38  *
  39  * We then run every possible request and ensure that each method in
  40  * each filter and the plugin is called in the right order.
  41  */
  42
  43 #include <config.h>
  44
  45 #include <stdio.h>
  46 #include <stdlib.h>
  47 #include <stdarg.h>
  48 #include <stdint.h>
  49 #include <inttypes.h>
  50 #include <string.h>
  51 #include <unistd.h>
  52 #include <errno.h>
  53 #include <sys/types.h>
  54 #include <fcntl.h>
  55
  56 #include <pthread.h>
  57
  58 #include <libnbd.h>
  59
  60 #include "byte-swapping.h"
  61 #include "cleanup.h"
  62
  63 /* Declare program_name. */
  64 #if HAVE_DECL_PROGRAM_INVOCATION_SHORT_NAME == 1
  65 #include <errno.h>
  66 #define program_name program_invocation_short_name
  67 #else
  68 #define program_name "nbdkit"
  69 #endif
  70
  71 #ifndef WIN32
  72
  73 static void *start_log_capture (void *);
  74 static void log_verify_seen (const char *msg);
  75 static void log_verify_seen_in_order (const char *msg, ...)
  76   __attribute__((sentinel));
  77 static void log_free (void);
  78 static void short_sleep (void);
  79
  80 static int extent (void *opaque, const char *context, uint64_t offset,
  81                    uint32_t *entries, size_t nr_entries, int *error)
  82 {
  83   return 0;
  84 }
  85
  86 #if LIBNBD_HAVE_NBD_SET_OPT_MODE
  87 static int export (void *opaque, const char *name, const char *desc)
  88 {
  89   return 0;
  90 }
  91 #endif
  92
  93 int
  94 main (int argc, char *argv[])
  95 {
  96   struct nbd_handle *nbd;
  97   int pfd[2];
  98   int r;
  99   int err;
 100   pthread_t thread;
 101   int orig_stderr;
 102   char data[512];
 103
 104   if (system ("nbdkit --exit-with-parent --version") != 0) {
 105     printf ("%s: this test requires --exit-with-parent functionality\n",
 106             program_name);
 107     exit (77);
 108   }
 109
 110   /* Prepare libnbd. */
 111   fprintf (stderr, "%s: beginning test\n", program_name);
 112   nbd = nbd_create ();
 113   if (nbd == NULL) {
 114     fprintf (stderr, "nbd_create: %s\n", nbd_get_error ());
 115     exit (EXIT_FAILURE);
 116   }
 117   if (nbd_add_meta_context (nbd, LIBNBD_CONTEXT_BASE_ALLOCATION) == -1) {
 118     fprintf (stderr, "nbd_add_meta_context: %s\n", nbd_get_error ());
 119     exit (EXIT_FAILURE);
 120   }
 121 #if LIBNBD_HAVE_NBD_SET_OPT_MODE
 122   if (nbd_set_opt_mode (nbd, true) == -1) {
 123     fprintf (stderr, "nbd_set_opt_mode: %s\n", nbd_get_error ());
 124     exit (EXIT_FAILURE);
 125   }
 126 #endif
 127
 128   /* Start a thread which will just listen on the pipe and
 129    * place the log messages in a memory buffer.
 130    */
 131 #ifdef HAVE_PIPE2
 132   r = pipe2 (pfd, O_CLOEXEC);
 133 #else
 134   /* Just ignore the O_CLOEXEC requirement, it's only a test. */
 135   r = pipe (pfd);
 136 #endif
 137   if (r == -1) {
 138     perror ("pipe2");
 139     exit (EXIT_FAILURE);
 140   }
 141   err = pthread_create (&thread, NULL, start_log_capture, &pfd[0]);
 142   if (err) {
 143     errno = err;
 144     perror ("pthread_create");
 145     exit (EXIT_FAILURE);
 146   }
 147   err = pthread_detach (thread);
 148   if (err) {
 149     errno = err;
 150     perror ("pthread_detach");
 151     exit (EXIT_FAILURE);
 152   }
 153
 154   /* Shuffle stderr. Until we restore it later, avoid direct use of stderr.  */
 155   orig_stderr = fcntl (STDERR_FILENO, F_DUPFD_CLOEXEC, STDERR_FILENO);
 156   if (orig_stderr == -1) {
 157     perror ("fcntl");
 158     exit (EXIT_FAILURE);
 159   }
 160   if (dup2 (pfd[1], STDERR_FILENO) == -1) {
 161     dprintf (orig_stderr, "dup2: %s\n", strerror (errno));
 162     exit (EXIT_FAILURE);
 163   }
 164
 165   /* Start nbdkit. */
 166   if (nbd_connect_command (nbd,
 167                            (char *[]) {
 168                              "nbdkit", "--exit-with-parent", "-fvns",
 169                              /* Because of asynchronous shutdown with
 170                               * threads, finalize isn't reliably
 171                               * called unless we disable parallel.
 172                               */
 173                              "-t", "1",
 174                              "--filter", ".libs/test-layers-filter3." SOEXT,
 175                              "--filter", ".libs/test-layers-filter2." SOEXT,
 176                              "--filter", ".libs/test-layers-filter1." SOEXT,
 177                              ".libs/test-layers-plugin." SOEXT,
 178                              "foo=bar",
 179                              NULL }) == -1) {
 180     dprintf (orig_stderr, "nbd_connect_command: %s\n", nbd_get_error ());
 181     exit (EXIT_FAILURE);
 182   }
 183
 184   /* Restore normal stderr, now that child is forked. */
 185   close (pfd[1]);
 186   dup2 (orig_stderr, STDERR_FILENO);
 187   close (orig_stderr);
 188
 189   short_sleep ();
 190   fprintf (stderr, "%s: nbdkit passed preconnect\n", program_name);
 191
 192   /* Note for the purposes of this test we're not very careful about
 193    * checking for errors (except for the bare minimum).  This is
 194    * because we can be certain about exactly which server we are
 195    * connecting to and what it supports.  Don't use this as example
 196    * code for connecting to NBD servers.
 197    *
 198    * Expect to receive newstyle handshake.
 199    */
 200   if (strcmp (nbd_get_protocol (nbd), "newstyle-fixed") != 0) {
 201     fprintf (stderr, "%s: unexpected NBDMAGIC or version\n",
 202              program_name);
 203     exit (EXIT_FAILURE);
 204   }
 205
 206   /* Plugin and 3 filters should run the load method in any order. */
 207   log_verify_seen ("test_layers_plugin_load");
 208   log_verify_seen ("filter1: test_layers_filter_load");
 209   log_verify_seen ("filter2: test_layers_filter_load");
 210   log_verify_seen ("filter3: test_layers_filter_load");
 211
 212   /* config methods called in order. */
 213   log_verify_seen_in_order
 214     ("testlayersfilter3: config key=foo, value=bar",
 215      "filter3: test_layers_filter_config",
 216      "testlayersfilter2: config key=foo, value=bar",
 217      "filter2: test_layers_filter_config",
 218      "testlayersfilter1: config key=foo, value=bar",
 219      "filter1: test_layers_filter_config",
 220      "testlayersplugin: config key=foo, value=bar",
 221      "test_layers_plugin_config",
 222      NULL);
 223
 224   /* config_complete methods called in order. */
 225   log_verify_seen_in_order
 226     ("testlayersfilter3: config_complete",
 227      "filter3: test_layers_filter_config_complete",
 228      "testlayersfilter2: config_complete",
 229      "filter2: test_layers_filter_config_complete",
 230      "testlayersfilter1: config_complete",
 231      "filter1: test_layers_filter_config_complete",
 232      "testlayersplugin: config_complete",
 233      "test_layers_plugin_config_complete",
 234      NULL);
 235
 236   /* thread_model methods called in inner-to-outer order. */
 237   log_verify_seen_in_order
 238     ("test_layers_plugin_thread_model",
 239      "filter1: test_layers_filter_thread_model",
 240      "filter2: test_layers_filter_thread_model",
 241      "filter3: test_layers_filter_thread_model",
 242      NULL);
 243
 244   /* get_ready methods called in inner-to-outer order. */
 245   log_verify_seen_in_order
 246     ("testlayersplugin: get_ready",
 247      "test_layers_plugin_get_ready",
 248      "testlayersfilter1: get_ready",
 249      "filter1: test_layers_filter_get_ready",
 250      "testlayersfilter2: get_ready",
 251      "filter2: test_layers_filter_get_ready",
 252      "testlayersfilter3: get_ready",
 253      "filter3: test_layers_filter_get_ready",
 254      NULL);
 255
 256   /* after_fork methods called in inner-to-outer order. */
 257   log_verify_seen_in_order
 258     ("testlayersplugin: after_fork",
 259      "test_layers_plugin_after_fork",
 260      "testlayersfilter1: after_fork",
 261      "filter1: test_layers_filter_after_fork",
 262      "testlayersfilter2: after_fork",
 263      "filter2: test_layers_filter_after_fork",
 264      "testlayersfilter3: after_fork",
 265      "filter3: test_layers_filter_after_fork",
 266      NULL);
 267
 268   /* preconnect methods called in outer-to-inner order, complete
 269    * in inner-to-outer order.
 270    */
 271   log_verify_seen_in_order
 272     ("testlayersfilter3: preconnect",
 273      "filter3: test_layers_filter_preconnect",
 274      "testlayersfilter2: preconnect",
 275      "filter2: test_layers_filter_preconnect",
 276      "testlayersfilter1: preconnect",
 277      "filter1: test_layers_filter_preconnect",
 278      "testlayersplugin: preconnect",
 279      "test_layers_plugin_preconnect",
 280      NULL);
 281
 282 #if LIBNBD_HAVE_NBD_SET_OPT_MODE
 283   /* We can only test .list_exports if we can send NBD_OPT_INFO; if we
 284    * can test it, they are called in order.
 285    */
 286   if (nbd_opt_list (nbd, (nbd_list_callback) { .callback = export }) == -1) {
 287     fprintf (stderr, "nbd_opt_list: %s\n", nbd_get_error ());
 288     exit (EXIT_FAILURE);
 289   }
 290   if (nbd_opt_go (nbd) == -1) {
 291     fprintf (stderr, "nbd_opt_go: %s\n", nbd_get_error ());
 292     exit (EXIT_FAILURE);
 293   }
 294
 295   short_sleep ();
 296   log_verify_seen_in_order
 297     ("testlayersfilter3: list_exports",
 298      "filter3: test_layers_filter_list_exports",
 299      "testlayersfilter2: list_exports",
 300      "filter2: test_layers_filter_list_exports",
 301      "testlayersfilter1: list_exports",
 302      "filter1: test_layers_filter_list_exports",
 303      "testlayersplugin: list_exports",
 304      "test_layers_plugin_list_exports",
 305      NULL);
 306 #endif /* LIBNBD_HAVE_NBD_SET_OPT_MODE */
 307
 308   fprintf (stderr, "%s: nbdkit running\n", program_name);
 309
 310   /* Verify export size (see tests/test-layers-plugin.c). */
 311   if (nbd_get_size (nbd) != 1024) {
 312     fprintf (stderr, "%s: unexpected export size %" PRIu64 " != 1024\n",
 313              program_name, nbd_get_size (nbd));
 314     exit (EXIT_FAILURE);
 315   }
 316
 317   /* Verify export flags. */
 318   if (nbd_is_read_only (nbd) != 0) {
 319     fprintf (stderr, "%s: unexpected eflags: NBD_FLAG_READ_ONLY not clear\n",
 320              program_name);
 321     exit (EXIT_FAILURE);
 322   }
 323   if (nbd_can_flush (nbd) != 1) {
 324     fprintf (stderr, "%s: unexpected eflags: NBD_FLAG_SEND_FLUSH not set\n",
 325              program_name);
 326     exit (EXIT_FAILURE);
 327   }
 328   if (nbd_can_fua (nbd) != 1) {
 329     fprintf (stderr, "%s: unexpected eflags: NBD_FLAG_SEND_FUA not set\n",
 330              program_name);
 331     exit (EXIT_FAILURE);
 332   }
 333   if (nbd_is_rotational (nbd) != 1) {
 334     fprintf (stderr, "%s: unexpected eflags: NBD_FLAG_ROTATIONAL not set\n",
 335              program_name);
 336     exit (EXIT_FAILURE);
 337   }
 338   if (nbd_can_trim (nbd) != 1) {
 339     fprintf (stderr, "%s: unexpected eflags: NBD_FLAG_SEND_TRIM not set\n",
 340              program_name);
 341     exit (EXIT_FAILURE);
 342   }
 343   if (nbd_can_zero (nbd) != 1) {
 344     fprintf (stderr,
 345              "%s: unexpected eflags: NBD_FLAG_SEND_WRITE_ZEROES not set\n",
 346              program_name);
 347     exit (EXIT_FAILURE);
 348   }
 349   if (nbd_can_meta_context (nbd, LIBNBD_CONTEXT_BASE_ALLOCATION) != 1) {
 350     fprintf (stderr,
 351              "%s: unexpected setup: META_CONTEXT not supported\n",
 352              program_name);
 353     exit (EXIT_FAILURE);
 354   }
 355
 356   /* default_export called in outer-to-inner order. */
 357   log_verify_seen_in_order
 358     ("testlayersfilter3: default_export",
 359      "filter3: test_layers_filter_default_export",
 360      "testlayersfilter2: default_export",
 361      "filter2: test_layers_filter_default_export",
 362      "testlayersfilter1: default_export",
 363      "filter1: test_layers_filter_default_export",
 364      "testlayersplugin: default_export",
 365      "test_layers_plugin_default_export",
 366      NULL);
 367
 368   /* open methods called in outer-to-inner order, but thanks to next
 369    * pointer, complete in inner-to-outer order. */
 370   log_verify_seen_in_order
 371     ("testlayersfilter3: open readonly=0",
 372      "testlayersfilter2: open readonly=0",
 373      "testlayersfilter1: open readonly=0",
 374      "testlayersplugin: open readonly=0",
 375      "test_layers_plugin_open",
 376      "filter1: test_layers_filter_open",
 377      "filter2: test_layers_filter_open",
 378      "filter3: test_layers_filter_open",
 379      NULL);
 380
 381   /* prepare methods called in inner-to-outer order.
 382    *
 383    * Note that prepare methods only exist for filters, and they must
 384    * be called from inner to outer (but finalize methods below are
 385    * called the other way around).
 386    */
 387   log_verify_seen_in_order
 388     ("filter1: test_layers_filter_prepare",
 389      "filter2: test_layers_filter_prepare",
 390      "filter3: test_layers_filter_prepare",
 391      NULL);
 392
 393   /* get_size methods called in order. */
 394   log_verify_seen_in_order
 395     ("filter3: test_layers_filter_get_size",
 396      "filter2: test_layers_filter_get_size",
 397      "filter1: test_layers_filter_get_size",
 398      "test_layers_plugin_get_size",
 399      NULL);
 400
 401   /* can_* / is_* methods called in order. */
 402   log_verify_seen_in_order
 403     ("filter3: test_layers_filter_can_write",
 404      "filter2: test_layers_filter_can_write",
 405      "filter1: test_layers_filter_can_write",
 406      "test_layers_plugin_can_write",
 407      NULL);
 408   log_verify_seen_in_order
 409     ("filter3: test_layers_filter_can_zero",
 410      "filter2: test_layers_filter_can_zero",
 411      "filter1: test_layers_filter_can_zero",
 412      "test_layers_plugin_can_zero",
 413      NULL);
 414   log_verify_seen_in_order
 415     ("filter3: test_layers_filter_can_fast_zero",
 416      "filter2: test_layers_filter_can_fast_zero",
 417      "filter1: test_layers_filter_can_fast_zero",
 418      "test_layers_plugin_can_fast_zero",
 419      NULL);
 420   log_verify_seen_in_order
 421     ("filter3: test_layers_filter_can_trim",
 422      "filter2: test_layers_filter_can_trim",
 423      "filter1: test_layers_filter_can_trim",
 424      "test_layers_plugin_can_trim",
 425      NULL);
 426   log_verify_seen_in_order
 427     ("filter3: test_layers_filter_can_fua",
 428      "filter2: test_layers_filter_can_fua",
 429      "filter1: test_layers_filter_can_fua",
 430      "test_layers_plugin_can_fua",
 431      NULL);
 432   log_verify_seen_in_order
 433     ("filter3: test_layers_filter_can_flush",
 434      "filter2: test_layers_filter_can_flush",
 435      "filter1: test_layers_filter_can_flush",
 436      "test_layers_plugin_can_flush",
 437      NULL);
 438   log_verify_seen_in_order
 439     ("filter3: test_layers_filter_is_rotational",
 440      "filter2: test_layers_filter_is_rotational",
 441      "filter1: test_layers_filter_is_rotational",
 442      "test_layers_plugin_is_rotational",
 443      NULL);
 444   log_verify_seen_in_order
 445     ("filter3: test_layers_filter_can_multi_conn",
 446      "filter2: test_layers_filter_can_multi_conn",
 447      "filter1: test_layers_filter_can_multi_conn",
 448      "test_layers_plugin_can_multi_conn",
 449      NULL);
 450   log_verify_seen_in_order
 451     ("filter3: test_layers_filter_can_extents",
 452      "filter2: test_layers_filter_can_extents",
 453      "filter1: test_layers_filter_can_extents",
 454      "test_layers_plugin_can_extents",
 455      NULL);
 456   log_verify_seen_in_order
 457     ("filter3: test_layers_filter_can_cache",
 458      "filter2: test_layers_filter_can_cache",
 459      "filter1: test_layers_filter_can_cache",
 460      "test_layers_plugin_can_cache",
 461      NULL);
 462
 463   fprintf (stderr, "%s: protocol connected\n", program_name);
 464
 465   /* Send one command of each type. */
 466   if (nbd_pread (nbd, data, sizeof data, 0, 0) != 0) {
 467     fprintf (stderr, "%s: NBD_CMD_READ failed with %d %s\n",
 468              program_name, nbd_get_errno (), nbd_get_error ());
 469     exit (EXIT_FAILURE);
 470   }
 471
 472   short_sleep ();
 473   log_verify_seen_in_order
 474     ("testlayersfilter3: pread count=512 offset=0",
 475      "filter3: test_layers_filter_pread",
 476      "testlayersfilter2: pread count=512 offset=0",
 477      "filter2: test_layers_filter_pread",
 478      "testlayersfilter1: pread count=512 offset=0",
 479      "filter1: test_layers_filter_pread",
 480      "testlayersplugin: pread count=512 offset=0",
 481      "test_layers_plugin_pread",
 482      NULL);
 483
 484   if (nbd_pwrite (nbd, data, sizeof data, 0, 0) != 0) {
 485     fprintf (stderr, "%s: NBD_CMD_WRITE failed with %d %s\n",
 486              program_name, nbd_get_errno (), nbd_get_error ());
 487     exit (EXIT_FAILURE);
 488   }
 489
 490   short_sleep ();
 491   log_verify_seen_in_order
 492     ("testlayersfilter3: pwrite count=512 offset=0 fua=0",
 493      "filter3: test_layers_filter_pwrite",
 494      "testlayersfilter2: pwrite count=512 offset=0 fua=0",
 495      "filter2: test_layers_filter_pwrite",
 496      "testlayersfilter1: pwrite count=512 offset=0 fua=0",
 497      "filter1: test_layers_filter_pwrite",
 498      "testlayersplugin: pwrite count=512 offset=0 fua=0",
 499      "test_layers_plugin_pwrite",
 500      NULL);
 501
 502   if (nbd_flush (nbd, 0) != 0) {
 503     fprintf (stderr, "%s: NBD_CMD_FLUSH failed with %d %s\n",
 504              program_name, nbd_get_errno (), nbd_get_error ());
 505     exit (EXIT_FAILURE);
 506   }
 507
 508   short_sleep ();
 509   log_verify_seen_in_order
 510     ("testlayersfilter3: flush",
 511      "filter3: test_layers_filter_flush",
 512      "testlayersfilter2: flush",
 513      "filter2: test_layers_filter_flush",
 514      "testlayersfilter1: flush",
 515      "filter1: test_layers_filter_flush",
 516      "testlayersplugin: flush",
 517      "test_layers_plugin_flush",
 518      NULL);
 519
 520   if (nbd_trim (nbd, sizeof data, 0, 0) != 0) {
 521     fprintf (stderr, "%s: NBD_CMD_TRIM failed with %d %s\n",
 522              program_name, nbd_get_errno (), nbd_get_error ());
 523     exit (EXIT_FAILURE);
 524   }
 525
 526   short_sleep ();
 527   log_verify_seen_in_order
 528     ("testlayersfilter3: trim count=512 offset=0 fua=0",
 529      "filter3: test_layers_filter_trim",
 530      "testlayersfilter2: trim count=512 offset=0 fua=0",
 531      "filter2: test_layers_filter_trim",
 532      "testlayersfilter1: trim count=512 offset=0 fua=0",
 533      "filter1: test_layers_filter_trim",
 534      "testlayersplugin: trim count=512 offset=0 fua=0",
 535      "test_layers_plugin_trim",
 536      NULL);
 537
 538   if (nbd_zero (nbd, sizeof data, 0, 0) != 0) {
 539     fprintf (stderr, "%s: NBD_CMD_WRITE_ZEROES failed with %d %s\n",
 540              program_name, nbd_get_errno (), nbd_get_error ());
 541     exit (EXIT_FAILURE);
 542   }
 543
 544   short_sleep ();
 545   log_verify_seen_in_order
 546     ("testlayersfilter3: zero count=512 offset=0 may_trim=1 fua=0 fast=0",
 547      "filter3: test_layers_filter_zero",
 548      "testlayersfilter2: zero count=512 offset=0 may_trim=1 fua=0 fast=0",
 549      "filter2: test_layers_filter_zero",
 550      "testlayersfilter1: zero count=512 offset=0 may_trim=1 fua=0 fast=0",
 551      "filter1: test_layers_filter_zero",
 552      "testlayersplugin: zero count=512 offset=0 may_trim=1 fua=0 fast=0",
 553      "test_layers_plugin_zero",
 554      NULL);
 555
 556   if (nbd_cache (nbd, sizeof data, 0, 0) != 0) {
 557     fprintf (stderr, "%s: NBD_CMD_CACHE failed with %d %s\n",
 558              program_name, nbd_get_errno (), nbd_get_error ());
 559     exit (EXIT_FAILURE);
 560   }
 561
 562   short_sleep ();
 563   log_verify_seen_in_order
 564     ("testlayersfilter3: cache count=512 offset=0",
 565      "filter3: test_layers_filter_cache",
 566      "testlayersfilter2: cache count=512 offset=0",
 567      "filter2: test_layers_filter_cache",
 568      "testlayersfilter1: cache count=512 offset=0",
 569      "filter1: test_layers_filter_cache",
 570      "testlayersplugin: cache count=512 offset=0",
 571      "test_layers_plugin_cache",
 572      NULL);
 573
 574   if (nbd_block_status (nbd, sizeof data, 0,
 575                         (nbd_extent_callback) { .callback = extent }, 0) != 0) {
 576     fprintf (stderr, "%s: NBD_CMD_BLOCK_STATUS failed with %d %s\n",
 577              program_name, nbd_get_errno (), nbd_get_error ());
 578     exit (EXIT_FAILURE);
 579   }
 580
 581   short_sleep ();
 582   log_verify_seen_in_order
 583     ("testlayersfilter3: extents count=512 offset=0",
 584      "filter3: test_layers_filter_extents",
 585      "testlayersfilter2: extents count=512 offset=0",
 586      "filter2: test_layers_filter_extents",
 587      "testlayersfilter1: extents count=512 offset=0",
 588      "filter1: test_layers_filter_extents",
 589      "testlayersplugin: extents count=512 offset=0",
 590      "test_layers_plugin_extents",
 591      NULL);
 592
 593   /* Close the connection. */
 594   fprintf (stderr, "%s: closing the connection\n", program_name);
 595   if (nbd_shutdown (nbd, 0) != 0) {
 596     fprintf (stderr, "%s: NBD_CMD_DISC failed with %d %s\n",
 597              program_name, nbd_get_errno (), nbd_get_error ());
 598     exit (EXIT_FAILURE);
 599   }
 600   nbd_close (nbd);
 601
 602   /* finalize methods called in reverse order of prepare */
 603   short_sleep ();
 604   log_verify_seen_in_order
 605     ("filter3: test_layers_filter_finalize",
 606      "filter2: test_layers_filter_finalize",
 607      "filter1: test_layers_filter_finalize",
 608      NULL);
 609
 610   /* close methods called outer-to-inner, which is reverse of completion
 611    * of open */
 612   log_verify_seen_in_order
 613     ("filter3: test_layers_filter_close",
 614      "filter2: test_layers_filter_close",
 615      "filter1: test_layers_filter_close",
 616      "test_layers_plugin_close",
 617      NULL);
 618
 619   /* cleanup methods called in outer-to-inner order. */
 620   log_verify_seen_in_order
 621     ("testlayersfilter3: cleanup",
 622      "filter3: test_layers_filter_cleanup",
 623      "testlayersfilter2: cleanup",
 624      "filter2: test_layers_filter_cleanup",
 625      "testlayersfilter1: cleanup",
 626      "filter1: test_layers_filter_cleanup",
 627      "testlayersplugin: cleanup",
 628      "test_layers_plugin_cleanup",
 629      NULL);
 630
 631   /* unload methods should be run in any order. */
 632   log_verify_seen ("test_layers_plugin_unload");
 633   log_verify_seen ("filter1: test_layers_filter_unload");
 634   log_verify_seen ("filter2: test_layers_filter_unload");
 635   log_verify_seen ("filter3: test_layers_filter_unload");
 636
 637   log_free ();
 638
 639   exit (EXIT_SUCCESS);
 640 }
 641
 642 /* The log from nbdkit is captured in a separate thread. */
 643 static char *log_buf = NULL;
 644 static size_t log_len = 0;
 645 static size_t last_out = 0;
 646 static pthread_mutex_t log_lock = PTHREAD_MUTEX_INITIALIZER;
 647
 648 static void *
 649 start_log_capture (void *arg)
 650 {
 651   int fd = *(int *)arg;
 652   size_t allocated = 0;
 653   ssize_t r;
 654
 655   for (;;) {
 656     {
 657       ACQUIRE_LOCK_FOR_CURRENT_SCOPE (&log_lock);
 658       if (allocated <= log_len) {
 659         allocated += 4096;
 660         log_buf = realloc (log_buf, allocated);
 661         if (log_buf == NULL) {
 662           perror ("log: realloc");
 663           exit (EXIT_FAILURE);
 664         }
 665       }
 666     }
 667
 668     r = read (fd, &log_buf[log_len], allocated-log_len);
 669     if (r == -1) {
 670       perror ("log: read");
 671       exit (EXIT_FAILURE);
 672     }
 673     if (r == 0)
 674       break;
 675
 676     ACQUIRE_LOCK_FOR_CURRENT_SCOPE (&log_lock);
 677     log_len += r;
 678   }
 679
 680   /* nbdkit closed the connection. */
 681   pthread_exit (NULL);
 682 }
 683
 684 static void short_sleep (void)
 685 {
 686   sleep (2);
 687   /* Copy what we have received so far into stderr */
 688   ACQUIRE_LOCK_FOR_CURRENT_SCOPE (&log_lock);
 689   if (fwrite (&log_buf[last_out], log_len - last_out, 1, stderr) == -1)
 690     perror ("log: fwrite");
 691   last_out = log_len;
 692 }
 693
 694 /* These functions are called from the main thread to verify messages
 695  * appeared as expected in the log.
 696  *
 697  * NB: The log buffer is NOT \0-terminated.
 698  */
 699
 700 static void no_message_error (const char *msg) __attribute__((noreturn));
 701
 702 static void
 703 no_message_error (const char *msg)
 704 {
 705   fprintf (stderr, "%s: did not find expected message \"%s\"\n",
 706            program_name, msg);
 707   exit (EXIT_FAILURE);
 708 }
 709
 710 static void
 711 log_verify_seen (const char *msg)
 712 {
 713   ACQUIRE_LOCK_FOR_CURRENT_SCOPE (&log_lock);
 714   if (memmem (log_buf, log_len, msg, strlen (msg)) == NULL)
 715     no_message_error (msg);
 716 }
 717
 718 static void messages_out_of_order (const char *msg1, const char *msg2)
 719   __attribute__((noreturn));
 720
 721 static void
 722 messages_out_of_order (const char *msg1, const char *msg2)
 723 {
 724   fprintf (stderr, "%s: message \"%s\" expected before message \"%s\"\n",
 725            program_name, msg1, msg2);
 726   exit (EXIT_FAILURE);
 727 }
 728
 729 static void
 730 log_verify_seen_in_order (const char *msg, ...)
 731 {
 732   va_list args;
 733   void *prev, *curr;
 734   const char *prev_msg, *curr_msg;
 735
 736   ACQUIRE_LOCK_FOR_CURRENT_SCOPE (&log_lock);
 737
 738   prev = memmem (log_buf, log_len, msg, strlen (msg));
 739   if (prev == NULL) no_message_error (msg);
 740   prev_msg = msg;
 741
 742   va_start (args, msg);
 743   while ((curr_msg = va_arg (args, char *)) != NULL) {
 744     curr = memmem (log_buf, log_len, curr_msg, strlen (curr_msg));
 745     if (curr == NULL) no_message_error (curr_msg);
 746     if (prev > curr) messages_out_of_order (prev_msg, curr_msg);
 747     prev_msg = curr_msg;
 748     prev = curr;
 749   }
 750   va_end (args);
 751 }
 752
 753 static void
 754 log_free (void)
 755 {
 756   ACQUIRE_LOCK_FOR_CURRENT_SCOPE (&log_lock);
 757   free (log_buf);
 758   log_buf = NULL;
 759   log_len = 0;
 760 }
 761
 762 #else /* WIN32 */
 763
 764 /* A lot of porting work required for Windows.  For now, skip the test. */
 765 int
 766 main (int argc, char *argv[])
 767 {
 768   fprintf (stderr, "%s: test skipped because not ported to Windows.\n",
 769            argv[0]);
 770   exit (77);
 771 }
 772
 773 #endif /* WIN32 */