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