Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 1782868

Summary: RFE: Allow nbdkit to filter out uninteresting log messages.
Product: Red Hat Enterprise Linux Advanced Virtualization Reporter: Richard W.M. Jones <rjones>
Component: nbdkitAssignee: Richard W.M. Jones <rjones>
Status: CLOSED ERRATA QA Contact: Virtualization Bugs <virt-bugs>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 8.2CC: eblake, jsuchane, mxie, mzhan, nperic, ptoscano, tzheng, virt-bugs, xiaodwan, zili
Target Milestone: rcKeywords: FutureFeature
Target Release: 8.0Flags: pm-rhel: mirror+
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: nbdkit-1.16.2-2.el8 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: 1782853 Environment:
Last Closed: 2020-05-05 09:52:16 UTC Type: Feature Request
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On: 1782853    
Bug Blocks:    
Attachments:
Description Flags
command without ssh.log none

Description Richard W.M. Jones 2019-12-12 14:19:16 UTC 
+++ 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 ;)
Comment 1 Richard W.M. Jones 2019-12-12 18:05:11 UTC 
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
Comment 2 Richard W.M. Jones 2020-01-28 14:13:34 UTC 
https://bugzilla.redhat.com/show_bug.cgi?id=1756307#c3
Comment 4 liuzi 2020-02-07 10:25:03 UTC 
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.
Comment 5 Richard W.M. Jones 2020-02-07 10:33:38 UTC 
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.
Comment 7 liuzi 2020-02-14 08:50:12 UTC 
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?
Comment 8 liuzi 2020-02-14 08:53:22 UTC 
Created attachment 1663060 [details]
command without ssh.log
Comment 9 Richard W.M. Jones 2020-02-18 11:59:01 UTC 
> 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.
Comment 10 liuzi 2020-02-20 02:02:29 UTC 
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.
Comment 12 errata-xmlrpc 2020-05-05 09:52:16 UTC 
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