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 from middlewared 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 and SYSLOG2.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 library syslog:

(see https://github.com/truenas/middleware/blob/779a7853cb6e01b835d7b63ff4097647bc9e2a76/src/freenas/etc/find_alias_for_smtplib.py#L131C1-L131C74 ; 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 the syslog.syslog call should be rewritten to something like syslog.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 stating find_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 mysterious 1, 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).