Richard W.M. Jones
2020-Aug-02 09:13 UTC
[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
Richard W.M. Jones
2020-Aug-03 09:46 UTC
Re: [Libguestfs] [nbdkit] Failure in test-retry-size.sh
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@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
On 8/3/20 4:46 AM, Richard W.M. Jones wrote:> 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.Yes, there have been complaints on the bash list that $SECONDS is rather imprecise: https://lists.gnu.org/archive/html/help-bash/2020-06/msg00033.html> > 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.And while each of our nbdkit_nanosleep(1,0) calls advanced by at least one second according to one clock, it could entirely be the case that bash is going by another clock that is undergoing slight adjustments from NTP or whatever where it indeed appears like 1.99 (rounded to 1) instead of 2.0 seconds of elapsed time. I'm not sure what the best fix is; bash has $EPOCHREALTIME which offers finer granularity but becomes a bit more awkward to manipulate using only shell math. -- Eric Blake, Principal Software Engineer Red Hat, Inc. +1-919-301-3226 Virtualization: qemu.org | libvirt.org