Bug 14803 - smbd/winbindd started in daemon mode generate output on stderr/stdout
Summary: smbd/winbindd started in daemon mode generate output on stderr/stdout
Status: RESOLVED FIXED
Alias: None
Product: Samba 4.1 and newer
Classification: Unclassified
Component: Other (show other bugs)
Version: 4.15.0rc2
Hardware: All All
: P5 regression (vote)
Target Milestone: 4.15
Assignee: Jule Anger
QA Contact: Samba QA Contact
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2021-08-18 11:15 UTC by Björn Jacke
Modified: 2021-11-08 11:37 UTC (History)
5 users (show)

See Also:


Attachments
WHATSNEW update for 4.15 (918 bytes, patch)
2021-09-02 04:49 UTC, Andreas Schneider
slow: review+
Details
WHATSNEW for 4.15 (1.88 KB, patch)
2021-09-05 12:48 UTC, Ralph Böhme
kseeger: review+
Details
Patch for 4.15 cherry-picked from master (33.95 KB, patch)
2021-09-06 14:32 UTC, Ralph Böhme
kseeger: review+
slow: review? (jra)
slow: review? (metze)
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Björn Jacke 2021-08-18 11:15:31 UTC
smbd/winbindd started in daemon mode generate output on stderr/stdout. This is probably an unintended side effect of the logging changes in 4.15. In daemon mode there should be no output on stdour/stderr though.
Comment 1 Andreas Schneider 2021-08-20 04:53:23 UTC
Can you please be more specific what the issue is?

All daemons log to stderr on startup till the log file has been set up. If we don't do that we would not see errors which happen before we can write to the logfile.
Comment 2 Björn Jacke 2021-08-20 12:00:12 UTC
if you have a classic init script, that starts smbd/winbindd, you will get more or less log output on the console (with high log level it will be annoyingly much actually).

If you use systemd only you might not notice that because it suppresses any output. The previous behaviour was that the default -D start option will not output anything and we should keep that behaviour. Init scripts will otherwise have to redirect stdout/sterr to /dev/null, which will not be helpful either.

If you want to output something in case the log file is not writable, then the setting up of the logging should be done before something is printed to stdour/stderr. And then only print to stdout/stderr if the logging can't be set up for some reason.
Comment 3 Karolin Seeger 2021-08-27 11:02:51 UTC
Currently, this is a showstopper for Samba 4.15.0 scheduled for September 1st.

I tried it and agree that it might be annoying. On the other hand, it's working and seems to be difficult to setup logging earlier. So, is this a change we can agree on for a major release?
Comment 4 Ralph Böhme 2021-08-30 08:14:54 UTC
I don't think this is a severe regression that requieres delaying the release.
Comment 5 Andreas Schneider 2021-08-30 10:10:19 UTC
When we initialize everything, we start logging to stderr so we do not miss errors. If you set debug level to 10 you will get debug messeage from debug setup, config loading and cmdline parsing to stderr.

This all happens before you actually know that you want to run in daemon mode. We set the logging to a file as soon as the cmdline options have been parsed.

If you don't want to see what is going on before file logging is initialized.

It shouldn't be hard to change a n init script to send stderr to /dev/null if you don't want to see it.
Comment 6 Björn Jacke 2021-08-30 12:29:51 UTC
IMHO it would be nice if it could be changed the way it was working before but if it is not easy to change, then we should add the new behaviour and the recommendation to redirect stderr/stdout to /dev/null for init scripts into the release notes.

The output of "systemctl status smbd" might also be different now, especially with higher log levels, I wasn't able to verify that systemd case yet though.
Comment 7 Ralph Böhme 2021-09-01 09:43:30 UTC
(In reply to Andreas Schneider from comment #5)
Afair file logging is somehow setup to use the process name, at least for the deamons. That's why this worked in 4.14 where in main.c the order of actions is:

1) parse cmdline with popt

2) setup logging to FILE backend unless stdout was requested on the cmdline

3) parse smb.conf

Now in 4.14, as smb.conf parsing was moved to the popt callback at step 1, we get the behaviour change.

https://git.samba.org/?p=slow/samba.git;a=commit;h=933d0e9df181c7c9d511fa00410fe4becdf9da77 is probably a step in the right direction to get the old behaviour back, but I guess it needs further tweaking to affect the daemons, as mentioned in the commit message.

May I propose we just keep this bug open to track the issue and hopefully find a way to restore the old behaviour with a subsequent 4.15.x bugfix release, but otherwise continue with the 4.15 release?

Andreas, can you provide a patch for WHATSNEW.txt? Thanks!
Comment 8 Andreas Schneider 2021-09-02 04:49:12 UTC
Created attachment 16759 [details]
WHATSNEW update for 4.15

The patch could fix this issue. As logging to stderr is always turned on and there could always be messages on stderr!

A bug could be opened that daemons should start logging to a file before loading the configuration.
Comment 9 Ralph Böhme 2021-09-02 04:54:43 UTC
Hm, the patch doesn't apply. Can you check? It's also missing your signed-of. Feel free to push with my +1.
Comment 10 Ralph Böhme 2021-09-02 05:17:51 UTC
(In reply to Ralph Böhme from comment #9)
D'oh! Sorry, too early in the morning... Tried to apply to master and push to autobuild master... Karolin, please apply and push to 4.15. :)
Comment 11 Ralph Böhme 2021-09-05 12:48:58 UTC
Created attachment 16770 [details]
WHATSNEW for 4.15
Comment 12 Samba QA Contact 2021-09-06 14:24:03 UTC
This bug was referenced in samba master:

aaa3c6a4132d2e739958e168e7dc3e78dfa4a72e
877183ac0b57f5b2902446e41bb6ab3191f84fa6
ae22442db437061aada6427adde205cd13f1d202
a20f63b384750d389aeafd4bd5e229aed72cb271
9d82454cdfc2b4b8007c7b54b3afd5686f49be19
28686f8713958726085bd38a0889aa7725c95371
Comment 13 Ralph Böhme 2021-09-06 14:32:56 UTC
Created attachment 16776 [details]
Patch for 4.15 cherry-picked from master
Comment 14 Ralph Böhme 2021-09-06 14:38:39 UTC
Reassigning to Jule for inclusion in 4.15.
Comment 15 Jule Anger 2021-09-06 20:19:52 UTC
Pushed to autobuild-v4-15-test.
Comment 16 Samba QA Contact 2021-09-06 20:43:37 UTC
This bug was referenced in samba v4-15-test:

29c895c6d8ab5360f7d6e2e536b7b3ddf9656f3b
476ed842726a77cd16a2dafd4dfbc987a12b6cfe
e1be4413c990f75f7efe9dc2c62a86646f2932d4
3eef217a9daba415774680b4f4c0bf1188909edd
c65fb0b0a0e2867c0656bb5a84606f70d02dbe65
defbbe7127fde7c73485b8dea18eb2543cda7973
Comment 17 Jule Anger 2021-09-07 06:32:19 UTC
Closing out bug report.

Thanks!
Comment 18 Samba QA Contact 2021-09-07 08:44:02 UTC
This bug was referenced in samba v4-15-stable (Release samba-4.15.0rc5):

29c895c6d8ab5360f7d6e2e536b7b3ddf9656f3b
476ed842726a77cd16a2dafd4dfbc987a12b6cfe
e1be4413c990f75f7efe9dc2c62a86646f2932d4
3eef217a9daba415774680b4f4c0bf1188909edd
c65fb0b0a0e2867c0656bb5a84606f70d02dbe65
defbbe7127fde7c73485b8dea18eb2543cda7973
Comment 19 Krzysztof Olędzki 2021-09-30 16:59:24 UTC
I just updated samba on my test Gentoo system by using the official 4.15 build (https://gitweb.gentoo.org/repo/gentoo.git/tree/net-fs/samba/samba-4.15.0-r1.ebuild). First thing I noticed was the problem with logging *continuously* going to the console:

# /etc/init.d/samba restart
 * Caching service dependencies ...                                                                                                                                                     [ ok ]
 * samba -> stop: samba4 ...                                                                                                                                                            [ ok ]
 * samba -> start: samba4 ...
samba version 4.15.0 started.
Copyright Andrew Tridgell and the Samba Team 1992-2021                                                                                                                                  [ ok ]
# binary_smbd_main: samba: using 'prefork' process model
/usr/sbin/samba_dnsupdate: ERROR: Record already exist; record could not be added. zone[ad9<...>] name[gnom3]
/usr/sbin/samba_dnsupdate: ERROR: Record already exist; record could not be added. zone[_msdcs.ad9<...>] name[47<...>da]
/usr/sbin/samba_dnsupdate: ERROR: Record already exist; record could not be added. zone[ad9<...>] name[@]
/usr/sbin/samba_dnsupdate: ERROR: Record already exist; record could not be added. zone[_msdcs.ad9<...>] name[@]
/usr/sbin/samba_dnsupdate: ERROR: Record already exist; record could not be added. zone[ad9<...>] name[@]
/usr/sbin/samba_dnsupdate: ERROR: Record already exist; record could not be added. zone[ad9<...>] name[_ldap._tcp]
(...)
dnsupdate_nameupdate_done: Failed DNS update with exit code 29

Note that even 24h later, my console is still being flooded with the dnsupdate messages.

I think the current behavior may not only be non-intuitive but also should be considered a regression. It is also hard to justify why this would be a WAI, if no --foreground / --interactive flags are specified. I don't understand the reason for the change - why this is considered a positive thing and why this was never needed in Samba it its almost 20 years of development, until now?

In my opinion, the common practice in Unix-like systems is for daemons to close (and re-open to /dev/null) stdin/stdout/stderr and then either log to syslog or to specific files. If for some reason logging to files is not possible (it is unclear why however, i.e. we logging cannot be initialized early) I wonder why syslog would not be a better choice that stderr / stdout. I also wonder what would happen if I close the terminal immediately after (re-)starting samba, and then the deamon tries to write something?


Overall, updating "WHATSNEW" does not seem like the proper fix IMO, and the fact that Gentoo has this problem suggest this may be a common trap all non-systemd distributions may be dealing with, one after another.