[Libguestfs] nbdkit Assertion `h->can_flush == 1' failed on Arch

[Richard W.M. Jones]

https://aur.archlinux.org/packages/nbdkit/#comment-733981 reports that
tests-parallel-nbd.sh hangs.  Looking at the log file from the test
reveals:

nbdkit: backend.c:523: backend_flush: Assertion `h->can_flush == 1' failed.

I've attached the full log.  If you want to see other logs from the
run (probably not relevant) then download
https://svenne.dk/nbdkit-20200315/nbdkit-logs-20200315.tar.gz

I believe the assertion comes from calling flush when can_flush
previously returned false, but also I don't quite understand why the
server is doing this.

However I think the wider problem is that the reporter is using the
non-libnbd "standalone" nbd plugin.  I basically never test this any
longer.  I wonder if we should think about either having a way to
routinely test it despite libnbd being installed, or simply dropping
it?

I will ask the reporter if they can try installing libnbd.

Rich.

-- 
Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones
Read my programming and virtualization blog: http://rwmj.wordpress.com
virt-p2v converts physical machines to virtual machines.  Boot with a
live CD or over the network (PXE) and turn machines into KVM guests.
http://libguestfs.org/virt-v2v
-------------- next part --------------
wrote 512/512 bytes at offset 512
512 bytes, 1 ops; 00.01 sec (38.349 KiB/sec and 76.6986 ops/sec)
wrote 512/512 bytes at offset 0
512 bytes, 1 ops; 00.01 sec (37.533 KiB/sec and 75.0660 ops/sec)
/home/sk/tmp/yay/nbdkit/src/nbdkit-1.18.0/server/nbdkit -v -P test-parallel-nbd.pid -U /tmp/tmp.mt7pumbkpL --filter=/home/sk/tmp/yay/nbdkit/src/nbdkit-1.18.0/filters/delay/.libs/nbdkit-delay-filter.so -- /home/sk/tmp/yay/nbdkit/src/nbdkit-1.18.0/plugins/file/.libs/nbdkit-file-plugin.so test-parallel-nbd.data wdelay=2 rdelay=1
nbdkit: debug: TLS disabled: could not load TLS certificates
nbdkit: debug: registering plugin /home/sk/tmp/yay/nbdkit/src/nbdkit-1.18.0/plugins/file/.libs/nbdkit-file-plugin.so
nbdkit: debug: registered plugin /home/sk/tmp/yay/nbdkit/src/nbdkit-1.18.0/plugins/file/.libs/nbdkit-file-plugin.so (name file)
nbdkit: debug: file: load
nbdkit: debug: registering filter /home/sk/tmp/yay/nbdkit/src/nbdkit-1.18.0/filters/delay/.libs/nbdkit-delay-filter.so
nbdkit: debug: registered filter /home/sk/tmp/yay/nbdkit/src/nbdkit-1.18.0/filters/delay/.libs/nbdkit-delay-filter.so (name delay)
nbdkit: debug: delay: load
nbdkit: debug: delay: config key=file, value=test-parallel-nbd.data
nbdkit: debug: file: config key=file, value=test-parallel-nbd.data
nbdkit: debug: delay: config key=wdelay, value=2
nbdkit: debug: delay: config key=rdelay, value=1
nbdkit: debug: delay: config_complete
nbdkit: debug: file: config_complete
nbdkit: debug: using thread model: parallel
nbdkit: debug: delay: get_ready
nbdkit: debug: file: get_ready
nbdkit: debug: bound to unix socket /tmp/tmp.mt7pumbkpL
nbdkit: debug: forked into background (new pid = 23751)
nbdkit: debug: written pidfile /home/sk/tmp/yay/nbdkit/src/nbdkit-1.18.0/tests/test-parallel-nbd.pid
/home/sk/tmp/yay/nbdkit/src/nbdkit-1.18.0/server/nbdkit -v -t 1 -U - "--run=
  qemu-io -f raw -c \"aio_write -P 2 512 512\" -c \"aio_read -P 1 0 512\" \\
  -c aio_flush \$nbd" -- /home/sk/tmp/yay/nbdkit/src/nbdkit-1.18.0/plugins/nbd/.libs/nbdkit-nbd-plugin.so socket=/tmp/tmp.mt7pumbkpL
nbdkit: debug: TLS disabled: could not load TLS certificates
nbdkit: debug: registering plugin /home/sk/tmp/yay/nbdkit/src/nbdkit-1.18.0/plugins/nbd/.libs/nbdkit-nbd-plugin.so
nbdkit: debug: registered plugin /home/sk/tmp/yay/nbdkit/src/nbdkit-1.18.0/plugins/nbd/.libs/nbdkit-nbd-plugin.so (name nbd)
nbdkit: debug: nbd: load
nbdkit: debug: nbd: config key=socket, value=/tmp/tmp.mt7pumbkpL
nbdkit: debug: nbd: config_complete
nbdkit: debug: using thread model: parallel
nbdkit: debug: nbd: get_ready
nbdkit: debug: bound to unix socket /tmp/nbdkitf5Ud3i/socket
nbdkit: debug: forked into background (new pid = 23755)
nbdkit: debug: accepted connection
nbdkit: nbd[1]: debug: nbd: preconnect
nbdkit: nbd[1]: debug: newstyle negotiation: flags: global 0x3
nbdkit: nbd[1]: debug: newstyle negotiation: client flags: 0x3
nbdkit: nbd[1]: debug: newstyle negotiation: NBD_OPT_STRUCTURED_REPLY: client requested structured replies
nbdkit: nbd[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: client requested export ''
nbdkit: nbd[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: set count: 1
nbdkit: nbd[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: set base:allocation
nbdkit: nbd[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: replying with base:allocation id 1
nbdkit: nbd[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: reply complete
nbdkit: nbd[1]: debug: newstyle negotiation: NBD_OPT_GO: client requested export ''
nbdkit: nbd[1]: debug: nbd: open readonly=0
nbdkit: nbd[1]: debug: connecting to Unix socket name=/tmp/tmp.mt7pumbkpL
nbdkit: debug: accepted connection
nbdkit: file[1]: debug: delay: preconnect
nbdkit: file[1]: debug: file: preconnect
nbdkit: file[1]: debug: newstyle negotiation: flags: global 0x3
nbdkit: nbd[1]: debug: trying newstyle connection
nbdkit: nbd[1]: debug: trying NBD_OPT_STRUCTURED_REPLY
nbdkit: file[1]: debug: newstyle negotiation: client flags: 0x3
nbdkit: file[1]: debug: newstyle negotiation: NBD_OPT_STRUCTURED_REPLY: client requested structured replies
nbdkit: nbd[1]: debug: structured replies enabled, trying NBD_OPT_SET_META_CONTEXT
nbdkit: file[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: client requested export ''
nbdkit: file[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: set count: 1
nbdkit: file[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: set base:allocation
nbdkit: file[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: replying with base:allocation id 1
nbdkit: nbdkit: filenbd[1][1]: : debug: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: reply completeignoring option reply payload

nbdkit: nbd[1]: debug: extents enabled
nbdkit: nbd[1]: debug: trying NBD_OPT_GO
nbdkit: file[1]: debug: newstyle negotiation: NBD_OPT_GO: client requested export ''
nbdkit: file[1]: debug: delay: open readonly=0
nbdkit: file[1]: debug: file: open readonly=0
nbdkit: file[1]: debug: file: open returned handle 0x56350a073a10
nbdkit: file[1]: debug: delay: open returned handle 0x7f092aaa1588
nbdkit: file[1]: debug: file: prepare readonly=0
nbdkit: file[1]: debug: delay: prepare readonly=0
nbdkit: file[1]: debug: delay: get_size
nbdkit: file[1]: debug: file: get_size
nbdkit: file[1]: debug: delay: can_write
nbdkit: file[1]: debug: file: can_write
nbdkit: file[1]: debug: delay: can_zero
nbdkit: file[1]: debug: file: can_zero
nbdkit: file[1]: debug: delay: can_fast_zero
nbdkit: file[1]: debug: file: can_fast_zero
nbdkit: file[1]: debug: delay: can_trim
nbdkit: file[1]: debug: file: can_trim
nbdkit: file[1]: debug: delay: can_fua
nbdkit: file[1]: debug: file: can_fua
nbdkit: file[1]: debug: delay: can_flush
nbdkit: file[1]: debug: file: can_flush
nbdkit: file[1]: debug: delay: is_rotational
nbdkit: file[1]: debug: file: is_rotational
nbdkit: file[1]: debug: delay: can_multi_conn
nbdkit: file[1]: debug: file: can_multi_conn
nbdkit: file[1]: debug: delay: can_cache
nbdkit: file[1]: debug: file: can_cache
nbdkit: file[1]: debug: delay: can_extents
nbdkit: file[1]: debug: file: can_extents
nbdkit: file[1]: debug: newstyle negotiation: flags: export 0x5ed
nbdkit: nbdkit: filenbd[1][1]: : debug: debug: handshake complete, processing requests with 16 threadsNBD_OPT_GO complete

nbdkit: nbdnbdkit: [1]debug: : starting worker thread file.0debug: 
nbd: open returned handle 0x55e6765d1160
nbdkit: nbd[1]nbdkit: : debug: debug: starting worker thread file.1nbd: prepare readonly=0

nbdkit: nbd[1]nbdkit: : debug: debug: starting worker thread file.2nbd: get_size

nbdkit: nbd[1]nbdkit: : debug: debug: starting worker thread file.5nbd: can_write

nbdkit: nbd[1]: nbdkit: debug: debug: nbd: can_zerostarting worker thread file.4

nbdkit: nbd[1]: nbdkit: debug: debug: nbd: can_fast_zerostarting worker thread file.3

nbdkit: nbd[1]: debug: nbdkit: nbd: can_trimdebug: 
starting worker thread file.6nbdkit: 
nbd[1]: debug: nbdkit: nbd: can_fuadebug: 
starting worker thread file.7nbdkit: 
nbd[1]: debug: nbdkit: nbd: can_flushdebug: 
starting worker thread file.8nbdkit: 
nbd[1]: nbdkit: debug: debug: nbd: is_rotationalstarting worker thread file.9

nbdkit: nbd[1]: debug: nbdkit: nbd: can_multi_conndebug: 
starting worker thread file.10nbdkit: 
nbd[1]: debug: nbd: can_cachenbdkit: 
debug: nbdkit: starting worker thread file.11nbd
[1]: debug: nbd: can_extentsnbdkit: 
debug: nbdkit: starting worker thread file.12nbd
[1]: debug: nbdkit: newstyle negotiation: flags: export 0x5eddebug: 
starting worker thread file.13
nbdkit: nbd[1]nbdkit: : debug: debug: starting worker thread file.15newstyle negotiation: NBD_OPT_GO: ignoring NBD_INFO_* request 3 (NBD_INFO_BLOCK_SIZE)

nbdkit: nbdkit: nbddebug: [1]starting worker thread file.14: 
debug: handshake complete, processing requests serially
nbdkit: nbd[1]: debug: nbd: pwrite count=512 offset=512 fua=1
nbdkit: nbd[1]: debug: sending request type 1 (NBD_CMD_WRITE), flags 0x1, offset 0x200, count 0x200, cookie 0
nbdkit: file.0: debug: delay: pwrite count=512 offset=512 fua=1
nbdkit: file.0: debug: file: pwrite count=512 offset=512 fua=1
nbdkit: debug: received simple reply for cookie 0, status NBD_SUCCESS
nbdkit: nbd[1]: debug: nbd: pread count=512 offset=0
nbdkit: nbd[1]: debug: sending request type 0 (NBD_CMD_READ), flags 0, offset 0, count 0x200, cookie 0x1
nbdkit: file.1: debug: delay: pread count=512 offset=0
nbdkit: file.1: debug: file: pread count=512 offset=0
nbdkit: debug: received structured reply NBD_REPLY_TYPE_OFFSET_DATA for cookie 0x1, payload length 520
nbdkit: backend.c:523: backend_flush: Assertion `h->can_flush == 1' failed.
nbdkit: file.2: debug: client closed input socket, closing connection
nbdkit: file.2: debug: exiting worker thread file.2
nbdkit: file.5: debug: exiting worker thread file.5
nbdkit: file.4: debug: exiting worker thread file.4
nbdkit: file.3: debug: exiting worker thread file.3
nbdkit: file.9: debug: exiting worker thread file.9
nbdkit: file.12: debug: exiting worker thread file.12
nbdkit: file.15: debug: exiting worker thread file.15
nbdkit: file.0: debug: exiting worker thread file.0
nbdkit: file.8: debug: exiting worker thread file.8
nbdkit: file.11: debug: exiting worker thread file.11
nbdkit: file.13: debug: exiting worker thread file.13
nbdkit: file.7: debug: exiting worker thread file.7
nbdkit: file.14: debug: exiting worker thread file.14
nbdkit: file.1: debug: exiting worker thread file.1
nbdkit: file.6: debug: exiting worker thread file.6
nbdkit: file.10: debug: exiting worker thread file.10
nbdkit: file[1]: debug: delay: finalize
nbdkit: file[1]: debug: file: finalize
nbdkit: file[1]: debug: delay: close
nbdkit: file[1]: debug: file: close