[ ] I have added information about changes made in this PR to CHANGELOG.md

Please also update the changelog.

@casperklein done

Sorry I was bit too slow to chime in on review 😓

With this modification, only log files < 180 days will be sent to pflogsumm for processing.

Could I please have some context for the approx 6 month value? My findings from below suggest this task is only meant to send mail from a < 48 hours span of time?

I have configured mail log retention to be several years instead of default.

How did you go about that btw?

Did you set something like LOGROTATE_INTERVAL=monthly + LOGROTATE_COUNT=36?

I assume your config hasn't changed the default LOGWATCH_INTERVAL=none? It seems like logwatch would otherwise encounter a similar problem that this PR has not addressed?

Could you add context as to why you prefer retaining internal logs for that length of time? No external backups or collection through the host such as systemd-journald? (may need to change the Docker log driver for that)

UPDATE: Given that the bug was actually due to an old log timestamp format lacking an associated year for filtering by, was this something you missed when upgrading to DMS v14 or newer? Our changelog did point out logs would be formatted differently. When did you upgrade?

Overview of logging feature / integration in DMS

Looking over the following context:

• https://docker-mailserver.github.io/docker-mailserver/v15.1/config/environment/#reports
• https://github.com/search?q=repo%3Adocker-mailserver%2Fdocker-mailserver%20pflogsumm&type=code

I have this understanding:

• Logging logic discussed below for scripts/startup/setup.d/log.sh are called here in start-mailserver.sh.
• LOGROTATE_INTERVAL supports rotating logs at intervals of daily, weekly, monthly (config logic handled here).
• LOGWATCH_INTERVAL calls the logwatch program to send a daily or weekly report (logic configured here as a cron job), or if set to none (default) then opt-out.
• PFLOGSUMM_TRIGGER supports either:
  • daily_cron (daily log mail sent via our script report-pflogsumm-yesterday which is scheduled as a cron job)
  • logrotate (after rotating logs will then invoke via config action postrotate our script postfix-summary which only sends the newly rotated /var/log/mail/mail.log.1)
  • none (default) opt-out of sending logs.

This PR only made a change to the report-pflogsumm-yesterday script, which collects rotated logs to pipe into pflogsumm --problems_first -d yesterday? Why would the mtime filter be 180 days then?

The postfix-summary script only cares about the newly rotated log file (pflogsumm /var/log/mail/mail.log.1 --problems-first), so no concern there.

When we configure logwatch to use either daily/weekly intervals, these are apparently filtering by timestamps in the log files themselves (pflogsumm presumably does similar, both using Perl), with configs:

$ cat /etc/logwatch/conf/logfiles/maillog.conf

#
# Extensions for docker-mailserver /var/log/mail/. log path
#

# Mail log files
LogFile = mail/mail.log
LogFile = mail/mail.log.1

# Support Archives
Archive = mail/mail.log.*.gz

$ cat /etc/logwatch/conf/logfiles/clam-update.conf

LogFile = /var/log/mail/freshclam.log

Since logrotate is configured to compress logs, that Archive line means they'll all get parsed regardless, and then filtered by timestamp.

Startup scripts - Related logic that affects log files mtime

NOTE: We also have log fixes applied in this container startup function:

• Although AFAIK only the clamav log files (/var/log/mail/{clamav,freshclam}.log) will get their mtime changed (due to touch) to the day of the container run (this includes standard container restarts as __log_fixes() is called here).
• The startup scripts also touch the primary log file, but that is irrelevant in this context.

TL;DR: Actual source of failure identified (old DMS logs used a different timestamp format that omitted the year).

Change in timestamp format since DMS v14 (June 2024)

Also worth noting is in June 2024 with the DMS v14 release (upgrade to Debian 12), the changelog Rsyslog notes mention the timestamp format was changed by Debian:

• From RSYSLOG_TraditionalFileFormat (similar to RFC 3164).
  • Timestamp format is non-standard Mmm dd hh:mm:ss (defined in RFC 3164 Section 4.1.2).
• To RSYSLOG_FileFormat (similar to RFC 5424).
  • Timestamp format is standardized, uses RFC 3339 (a strict subset of ISO 8601).

I provided more insights here, but these two snippets below are worth pointing out.

EDIT:Another related PR

• I provided a review comment noting there is another template with rsyslog RSYSLOG_SyslogRFC5424Format (beneficial if preferring that log format for forwarding/ingesting elsewhere).
• That PR also contains my review comment detailing the change by Debian (since 2012) that was finally removed for Debian 12.

The logger command with actual RFC 3164 vs RFC 5424 format output:

# Old RFC 3164 format (lacks a year, assumes present year):
$ logger --rfc3164 --priority mail.error --id=1337 --tag dms-changedetector "This is an example error message!"
<19>May 26 11:45:27 mail dms-changedetector[1337]: This is an example error message!

# RFC 5424 format (notq omits the structured data regarding time, msgid is rfc5424 only):
$ logger --rfc5424=notq --priority mail.error --id=1337 --msgid=hello --tag dms-changedetector "This is an example error message!"
<19>1 2024-05-26T11:45:28.305480+00:00 mail.example.test dms-changedetector 1337 hello - This is an example error message!

While in DMS this is how the formats differ from the above two logger commands (indicated below as 1st line as RFC 3164 + 2nd line as RFC 5424) after being processed through rsyslog (which ingests logger syslog input, and then formats it slightly differently), comparing between DMS v13.3 vs DMS v14:

# DMS v13.3 (RSYSLOG_TraditionalFileFormat):
May 26 11:51:14 mail mail dms-changedetector[1337]: This is an example error message!
May 26 11:55:07 mail 1 2024-05-26T11:55:07.509942+00:00 mail.example.test dms-changedetector 1337 - - This is an example error message!

# DMS v14 (RSYSLOG_FileFormat):
2024-05-26T12:05:58.700336+00:00 mail mail dms-changedetector[1337]: This is an example error message!
2024-05-26T12:17:07.824094+00:00 mail 1 2024-05-26T12:17:07.824035+00:00 mail.example.test dms-changedetector 1337 hello - This is an example error message!

So rsyslog isn't outputting RFC 3164 or RFC 5424 syslog formats regardless, just ingesting either , displaing the message and differing by timestamp format. Notice the lack of year in logs for DMS v13.3 / RSYSLOG_TraditionalFileFormat? That's likely the culprit 😓

Reproduction - Verified assumptions

I've confirmed what might have been obvious by now, the RFC 3339 timestamps on logs are fine, it's the old DMS releases logs that were using RFC 3164 until Debian 12 / DMS 14 finally switched to using RFC 3339 timestamps.

verify-log-parsing.sh:

#!/bin/bash

# Prepend some timestamps for the log processors to filter by:
function _generate_mock_logs() {
  local LOG_MESSAGE="${1:?Expected a log message}"

  # RFC 3339 timestamp from yesterday, with offsets by year:
  RFC_3339_YMD0=$(date -d "yesterday" +"%Y-%m-%d")
  RFC_3339_YMD1=$(date -d "yesterday - 1 year" +"%Y-%m-%d")
  RFC_3339_YMD2=$(date -d "yesterday - 2 years" +"%Y-%m-%d")

  # RFC 3164 timestamps are like `Jan  1 12:34:56` (format lacks context of which year)
  RFC_3164_MD=$(date -d "yesterday - 2 years" +"%b %e")

  # RFC 3339 Format: <YYYY-MM-DD>T<HH:mm:ss>[.<fractional-seconds: 1-7 decimal places)>]<UTC offset: (Z|+HH:mm|-HH:mm)>
  RFC_3339_SUFFIX='00:00:00.100001+00:00'

  local LOG_LINES=(
    "${RFC_3339_YMD0}T${RFC_3339_SUFFIX} ${LOG_MESSAGE}" # 2026
    "${RFC_3339_YMD1}T${RFC_3339_SUFFIX} ${LOG_MESSAGE}" # 2025
    "${RFC_3339_YMD2}T${RFC_3339_SUFFIX} ${LOG_MESSAGE}" # 2024
    "${RFC_3164_MD} 00:00:00 ${LOG_MESSAGE}"             # 2026 (year could not be encoded)
  )

  # Output the array as a multi-line string
  printf "%s\n" "${LOG_LINES[@]}"
}

# Example log messages (neither message below was mutually reported across both commands, thus separate examples used):
JSON_DATA=$(printf '%s' '
[
  {
    "CMD": "pflogsumm",
    "LOG_MESSAGE": "mail postfix/master[762]: daemon started -- version 3.7.11, configuration /etc/postfix"
  },
  {
    "CMD": "logwatch",
    "LOG_MESSAGE": "mail postfix/postfix-script[761]: starting the Postfix mail system"
  }
]')

function _run_log_reporters() {
  local MAIL_LOG="${TMP_DIR}/mail.log"

  # Iterating over objects/structs in Bash is awkward..
  # JSON used with tab delimiter to split object properties into variable assignments.
  local CMD LOG_MESSAGE REPORT
  while IFS=$'\t' read -r CMD LOG_MESSAGE; do
    _generate_mock_logs "${LOG_MESSAGE}" > "${MAIL_LOG}"

    case "${CMD}" in
      # `pflogsumm` can accept log files as args or via stdin, otherwise hangs?:
      ('pflogsumm')
        REPORT=$(pflogsumm -d yesterday "${MAIL_LOG}" | grep -i -A2 master)
        ;;

      # `logwatch` can only process log files via resolved config files via `LogFile` setting.
      # - `--logfile` (a service group) or `--service` restricts what logs to process.
      # - `--logdir` can add additional logdirs (however `/var/log` + `/var/adm` are always implicit).
      # NOTE: To ignore `/var/log` as a logdir, ensure the generated logs and `--range` wouldn't overlap with `/var/log/mail.log`.
      ('logwatch')
        REPORT=$(TZ=UTC logwatch --service postfix --range yesterday --logdir "${TMP_DIR}" | grep -A5 'Postfix Begin')
       ;;
    esac

    echo -e "\n\nReport (filtered) from '${CMD}':"
    sed 's/^/\t/' <<< "${REPORT}"
  done < <(jaq -r '.[] | .CMD + "\t" + .LOG_MESSAGE' <<< "${JSON_DATA}")
}

TMP_DIR=$(mktemp -d)
_run_log_reporters
rm -rf "${TMP_DIR}"

# RFC 3164 log line (used prior to DMS v14) was counted:
$ bash verify-log-parsing.sh

Report (filtered) from 'pflogsumm':
        Master daemon messages
        ----------------------
              2   daemon started -- version 3.7.11, configuration /etc/postfix


Report (filtered) from 'logwatch':
         --------------------- Postfix Begin ------------------------

                2   Postfix start                                    2


         ---------------------- Postfix End -------------------------

Hey @polarathene, thanks for the detailled review! I will try to answer to everything.

With this modification, only log files < 180 days will be sent to pflogsumm for processing.

Could I please have some context for the approx 6 month value? My findings from below suggest this task is only meant to send mail from a < 48 hours span of time?

Actually you're right! 180 is definitely not necessary. Since the issue appeared after one year, I just reduced to half without thinking too much about it. My bad :-(

I have configured mail log retention to be several years instead of default.

How did you go about that btw?

I'm using a custom user-patches.sh script, with something like:

echo "Updating maillog to 10 years retention..."
sed -i -e 's/rotate 4/rotate 520/' /etc/logrotate.d/maillog

Did you set something like LOGROTATE_INTERVAL=monthly + LOGROTATE_COUNT=36?

Nope, I think this was introduced in a more recent version (I'm not on latest, see below).

I assume your config hasn't changed the default LOGWATCH_INTERVAL=none? It seems like logwatch would otherwise encounter a similar problem that this PR has not addressed?

Yes, I'm not using logwatch

Could you add context as to why you prefer retaining internal logs for that length of time? No external backups or collection through the host such as systemd-journald? (may need to change the Docker log driver for that)

Of course! I'm using DMS for my personal mail, so rather low traffic. Some time ago a friend of mine sent me an email, but I never received it. Some weeks later he told me about it, and I couldn't find anything in the logs since they had been rotated.
That's why I decided to increase log retention, to be able to investigate such cases (pretty rare, but I still have issues with some mail providers, despite having SPF+DKMS enabled)
Regarding external backups, it could be possible but I prefer to keep everything at the same place, to be able to launch a simple "grep".

UPDATE: Given that the bug was actually due to an old log timestamp format lacking an associated year for filtering by, was this something you missed when upgrading to DMS v14 or newer? Our changelog did point out logs would be formatted differently. When did you upgrade?

Actually I'm still using 12.1 😅 I remember I tried to upgrade some time ago and encountered some regressions, so I kept the working version. I will try to upgrade again to latest stable release

Overview of logging feature / integration in DMS

[...]

To conclude, this may not be necessary on newer versions, but for performance issue it still might be relevant, to avoid unzipping hundreds of log files.

@polarathene I updated to restrict to 3 days only (2 + 1 to avoid edge cases)

@piwai it looks like you opened a PR to your own fork of DMS by accident? 😅

I have a suggestion below that might be a better approach (no mtime filtering needed).

You are correct about the LOGROTATE_COUNT ENV, that was also introduced in DMS v14.

Once you've upgraded you can drop the custom patch if you like 👍 (NOTE: LOGROTATE_COUNT affects log retention for other service logs too fail2ban and rspamd have logrotate configs configured by DMS with that ENV too)

To conclude, this may not be necessary on newer versions, but for performance issue it still might be relevant, to avoid unzipping hundreds of log files.

I agree that the previous logic wasn't ideal. Thanks for contributing to the project so we could resolve that ❤️

I don't know if we really need an mtime filter though? Since we're only concerned with processing logs for -d yesterday only two files matter? (mail.log + mail.log.1), the .gz archives will be older than that so never relevant.

I think this would be sufficient (No pipe with cat/gzip/find/sort -rV needed now):

# `pflogsumm` expects files in chronological order, while for `-d yesterday`
# the only relevant log files to process are `mail.log.1` (oldest) and `mail.log`:
BODY=$(/usr/sbin/pflogsumm --problems_first -d yesterday /var/log/mail/mail.log{.1,})

I included some inline commentary for context.

Additional note... I've noticed that logrotate can result in both of those files having the same mtime, so if we weren't able to rely on the filename convention for some reason, sorting by timestamps with ls -rt would not be reliable.

Below is just some notes addressing concerns I had raised earlier (like with logwatch). These are resolved now and can be ignored 😎

Mixed intervals

Summary: No issues to address. Can ignore.

DMS officially supports configuring logrotate intervals of daily, weekly (default), and monthly. Interaction with pflogsumm and logwatch reporters:

• pflogsumm reports (PFLOGSUMM_TRIGGER with daily_cron / logrotate):
  • ✅: daily_cron paired with any LOGROTATE_INTERVAL. In all cases I think the only relevant log files are /var/log/mail/mail.log{.1,}? (that bash syntax {.1,} expands path stems to mail.log + mail.log.1)
  • ✅: logrotate trigger is always on /var/log/mail/mail.log.1.
• logwatch reports (daily or weekly intervals).
  • ✅: When LOGWATCH_INTERVAL is matching LOGROTATE_INTERVAL (or this interval is higher), then similar to pflogsumm only two log files are relevant, archives won't matter.
  • ⚠️? (UPDATE: ✅): A LOGWATCH_INTERVAL=weekly + LOGROTATE_INTERVAL=daily combination would require setting at least LOGROTATE_COUNT=7 (thus archived logs will also be processed). If LOGROTATE_COUNT were notably higher, I'm not sure how we would limit the number of archives to process? (UPDATE: logwatch uses mtime itself on archives to filter, so not an issue).

logwatch internally filters archives by mtime (2 day buffer)

Summary: logwatch does not require a related change 😎

I have investigated source code of logwatch and verified that LogFile paths in maillog.conf config are checked regardless, but Archive entries are filtered by the requested --range and mtime check, with a 2 day buffer for timezones.

• If logwatch were run with a --range 'between 7 days ago and yesterday' filter, while that does extend to 9 days, the buffer offset is in seconds (86_400 * 2), and AFAIK is from when the command is invoked, thus if the mtime of an archive is from earlier that day than the unix timestamp (even by a second), it will be excluded.
• That buffer however should prevent any race condition concerns as a bonus (from separate cron tasks invoking logrotate and logwatch at roughly the same time). Both mail.log and mail.log.1 files get unconditionally processed, and then any subsequent mail.log.*.gz archives filtered conditionally based on the given range query (with approx 2 day buffer/padding) 👍

sorry for the delay. @polarathene I finally tested your suggestion to keep only mail.log{.1,} and it works as expected. I opened #4722
(and BTW I finally upgraded to DMS 15.1)