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   /* preconnect methods called in outer-to-inner order, complete
 292    * in inner-to-outer order.
 293    */
 294   log_verify_seen_in_order
 295     ("testlayersfilter3: preconnect",
 296      "filter3: test_layers_filter_preconnect",
 297      "testlayersfilter2: preconnect",
 298      "filter2: test_layers_filter_preconnect",
 299      "testlayersfilter1: preconnect",
 300      "filter1: test_layers_filter_preconnect",
 301      "testlayersplugin: preconnect",
 302      "test_layers_plugin_preconnect",
 303      NULL);
 304
 305   /* open methods called in outer-to-inner order, but thanks to next
 306    * pointer, complete in inner-to-outer order. */
 307   log_verify_seen_in_order
 308     ("testlayersfilter3: open readonly=0",
 309      "testlayersfilter2: open readonly=0",
 310      "testlayersfilter1: open readonly=0",
 311      "testlayersplugin: open readonly=0",
 312      "test_layers_plugin_open",
 313      "filter1: test_layers_filter_open",
 314      "filter2: test_layers_filter_open",
 315      "filter3: test_layers_filter_open",
 316      NULL);
 317
 318   /* prepare methods called in inner-to-outer order.
 319    *
 320    * Note that prepare methods only exist for filters, and they must
 321    * be called from inner to outer (but finalize methods below are
 322    * called the other way around).
 323    */
 324   log_verify_seen_in_order
 325     ("filter1: test_layers_filter_prepare",
 326      "filter2: test_layers_filter_prepare",
 327      "filter3: test_layers_filter_prepare",
 328      NULL);
 329
 330   /* get_size methods called in order. */
 331   log_verify_seen_in_order
 332     ("filter3: test_layers_filter_get_size",
 333      "filter2: test_layers_filter_get_size",
 334      "filter1: test_layers_filter_get_size",
 335      "test_layers_plugin_get_size",
 336      NULL);
 337
 338   /* can_* / is_* methods called in order. */
 339   log_verify_seen_in_order
 340     ("filter3: test_layers_filter_can_write",
 341      "filter2: test_layers_filter_can_write",
 342      "filter1: test_layers_filter_can_write",
 343      "test_layers_plugin_can_write",
 344      NULL);
 345   log_verify_seen_in_order
 346     ("filter3: test_layers_filter_can_zero",
 347      "filter2: test_layers_filter_can_zero",
 348      "filter1: test_layers_filter_can_zero",
 349      "test_layers_plugin_can_zero",
 350      NULL);
 351   log_verify_seen_in_order
 352     ("filter3: test_layers_filter_can_trim",
 353      "filter2: test_layers_filter_can_trim",
 354      "filter1: test_layers_filter_can_trim",
 355      "test_layers_plugin_can_trim",
 356      NULL);
 357   log_verify_seen_in_order
 358     ("filter3: test_layers_filter_can_fua",
 359      "filter2: test_layers_filter_can_fua",
 360      "filter1: test_layers_filter_can_fua",
 361      "test_layers_plugin_can_fua",
 362      NULL);
 363   log_verify_seen_in_order
 364     ("filter3: test_layers_filter_can_flush",
 365      "filter2: test_layers_filter_can_flush",
 366      "filter1: test_layers_filter_can_flush",
 367      "test_layers_plugin_can_flush",
 368      NULL);
 369   log_verify_seen_in_order
 370     ("filter3: test_layers_filter_is_rotational",
 371      "filter2: test_layers_filter_is_rotational",
 372      "filter1: test_layers_filter_is_rotational",
 373      "test_layers_plugin_is_rotational",
 374      NULL);
 375   log_verify_seen_in_order
 376     ("filter3: test_layers_filter_can_multi_conn",
 377      "filter2: test_layers_filter_can_multi_conn",
 378      "filter1: test_layers_filter_can_multi_conn",
 379      "test_layers_plugin_can_multi_conn",
 380      NULL);
 381   log_verify_seen_in_order
 382     ("filter3: test_layers_filter_can_extents",
 383      "filter2: test_layers_filter_can_extents",
 384      "filter1: test_layers_filter_can_extents",
 385      "test_layers_plugin_can_extents",
 386      NULL);
 387   log_verify_seen_in_order
 388     ("filter3: test_layers_filter_can_cache",
 389      "filter2: test_layers_filter_can_cache",
 390      "filter1: test_layers_filter_can_cache",
 391      "test_layers_plugin_can_cache",
 392      NULL);
 393
 394   fprintf (stderr, "%s: protocol connected\n", program_name);
 395
 396   /* Send one command of each type. */
 397   request.magic = htobe32 (NBD_REQUEST_MAGIC);
 398   request.handle = htobe64 (0);
 399
 400   request.type = htobe16 (NBD_CMD_READ);
 401   request.offset = htobe64 (0);
 402   request.count = htobe32 (512);
 403   request.flags = htobe16 (0);
 404   if (send (sock, &request, sizeof request, 0) != sizeof request) {
 405     perror ("send: NBD_CMD_READ");
 406     exit (EXIT_FAILURE);
 407   }
 408   if (recv (sock, &reply, sizeof reply, MSG_WAITALL) != sizeof reply) {
 409     perror ("recv: NBD_CMD_READ reply");
 410     exit (EXIT_FAILURE);
 411   }
 412   if (reply.error != NBD_SUCCESS) {
 413     fprintf (stderr, "%s: NBD_CMD_READ failed with %d\n",
 414              program_name, reply.error);
 415     exit (EXIT_FAILURE);
 416   }
 417   if (recv (sock, data, sizeof data, MSG_WAITALL) != sizeof data) {
 418     perror ("recv: NBD_CMD_READ data");
 419     exit (EXIT_FAILURE);
 420   }
 421
 422   short_sleep ();
 423   log_verify_seen_in_order
 424     ("testlayersfilter3: pread count=512 offset=0",
 425      "filter3: test_layers_filter_pread",
 426      "testlayersfilter2: pread count=512 offset=0",
 427      "filter2: test_layers_filter_pread",
 428      "testlayersfilter1: pread count=512 offset=0",
 429      "filter1: test_layers_filter_pread",
 430      "testlayersplugin: pread count=512 offset=0",
 431      "test_layers_plugin_pread",
 432      NULL);
 433
 434   request.type = htobe16 (NBD_CMD_WRITE);
 435   request.offset = htobe64 (0);
 436   request.count = htobe32 (512);
 437   request.flags = htobe16 (0);
 438   if (send (sock, &request, sizeof request, 0) != sizeof request) {
 439     perror ("send: NBD_CMD_WRITE");
 440     exit (EXIT_FAILURE);
 441   }
 442   if (send (sock, data, sizeof data, 0) != sizeof data) {
 443     perror ("send: NBD_CMD_WRITE data");
 444     exit (EXIT_FAILURE);
 445   }
 446   if (recv (sock, &reply, sizeof reply, MSG_WAITALL) != sizeof reply) {
 447     perror ("recv: NBD_CMD_WRITE");
 448     exit (EXIT_FAILURE);
 449   }
 450   if (reply.error != NBD_SUCCESS) {
 451     fprintf (stderr, "%s: NBD_CMD_WRITE failed with %d\n",
 452              program_name, reply.error);
 453     exit (EXIT_FAILURE);
 454   }
 455
 456   short_sleep ();
 457   log_verify_seen_in_order
 458     ("testlayersfilter3: pwrite count=512 offset=0 fua=0",
 459      "filter3: test_layers_filter_pwrite",
 460      "testlayersfilter2: pwrite count=512 offset=0 fua=0",
 461      "filter2: test_layers_filter_pwrite",
 462      "testlayersfilter1: pwrite count=512 offset=0 fua=0",
 463      "filter1: test_layers_filter_pwrite",
 464      "testlayersplugin: pwrite count=512 offset=0 fua=0",
 465      "test_layers_plugin_pwrite",
 466      NULL);
 467
 468   request.type = htobe16 (NBD_CMD_FLUSH);
 469   request.offset = htobe64 (0);
 470   request.count = htobe32 (0);
 471   request.flags = htobe16 (0);
 472   if (send (sock, &request, sizeof request, 0) != sizeof request) {
 473     perror ("send: NBD_CMD_FLUSH");
 474     exit (EXIT_FAILURE);
 475   }
 476   if (recv (sock, &reply, sizeof reply, MSG_WAITALL) != sizeof reply) {
 477     perror ("recv: NBD_CMD_FLUSH");
 478     exit (EXIT_FAILURE);
 479   }
 480   if (reply.error != NBD_SUCCESS) {
 481     fprintf (stderr, "%s: NBD_CMD_FLUSH failed with %d\n",
 482              program_name, reply.error);
 483     exit (EXIT_FAILURE);
 484   }
 485
 486   short_sleep ();
 487   log_verify_seen_in_order
 488     ("testlayersfilter3: flush",
 489      "filter3: test_layers_filter_flush",
 490      "testlayersfilter2: flush",
 491      "filter2: test_layers_filter_flush",
 492      "testlayersfilter1: flush",
 493      "filter1: test_layers_filter_flush",
 494      "testlayersplugin: flush",
 495      "test_layers_plugin_flush",
 496      NULL);
 497
 498   request.type = htobe16 (NBD_CMD_TRIM);
 499   request.offset = htobe64 (0);
 500   request.count = htobe32 (512);
 501   request.flags = htobe16 (0);
 502   if (send (sock, &request, sizeof request, 0) != sizeof request) {
 503     perror ("send: NBD_CMD_TRIM");
 504     exit (EXIT_FAILURE);
 505   }
 506   if (recv (sock, &reply, sizeof reply, MSG_WAITALL) != sizeof reply) {
 507     perror ("recv: NBD_CMD_TRIM");
 508     exit (EXIT_FAILURE);
 509   }
 510   if (reply.error != NBD_SUCCESS) {
 511     fprintf (stderr, "%s: NBD_CMD_TRIM failed with %d\n",
 512              program_name, reply.error);
 513     exit (EXIT_FAILURE);
 514   }
 515
 516   short_sleep ();
 517   log_verify_seen_in_order
 518     ("testlayersfilter3: trim count=512 offset=0 fua=0",
 519      "filter3: test_layers_filter_trim",
 520      "testlayersfilter2: trim count=512 offset=0 fua=0",
 521      "filter2: test_layers_filter_trim",
 522      "testlayersfilter1: trim count=512 offset=0 fua=0",
 523      "filter1: test_layers_filter_trim",
 524      "testlayersplugin: trim count=512 offset=0 fua=0",
 525      "test_layers_plugin_trim",
 526      NULL);
 527
 528   request.type = htobe16 (NBD_CMD_WRITE_ZEROES);
 529   request.offset = htobe64 (0);
 530   request.count = htobe32 (512);
 531   request.flags = htobe16 (0);
 532   if (send (sock, &request, sizeof request, 0) != sizeof request) {
 533     perror ("send: NBD_CMD_WRITE_ZEROES");
 534     exit (EXIT_FAILURE);
 535   }
 536   if (recv (sock, &reply, sizeof reply, MSG_WAITALL) != sizeof reply) {
 537     perror ("recv: NBD_CMD_WRITE_ZEROES");
 538     exit (EXIT_FAILURE);
 539   }
 540   if (reply.error != NBD_SUCCESS) {
 541     fprintf (stderr, "%s: NBD_CMD_WRITE_ZEROES failed with %d\n",
 542              program_name, reply.error);
 543     exit (EXIT_FAILURE);
 544   }
 545
 546   short_sleep ();
 547   log_verify_seen_in_order
 548     ("testlayersfilter3: zero count=512 offset=0 may_trim=1 fua=0 fast=0",
 549      "filter3: test_layers_filter_zero",
 550      "testlayersfilter2: zero count=512 offset=0 may_trim=1 fua=0 fast=0",
 551      "filter2: test_layers_filter_zero",
 552      "testlayersfilter1: zero count=512 offset=0 may_trim=1 fua=0 fast=0",
 553      "filter1: test_layers_filter_zero",
 554      "testlayersplugin: zero count=512 offset=0 may_trim=1 fua=0 fast=0",
 555      "test_layers_plugin_zero",
 556      NULL);
 557
 558   request.type = htobe16 (NBD_CMD_CACHE);
 559   request.offset = htobe64 (0);
 560   request.count = htobe32 (512);
 561   request.flags = htobe16 (0);
 562   if (send (sock, &request, sizeof request, 0) != sizeof request) {
 563     perror ("send: NBD_CMD_CACHE");
 564     exit (EXIT_FAILURE);
 565   }
 566   if (recv (sock, &reply, sizeof reply, MSG_WAITALL) != sizeof reply) {
 567     perror ("recv: NBD_CMD_CACHE");
 568     exit (EXIT_FAILURE);
 569   }
 570   if (reply.error != NBD_SUCCESS) {
 571     fprintf (stderr, "%s: NBD_CMD_CACHE failed with %d\n",
 572              program_name, reply.error);
 573     exit (EXIT_FAILURE);
 574   }
 575
 576   short_sleep ();
 577   log_verify_seen_in_order
 578     ("testlayersfilter3: cache count=512 offset=0",
 579      "filter3: test_layers_filter_cache",
 580      "testlayersfilter2: cache count=512 offset=0",
 581      "filter2: test_layers_filter_cache",
 582      "testlayersfilter1: cache count=512 offset=0",
 583      "filter1: test_layers_filter_cache",
 584      "testlayersplugin: cache count=512 offset=0",
 585      "test_layers_plugin_cache",
 586      NULL);
 587
 588   /* XXX We should test NBD_CMD_BLOCK_STATUS here.  However it
 589    * requires that we negotiate structured replies and base:allocation
 590    * in the handshake, and the format of the reply is more complex
 591    * than what we expect in this naive test.
 592    */
 593
 594   /* Close the connection. */
 595   fprintf (stderr, "%s: closing the connection\n", program_name);
 596   request.type = htobe16 (NBD_CMD_DISC);
 597   request.offset = htobe64 (0);
 598   request.count = htobe32 (0);
 599   request.flags = htobe16 (0);
 600   if (send (sock, &request, sizeof request, 0) != sizeof request) {
 601     perror ("send: NBD_CMD_DISC");
 602     exit (EXIT_FAILURE);
 603   }
 604   /* (no reply from NBD_CMD_DISC) */
 605   close (sock);
 606
 607   /* Clean up the child process. */
 608   if (waitpid (pid, NULL, 0) == -1)
 609     perror ("waitpid");
 610
 611   /* finalize methods called in reverse order of prepare */
 612   short_sleep ();
 613   log_verify_seen_in_order
 614     ("filter3: test_layers_filter_finalize",
 615      "filter2: test_layers_filter_finalize",
 616      "filter1: test_layers_filter_finalize",
 617      NULL);
 618
 619   /* close methods called outer-to-inner, which is reverse of completion
 620    * of open */
 621   log_verify_seen_in_order
 622     ("filter3: test_layers_filter_close",
 623      "filter2: test_layers_filter_close",
 624      "filter1: test_layers_filter_close",
 625      "test_layers_plugin_close",
 626      NULL);
 627
 628   /* unload methods should be run in any order. */
 629   log_verify_seen ("test_layers_plugin_unload");
 630   log_verify_seen ("filter1: test_layers_filter_unload");
 631   log_verify_seen ("filter2: test_layers_filter_unload");
 632   log_verify_seen ("filter3: test_layers_filter_unload");
 633
 634   log_free ();
 635
 636   exit (EXIT_SUCCESS);
 637 }
 638
 639 /* The log from nbdkit is captured in a separate thread. */
 640 static char *log_buf = NULL;
 641 static size_t log_len = 0;
 642 static pthread_mutex_t log_lock = PTHREAD_MUTEX_INITIALIZER;
 643
 644 static void *
 645 start_log_capture (void *arg)
 646 {
 647   int fd = *(int *)arg;
 648   size_t allocated = 0;
 649   ssize_t r;
 650
 651   for (;;) {
 652     {
 653       ACQUIRE_LOCK_FOR_CURRENT_SCOPE (&log_lock);
 654       if (allocated <= log_len) {
 655         allocated += 4096;
 656         log_buf = realloc (log_buf, allocated);
 657         if (log_buf == NULL) {
 658           perror ("log: realloc");
 659           exit (EXIT_FAILURE);
 660         }
 661       }
 662     }
 663
 664     r = read (fd, &log_buf[log_len], allocated-log_len);
 665     if (r == -1) {
 666       perror ("log: read");
 667       exit (EXIT_FAILURE);
 668     }
 669     if (r == 0)
 670       break;
 671
 672     /* Dump the log as we receive it to stderr, for debugging. */
 673     if (write (2, &log_buf[log_len], r) == -1)
 674       perror ("log: write");
 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 /* These functions are called from the main thread to verify messages
 685  * appeared as expected in the log.
 686  *
 687  * NB: The log buffer is NOT \0-terminated.
 688  */
 689
 690 static void no_message_error (const char *msg) __attribute__((noreturn));
 691
 692 static void
 693 no_message_error (const char *msg)
 694 {
 695   fprintf (stderr, "%s: did not find expected message \"%s\"\n",
 696            program_name, msg);
 697   exit (EXIT_FAILURE);
 698 }
 699
 700 static void
 701 log_verify_seen (const char *msg)
 702 {
 703   ACQUIRE_LOCK_FOR_CURRENT_SCOPE (&log_lock);
 704   if (memmem (log_buf, log_len, msg, strlen (msg)) == NULL)
 705     no_message_error (msg);
 706 }
 707
 708 static void messages_out_of_order (const char *msg1, const char *msg2)
 709   __attribute__((noreturn));
 710
 711 static void
 712 messages_out_of_order (const char *msg1, const char *msg2)
 713 {
 714   fprintf (stderr, "%s: message \"%s\" expected before message \"%s\"\n",
 715            program_name, msg1, msg2);
 716   exit (EXIT_FAILURE);
 717 }
 718
 719 static void
 720 log_verify_seen_in_order (const char *msg, ...)
 721 {
 722   va_list args;
 723   void *prev, *curr;
 724   const char *prev_msg, *curr_msg;
 725
 726   ACQUIRE_LOCK_FOR_CURRENT_SCOPE (&log_lock);
 727
 728   prev = memmem (log_buf, log_len, msg, strlen (msg));
 729   if (prev == NULL) no_message_error (msg);
 730   prev_msg = msg;
 731
 732   va_start (args, msg);
 733   while ((curr_msg = va_arg (args, char *)) != NULL) {
 734     curr = memmem (log_buf, log_len, curr_msg, strlen (curr_msg));
 735     if (curr == NULL) no_message_error (curr_msg);
 736     if (prev > curr) messages_out_of_order (prev_msg, curr_msg);
 737     prev_msg = curr_msg;
 738     prev = curr;
 739   }
 740   va_end (args);
 741 }
 742
 743 static void
 744 log_free (void)
 745 {
 746   ACQUIRE_LOCK_FOR_CURRENT_SCOPE (&log_lock);
 747   free (log_buf);
 748   log_buf = NULL;
 749   log_len = 0;
 750 }