Bug 15377 - systemd stumbled over copyright-message at smbd startup
Summary: systemd stumbled over copyright-message at smbd startup
Status: RESOLVED FIXED
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: Jule Anger
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: 2024-01-08 14:39 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
metze: review+
bjacke: ci-passed+
Details
backport patch for 4.19 v2 (29.43 KB, patch)
2023-12-17 17:22 UTC, Björn Jacke
metze: review+
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
Comment 21 Samba QA Contact 2023-12-15 10:45:04 UTC
This bug was referenced in samba master:

d23d6145bf08c4765479951237e697c4b2b11aa2
Comment 22 Björn Jacke 2023-12-17 17:22:14 UTC
Created attachment 18202 [details]
backport patch for 4.19 v2
Comment 23 Jule Anger 2023-12-19 09:45:20 UTC
Pushed to autobuild-v4-19-test.
Comment 24 Samba QA Contact 2023-12-19 10:44:04 UTC
This bug was referenced in samba v4-19-test:

8b913da8b990914071eb61097905c8a3b784dac5
c05330a909f18d9d5316e7beda6ec5beb4e0e2e3
13748870c37929e60835a5affdf5ac405cb436d2
fb08893cde411072fba125accff328138530f900
51ce833dd52f2dfc3876f2dbde56c189bc2032da
ed2806fd166e259aa31f354858d20eee69dc3ea7
928dfe6e94d71018fc53136d03028143af65dab2
98d794260222c287c187d38bc57f9f836e4923ab
2298b92f1832a893b2e9a8eb193c219e2221174b
efc1a606a2710d0e28a632436088c13d05b116da
Comment 25 Jule Anger 2023-12-28 15:59:41 UTC
Closing out bug report.

Thanks!
Comment 26 Samba QA Contact 2024-01-08 14:39:06 UTC
This bug was referenced in samba v4-19-stable (Release samba-4.19.4):

8b913da8b990914071eb61097905c8a3b784dac5
c05330a909f18d9d5316e7beda6ec5beb4e0e2e3
13748870c37929e60835a5affdf5ac405cb436d2
fb08893cde411072fba125accff328138530f900
51ce833dd52f2dfc3876f2dbde56c189bc2032da
ed2806fd166e259aa31f354858d20eee69dc3ea7
928dfe6e94d71018fc53136d03028143af65dab2
98d794260222c287c187d38bc57f9f836e4923ab
2298b92f1832a893b2e9a8eb193c219e2221174b
efc1a606a2710d0e28a632436088c13d05b116da