Test failures and issues from opting-out of syslog to a separate log file

The bulk of the test failures was caused by Postfix logs being relocated to supervisor postfix.log location.

• By no longer sending logs to rsyslog (default behaviour for Postfix), they were no longer part of the syslog configured (/etc/rsyslog.conf) facility mail, which was configured to write logs to /var/log/mail/mail.log (and which start-mailserver.sh tails for terminal output).
• This is an issue for some other tests:
  • Rspamd tests call _print_mail_log_for_id() helper to match multiple log lines from different services involved in processing mail (eg Postfix + ClamAV).
  • Fail2Ban tests fail due to upstream default log file being monitored for Postfix no longer getting Postfix log content, thus f2b rules have nothing to match to trigger bans.

I wouldn't be surprised if that impacts anything else not being caught by existing tests. Or potential for users to likewise monitor that file (or log output to terminal / docker logging driver).

Investigation

Looking into supervisord + rsyslog services while I tried to understand how the logging situation with Postfix was working / changed. Documenting notes here.

supervisord

Config for services has roughly the same pattern repeated, pointing both stdout and stderr streams to the same file based on the service name. The stderr could instead achieve that save approach by redirecting to stdout stream to write to the same file with redirect_stderr = true.

This config could likely just leverage the AUTO log mode with childlogdir, which would achieve similar result with less repetitive config, placing log files with service names into the given location, albeit separating out stdout + stderr streams to their own files. It is already configured to the same /var/log/supervisor location we're using.

Additionally, considering observations with process management, when a service is misconfigured and fails to start, supervisor by default is more than happy to restart it constantly, spamming logs thousands of times rather quickly. That could be avoided by setting a limit with startretries, which also has a backoff strategy to delay each additional restart attempt.

Relevant to logging, there is an implicit stdout_logfile_maxbytes setting enabled for services logs, which would handle logfile rotation, it comes with the following warning:

It is not possible for two processes to share a single log file (stdout_logfile) when rotation (stdout_logfile_maxbytes) is enabled. This will result in the file being corrupted.

There is no service with a shared log file (except for the stdout + stderr combo of each service / process), but Postgrey presently configures itself to /var/log/mail/mail.log for some reason..

I haven't looked into why Postgrey was configured that way, but presumably it lacked support / config to integrate with syslog and have it's content merged in with /var/log/mail/mail.log 🤷‍♂️ (still, it probably shouldn't be writing to a file that is frequently written to by another process(es)?)

There is another config setting stdout_syslog=true that supervisor allows for. I observed it as writing to /var/log/syslog, but it would add a supervisord: <service> syslog tag, along with other syslog metadata being duplicated, such as with this attempt with Postfix:

Mar  1 02:31:34 example supervisord: postfix Mar 01 02:31:34 example postfix/postfix-script[458]: starting the Postfix mail system

syslog

• Wikipedia for Syslog and Rsyslog.
• Docs, config file docs

I got a bit more familiar with syslog while investigating this. There's a feature to configure watching log files as source inputs with the imfile module:

module(load="imfile" Mode="inotify") #needs to be done just once

# File 1
input(type="imfile"
      File="/var/log/supervisor/postfix.log"
      Tag="testing"
      Facility="mail")

input(type="imfile"
      File="/var/log/supervisor/postgrey.log"
      Facility="mail")

But as it turns out the tag field is mandatory, and I observed that this wasn't any better than the Supervisor feature, other than being able to specify the facility, I still got the timestamp, host and configured tag prefixed to log lines.

Postfix itself doesn't appear to have much means to configure that log format / prefix, even though we changed to opt-out of syslog in this PR. I also looked into the postlog (and postlogd) docs, but found nothing there to customize the Postfix log format.

It seemed a little promising, since the docs for the imfile() module mention it can handle tailing log rotated files and such.

I think it may still be possible to use rsyslog features to parse / transform the log file and resolve that, however I was not really into the docs and decided that wasn't something I wanted to dig further into 😅 (maybe this or this would be relevant)

Amavis

# lines of interest grepped with `log` in /etc/amavis/conf.d/20-debian_defaults:

$DO_SYSLOG = 1;
$syslog_ident = 'amavis';    # syslog ident tag, prepended to all messages
$syslog_facility = 'mail';
$syslog_priority = 'debug';  # switch to info to drop debug output, etc

Out of curiosity, I also looked into Amavis. Which is configured to use syslog. $do_syslog = 0; will opt-out of that and output to stdout where supervisor service config for Amavis could then actually write the content to it's log file.

Same issue of course as other services where logs were part of /var/log/mail/mail.log. There are other settings if wanting to write to a log file without supervisor handling that. Docs on such settings weren't easy to find, but I did find the Amavis source on Gitlab to reference and an old mailing list of similar config prior to that from 2002.

When not using syslog, it outputs log lines that appear to be syslog format, but slightly different than Postfix, starting with numeric identifier <5>, which I think is the notice severity level, but could also be the syslog internal facility too 🤷‍♂️

I was investigating this issue as well, but noticed weird behaviour in some of the test helpers.

I'd be nice if you find a solution to this problem; I will tend to the helpers.

What if we just set Postfi'x log file to /var/log/mail/mail.log (too)? (probably need to disable log rotation from supervisor then?)

What if we just set Postfi'x log file to /var/log/mail/mail.log (too)?

As per concerns raised in investigation notes with Postgrey service logs by supervisor, I don't feel it's a good idea to have multiple writers to the same file. Technically I'd expect that wouldn't increase the existing processes writing since it'd just be Supervisor still (with rsyslog being the other involved that comes to mind).

We could try it as a workaround / quick fix, at the risk of the log being updated concurrently by both processes at some point messing up the log or corrupting it.

Something I didn't get around to yesterday is checking if without the chroot jail, would Postfix use /dev/log for syslog, instead of the relative path from it's queue_directory? If it would, then this would probably be the best choice for now, otherwise the next best option is to not attempt to remove this /var/spool/postfix/dev location (at least keeping the folder, contents can be removed).

Vector for log management

One potential proper fix for the logging concern in this PR is to evaluate how viable overhauling our logging is handled. I was looking into vector for this, which has been interesting to me for quite some time. Supervisor could manage this as a service that can take in file sources for the supervisor logs (log rotated inputs is supported just like rsyslog), as well as syslog source, where we can do any necessary transforms.

The config and docs for Vector seems much more pleasant than rsyslog, the syntax is called VRL and it's built off rust 😛

Presently the output options (sinks) are lacking one for syslog style. There's a tracking issue related to that, and it seems that they've made progress late last year towards getting the socket sink to support syslog formatted logs, but not quite there yet. I came across this 2021 discussion which might offer something in the interim if we need that. Alternatively, we could just use Vector to remove the syslog metadata that was an issue, and have rsyslog with imfile() process that instead of replacing rsyslogs /var/log/mail/mail.log file 🤷‍♂️

There is some potential concerns though with Vector and log rotated file sources:

• Stuck file descriptors for rotated files vectordotdev/vector#15067
• Vector keeps old Inodes, clogging up disk vectordotdev/vector#11742

While Vector can output to a file based log as well, it does not manage log rotation itself. I see that we're using logrotate already for that beyond what supervisor is doing for the logs it manages. I've come across this helpful guide on logrotate, so can probably make this work 😅

I'll need to give the above some more thought, but it might work well for us.

Vector seems very interesting! Keep us posted here, I read through all of it and this is nice!

As for now, we may want to apply "a quick fix" just proving /var/log/mail/mail.log for Postfix's log file? This way, we could merge the other PR.

See next post.

Afaik the only "issue" we currently have is this line appearing in /var/log/syslog:

Mar 3 00:19:10 mail rsyslogd: cannot create '/var/spool/postfix/dev/log': No such file or directory [v8.2102.0 try https://www.rsyslog.com/e/2176 ]

Just deleting /etc/rsyslog.d/postfix.conf should be enough?

Also, with logging to just one file we would lose rsyslog's feature to log by facility:

grep ^mail /etc/rsyslog.conf
mail.*                          -/var/log/mail/mail.log
mail.info                       -/var/log/mail/mail.info
mail.warn                       -/var/log/mail/mail.warn
mail.err                        /var/log/mail/mail.err

Just deleting /etc/rsyslog.d/postfix.conf should be enough?

Yep, I wasn't paying attention before, and only just realized that myself 😂

Also, with logging to just one file we would lose rsyslog's feature to log by facility:

I also had another misunderstanding there with postlog thinking it wasn't leveraging syslog severity levels 😅

Facility I don't think would matter in this sense, as Postfix just uses the mail facility? This PR was about writing Postfix logs to a separate file, and then thinking how to get a copy back into /var/log/mail/mail.log.

All good. I think there is benefit in bringing Vector in at a later point. But for now there's a quick and easy fix 👍 (only removing /etc/rsyslog.d/postfix.conf)

When @casperklein's review is finished, I can merge this even if GH actions is till bugged. Just tell me :)

When @casperklein's review is finished

I think it's finished, the concern was resolved 👍

setup_cli.bats failed with:

not ok 61 [setup.sh] exit with error when wrong arguments provided in 264ms
# (from function `assert_line' in file test/test_helper/bats-assert/src/assert_line.bash, line 134,
#  in test file test/tests/parallel/set3/scripts/setup_cli.bats, line 37)
#   `assert_line --index 0 --partial "The command 'lol troll' is invalid."' failed
# /home/runner/work/docker-mailserver/docker-mailserver/test/test_helper/bats-assert/src/assert_line.bash: line 134: lines: parameter not set

Not sure what caused that failure. assert_failure was successful at detecting failure, but no error message was output?

Re-ran test and it passes now 🤷‍♂️

@casperklein when you approve, please go ahead and merge this straight away :)