tests/test-layers.c

   1 /* nbdkit
   2  * Copyright (C) 2018-2019 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.  This
  41  * cannot be done with libguestfs or qemu-io, instead we must make NBD
  42  * client requests over a socket directly.
  43  */
  44
  45 #include <config.h>
  46
  47 #include <stdio.h>
  48 #include <stdlib.h>
  49 #include <stdarg.h>
  50 #include <stdint.h>
  51 #include <inttypes.h>
  52 #include <string.h>
  53 #include <unistd.h>
  54 #include <errno.h>
  55 #include <sys/types.h>
  56 #include <sys/socket.h>
  57 #include <sys/wait.h>
  58
  59 #include <pthread.h>
  60
  61 #include "byte-swapping.h"
  62 #include "cleanup.h"
  63 #include "exit-with-parent.h"
  64 #include "nbd-protocol.h"
  65
  66 /* Declare program_name. */
  67 #if HAVE_DECL_PROGRAM_INVOCATION_SHORT_NAME == 1
  68 #include <errno.h>
  69 #define program_name program_invocation_short_name
  70 #else
  71 #define program_name "nbdkit"
  72 #endif
  73
  74 static void *start_log_capture (void *);
  75 static void log_verify_seen (const char *msg);
  76 static void log_verify_seen_in_order (const char *msg, ...)
  77   __attribute__((sentinel));
  78 static void log_free (void);
  79
  80 static inline void
  81 short_sleep (void)
  82 {
  83   sleep (2);
  84 }
  85
  86 int
  87 main (int argc, char *argv[])
  88 {
  89   pid_t pid;
  90   int sfd[2];
  91   int pfd[2];
  92   int err;
  93   pthread_t thread;
  94   int sock;
  95   struct nbd_new_handshake handshake;
  96   uint32_t cflags;
  97   struct nbd_new_option option;
  98   struct nbd_export_name_option_reply handshake_finish;
  99   uint16_t eflags;
 100   struct nbd_request request;
 101   struct nbd_simple_reply reply;
 102   char data[512];
 103
 104 #ifndef HAVE_EXIT_WITH_PARENT
 105   printf ("%s: this test requires --exit-with-parent functionality\n",
 106           program_name);
 107   exit (77);
 108 #endif
 109
 110   /* Socket for communicating with nbdkit. The test doesn't care about
 111    * fd leaks, so we don't bother with CLOEXEC.
 112    */
 113   if (socketpair (AF_LOCAL, SOCK_STREAM, 0, sfd) == -1) {
 114     perror ("socketpair");
 115     exit (EXIT_FAILURE);
 116   }
 117   sock = sfd[0];
 118
 119   /* Start nbdkit. */
 120   if (pipe (pfd) == -1) {       /* Pipe for log messages. */
 121     perror ("pipe");
 122     exit (EXIT_FAILURE);
 123   }
 124   pid = fork ();
 125   if (pid == 0) {               /* Child. */
 126     dup2 (sfd[1], 0);
 127     dup2 (sfd[1], 1);
 128     close (pfd[0]);
 129     dup2 (pfd[1], 2);
 130     close (pfd[1]);
 131     execlp ("nbdkit", "nbdkit",
 132             "--exit-with-parent",
 133             "-fvns",
 134             /* Because of asynchronous shutdown with threads, finalize
 135              * isn't reliably called unless we disable parallel.
 136              */
 137             "-t", "1",
 138             "--filter", ".libs/test-layers-filter3.so",
 139             "--filter", ".libs/test-layers-filter2.so",
 140             "--filter", ".libs/test-layers-filter1.so",
 141             ".libs/test-layers-plugin.so",
 142             "foo=bar",
 143             NULL);
 144     perror ("exec: nbdkit");
 145     _exit (EXIT_FAILURE);
 146   }
 147
 148   /* Parent (test). */
 149   close (sfd[1]);
 150   close (pfd[1]);
 151
 152   fprintf (stderr, "%s: nbdkit running\n", program_name);
 153
 154   /* Start a thread which will just listen on the pipe and
 155    * place the log messages in a memory buffer.
 156    */
 157   err = pthread_create (&thread, NULL, start_log_capture, &pfd[0]);
 158   if (err) {
 159     errno = err;
 160     perror ("pthread_create");
 161     exit (EXIT_FAILURE);
 162   }
 163   err = pthread_detach (thread);
 164   if (err) {
 165     errno = err;
 166     perror ("pthread_detach");
 167     exit (EXIT_FAILURE);
 168   }
 169
 170   /* Note for the purposes of this test we're not very careful about
 171    * checking for errors (except for the bare minimum) or handling the
 172    * full NBD protocol.  This is because we can be certain about
 173    * exactly which server we are connecting to and what it supports.
 174    * Don't use this as example code for connecting to NBD servers.
 175    *
 176    * Expect to receive newstyle handshake.
 177    */
 178   if (recv (sock, &handshake, sizeof handshake,
 179             MSG_WAITALL) != sizeof handshake) {
 180     perror ("recv: handshake");
 181     exit (EXIT_FAILURE);
 182   }
 183   if (be64toh (handshake.nbdmagic) != NBD_MAGIC ||
 184       be64toh (handshake.version) != NBD_NEW_VERSION) {
 185     fprintf (stderr, "%s: unexpected NBDMAGIC or version\n",
 186              program_name);
 187     exit (EXIT_FAILURE);
 188   }
 189
 190   /* Send client flags. */
 191   cflags = htobe32 (be16toh (handshake.gflags));
 192   if (send (sock, &cflags, sizeof cflags, 0) != sizeof cflags) {
 193     perror ("send: flags");
 194     exit (EXIT_FAILURE);
 195   }
 196
 197   /* Send NBD_OPT_EXPORT_NAME with no export name. */
 198   option.version = htobe64 (NBD_NEW_VERSION);
 199   option.option = htobe32 (NBD_OPT_EXPORT_NAME);
 200   option.optlen = htobe32 (0);
 201   if (send (sock, &option, sizeof option, 0) != sizeof option) {
 202     perror ("send: option");
 203     exit (EXIT_FAILURE);
 204   }
 205
 206   /* Receive handshake finish. */
 207   if (recv (sock, &handshake_finish, sizeof handshake_finish - 124,
 208             MSG_WAITALL) != sizeof handshake_finish - 124) {
 209     perror ("recv: handshake finish");
 210     exit (EXIT_FAILURE);
 211   }
 212
 213   /* Verify export size (see tests/test-layers-plugin.c). */
 214   if (be64toh (handshake_finish.exportsize) != 1024) {
 215     fprintf (stderr, "%s: unexpected export size %" PRIu64 " != 1024\n",
 216              program_name, be64toh (handshake_finish.exportsize));
 217     exit (EXIT_FAILURE);
 218   }
 219
 220   /* Verify export flags. */
 221   eflags = be16toh (handshake_finish.eflags);
 222   if ((eflags & NBD_FLAG_READ_ONLY) != 0) {
 223     fprintf (stderr, "%s: unexpected eflags: NBD_FLAG_READ_ONLY not clear\n",
 224              program_name);
 225     exit (EXIT_FAILURE);
 226   }
 227   if ((eflags & NBD_FLAG_SEND_FLUSH) == 0) {
 228     fprintf (stderr, "%s: unexpected eflags: NBD_FLAG_SEND_FLUSH not set\n",
 229              program_name);
 230     exit (EXIT_FAILURE);
 231   }
 232   if ((eflags & NBD_FLAG_SEND_FUA) == 0) {
 233     fprintf (stderr, "%s: unexpected eflags: NBD_FLAG_SEND_FUA not set\n",
 234              program_name);
 235     exit (EXIT_FAILURE);
 236   }
 237   if ((eflags & NBD_FLAG_ROTATIONAL) == 0) {
 238     fprintf (stderr, "%s: unexpected eflags: NBD_FLAG_ROTATIONAL not set\n",
 239              program_name);
 240     exit (EXIT_FAILURE);
 241   }
 242   if ((eflags & NBD_FLAG_SEND_TRIM) == 0) {
 243     fprintf (stderr, "%s: unexpected eflags: NBD_FLAG_SEND_TRIM not set\n",
 244              program_name);
 245     exit (EXIT_FAILURE);
 246   }
 247   if ((eflags & NBD_FLAG_SEND_WRITE_ZEROES) == 0) {
 248     fprintf (stderr,
 249              "%s: unexpected eflags: NBD_FLAG_SEND_WRITE_ZEROES not set\n",
 250              program_name);
 251     exit (EXIT_FAILURE);
 252   }
 253
 254   /* Sleep briefly to allow the log to catch up. */
 255   short_sleep ();
 256
 257   /* Verify expected log messages were seen during the handshake and
 258    * option negotiation phases.
 259    */
 260
 261   /* Plugin and 3 filters should run the load method in any order. */
 262   log_verify_seen ("test_layers_plugin_load");
 263   log_verify_seen ("filter1: test_layers_filter_load");
 264   log_verify_seen ("filter2: test_layers_filter_load");
 265   log_verify_seen ("filter3: test_layers_filter_load");
 266
 267   /* config methods called in order. */
 268   log_verify_seen_in_order
 269     ("testlayersfilter3: config key=foo, value=bar",
 270      "filter3: test_layers_filter_config",
 271      "testlayersfilter2: config key=foo, value=bar",
 272      "filter2: test_layers_filter_config",
 273      "testlayersfilter1: config key=foo, value=bar",
 274      "filter1: test_layers_filter_config",
 275      "testlayersplugin: config key=foo, value=bar",
 276      "test_layers_plugin_config",
 277      NULL);
 278
 279   /* config_complete methods called in order. */
 280   log_verify_seen_in_order
 281     ("testlayersfilter3: config_complete",
 282      "filter3: test_layers_filter_config_complete",
 283      "testlayersfilter2: config_complete",
 284      "filter2: test_layers_filter_config_complete",
 285      "testlayersfilter1: config_complete",
 286      "filter1: test_layers_filter_config_complete",
 287      "testlayersplugin: config_complete",
 288      "test_layers_plugin_config_complete",
 289      NULL);
 290
 291   /* open methods called in outer-to-inner order, but thanks to next
 292    * pointer, complete in inner-to-outer order. */
 293   log_verify_seen_in_order
 294     ("testlayersfilter3: open readonly=0",
 295      "testlayersfilter2: open readonly=0",
 296      "testlayersfilter1: open readonly=0",
 297      "testlayersplugin: open readonly=0",
 298      "test_layers_plugin_open",
 299      "filter1: test_layers_filter_open",
 300      "filter2: test_layers_filter_open",
 301      "filter3: test_layers_filter_open",
 302      NULL);
 303
 304   /* prepare methods called in inner-to-outer order.
 305    *
 306    * Note that prepare methods only exist for filters, and they must
 307    * be called from inner to outer (but finalize methods below are
 308    * called the other way around).
 309    */
 310   log_verify_seen_in_order
 311     ("filter1: test_layers_filter_prepare",
 312      "filter2: test_layers_filter_prepare",
 313      "filter3: test_layers_filter_prepare",
 314      NULL);
 315
 316   /* get_size methods called in order. */
 317   log_verify_seen_in_order
 318     ("filter3: test_layers_filter_get_size",
 319      "filter2: test_layers_filter_get_size",
 320      "filter1: test_layers_filter_get_size",
 321      "test_layers_plugin_get_size",
 322      NULL);
 323
 324   /* can_* / is_* methods called in order. */
 325   log_verify_seen_in_order
 326     ("filter3: test_layers_filter_can_write",
 327      "filter2: test_layers_filter_can_write",
 328      "filter1: test_layers_filter_can_write",
 329      "test_layers_plugin_can_write",
 330      NULL);
 331   log_verify_seen_in_order
 332     ("filter3: test_layers_filter_can_zero",
 333      "filter2: test_layers_filter_can_zero",
 334      "filter1: test_layers_filter_can_zero",
 335      "test_layers_plugin_can_zero",
 336      NULL);
 337   log_verify_seen_in_order
 338     ("filter3: test_layers_filter_can_trim",
 339      "filter2: test_layers_filter_can_trim",
 340      "filter1: test_layers_filter_can_trim",
 341      "test_layers_plugin_can_trim",
 342      NULL);
 343   log_verify_seen_in_order
 344     ("filter3: test_layers_filter_can_fua",
 345      "filter2: test_layers_filter_can_fua",
 346      "filter1: test_layers_filter_can_fua",
 347      "test_layers_plugin_can_fua",
 348      NULL);
 349   log_verify_seen_in_order
 350     ("filter3: test_layers_filter_can_flush",
 351      "filter2: test_layers_filter_can_flush",
 352      "filter1: test_layers_filter_can_flush",
 353      "test_layers_plugin_can_flush",
 354      NULL);
 355   log_verify_seen_in_order
 356     ("filter3: test_layers_filter_is_rotational",
 357      "filter2: test_layers_filter_is_rotational",
 358      "filter1: test_layers_filter_is_rotational",
 359      "test_layers_plugin_is_rotational",
 360      NULL);
 361   log_verify_seen_in_order
 362     ("filter3: test_layers_filter_can_multi_conn",
 363      "filter2: test_layers_filter_can_multi_conn",
 364      "filter1: test_layers_filter_can_multi_conn",
 365      "test_layers_plugin_can_multi_conn",
 366      NULL);
 367   log_verify_seen_in_order
 368     ("filter3: test_layers_filter_can_extents",
 369      "filter2: test_layers_filter_can_extents",
 370      "filter1: test_layers_filter_can_extents",
 371      "test_layers_plugin_can_extents",
 372      NULL);
 373   log_verify_seen_in_order
 374     ("filter3: test_layers_filter_can_cache",
 375      "filter2: test_layers_filter_can_cache",
 376      "filter1: test_layers_filter_can_cache",
 377      "test_layers_plugin_can_cache",
 378      NULL);
 379
 380   fprintf (stderr, "%s: protocol connected\n", program_name);
 381
 382   /* Send one command of each type. */
 383   request.magic = htobe32 (NBD_REQUEST_MAGIC);
 384   request.handle = htobe64 (0);
 385
 386   request.type = htobe16 (NBD_CMD_READ);
 387   request.offset = htobe64 (0);
 388   request.count = htobe32 (512);
 389   request.flags = htobe16 (0);
 390   if (send (sock, &request, sizeof request, 0) != sizeof request) {
 391     perror ("send: NBD_CMD_READ");
 392     exit (EXIT_FAILURE);
 393   }
 394   if (recv (sock, &reply, sizeof reply, MSG_WAITALL) != sizeof reply) {
 395     perror ("recv: NBD_CMD_READ reply");
 396     exit (EXIT_FAILURE);
 397   }
 398   if (reply.error != NBD_SUCCESS) {
 399     fprintf (stderr, "%s: NBD_CMD_READ failed with %d\n",
 400              program_name, reply.error);
 401     exit (EXIT_FAILURE);
 402   }
 403   if (recv (sock, data, sizeof data, MSG_WAITALL) != sizeof data) {
 404     perror ("recv: NBD_CMD_READ data");
 405     exit (EXIT_FAILURE);
 406   }
 407
 408   short_sleep ();
 409   log_verify_seen_in_order
 410     ("testlayersfilter3: pread count=512 offset=0",
 411      "filter3: test_layers_filter_pread",
 412      "testlayersfilter2: pread count=512 offset=0",
 413      "filter2: test_layers_filter_pread",
 414      "testlayersfilter1: pread count=512 offset=0",
 415      "filter1: test_layers_filter_pread",
 416      "testlayersplugin: pread count=512 offset=0",
 417      "test_layers_plugin_pread",
 418      NULL);
 419
 420   request.type = htobe16 (NBD_CMD_WRITE);
 421   request.offset = htobe64 (0);
 422   request.count = htobe32 (512);
 423   request.flags = htobe16 (0);
 424   if (send (sock, &request, sizeof request, 0) != sizeof request) {
 425     perror ("send: NBD_CMD_WRITE");
 426     exit (EXIT_FAILURE);
 427   }
 428   if (send (sock, data, sizeof data, 0) != sizeof data) {
 429     perror ("send: NBD_CMD_WRITE data");
 430     exit (EXIT_FAILURE);
 431   }
 432   if (recv (sock, &reply, sizeof reply, MSG_WAITALL) != sizeof reply) {
 433     perror ("recv: NBD_CMD_WRITE");
 434     exit (EXIT_FAILURE);
 435   }
 436   if (reply.error != NBD_SUCCESS) {
 437     fprintf (stderr, "%s: NBD_CMD_WRITE failed with %d\n",
 438              program_name, reply.error);
 439     exit (EXIT_FAILURE);
 440   }
 441
 442   short_sleep ();
 443   log_verify_seen_in_order
 444     ("testlayersfilter3: pwrite count=512 offset=0 fua=0",
 445      "filter3: test_layers_filter_pwrite",
 446      "testlayersfilter2: pwrite count=512 offset=0 fua=0",
 447      "filter2: test_layers_filter_pwrite",
 448      "testlayersfilter1: pwrite count=512 offset=0 fua=0",
 449      "filter1: test_layers_filter_pwrite",
 450      "testlayersplugin: pwrite count=512 offset=0 fua=0",
 451      "test_layers_plugin_pwrite",
 452      NULL);
 453
 454   request.type = htobe16 (NBD_CMD_FLUSH);
 455   request.offset = htobe64 (0);
 456   request.count = htobe32 (0);
 457   request.flags = htobe16 (0);
 458   if (send (sock, &request, sizeof request, 0) != sizeof request) {
 459     perror ("send: NBD_CMD_FLUSH");
 460     exit (EXIT_FAILURE);
 461   }
 462   if (recv (sock, &reply, sizeof reply, MSG_WAITALL) != sizeof reply) {
 463     perror ("recv: NBD_CMD_FLUSH");
 464     exit (EXIT_FAILURE);
 465   }
 466   if (reply.error != NBD_SUCCESS) {
 467     fprintf (stderr, "%s: NBD_CMD_FLUSH failed with %d\n",
 468              program_name, reply.error);
 469     exit (EXIT_FAILURE);
 470   }
 471
 472   short_sleep ();
 473   log_verify_seen_in_order
 474     ("testlayersfilter3: flush",
 475      "filter3: test_layers_filter_flush",
 476      "testlayersfilter2: flush",
 477      "filter2: test_layers_filter_flush",
 478      "testlayersfilter1: flush",
 479      "filter1: test_layers_filter_flush",
 480      "testlayersplugin: flush",
 481      "test_layers_plugin_flush",
 482      NULL);
 483
 484   request.type = htobe16 (NBD_CMD_TRIM);
 485   request.offset = htobe64 (0);
 486   request.count = htobe32 (512);
 487   request.flags = htobe16 (0);
 488   if (send (sock, &request, sizeof request, 0) != sizeof request) {
 489     perror ("send: NBD_CMD_TRIM");
 490     exit (EXIT_FAILURE);
 491   }
 492   if (recv (sock, &reply, sizeof reply, MSG_WAITALL) != sizeof reply) {
 493     perror ("recv: NBD_CMD_TRIM");
 494     exit (EXIT_FAILURE);
 495   }
 496   if (reply.error != NBD_SUCCESS) {
 497     fprintf (stderr, "%s: NBD_CMD_TRIM failed with %d\n",
 498              program_name, reply.error);
 499     exit (EXIT_FAILURE);
 500   }
 501
 502   short_sleep ();
 503   log_verify_seen_in_order
 504     ("testlayersfilter3: trim count=512 offset=0 fua=0",
 505      "filter3: test_layers_filter_trim",
 506      "testlayersfilter2: trim count=512 offset=0 fua=0",
 507      "filter2: test_layers_filter_trim",
 508      "testlayersfilter1: trim count=512 offset=0 fua=0",
 509      "filter1: test_layers_filter_trim",
 510      "testlayersplugin: trim count=512 offset=0 fua=0",
 511      "test_layers_plugin_trim",
 512      NULL);
 513
 514   request.type = htobe16 (NBD_CMD_WRITE_ZEROES);
 515   request.offset = htobe64 (0);
 516   request.count = htobe32 (512);
 517   request.flags = htobe16 (0);
 518   if (send (sock, &request, sizeof request, 0) != sizeof request) {
 519     perror ("send: NBD_CMD_WRITE_ZEROES");
 520     exit (EXIT_FAILURE);
 521   }
 522   if (recv (sock, &reply, sizeof reply, MSG_WAITALL) != sizeof reply) {
 523     perror ("recv: NBD_CMD_WRITE_ZEROES");
 524     exit (EXIT_FAILURE);
 525   }
 526   if (reply.error != NBD_SUCCESS) {
 527     fprintf (stderr, "%s: NBD_CMD_WRITE_ZEROES failed with %d\n",
 528              program_name, reply.error);
 529     exit (EXIT_FAILURE);
 530   }
 531
 532   short_sleep ();
 533   log_verify_seen_in_order
 534     ("testlayersfilter3: zero count=512 offset=0 may_trim=1 fua=0 fast=0",
 535      "filter3: test_layers_filter_zero",
 536      "testlayersfilter2: zero count=512 offset=0 may_trim=1 fua=0 fast=0",
 537      "filter2: test_layers_filter_zero",
 538      "testlayersfilter1: zero count=512 offset=0 may_trim=1 fua=0 fast=0",
 539      "filter1: test_layers_filter_zero",
 540      "testlayersplugin: zero count=512 offset=0 may_trim=1 fua=0 fast=0",
 541      "test_layers_plugin_zero",
 542      NULL);
 543
 544   request.type = htobe16 (NBD_CMD_CACHE);
 545   request.offset = htobe64 (0);
 546   request.count = htobe32 (512);
 547   request.flags = htobe16 (0);
 548   if (send (sock, &request, sizeof request, 0) != sizeof request) {
 549     perror ("send: NBD_CMD_CACHE");
 550     exit (EXIT_FAILURE);
 551   }
 552   if (recv (sock, &reply, sizeof reply, MSG_WAITALL) != sizeof reply) {
 553     perror ("recv: NBD_CMD_CACHE");
 554     exit (EXIT_FAILURE);
 555   }
 556   if (reply.error != NBD_SUCCESS) {
 557     fprintf (stderr, "%s: NBD_CMD_CACHE failed with %d\n",
 558              program_name, reply.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   /* XXX We should test NBD_CMD_BLOCK_STATUS here.  However it
 575    * requires that we negotiate structured replies and base:allocation
 576    * in the handshake, and the format of the reply is more complex
 577    * than what we expect in this naive test.
 578    */
 579
 580   /* Close the connection. */
 581   fprintf (stderr, "%s: closing the connection\n", program_name);
 582   request.type = htobe16 (NBD_CMD_DISC);
 583   request.offset = htobe64 (0);
 584   request.count = htobe32 (0);
 585   request.flags = htobe16 (0);
 586   if (send (sock, &request, sizeof request, 0) != sizeof request) {
 587     perror ("send: NBD_CMD_DISC");
 588     exit (EXIT_FAILURE);
 589   }
 590   /* (no reply from NBD_CMD_DISC) */
 591   close (sock);
 592
 593   /* Clean up the child process. */
 594   if (waitpid (pid, NULL, 0) == -1)
 595     perror ("waitpid");
 596
 597   /* finalize methods called in reverse order of prepare */
 598   short_sleep ();
 599   log_verify_seen_in_order
 600     ("filter3: test_layers_filter_finalize",
 601      "filter2: test_layers_filter_finalize",
 602      "filter1: test_layers_filter_finalize",
 603      NULL);
 604
 605   /* close methods called outer-to-inner, which is reverse of completion
 606    * of open */
 607   log_verify_seen_in_order
 608     ("filter3: test_layers_filter_close",
 609      "filter2: test_layers_filter_close",
 610      "filter1: test_layers_filter_close",
 611      "test_layers_plugin_close",
 612      NULL);
 613
 614   /* unload methods should be run in any order. */
 615   log_verify_seen ("test_layers_plugin_unload");
 616   log_verify_seen ("filter1: test_layers_filter_unload");
 617   log_verify_seen ("filter2: test_layers_filter_unload");
 618   log_verify_seen ("filter3: test_layers_filter_unload");
 619
 620   log_free ();
 621
 622   exit (EXIT_SUCCESS);
 623 }
 624
 625 /* The log from nbdkit is captured in a separate thread. */
 626 static char *log_buf = NULL;
 627 static size_t log_len = 0;
 628 static pthread_mutex_t log_lock = PTHREAD_MUTEX_INITIALIZER;
 629
 630 static void *
 631 start_log_capture (void *arg)
 632 {
 633   int fd = *(int *)arg;
 634   size_t allocated = 0;
 635   ssize_t r;
 636
 637   for (;;) {
 638     {
 639       ACQUIRE_LOCK_FOR_CURRENT_SCOPE (&log_lock);
 640       if (allocated <= log_len) {
 641         allocated += 4096;
 642         log_buf = realloc (log_buf, allocated);
 643         if (log_buf == NULL) {
 644           perror ("log: realloc");
 645           exit (EXIT_FAILURE);
 646         }
 647       }
 648     }
 649
 650     r = read (fd, &log_buf[log_len], allocated-log_len);
 651     if (r == -1) {
 652       perror ("log: read");
 653       exit (EXIT_FAILURE);
 654     }
 655     if (r == 0)
 656       break;
 657
 658     /* Dump the log as we receive it to stderr, for debugging. */
 659     if (write (2, &log_buf[log_len], r) == -1)
 660       perror ("log: write");
 661
 662     ACQUIRE_LOCK_FOR_CURRENT_SCOPE (&log_lock);
 663     log_len += r;
 664   }
 665
 666   /* nbdkit closed the connection. */
 667   pthread_exit (NULL);
 668 }
 669
 670 /* These functions are called from the main thread to verify messages
 671  * appeared as expected in the log.
 672  *
 673  * NB: The log buffer is NOT \0-terminated.
 674  */
 675
 676 static void no_message_error (const char *msg) __attribute__((noreturn));
 677
 678 static void
 679 no_message_error (const char *msg)
 680 {
 681   fprintf (stderr, "%s: did not find expected message \"%s\"\n",
 682            program_name, msg);
 683   exit (EXIT_FAILURE);
 684 }
 685
 686 static void
 687 log_verify_seen (const char *msg)
 688 {
 689   ACQUIRE_LOCK_FOR_CURRENT_SCOPE (&log_lock);
 690   if (memmem (log_buf, log_len, msg, strlen (msg)) == NULL)
 691     no_message_error (msg);
 692 }
 693
 694 static void messages_out_of_order (const char *msg1, const char *msg2)
 695   __attribute__((noreturn));
 696
 697 static void
 698 messages_out_of_order (const char *msg1, const char *msg2)
 699 {
 700   fprintf (stderr, "%s: message \"%s\" expected before message \"%s\"\n",
 701            program_name, msg1, msg2);
 702   exit (EXIT_FAILURE);
 703 }
 704
 705 static void
 706 log_verify_seen_in_order (const char *msg, ...)
 707 {
 708   va_list args;
 709   void *prev, *curr;
 710   const char *prev_msg, *curr_msg;
 711
 712   ACQUIRE_LOCK_FOR_CURRENT_SCOPE (&log_lock);
 713
 714   prev = memmem (log_buf, log_len, msg, strlen (msg));
 715   if (prev == NULL) no_message_error (msg);
 716   prev_msg = msg;
 717
 718   va_start (args, msg);
 719   while ((curr_msg = va_arg (args, char *)) != NULL) {
 720     curr = memmem (log_buf, log_len, curr_msg, strlen (curr_msg));
 721     if (curr == NULL) no_message_error (curr_msg);
 722     if (prev > curr) messages_out_of_order (prev_msg, curr_msg);
 723     prev_msg = curr_msg;
 724     prev = curr;
 725   }
 726   va_end (args);
 727 }
 728
 729 static void
 730 log_free (void)
 731 {
 732   ACQUIRE_LOCK_FOR_CURRENT_SCOPE (&log_lock);
 733   free (log_buf);
 734   log_buf = NULL;
 735   log_len = 0;
 736 }