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:
: 14698 (view as bug list)
Depends on:
Blocks:
 
Reported: 2023-05-25 14:08 UTC by zeskotron
Modified: 2023-11-25 18:31 UTC (History)
4 users (show)

See Also:


Attachments
backport patch for 4.19 (15.86 KB, patch)
2023-11-20 12:10 UTC, Björn Jacke
no flags Details
backport patch for 4.19 (18.91 KB, patch)
2023-11-25 18:31 UTC, Björn Jacke
bjacke: review? (metze)
bjacke: ci-passed+
Details

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?
Comment 12 Björn Jacke 2023-06-06 21:42:17 UTC
*** Bug 14698 has been marked as a duplicate of this bug. ***
Comment 13 Samba QA Contact 2023-11-20 04:50:05 UTC
This bug was referenced in samba master:

b7631bf603fbce9b80b19410f0680ce8c4170a1b
ccfe345fece0a5a44d766fb9426d43c2e046d040
159cfde446c95c387ef212be103b109ea0dca93d
bb370b9381e5d223ff4ac62f612888f90a63fcc5
50337acaa566b6696e035e38f6408f65805182a0
72f20311acc4ab8851f18ac2b87f7ecc7803afad
55d895dc42248ad524a10812b9975ac05a722fdc
baa67024bca391f2e212b91131f544cc911c6895
Comment 14 Björn Jacke 2023-11-20 12:10:09 UTC
Created attachment 18190 [details]
backport patch for 4.19
Comment 15 Stefan Metzmacher 2023-11-20 12:55:02 UTC
Comment on attachment 18190 [details]
backport patch for 4.19

Do we really want DBG_PREFIX(DBGLVL_STARTUP_NOTICE ?
I would have expected just DEBUG(DBGLVL_STARTUP_NOTICE similar to
D_ERR()...
Comment 16 Björn Jacke 2023-11-21 06:34:20 UTC
new startup message looks like this:

[2023/11/21 07:05:41.432900, -1, pid=1182207, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:1441(main)
  main: winbindd version 4.20.0pre1-GIT-b1205a089996 started.
  Copyright Andrew Tridgell and the Samba Team 1992-2023

old startup message looked like this:
[2023/11/20 14:28:21.241979,  0, pid=1019294, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:1441(main)
  winbindd version 4.19.2-SerNet-5ubuntu20.04 started.
  Copyright Andrew Tridgell and the Samba Team 1992-2023

I see no difference except for the the log level number. Isn't this what we want this way?
Comment 17 Stefan Metzmacher 2023-11-22 10:46:47 UTC
(In reply to Björn Jacke from comment #16)

see the 'main: ' in front, I don't think we want that
Comment 18 Stefan Metzmacher 2023-11-22 16:33:12 UTC
(In reply to Stefan Metzmacher from comment #17)

Here's an additional MR https://gitlab.com/samba-team/samba/-/merge_requests/3409

It removed the prefix problem, but also a general problem with using log level -1
Comment 19 Samba QA Contact 2023-11-24 10:35:05 UTC
This bug was referenced in samba master:

bd21a0cdefb30ef5522f81d865c03d11a182a63c
cd8dcff9e9cbfffab8c502c8701c00b0c8e3512b
f5c76c3c814dac2b0c09026520f75c0b0e22b6b4
Comment 20 Björn Jacke 2023-11-25 18:31:58 UTC
Created attachment 18192 [details]
backport patch for 4.19