[Libguestfs] [nbdkit] Failure in test-retry-size.sh

This happened on s390 in Koji, once. The key lines from the log are: + start_t=0 nbdkit: sh[1]: debug: retry 1: waiting 1 seconds before retrying nbdkit: sh[1]: debug: retry 1: waiting 1 seconds before retrying + end_t=1 Somehow nbdkit did wait 2 seconds (or at least, nbdkit_nanosleep (1, 0) was called twice by the retry filter). But in the bash script, time (as measured by $SECONDS) advanced from 0 to 1. I'm not sure I can explain that ... It should be possible to make the test more robust by increasing the retry time and subtracting a bit of slop in the test of end_t - start_t, but I'd like to come up with at least a plausible explanation for this first. Rich. + fail=0 + requires qemu-io --version + requires dd iflag=count_bytes + files='retry-size-open-count retry-size-fail' + rm -f retry-size-open-count retry-size-fail + cleanup_fn rm -f retry-size-open-count retry-size-fail + _cleanup_hook[${#_cleanup_hook[@]}]='rm -f retry-size-open-count retry-size-fail' + touch retry-size-open-count + start_t=0 + st=0 + nbdkit -v -U - sh - --filter=retry retry-delay=1 --run 'qemu-io -f raw -r $nbd \ -c "r 0 512" -c "r 512 512"' /builddir/build/BUILD/nbdkit-1.21.20/server/nbdkit -v -U - --filter=/builddir/build/BUILD/nbdkit-1.21.20/filters/retry/.libs/nbdkit-retry-filter.so "--run=qemu-io -f raw -r \$nbd \\ -c \"r 0 512\" -c \"r 512 512\"" -- /builddir/build/BUILD/nbdkit-1.21.20/plugins/sh/.libs/nbdkit-sh-plugin.so - retry-delay=1 nbdkit: debug: TLS disabled: could not load TLS certificates nbdkit: debug: registering plugin /builddir/build/BUILD/nbdkit-1.21.20/plugins/sh/.libs/nbdkit-sh-plugin.so nbdkit: debug: registered plugin /builddir/build/BUILD/nbdkit-1.21.20/plugins/sh/.libs/nbdkit-sh-plugin.so (name sh) nbdkit: debug: sh: load nbdkit: debug: load: tmpdir: /tmp/nbdkitpKY00D nbdkit: debug: registering filter /builddir/build/BUILD/nbdkit-1.21.20/filters/retry/.libs/nbdkit-retry-filter.so nbdkit: debug: registered filter /builddir/build/BUILD/nbdkit-1.21.20/filters/retry/.libs/nbdkit-retry-filter.so (name retry) nbdkit: debug: retry: load nbdkit: debug: retry: config key=script, value=- nbdkit: debug: sh: config key=script, value=- nbdkit: debug: calling: /tmp/nbdkitpKY00D/inline-script.sh load nbdkit: debug: completed: /tmp/nbdkitpKY00D/inline-script.sh load: status 2 nbdkit: debug: calling: /tmp/nbdkitpKY00D/inline-script.sh magic_config_key nbdkit: debug: completed: /tmp/nbdkitpKY00D/inline-script.sh magic_config_key: status 2 nbdkit: debug: retry: config key=retry-delay, value=1 nbdkit: debug: retry: config_complete nbdkit: debug: sh: config_complete nbdkit: debug: calling: /tmp/nbdkitpKY00D/inline-script.sh config_complete nbdkit: debug: completed: /tmp/nbdkitpKY00D/inline-script.sh config_complete: status 2 nbdkit: debug: calling: /tmp/nbdkitpKY00D/inline-script.sh thread_model nbdkit: debug: completed: /tmp/nbdkitpKY00D/inline-script.sh thread_model: status 2 nbdkit: debug: using thread model: serialize_all_requests nbdkit: debug: retry: get_ready nbdkit: debug: sh: get_ready nbdkit: debug: calling: /tmp/nbdkitpKY00D/inline-script.sh get_ready nbdkit: debug: completed: /tmp/nbdkitpKY00D/inline-script.sh get_ready: status 2 nbdkit: debug: bound to unix socket /tmp/nbdkitEtiOcF/socket nbdkit: debug: forked into background (new pid = 4095481) nbdkit: debug: retry: after_fork nbdkit: debug: sh: after_fork nbdkit: debug: calling: /tmp/nbdkitpKY00D/inline-script.sh after_fork nbdkit: debug: completed: /tmp/nbdkitpKY00D/inline-script.sh after_fork: status 2 nbdkit: debug: accepted connection nbdkit: sh[1]: debug: retry: preconnect nbdkit: sh[1]: debug: sh: preconnect nbdkit: sh[1]: debug: calling: /tmp/nbdkitpKY00D/inline-script.sh preconnect false "" nbdkit: sh[1]: debug: completed: /tmp/nbdkitpKY00D/inline-script.sh preconnect: status 2 nbdkit: sh[1]: debug: newstyle negotiation: flags: global 0x3 nbdkit: sh[1]: debug: newstyle negotiation: client flags: 0x3 nbdkit: sh[1]: debug: newstyle negotiation: NBD_OPT_STRUCTURED_REPLY: client requested structured replies nbdkit: sh[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: client requested export '' nbdkit: sh[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: set count: 1 nbdkit: sh[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: set base:allocation nbdkit: sh[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: replying with base:allocation id 1 nbdkit: sh[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: reply complete nbdkit: sh[1]: debug: newstyle negotiation: NBD_OPT_GO: client requested export '' nbdkit: sh[1]: debug: retry: open readonly=0 exportname="" nbdkit: sh[1]: debug: sh: open readonly=0 exportname="" nbdkit: sh[1]: debug: calling: /tmp/nbdkitpKY00D/inline-script.sh open false "" nbdkit: sh[1]: debug: completed: /tmp/nbdkitpKY00D/inline-script.sh open: status 0 nbdkit: sh[1]: debug: sh: open returned handle 0x2aa2a0ee2a0 nbdkit: sh[1]: debug: retry: open returned handle 0x2aa2a10e5c0 nbdkit: sh[1]: debug: sh: prepare readonly=0 nbdkit: sh[1]: debug: retry: prepare readonly=0 nbdkit: sh[1]: debug: retry: get_size nbdkit: sh[1]: debug: sh: get_size nbdkit: sh[1]: debug: calling: /tmp/nbdkitpKY00D/inline-script.sh get_size "" nbdkit: sh[1]: debug: completed: /tmp/nbdkitpKY00D/inline-script.sh get_size: status 0 nbdkit: sh[1]: debug: retry: can_write nbdkit: sh[1]: debug: sh: can_write nbdkit: sh[1]: debug: calling: /tmp/nbdkitpKY00D/inline-script.sh can_write "" nbdkit: sh[1]: debug: completed: /tmp/nbdkitpKY00D/inline-script.sh can_write: status 2 nbdkit: sh[1]: debug: retry: can_zero nbdkit: sh[1]: debug: retry: can_fast_zero nbdkit: sh[1]: debug: retry: can_trim nbdkit: sh[1]: debug: retry: can_fua nbdkit: sh[1]: debug: retry: can_flush nbdkit: sh[1]: debug: sh: can_flush nbdkit: sh[1]: debug: calling: /tmp/nbdkitpKY00D/inline-script.sh can_flush "" nbdkit: sh[1]: debug: completed: /tmp/nbdkitpKY00D/inline-script.sh can_flush: status 2 nbdkit: sh[1]: debug: retry: is_rotational nbdkit: sh[1]: debug: sh: is_rotational nbdkit: sh[1]: debug: calling: /tmp/nbdkitpKY00D/inline-script.sh is_rotational "" nbdkit: sh[1]: debug: completed: /tmp/nbdkitpKY00D/inline-script.sh is_rotational: status 2 nbdkit: sh[1]: debug: retry: can_multi_conn nbdkit: sh[1]: debug: sh: can_multi_conn nbdkit: sh[1]: debug: calling: /tmp/nbdkitpKY00D/inline-script.sh can_multi_conn "" nbdkit: sh[1]: debug: completed: /tmp/nbdkitpKY00D/inline-script.sh can_multi_conn: status 2 nbdkit: sh[1]: debug: retry: can_cache nbdkit: sh[1]: debug: sh: can_cache nbdkit: sh[1]: debug: calling: /tmp/nbdkitpKY00D/inline-script.sh can_cache "" nbdkit: sh[1]: debug: completed: /tmp/nbdkitpKY00D/inline-script.sh can_cache: status 2 nbdkit: sh[1]: debug: retry: can_extents nbdkit: sh[1]: debug: sh: can_extents nbdkit: sh[1]: debug: calling: /tmp/nbdkitpKY00D/inline-script.sh can_extents "" nbdkit: sh[1]: debug: completed: /tmp/nbdkitpKY00D/inline-script.sh can_extents: status 2 nbdkit: sh[1]: debug: newstyle negotiation: flags: export 0x83 nbdkit: sh[1]: debug: newstyle negotiation: NBD_OPT_GO: ignoring NBD_INFO_* request 3 (NBD_INFO_BLOCK_SIZE) nbdkit: sh[1]: debug: handshake complete, processing requests serially nbdkit: sh[1]: debug: retry: pread count=512 offset=0 nbdkit: sh[1]: debug: sh: pread count=512 offset=0 nbdkit: sh[1]: debug: calling: /tmp/nbdkitpKY00D/inline-script.sh pread "" 512 0 nbdkit: sh[1]: debug: completed: /tmp/nbdkitpKY00D/inline-script.sh pread: status 1 nbdkit: sh[1]: error: /tmp/nbdkitpKY00D/inline-script.sh: too soon to read nbdkit: sh[1]: debug: pread failed: original errno = 5 nbdkit: sh[1]: debug: retry 1: waiting 1 seconds before retrying nbdkit: sh[1]: debug: sh: reopen readonly=0 exportname="" nbdkit: sh[1]: debug: sh: finalize nbdkit: sh[1]: debug: sh: close nbdkit: sh[1]: debug: calling: /tmp/nbdkitpKY00D/inline-script.sh close "" nbdkit: sh[1]: debug: completed: /tmp/nbdkitpKY00D/inline-script.sh close: status 2 nbdkit: sh[1]: debug: sh: open readonly=0 exportname="" nbdkit: sh[1]: debug: calling: /tmp/nbdkitpKY00D/inline-script.sh open false "" nbdkit: sh[1]: debug: completed: /tmp/nbdkitpKY00D/inline-script.sh open: status 0 nbdkit: sh[1]: debug: sh: open returned handle 0x2aa2a0ee2a0 nbdkit: sh[1]: debug: sh: prepare readonly=0 nbdkit: sh[1]: debug: sh: get_size nbdkit: sh[1]: debug: calling: /tmp/nbdkitpKY00D/inline-script.sh get_size "" nbdkit: sh[1]: debug: completed: /tmp/nbdkitpKY00D/inline-script.sh get_size: status 0 nbdkit: sh[1]: debug: sh: pread count=512 offset=0 nbdkit: sh[1]: debug: calling: /tmp/nbdkitpKY00D/inline-script.sh pread "" 512 0 nbdkit: sh[1]: debug: completed: /tmp/nbdkitpKY00D/inline-script.sh pread: status 0 nbdkit: sh[1]: debug: retry: pread count=512 offset=512 nbdkit: sh[1]: debug: pread failed: original errno = 5 nbdkit: sh[1]: debug: retry 1: waiting 1 seconds before retrying nbdkit: sh[1]: debug: sh: reopen readonly=0 exportname="" nbdkit: sh[1]: debug: sh: finalize nbdkit: sh[1]: debug: sh: close nbdkit: sh[1]: debug: calling: /tmp/nbdkitpKY00D/inline-script.sh close "" nbdkit: sh[1]: debug: completed: /tmp/nbdkitpKY00D/inline-script.sh close: status 2 nbdkit: sh[1]: debug: sh: open readonly=0 exportname="" nbdkit: sh[1]: debug: calling: /tmp/nbdkitpKY00D/inline-script.sh open false "" nbdkit: sh[1]: debug: completed: /tmp/nbdkitpKY00D/inline-script.sh open: status 0 nbdkit: sh[1]: debug: sh: open returned handle 0x2aa2a0ee2a0 nbdkit: sh[1]: debug: sh: prepare readonly=0 nbdkit: sh[1]: debug: sh: get_size nbdkit: sh[1]: debug: calling: /tmp/nbdkitpKY00D/inline-script.sh get_size "" nbdkit: sh[1]: debug: completed: /tmp/nbdkitpKY00D/inline-script.sh get_size: status 0 nbdkit: sh[1]: debug: sh: pread count=512 offset=512 nbdkit: sh[1]: debug: calling: /tmp/nbdkitpKY00D/inline-script.sh pread "" 512 512 nbdkit: sh[1]: debug: completed: /tmp/nbdkitpKY00D/inline-script.sh pread: status 0 read 512/512 bytes at offset 0 512 bytes, 1 ops; 0:00:01.03 (496.196279 bytes/sec and 0.9691 ops/sec) read 512/512 bytes at offset 512 512 bytes, 1 ops; 0:00:01.02 (503.602359 bytes/sec and 0.9836 ops/sec) nbdkit: sh[1]: debug: client sent NBD_CMD_DISC, closing connection nbdkit: sh[1]: debug: retry: finalize nbdkit: sh[1]: debug: sh: finalize nbdkit: debug: sh: unload plugin nbdkit: debug: calling: /tmp/nbdkitpKY00D/inline-script.sh unload nbdkit: debug: completed: /tmp/nbdkitpKY00D/inline-script.sh unload: status 2 nbdkit: debug: retry: unload filter + end_t=1 + '[' 1 -lt 2 ']' + echo './test-retry-size.sh: test ran too quickly' ./test-retry-size.sh: test ran too quickly + fail=1 + read open_count + '[' 3 -ne 3 ']' + '[' -e retry-size-fail ']' + exit 1 + _run_cleanup_hooks + local _status=1 _i + set +e + trap '' INT QUIT TERM EXIT ERR + echo ./test-retry-size.sh: run cleanup hooks: exit code 1 ./test-retry-size.sh: run cleanup hooks: exit code 1 + (( _i = 0 )) + (( _i < 1 )) + rm -f retry-size-open-count retry-size-fail + (( ++_i )) + (( _i < 1 )) + exit 1 FAIL test-retry-size.sh (exit status: 1) -- Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones Read my programming and virtualization blog: http://rwmj.wordpress.com virt-top is 'top' for virtual machines. Tiny program with many powerful monitoring features, net stats, disk stats, logging, etc. http://people.redhat.com/~rjones/virt-top