+++ This bug was initially created as a clone of Bug #1782853 +++ Description of problem: nbdkit in verbose mode has very verbose logs. A lot of this is uninteresting, especially multiple layers of NBD requests like this: nbdkit: python[1]: debug: pwrite count=2097152 offset=236994953216 fua=0 nbdkit: vddk[3]: debug: pread count=2097152 offset=236999147520 (When using later versions of virt-v2v even more filters are used and you get even more messages). I posted a suggested patch series upstream: https://www.redhat.com/archives/libguestfs/2019-December/msg00043.html Version-Release number of selected component (if applicable): nbdkit 1.16 Steps to Reproduce: 1. Run conversion 2. Check logs ;)
Upstream in ... https://github.com/libguestfs/nbdkit/commit/a0715ed912f73cc15f10acb15d554405db23ed6d https://github.com/libguestfs/nbdkit/commit/a1dee1c830e91842093ba19bd0f742d9cdeef856 https://github.com/libguestfs/nbdkit/commit/208ed8aedf6c22b196db51d3f7a380ba30a398cd https://github.com/libguestfs/nbdkit/commit/f5a1ff71f352b5bc730856ffd3382faab5d2e13a https://github.com/libguestfs/nbdkit/commit/cb910a6c25c289812fbb50330e6ae1b5b30f5687 https://github.com/libguestfs/nbdkit/commit/3b45db234a691f8ff926a6fef583e11c3601f112 https://github.com/libguestfs/nbdkit/commit/531729188b6a5709a49de39aba8c5947c2738340 https://github.com/libguestfs/nbdkit/commit/a895fa84aaa50f52af68319523020046394c789f https://github.com/libguestfs/nbdkit/commit/231717e8cd5f27d76631be6651062d5a5ccf7fdc
https://bugzilla.redhat.com/show_bug.cgi?id=1756307#c3
Test bug with build: nbdkit-1.16.2-1.module+el8.2.0+5579+d71178e0.x86_64 Steps: 1.Check nbdkit man page about new filter "debug flags" SERVER DEBUG FLAGS As well as enabling or disabling debugging in the server using --verbose you can control extra debugging in the server using the "-D nbdkit.*" flags listed in this section. Note these flags are an internal implementation detail of the server and may be changed or removed at any time in the future. -D nbdkit.backend.controlpath=0 -D nbdkit.backend.controlpath=1 -D nbdkit.backend.datapath=0 -D nbdkit.backend.datapath=1 These flags control the verbosity of nbdkit backend debugging messages (the ones which show every request processed by the server). The default for both settings is 1 (normal debugging) but you can set them to 0 to suppress these messages. "-D nbdkit.backend.datapath=0" is the more useful setting which lets you suppress messages about pread, pwrite, zero, trim, etc. commands. When transferring large amounts of data these messages are numerous and not usually very interesting. 2.Set nbdkit.backend.datapath=0 to filter some messages. # nbdkit -f -U - ssh host=10.66.87.212 /tmp/disk1.img --run 'qemu-img convert -p -f raw $nbd /tmp/out1.img' --debug nbdkit.backend.datapath=0 -v nbdkit: debug: TLS disabled: could not load TLS certificates nbdkit: debug: registering plugin /usr/lib64/nbdkit/plugins/nbdkit-ssh-plugin.so nbdkit: debug: registered plugin /usr/lib64/nbdkit/plugins/nbdkit-ssh-plugin.so (name ssh) nbdkit: debug: ssh: load nbdkit: warning: debug flag -D nbdkit.backend.datapath was not used [...] nbdkit: ssh[1]: debug: ssh: pread count=2097152 offset=0 nbdkit: ssh[1]: debug: ssh: pread count=2097152 offset=2097152 Result:As the warning:debug flag -D nbdkit.backend.datapath was not used,so this bug not be fixed.now change the bug from ON_QA to ASSIGNED.
I forgot one of the upstream commits when I was backporting this feature. It should be fixed in nbdkit-1.16.2-2.el8. By the way, a slightly simpler way to test this which doesn't involve using ssh is: $ nbdkit -f -v -U - -D nbdkit.backend.datapath=0 null size=1M --run 'qemu-img info $nbd' With -D nbdkit.backend.datapath=1 (or omitted) you will see the log message: nbdkit: null.0: debug: null: pread count=512 offset=0 With -D nbdkit.backend.datapath=0 this log message should be suppressed.
Test bug with build: nbdkit-1.16.2-2.module+el8.2.0+5664+dd92f997.x86_64 Steps: 1.Check nbdkit man page about new filter "debug flags" SERVER DEBUG FLAGS -D nbdkit.backend.controlpath=0 -D nbdkit.backend.controlpath=1 -D nbdkit.backend.datapath=0 -D nbdkit.backend.datapath=1 These flags control the verbosity of nbdkit backend debugging messages (the ones which show every request processed by the server). The default for both settings is 1 (normal debugging) but you can set them to 0 to suppress these messages. "-D nbdkit.backend.datapath=0" is the more useful setting which lets you suppress messages about pread, pwrite, zero, trim, etc. commands. When transferring large amounts of data these messages are numerous and not usually very interesting. "-D nbdkit.backend.controlpath=0" suppresses the non-datapath commands (config, open, close, can_write, etc.) scenario 1 not use any debug flag (keep all flags value as default) # nbdkit -f -U - ssh host=10.66.87.212 /tmp/disk1.img --run 'qemu-img convert -p -f raw $nbd /tmp/out1.img' -v nbdkit: debug: TLS disabled: could not load TLS certificates nbdkit: debug: registering plugin /usr/lib64/nbdkit/plugins/nbdkit-ssh-plugin.so nbdkit: debug: registered plugin /usr/lib64/nbdkit/plugins/nbdkit-ssh-plugin.so (name ssh) nbdkit: debug: ssh: load nbdkit: debug: ssh: config key=host, value=10.66.87.212 nbdkit: debug: ssh: config key=path, value=/tmp/disk1.img nbdkit: debug: ssh: config_complete nbdkit: debug: using thread model: serialize_requests nbdkit: debug: bound to unix socket /tmp/nbdkit3QmPYJ/socket nbdkit: debug: forked into background (new pid = 28353) nbdkit: debug: accepted connection nbdkit: ssh[1]: debug: newstyle negotiation: flags: global 0x3 nbdkit: ssh[1]: debug: newstyle negotiation: client flags: 0x3 nbdkit: ssh[1]: debug: newstyle negotiation: NBD_OPT_STRUCTURED_REPLY: client requested structured replies nbdkit: ssh[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: client requested export '' nbdkit: ssh[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: set count: 1 nbdkit: ssh[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: set base:allocation nbdkit: ssh[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: replying with base:allocation id 1 nbdkit: ssh[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: reply complete nbdkit: ssh[1]: debug: newstyle negotiation: NBD_OPT_GO: client requested export '' nbdkit: ssh[1]: debug: ssh: open readonly=0 nbdkit: ssh[1]: debug: opened libssh handle nbdkit: ssh[1]: debug: ssh: open returned handle 0x7fd868001d70 nbdkit: ssh[1]: debug: ssh: prepare readonly=0 nbdkit: ssh[1]: debug: ssh: get_size nbdkit: ssh[1]: debug: ssh: can_write nbdkit: ssh[1]: debug: ssh: can_zero nbdkit: ssh[1]: debug: ssh: can_write nbdkit: ssh[1]: debug: ssh: can_fast_zero nbdkit: ssh[1]: debug: ssh: can_zero nbdkit: ssh[1]: debug: ssh: can_trim nbdkit: ssh[1]: debug: ssh: can_write nbdkit: ssh[1]: debug: ssh: can_fua nbdkit: ssh[1]: debug: ssh: can_write nbdkit: ssh[1]: debug: ssh: can_flush nbdkit: ssh[1]: debug: ssh: is_rotational nbdkit: ssh[1]: debug: ssh: can_multi_conn nbdkit: ssh[1]: debug: ssh: can_cache nbdkit: ssh[1]: debug: ssh: can_extents nbdkit: ssh[1]: debug: newstyle negotiation: flags: export 0x8cd nbdkit: ssh[1]: debug: newstyle negotiation: NBD_OPT_GO: ignoring NBD_INFO_* request 3 (NBD_INFO_BLOCK_SIZE) nbdkit: ssh[1]: debug: handshake complete, processing requests serially nbdkit: ssh[1]: debug: ssh: get_size nbdkit: ssh[1]: debug: ssh: extents count=2147483136 offset=0 req_one=1 nbdkit: ssh[1]: debug: ssh: get_size nbdkit: ssh[1]: debug: ssh: extents count=1753973248 offset=2147483136 req_one=1 nbdkit: ssh[1]: debug: ssh: get_size nbdkit: ssh[1]: debug: ssh: extents count=2147483136 offset=0 req_one=1 nbdkit: ssh[1]: debug: ssh: pread count=2097152 offset=0 nbdkit: ssh[1]: debug: ssh: pread count=2097152 offset=2097152 nbdkit: ssh[1]: debug: ssh: pread count=2097152 offset=4194304 nbdkit: ssh[1]: debug: ssh: pread count=2097152 offset=6291456 [...] nbdkit: ssh[1]: debug: ssh: pread count=754176 offset=3900702208 (100.00/100%) nbdkit: ssh[1]: debug: client sent NBD_CMD_DISC, closing connection nbdkit: ssh[1]: debug: ssh: finalize nbdkit: ssh[1]: debug: ssh: close nbdkit: debug: ssh: unload plugin scenario 2 Set --debug nbdkit.backend.datapath=0 to suppress messages about pread, pwrite, zero, trim, etc. # nbdkit -f -U - ssh host=10.66.87.212 /tmp/disk1.img --run 'qemu-img convert -p -f raw $nbd /tmp/out1.img' -v --debug nbdkit.backend.datapath=0 nbdkit: debug: TLS disabled: could not load TLS certificates nbdkit: debug: registering plugin /usr/lib64/nbdkit/plugins/nbdkit-ssh-plugin.so nbdkit: debug: registered plugin /usr/lib64/nbdkit/plugins/nbdkit-ssh-plugin.so (name ssh) nbdkit: debug: ssh: load nbdkit: debug: ssh: config key=host, value=10.66.87.212 nbdkit: debug: ssh: config key=path, value=/tmp/disk1.img nbdkit: debug: ssh: config_complete nbdkit: debug: using thread model: serialize_requests nbdkit: debug: bound to unix socket /tmp/nbdkit8CqWMw/socket nbdkit: debug: forked into background (new pid = 28374) nbdkit: debug: accepted connection nbdkit: ssh[1]: debug: newstyle negotiation: flags: global 0x3 nbdkit: ssh[1]: debug: newstyle negotiation: client flags: 0x3 nbdkit: ssh[1]: debug: newstyle negotiation: NBD_OPT_STRUCTURED_REPLY: client requested structured replies nbdkit: ssh[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: client requested export '' nbdkit: ssh[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: set count: 1 nbdkit: ssh[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: set base:allocation nbdkit: ssh[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: replying with base:allocation id 1 nbdkit: ssh[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: reply complete nbdkit: ssh[1]: debug: newstyle negotiation: NBD_OPT_GO: client requested export '' nbdkit: ssh[1]: debug: ssh: open readonly=0 nbdkit: ssh[1]: debug: opened libssh handle nbdkit: ssh[1]: debug: ssh: open returned handle 0x7f3840001d70 nbdkit: ssh[1]: debug: ssh: prepare readonly=0 nbdkit: ssh[1]: debug: ssh: get_size nbdkit: ssh[1]: debug: ssh: can_write nbdkit: ssh[1]: debug: ssh: can_zero nbdkit: ssh[1]: debug: ssh: can_write nbdkit: ssh[1]: debug: ssh: can_fast_zero nbdkit: ssh[1]: debug: ssh: can_zero nbdkit: ssh[1]: debug: ssh: can_trim nbdkit: ssh[1]: debug: ssh: can_write nbdkit: ssh[1]: debug: ssh: can_fua nbdkit: ssh[1]: debug: ssh: can_write nbdkit: ssh[1]: debug: ssh: can_flush nbdkit: ssh[1]: debug: ssh: is_rotational nbdkit: ssh[1]: debug: ssh: can_multi_conn nbdkit: ssh[1]: debug: ssh: can_cache nbdkit: ssh[1]: debug: ssh: can_extents nbdkit: ssh[1]: debug: newstyle negotiation: flags: export 0x8cd nbdkit: ssh[1]: debug: newstyle negotiation: NBD_OPT_GO: ignoring NBD_INFO_* request 3 (NBD_INFO_BLOCK_SIZE) nbdkit: ssh[1]: debug: handshake complete, processing requests serially nbdkit: ssh[1]: debug: ssh: get_size nbdkit: ssh[1]: debug: ssh: get_size nbdkit: ssh[1]: debug: ssh: get_size nbdkit: ssh[1]: debug: ssh: get_size (100.00/100%) nbdkit: ssh[1]: debug: client sent NBD_CMD_DISC, closing connection nbdkit: ssh[1]: debug: ssh: finalize nbdkit: ssh[1]: debug: ssh: close nbdkit: debug: ssh: unload plugin Result 2:When set nbdkit.backend.datapath=0,nbdkit can suppress messages about pread. Scenario 3 Set nbdkit.backend.controlpath=0 to suppresses the non-datapath commands (config, open, close, can_write, etc. # nbdkit -f -U - ssh host=10.66.87.212 /tmp/disk1.img --run 'qemu-img convert -p -f raw $nbd /tmp/out1.img' -v --debug nbdkit.backend.controlpath=0 nbdkit: debug: TLS disabled: could not load TLS certificates nbdkit: debug: registering plugin /usr/lib64/nbdkit/plugins/nbdkit-ssh-plugin.so nbdkit: debug: registered plugin /usr/lib64/nbdkit/plugins/nbdkit-ssh-plugin.so (name ssh) nbdkit: debug: ssh: load nbdkit: debug: ssh: config key=host, value=10.66.87.212 nbdkit: debug: ssh: config key=path, value=/tmp/disk1.img nbdkit: debug: ssh: config_complete nbdkit: debug: using thread model: serialize_requests nbdkit: debug: bound to unix socket /tmp/nbdkitjhUWu8/socket nbdkit: debug: forked into background (new pid = 28449) nbdkit: debug: accepted connection nbdkit: ssh[1]: debug: newstyle negotiation: flags: global 0x3 nbdkit: ssh[1]: debug: newstyle negotiation: client flags: 0x3 nbdkit: ssh[1]: debug: newstyle negotiation: NBD_OPT_STRUCTURED_REPLY: client requested structured replies nbdkit: ssh[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: client requested export '' nbdkit: ssh[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: set count: 1 nbdkit: ssh[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: set base:allocation nbdkit: ssh[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: replying with base:allocation id 1 nbdkit: ssh[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: reply complete nbdkit: ssh[1]: debug: newstyle negotiation: NBD_OPT_GO: client requested export '' nbdkit: ssh[1]: debug: opened libssh handle nbdkit: ssh[1]: debug: newstyle negotiation: flags: export 0x8cd nbdkit: ssh[1]: debug: newstyle negotiation: NBD_OPT_GO: ignoring NBD_INFO_* request 3 (NBD_INFO_BLOCK_SIZE) nbdkit: ssh[1]: debug: handshake complete, processing requests serially nbdkit: ssh[1]: debug: ssh: extents count=2147483136 offset=0 req_one=1 nbdkit: ssh[1]: debug: ssh: extents count=1753973248 offset=2147483136 req_one=1 nbdkit: ssh[1]: debug: ssh: extents count=2147483136 offset=0 req_one=1 nbdkit: ssh[1]: debug: ssh: pread count=2097152 offset=0 nbdkit: ssh[1]: debug: ssh: pread count=2097152 offset=2097152 nbdkit: ssh[1]: debug: ssh: pread count=2097152 offset=4194304 [...] Result 3:When set nbdkit.backend.controlpath=0,nbdkit can suppresses the non-datapath commands (config, open, close, can_write,etc) Scenario 4:Set both parameters to 0 # nbdkit -f -U - ssh host=10.66.87.212 /tmp/disk1.img --run 'qemu-img convert -p -f raw $nbd /tmp/out1.img' -v --debug nbdkit.backend.controlpath=0 --debug nbdkit.backend.datapath=0 nbdkit: debug: TLS disabled: could not load TLS certificates nbdkit: debug: registering plugin /usr/lib64/nbdkit/plugins/nbdkit-ssh-plugin.so nbdkit: debug: registered plugin /usr/lib64/nbdkit/plugins/nbdkit-ssh-plugin.so (name ssh) nbdkit: debug: ssh: load nbdkit: debug: ssh: config key=host, value=10.66.87.212 nbdkit: debug: ssh: config key=path, value=/tmp/disk1.img nbdkit: debug: ssh: config_complete nbdkit: debug: using thread model: serialize_requests nbdkit: debug: bound to unix socket /tmp/nbdkit0hhdhf/socket nbdkit: debug: forked into background (new pid = 28465) nbdkit: debug: accepted connection nbdkit: ssh[1]: debug: newstyle negotiation: flags: global 0x3 nbdkit: ssh[1]: debug: newstyle negotiation: client flags: 0x3 nbdkit: ssh[1]: debug: newstyle negotiation: NBD_OPT_STRUCTURED_REPLY: client requested structured replies nbdkit: ssh[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: client requested export '' nbdkit: ssh[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: set count: 1 nbdkit: ssh[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: set base:allocation nbdkit: ssh[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: replying with base:allocation id 1 nbdkit: ssh[1]: debug: newstyle negotiation: NBD_OPT_SET_META_CONTEXT: reply complete nbdkit: ssh[1]: debug: newstyle negotiation: NBD_OPT_GO: client requested export '' nbdkit: ssh[1]: debug: opened libssh handle nbdkit: ssh[1]: debug: newstyle negotiation: flags: export 0x8cd nbdkit: ssh[1]: debug: newstyle negotiation: NBD_OPT_GO: ignoring NBD_INFO_* request 3 (NBD_INFO_BLOCK_SIZE) nbdkit: ssh[1]: debug: handshake complete, processing requests serially (100.00/100%) nbdkit: ssh[1]: debug: client sent NBD_CMD_DISC, closing connection Result 4: These flags control the verbosity of nbdkit backend debugging messages. Hi,Rjones: As the above tests,I think this bug has been fixed.But I met a problem during my testing. I tried to use the command as you mentioned in comment5: $ nbdkit -f -v -U - -D nbdkit.backend.datapath=0 null size=1M --run 'qemu-img info $nbd' But I cannot get expected result when I set -D nbdkit.backend.datapath=1. Could you help to review the log?
Created attachment 1663060 [details] command without ssh.log
> But I met a problem during my testing. > I tried to use the command as you mentioned in comment5: > $ nbdkit -f -v -U - -D nbdkit.backend.datapath=0 null size=1M --run 'qemu-img info $nbd' > But I cannot get expected result when I set -D nbdkit.backend.datapath=1. That's very strange! Is it possible that you set both -D nbdkit.backend.datapath=0 and -D nbdkit.backend.datapath=1 at the same time? I am not able to reproduce any problem, here is my test: while nbdkit -f -v -U - -D nbdkit.backend.datapath=1 null size=1M --run 'qemu-img info $nbd' >& /tmp/out; grep -sq pread /tmp/out ; do echo -n .; done which runs forever with nbdkit-1.16.2-2.module+el8.2.0+5664+dd92f997.x86_64. I'll leave it running for some time in case the error is intermittent.
After discussion,I have resolved the problem in comment 9. As the test result in comment 7,now change the bug from ON_QA to VERIFIED.
Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory, and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://access.redhat.com/errata/RHBA-2020:2017