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