Multiple issues with logging messages to syslog
Description
Steps to Reproduce
Expected Result
Actual Result
Environment
Hardware Health
Error Message (if applicable)
Activity
Bug Clerk November 26, 2024 at 4:58 PM
Hi , this will not be fixed in CORE since we’re only fixing critical CVE’s and/or data corruption bugs for that release. I’d recommend upgrading to SCALE since that’s where all future development is focused on.
Phil Knüfer November 26, 2024 at 4:46 PM
First of all thank you for the quick fix! Impressive response time for something that isn’t really critical :). I see that the pull requests are made against the TrueNAS Scale codebase (or rather against “master”, but the PR is labelled “25.04”). Is this something that will also be fixed in a future TrueNAS Core version?
Bug Clerk November 26, 2024 at 4:38 PM
This issue has now been closed. Comments made after this point may not be viewed by the TrueNAS Teams. Please open a new issue if you have found a problem or need to re-engage with the TrueNAS Engineering Teams.
Bug Clerk November 26, 2024 at 4:31 PM
24.10.2 PR: https://github.com/truenas/middleware/pull/15044
After connecting TrueNAS to an external syslog server, I found that there are some log messages that somehow break out of the expected log format. For reference, the syslog server is running rsyslogd and is configured so that it stores all messages of a host in a single file:
Excerpt from rsyslog conf:
I found that this correctly places messages of Linux and other BSD hosts in a single file. However, I found that the log folder also contained a mysterious file called
Backup.log
with the following content:After lots of debugging (I’ll spare you the details) I found that the reason is a backup script that is configured to run on TrueNAS as a cronjob. The script output is correctly sent via email and the following is logged on TrueNAS in
/var/log/mail.log
:Note that the two log entries are created for the mail (one stemming from
find_alias_for_smtplib.py
` and one frommiddlewared
and also note that the first one contains the mail body while the second one doesn’t.On my receiving syslog server I find the following in HOSTNAME.log:
Note that the mail body is missing from the first log message. Instead, for this specific case, two separate files
SYSLOGTEST.log
andSYSLOG2.log
(one for every line of the mail body) are created on the syslog server.I found that
find_alias_for_smtplib.py
creates this log message by issuing the following call to the Python librarysyslog
:(see ; a similar syslog statement is used in line 20 of the same file)
There is a possibility that the weird behavior could be mitigated by adapting the configuration of the remote syslog server. However, I haven’t seen this behavior on systems other than TrueNAS so far.
Independent of any potential syslog reconfiguration I identified the following things that I consider bugs/issues, or at least noticeable:
find_alias_for_smtplib.py
passes a snippet of the raw email to the local syslog. It is established practice that syslog messages should contain a single line. This assumption is broken by passing not only a newline directly in the command, but a message that itself contains multiple newlines. I can imagine cases where one would not want to log the content of an email because it might contain confidential information. As far as my (very limited) knowledge of typical mail server logs goes, usually the message id is used in log message. So maybe thesyslog.syslog
call should be rewritten to something likesyslog.syslog("sending mail with id " + message_id + " to " + ', '.join(to)")
.For some reason there are two log entries created for this single event. One originating from
middlewared
(which I think is what one would expect when analyzing log files) and one statingfind_alias_for_smtplib.py
as the sender. This seems redundant, even though they contain slightly different content (again, I think they shouldn’t contain any message content at all).I note that the weird behavior begins after the empty line that separates the email headers from the body. Maybe, if the rest of the issue is considered a WONTFIX, there should at least be some kind of filtering to strip the empty line?
While looking at the TrueNAS syslog messages I realized that the whole format of log messages in itself seems strange:
Nov 20 17:59:32 HOSTNAME 1 2024-11-20T17:59:32.178488+01:00 HOSTNAME find_alias_for_smtplib.py 74230 - - sending mail to admin@example.com
The timestamp (in
%b %d %H:%M:%S
format), the hostname, a mysterious1
, the timestamp (in ISO 8601 format), and once again the hostname seem redundant.It seems that a regular syslog message that I know from other systems is prepended with
<timestamp> <hostname> 1
.This does not only affect the above-mentioned messages related to email but apparently everything logged on TrueNAS (at least it is also the case for SMB audit logs).
I currently cannot intercept the syslog TCP traffic. I am wondering if the messages are sent to the syslog server as a single syslog message packet (which in my opinion would be the correct way to do it) or if the sending part of TrueNAS somehow wraps it in multiple packets/messages. This could be another issue that, if present, should be considered a bug (I think).