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

Richard W.M. Jones rjones at redhat.com
Mon Aug 3 09:46:27 UTC 2020 

On Sun, Aug 02, 2020 at 10:13:05AM +0100, Richard W.M. Jones wrote:
> 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.

FWIW $SECONDS is calculated by bash in the obvious way.  It saves
time(2) when the shell starts, and then when you ask for $SECONDS it
returns the current time(2) - the saved time.

If the time difference was 1.999 then it would return 1, but we expect
after the two calls to nbdkit_nanosleep that the elapsed time must be > 2.

Rich.

> 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
> 
> _______________________________________________
> Libguestfs mailing list
> Libguestfs at redhat.com
> https://www.redhat.com/mailman/listinfo/libguestfs

-- 
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