nbdkit logs to stderr when "--verbose" flag given even without "--foreground" flag

[archiecobbs]

Versions:

$ rpm -qa|grep nbd|sort
nbd-3.24-150000.3.3.1.x86_64
nbdkit-1.29.4-150300.8.6.1.x86_64
nbdkit-basic-filters-1.29.4-150300.8.6.1.x86_64
nbdkit-basic-plugins-1.29.4-150300.8.6.1.x86_64
nbdkit-debuginfo-1.29.4-150300.8.6.1.x86_64
nbdkit-devel-1.29.4-150300.8.6.1.x86_64
nbdkit-server-1.29.4-150300.8.6.1.x86_64
nbdkit-server-debuginfo-1.29.4-150300.8.6.1.x86_64

Not sure if I'm doing something wrong, but it seems like logging to stderr works too well, and logging to syslog completely does not work.

Problem 1: when the --verbose flag is given to nbdkit(1), it logs to stderr (a) even though the --foreground flag is not given. This happens even if the --log=syslog flag is given.

Here's an example. When my program (s3backer) runs with the --debug flag, it fork()'s off nbdkit(1) as shown in the log below with the --verbose flag. But then nbdkit(1) continues to log stuff to syslog even after it's forked into the background:

$ ./s3backer --nbd --debug --listBlocks --readOnly s3backer-demo /dev/nbd1
2022-07-08 12:42:57 INFO: s3backer: executing /usr/sbin/nbdkit with these parameters:
2022-07-08 12:42:57 INFO: s3backer:   [00] "/usr/sbin/nbdkit"
2022-07-08 12:42:57 INFO: s3backer:   [01] "--verbose"
2022-07-08 12:42:57 INFO: s3backer:   [02] "--read-only"
2022-07-08 12:42:57 INFO: s3backer:   [03] "--log=syslog"
2022-07-08 12:42:57 INFO: s3backer:   [04] "--filter=exitlast"
2022-07-08 12:42:57 INFO: s3backer:   [05] "--unix"
2022-07-08 12:42:57 INFO: s3backer:   [06] "/var/run/s3backer-nbd/0000000000000006_0000000000000538"
2022-07-08 12:42:57 INFO: s3backer:   [07] "s3backer"
2022-07-08 12:42:57 INFO: s3backer:   [08] "s3b_debug=true"
2022-07-08 12:42:57 INFO: s3backer:   [09] "s3b_listBlocks=true"
2022-07-08 12:42:57 INFO: s3backer:   [10] "s3b_readOnly=true"
2022-07-08 12:42:57 INFO: s3backer:   [11] "bucket=s3backer-demo"
2022-07-08 12:42:57 INFO: s3backer: started /usr/sbin/nbdkit as process 29690
nbdkit: debug: nbdkit 1.29.4 (nbdkit-1.29.4)
nbdkit: debug: TLS disabled: could not load TLS certificates
nbdkit: debug: registering plugin /usr/lib64/nbdkit/plugins/nbdkit-s3backer-plugin.so
nbdkit: debug: registered plugin /usr/lib64/nbdkit/plugins/nbdkit-s3backer-plugin.so (name s3backer)
nbdkit: debug: s3backer: load
nbdkit: debug: registering filter /usr/lib64/nbdkit/filters/nbdkit-exitlast-filter.so
nbdkit: debug: registered filter /usr/lib64/nbdkit/filters/nbdkit-exitlast-filter.so (name exitlast)
nbdkit: debug: exitlast: load
nbdkit: debug: exitlast: config key=s3b_debug, value=true
nbdkit: debug: s3backer: config key=s3b_debug, value=true
nbdkit: debug: exitlast: config key=s3b_listBlocks, value=true
nbdkit: debug: s3backer: config key=s3b_listBlocks, value=true
nbdkit: debug: exitlast: config key=s3b_readOnly, value=true
nbdkit: debug: s3backer: config key=s3b_readOnly, value=true
nbdkit: debug: exitlast: config key=bucket, value=s3backer-demo
nbdkit: debug: s3backer: config key=bucket, value=s3backer-demo
nbdkit: debug: exitlast: config_complete
nbdkit: debug: s3backer: config_complete
nbdkit: debug: recording bucket parameter "s3backer-demo"
...
nbdkit: debug: accepted connection
nbdkit: s3backer[1]: debug: exitlast: preconnect
nbdkit: s3backer[1]: debug: s3backer: preconnect
nbdkit: s3backer[1]: debug: newstyle negotiation: flags: global 0x3
nbdkit: s3backer[1]: debug: newstyle negotiation: client flags: 0x3
nbdkit: s3backer[1]: debug: newstyle negotiation: NBD_OPT_GO: client requested export ''
nbdkit: s3backer[1]: debug: exitlast: open readonly=1 exportname="" tls=0
nbdkit: s3backer[1]: debug: exitlast: default_export readonly=1 tls=0
nbdkit: s3backer[1]: debug: s3backer: default_export readonly=1 tls=0
nbdkit: s3backer[1]: debug: s3backer: open readonly=1 exportname="" tls=0
nbdkit: s3backer[1]: debug: s3backer: default_export readonly=1 tls=0
nbdkit: s3backer[1]: debug: s3backer: open returned handle 0x7f4a5dffb580
nbdkit: s3backer[1]: debug: exitlast: open returned handle 0x7f4a5dffb580
nbdkit: s3backer[1]: debug: s3backer: prepare readonly=1
nbdkit: s3backer[1]: debug: exitlast: prepare readonly=1
nbdkit: s3backer[1]: debug: exitlast: get_size
nbdkit: s3backer[1]: debug: s3backer: get_size
nbdkit: s3backer[1]: debug: exitlast: can_zero
nbdkit: s3backer[1]: debug: exitlast: can_fast_zero
nbdkit: s3backer[1]: debug: exitlast: can_trim
...

My NBD plugin also ends up logging stuff to stderr (not shown) in this situation - presumably because it is logging via nbdkit_vdebug() and that goes to the same place.

Problem 2: When nbdkit(1) is invoked without the --verbose flag, logging completely disappears. It should be going to syslog but never shows up in /var/log/messages (even with --log=syslog).

Example:

$ ./s3backer --nbd --debug --listBlocks --readOnly s3backer-demo /dev/nbd1
2022-07-08 12:57:04 INFO: s3backer: executing /usr/sbin/nbdkit with these parameters:
2022-07-08 12:57:04 INFO: s3backer:   [00] "/usr/sbin/nbdkit"
2022-07-08 12:57:04 INFO: s3backer:   [01] "--read-only"
2022-07-08 12:57:04 INFO: s3backer:   [02] "--log=syslog"
2022-07-08 12:57:04 INFO: s3backer:   [03] "--filter=exitlast"
2022-07-08 12:57:04 INFO: s3backer:   [04] "--unix"
2022-07-08 12:57:04 INFO: s3backer:   [05] "/var/run/s3backer-nbd/0000000000000006_0000000000000538"
2022-07-08 12:57:04 INFO: s3backer:   [06] "s3backer"
2022-07-08 12:57:04 INFO: s3backer:   [07] "s3b_debug=true"
2022-07-08 12:57:04 INFO: s3backer:   [08] "s3b_listBlocks=true"
2022-07-08 12:57:04 INFO: s3backer:   [09] "s3b_readOnly=true"
2022-07-08 12:57:04 INFO: s3backer:   [10] "bucket=s3backer-demo"
2022-07-08 12:57:04 INFO: s3backer: started /usr/sbin/nbdkit as process 29116

What am I doing wrong? Thanks.

[rwmjones]

FYI upstream issues are here: https://gitlab.com/nbdkit/nbdkit/-/issues

The issue is that debug messages and error messages are handled separately.

Debug messages are only generated when --verbose is present, and are always sent to stderr: https://gitlab.com/nbdkit/nbdkit/-/blob/master/server/debug.c It's not possible to change this, but you can redirect fd 2 of the nbdkit subprocess to somewhere else (maybe to the logger command?)

Error messages are generated for error conditions, and they go to stderr or the syslog depending on the --log setting, as described in the manual. https://gitlab.com/nbdkit/nbdkit/-/blob/master/server/log.c

So it's working as expected as far as I can see. I would suggest for the debug messages that you redirect fd 2 of the nbdkit process after forking.

[archiecobbs]

OK - thanks for the explanation and sorry about targeting the wrong project!