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

Richard W.M. Jones rjones at redhat.com
Sun Aug 2 09:13:05 UTC 2020 

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

More information about the Libguestfs mailing list