Bug 15377 - systemd stumbled over copyright-message at smbd startup
Summary: systemd stumbled over copyright-message at smbd startup
Status: REOPENED
Alias: None
Product: Samba 4.1 and newer
Classification: Unclassified
Component: Other (show other bugs)
Version: 4.18.2
Hardware: All Linux
: P5 normal (vote)
Target Milestone: ---
Assignee: Samba QA Contact
QA Contact: Samba QA Contact
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2023-05-25 14:08 UTC by zeskotron
Modified: 2023-06-01 15:46 UTC (History)
1 user (show)

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description zeskotron 2023-05-25 14:08:05 UTC
I get the error messages about "Samba version" and "copyright" in systend-journal log every starting Samba service in any Arch based distro.

These error messages:
"""""""""""""""""""

[2023/05/25 09:39:08.726464,  0] ../../source3/smbd/server.c:1746(main)
  smbd version 4.18.2 started.
  Copyright Andrew Tridgell and the Samba Team 1992-2023

""""""""""""""""""""

### A real issue: 

The systemd-journal-notification-app automatically detects these error messages and notifies me on Desktop, but it is unexpected.

and "systemctl is-system-running" shows sometimes "degraded" because of these messages when samba unit "failed". It stops my other systemd services for example: system backup service should be stopped.

See systemctl document: What is "degraded":

https://www.freedesktop.org/software/systemd/man/systemctl.html#is-system-running -> Information about "is-system-running" output -> "degraded".


### How to fix:

I would ask you to change error level of these messages to info level.

See code at line 1746 in the source code file "../source3/smbd/server.c" :

```
DEBUG(0,("smbd version %s started.\n", samba_version_string()));
DEBUGADD(0,("%s\n", COPYRIGHT_STARTUP_MESSAGE));
```

https://github.com/samba-team/samba/blob/master/source3/smbd/server.c#L1746


Thanks!
Comment 1 Björn Jacke 2023-05-25 18:42:22 UTC
"degraded" is documented there as "The system is operational but one or more units failed.". Okay. But why does it assume this state?

I don't see how changing the log level to "info level" should fix this in any way. It would just shift the issue to setups that run in a higher log level. It looks actually more like a problem of the log file parser, which interprets certain strings in a wrong way. Or do I miss something here?

If you can tell us which strings get misinterpreted, we could discuss if it there might be a good point in fixing the log output strings.
Comment 2 zeskotron 2023-05-26 08:49:03 UTC
> "degraded" is documented there as "The system is operational but one or more units failed.". Okay. But why does it assume this state?

I do not know why is that, but this "degraded" state appears randomly after reboot, the probability is 1 in 10 reboots. Every reboot shows only 3 lines of the same error messages in journalctl log that is exactly like:

"""""""""""""""""""
[2023/05/25 09:39:08.726464,  0] ../../source3/smbd/server.c:1746(main)
  smbd version 4.18.2 started.
  Copyright Andrew Tridgell and the Samba Team 1992-2023
""""""""""""""""""""

I found a solution in Arch-forum:  https://bbs.archlinux.org/viewtopic.php?id=272979

Can you change:

```
DEBUG(0,("smbd version %s started.\n", samba_version_string()));
DEBUGADD(0,("%s\n", COPYRIGHT_STARTUP_MESSAGE));
```

to

```
DEBUG(2,("smbd version %s started.\n", samba_version_string()));
DEBUGADD(2,("%s\n", COPYRIGHT_STARTUP_MESSAGE));
```

My guess is that 0 is error level. 2 is info level. 

Thanks!
Comment 3 Björn Jacke 2023-05-26 08:53:45 UTC
as I mentioned before: this only shifts the message to log level 2, so that it will not appear in a setup with default log level. This is *not* a solution, this is just hiding the problem for you, it will pop up again as soon as you set log level = 2 in smb.conf then. You need to find out why those lines make that systemd log parser unhappy.
Comment 4 zeskotron 2023-05-26 11:25:04 UTC

If these messages are at log level 0 by default and I added "log level = 2" in smb.conf for example:

"""""
[global]
workgroup = WORKGROUP
server string = Arch-NAS
max log size = 100
client min protocol = SMB2
logging = systemd
log level = 2

"""""

I still get the same *error* messages in journalctl log, but log level 0 and 2 are no different. shift of log level has no effect.
Comment 5 Björn Jacke 2023-05-26 11:47:06 UTC
I'm closing this bug report now as INVALID for Samba, this is not a primary Samba problem, it's a problem of the log parser, which is mis-interpreting the strings for whatever reason.
Comment 6 zeskotron 2023-05-26 13:25:55 UTC
I reported this issue in systemd github.

https://github.com/systemd/systemd/issues/27799

Systemd developer wrote:

> Hence journald is doing everything right. sambda simply sets a bogus priority on the message it sent there.
Comment 7 zeskotron 2023-05-26 13:38:49 UTC
Can you change "DEBUG(0, …"  to "DEBUG(DBGLVL_INFO, …" ? 
This quote was asked by Systemd developers.

If you have any question or want to answer, please report directly to Systemd github https://github.com/systemd/systemd/issues/27799.

I'm not an expert on systemd and samba myself.

Thanks!
Comment 8 Björn Jacke 2023-05-30 22:40:11 UTC
ah, now I see, debug_level_to_priority() translates log level 0 messages to LOG_ERR - this is not ideal here, true.
Comment 9 Andrew Bartlett 2023-05-30 22:59:53 UTC
We should ensure the copyright notice to shows at the default debug level of 1, will LOG_WARNING still trigger this?
Comment 10 zeskotron 2023-05-31 06:34:15 UTC
> We should ensure the copyright notice to shows at the default debug level of 1, will LOG_WARNING still trigger this?


LOG_INFO fits very well for everyone, but LOG_WARNING is okay for me.
Comment 11 Björn Jacke 2023-05-31 17:17:30 UTC
LOG_WARNING would trigger this if you filter with -p warning.
Our log level debug message usage really doesn't fit very well with the syslog priorities.
How about if we make log level 0 be an "pure information broadcast" log level, where only messages like the startup/copyright notice appear, we would map that to syslog "notice" or "info" priorities.
Log level 1-9 would move one up in the syslog priority mapping accordingly but we don't have strict log message assignments for our log levels anyway.

Basically all we would have to do is go though all the log level 0 and 1 messages and see if we should ++ them or not. How about that idea?