From 463d4ff3fef5d1f02814657bae1be47fac6ecdbf Mon Sep 17 00:00:00 2001 From: Mix Date: Wed, 14 Oct 2026 23:12:37 +0300 Subject: [PATCH] log tailer: the rotated mail.log read until postlogd lets it go postlogd opens maillog_file once per process (Postfix 3.7.11, src/postlogd/postlogd.c, pre_jail_init()) and leaves it only when it exits: at "postfix reload" master closes the service's status pipe (src/master/master_service.c, master_restart_service() -> master_status_cleanup()) and dgram_server_abort() exits on reading its end (src/master/dgram_server.c). logrotate renames and creates, then runs the reload (build/logrotate-mail.conf postrotate; logrotate 3.21.0, logrotate.c, rotateLogSet(), after rotateSingleLog()), so lines go to the renamed file in between, and the tailer, already on the new one, never read them (assumptions A-33). follow() now keeps the renamed file open as a rotatedTail and reads it on each tick for rotatedGrace (a minute, far longer than the gap); its places are never saved as the resume point, so a restart still reads the rotated file through readRotated. A truncated file is not kept. The RFC 3339 stamp goes (A-12): it was written for a maillog_file_format said to arrive in Postfix 3.9; there is none in 3.7.11 nor in the 3.12 snapshot of 2026-09-25 (proto/postconf.proto; msg_logger.c, msg_logger_print() keeps strftime("%b %d %H:%M:%S ")). Every fixture now carries the stamp Postfix writes; logtail's TestMain fixes time.Local to UTC, since the stamp is local time and this PC is UTC+3. Tests: TestFollowReadsTheRotatedFileAfterTheSwitch (Linux: a line appended to the renamed file after the switch reaches the store). Stand (2026-10-14): go vet and go test ./... pass on the server (23 packages); make e2e exit 0, delivery_log_survives_rotation included. The tested tree was this commit plus the previous one; the CHANGELOG entry was written after the run, and a comment's logrotate citation corrected (rotateLogSet runs postrotate, not rotateSingleLog). Co-Authored-By: Claude Opus 5.5 --- CHANGELOG.md | 6 + internal/logtail/inbound.go | 7 -- internal/logtail/inbound_test.go | 10 +- internal/logtail/logtail.go | 118 +++++++++++++----- internal/logtail/logtail_test.go | 64 +++++++--- internal/logtail/main_test.go | 17 +++ internal/logtail/refusals_test.go | 22 ++-- internal/logtail/sendercheck_test.go | 60 ++++----- .../web/handlers/handlers_monitor_test.go | 24 ++-- .../handlers/handlers_outbound_log_test.go | 2 +- internal/web/handlers/handlers_users_test.go | 2 +- 11 files changed, 216 insertions(+), 116 deletions(-) create mode 100644 internal/logtail/main_test.go diff --git a/CHANGELOG.md b/CHANGELOG.md index 4925205..1aa2d7d 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -43,6 +43,12 @@ Format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/); version message forced to expire (`postsuper -e`, `#` in the queue listing) is still counted as held (audit 2026-10-12, stage 2c; assumptions A-8, B-PQ1). +- **Lines Postfix writes while `mail.log` is being rotated are read.** + Postfix's log writer keeps the old file open until the reload that + follows the rotation; the log tailer switched to the new file at once, + so a delivery written in between never reached its row, which the sweep + later closed as `bounced`. The tailer now reads the rotated file for a + minute more (assumptions A-33). - **Postfix's time values are read as Postfix reads them.** A bare number took seconds, so `maximal_queue_lifetime = 3` was three seconds to the panel and three days to Postfix; `1h7m` was 67 minutes to the panel and diff --git a/internal/logtail/inbound.go b/internal/logtail/inbound.go index 0bb71dc..cef9014 100644 --- a/internal/logtail/inbound.go +++ b/internal/logtail/inbound.go @@ -269,13 +269,6 @@ func printable(s string, max int) string { // process has the container's zone (TZ is in import_environment, // src/global/mail_params.h). A line with no readable stamp is dated now. func lineTime(line string, now time.Time) (time.Time, string) { - if m := isoStampRe.FindStringSubmatch(line); m != nil { - rest := strings.TrimSpace(line[len(m[0]):]) - if t, err := time.Parse(time.RFC3339Nano, strings.TrimSpace(m[0])); err == nil { - return t.UTC(), rest - } - return now, rest - } if m := syslogStampRe.FindStringSubmatch(line); m != nil { rest := strings.TrimSpace(line[len(m[0]):]) stamp := strings.Join(strings.Fields(m[1]), " ") diff --git a/internal/logtail/inbound_test.go b/internal/logtail/inbound_test.go index 278964b..acddfd7 100644 --- a/internal/logtail/inbound_test.go +++ b/internal/logtail/inbound_test.go @@ -54,10 +54,10 @@ var tailNow = time.Date(2026, 10, 11, 18, 0, 0, 0, time.UTC) // The mail.log lines in this file are composed by hand, after // src/smtpd/smtpd_check.c log_whatsup() and src/cleanup/cleanup_milter.c -// cleanup_milter_apply() (Postfix 3.7.11). Their ISO stamp is not a format -// Postfix writes (assumptions A-12); TestLineTime has the syslog one. +// cleanup_milter_apply() (Postfix 3.7.11), with the stamp Postfix 3.7 writes +// (src/util/msg_logger.c, "%b %d %H:%M:%S"). const ( - head = "2026-10-11T12:00:05.123456+00:00 mail " + head = "Oct 11 12:00:05 mail " unknownRcp = head + "postfix/inbound/smtpd[41]: NOQUEUE: reject: RCPT from mx.example.net[203.0.113.9]: 550 5.1.1 : Recipient address rejected: User unknown in relay recipient table; from= to= proto=ESMTP helo=" ) @@ -74,7 +74,7 @@ func TestInboundRejectByPostfix(t *testing.T) { From: "a@example.net", To: "nobody@in.example.com", Decision: store.SpamDecisionReject, Engine: store.SpamEnginePostfix, Detail: "550 5.1.1 : Recipient address rejected: User unknown in relay recipient table", - At: time.Date(2026, 10, 11, 12, 0, 5, 123456000, time.UTC), + At: time.Date(2026, 10, 11, 12, 0, 5, 0, time.UTC), } if st.rows[0] != want { t.Errorf("row = %+v\nwant %+v", st.rows[0], want) @@ -280,7 +280,7 @@ func TestLineTime(t *testing.T) { want time.Time rest string }{ - {"2026-01-02T09:00:00.5+03:00 mail postfix/x: y", time.Date(2026, 1, 2, 6, 0, 0, 500000000, time.UTC), "mail postfix/x: y"}, + {"Jan 02 09:00:00 mail postfix/x: y", time.Date(2026, 1, 2, 9, 0, 0, 0, time.Local).UTC(), "mail postfix/x: y"}, {"Jan 2 09:30:00 mail postfix/x: y", time.Date(2026, 1, 2, 9, 30, 0, 0, time.Local).UTC(), "mail postfix/x: y"}, // December read in January is last year's. {"Dec 31 23:59:00 mail postfix/x: y", time.Date(2025, 12, 31, 23, 59, 0, 0, time.Local).UTC(), "mail postfix/x: y"}, diff --git a/internal/logtail/logtail.go b/internal/logtail/logtail.go index 60eccc6..98a8172 100644 --- a/internal/logtail/logtail.go +++ b/internal/logtail/logtail.go @@ -581,41 +581,28 @@ func isQueueIDByte(b byte) bool { return b >= '0' && b <= '9' || b >= 'A' && b <= 'Z' || b >= 'a' && b <= 'z' } -// Timestamps at the head of a mail.log line (maillog_file in -// build/postfix-config.sh): the one format postlogd writes, and an ISO one. -// -// syslogStampRe is the one that matches. Postfix 3.7.11, +// syslogStampRe is the timestamp at the head of a mail.log line (maillog_file +// in build/postfix-config.sh), the one format Postfix 3.7 writes. Postfix 3.7.11, // src/util/msg_logger.c, msg_logger_print(): every record is stamped // strftime("%b %d %H:%M:%S ") in the logging process's local time (the day // zero-padded), then the first label of the host name, and postlogd writes it // as received (src/postlogd/postlogd.c, postlogd_service()). It carries no // year and no zone, so the stamp shown is a wall clock and nothing more, -// which is all this column claims to be. -// -// isoStampRe was written for an RFC 3339 format said to come with a -// maillog_file_format parameter of Postfix 3.9. No such parameter exists in -// 3.7.11, nor in the 3.12 snapshot of 2026-09-25 (postconf.proto, and -// msg_logger.c still uses the same strftime) - assumptions A-12. No line -// Postfix writes matches it. -var ( - isoStampRe = regexp.MustCompile(`^(\d{4}-\d{2}-\d{2})T(\d{2}:\d{2}:\d{2})(?:\.\d+)?(?:Z|[+-]\d{2}:?\d{2})?\s`) - syslogStampRe = regexp.MustCompile(`^([A-Z][a-z]{2}\s+\d{1,2} \d{2}:\d{2}:\d{2})\s`) -) +// which is all this column claims to be. An RFC 3339 stamp once matched +// here too, for a maillog_file_format parameter said to arrive in Postfix +// 3.9; there is none in 3.7.11, nor in the 3.12 snapshot of 2026-09-25 +// (proto/postconf.proto; msg_logger.c keeps the strftime) - assumptions A-12. +var syslogStampRe = regexp.MustCompile(`^([A-Z][a-z]{2}\s+\d{1,2} \d{2}:\d{2}:\d{2})\s`) // SplitTimestamp separates the timestamp at the head of a mail.log line from // the rest of it, so a page can put the two in their own columns. The stamp -// comes back without its fractional seconds and zone offset — five decimal -// places of microsecond are the widest part of the column and the least worth -// reading — but is otherwise the log's own wall clock, not converted: what is -// on the page is what is in the file. +// is the log's own wall clock, not converted: what is on the page is what is +// in the file. // // A line whose head is not a timestamp this recognises comes back whole, as // rest, with an empty stamp. Nothing is ever dropped: the point of showing the // log is that it says what it says. func SplitTimestamp(line string) (stamp, rest string) { - if m := isoStampRe.FindStringSubmatch(line); m != nil { - return m[1] + " " + m[2], strings.TrimSpace(line[len(m[0]):]) - } if m := syslogStampRe.FindStringSubmatch(line); m != nil { return m[1], strings.TrimSpace(line[len(m[0]):]) } @@ -647,6 +634,8 @@ func follow(ctx context.Context, path string, tr *tracker, caughtUp chan struct{ // consumed is the offset just past what the reader has handed over, // pending included: where a complete line ends. consumed int64 + // old is the file rotated away, still read for rotatedGrace. + old *rotatedTail ) openAt := func(offset int64, whence int) error { nf, err := os.Open(path) @@ -727,6 +716,39 @@ func follow(ctx context.Context, path string, tr *tracker, caughtUp chan struct{ return pos - int64(len(pending)) } + // drainOld reads what was written to the rotated file since the switch. + // Its lines take places in that file, which the tracker never saves as + // the place to resume from: on a restart the rotated file is read from + // the saved place in the new one onward only (readRotated). + drainOld := func(now time.Time) { + if old == nil { + return + } + defer flush() + for { + line, err := old.r.ReadString('\n') + old.consumed += int64(len(line)) + if err != nil { + old.pending += line + break + } + full := old.pending + line + old.pending = "" + tr.line = Place{FP: old.fp, End: old.consumed} + tr.lineStart = old.consumed - int64(len(full)) + handle(strings.TrimRight(full, "\r\n")) + } + if now.After(old.until) { + old.f.Close() + old = nil + } + } + defer func() { + if old != nil { + old.f.Close() + } + }() + var once sync.Once blind := &blindness{add: tr.st.AddTailerBlind} @@ -739,6 +761,7 @@ func follow(ctx context.Context, path string, tr *tracker, caughtUp chan struct{ tr.record(f, read(), true) // shutdown: the next start resumes here return nil case <-ticker.C: + drainOld(time.Now()) drain() once.Do(func() { close(caughtUp) }) ni, err := os.Stat(path) @@ -751,19 +774,33 @@ func follow(ctx context.Context, path string, tr *tracker, caughtUp chan struct{ // Rotated away or truncated: the old (renamed) inode may have // gained lines between the drain() above and this check, since // Postfix keeps writing to it until it reloads. Drain it once - // more before switching so nothing in that gap is lost. - // Postfix 3.7.11, src/postlogd/postlogd.c, pre_jail_init(): - // maillog_file is opened once per postlogd process, which ends - // at "postfix reload" (README_FILES/MAILLOG_README) or after - // max_idle without a record (src/master/dgram_server.c). Lines - // it writes to the old inode after this switch and before the - // reload are not read - assumptions A-33. + // more before switching, and - renamed, not truncated - go on + // reading it for rotatedGrace after the switch, for what + // postlogd writes there until the reload (assumptions A-33). drain() + renamed := !os.SameFile(info, ni) + if old != nil { + drainOld(time.Time{}) // a second rotation within the grace + if old != nil { + old.f.Close() + old = nil + } + } + prev := &rotatedTail{f: f, r: r, pending: pending, consumed: consumed, fp: tr.fp, until: time.Now().Add(rotatedGrace)} + if renamed { + f = nil // openAt closes the file it replaces; this one is kept + } if err := openAt(0, io.SeekStart); err != nil { + if renamed { + f, r = prev.f, prev.r + } log.Printf("log-tailer: reopen %s: %v", path, err) blind.see(time.Now(), true) continue } + if renamed { + old = prev + } blind.see(time.Now(), false) tr.adopt(f) continue @@ -774,6 +811,29 @@ func follow(ctx context.Context, path string, tr *tracker, caughtUp chan struct{ } } +// rotatedTail is mail.log just rotated away, still open: postlogd writes to +// it until "postfix reload" makes it exit. Postfix 3.7.11, +// src/postlogd/postlogd.c, pre_jail_init(): maillog_file is opened once per +// postlogd process; src/master/master_service.c, master_restart_service(), +// closes the service's status pipe at a reload (master_status_cleanup()), +// and src/master/dgram_server.c, dgram_server_abort(), exits when it reads +// its end - the next postlogd opens the new file. logrotate runs the reload +// right after the rename and create (build/logrotate-mail.conf, postrotate; +// logrotate 3.21.0, logrotate.c, rotateLogSet(): the postrotate script runs +// right after rotateSingleLog() has renamed and created), so the gap is short; +// rotatedGrace is far longer than it. +type rotatedTail struct { + f *os.File + r *bufio.Reader + pending string + consumed int64 + fp string + until time.Time +} + +// rotatedGrace is how long the rotated file is still read after the switch. +const rotatedGrace = time.Minute + // blindness measures the stretches in which follow cannot read mail.log - the // file gone, reopening it failing - for delivery_log_days. A stretch is // stored when it ends, and every minute while it lasts, so a long one is not diff --git a/internal/logtail/logtail_test.go b/internal/logtail/logtail_test.go index d4f722c..e47f47d 100644 --- a/internal/logtail/logtail_test.go +++ b/internal/logtail/logtail_test.go @@ -16,9 +16,10 @@ import ( // The mail.log lines in this file are composed by hand, after the formats the // code cites (Postfix 3.7.11, src/global/log_adhoc.c and the others), unless a -// comment says where one was seen. Some are shapes Postfix does not write: -// ISO stamps (msg_logger.c writes "%b %d %H:%M:%S" - A-12), and opendkim -// lines in mail.log (build/opendkim.conf has Syslog no). +// comment says where one was seen; some carry no stamp, which the parsers +// take as they come. One shape Postfix does not write here: opendkim lines in +// mail.log (build/opendkim.conf has Syslog no). + // qmgr's expiry line, as Postfix 3.7.11 writes it (src/qmgr/qmgr_active.c, // qmgr_active_done_25_generic(): "%s: from=<%s>, status=%s, returned to // sender"); composed by hand after that format. The sender is the client's @@ -89,7 +90,7 @@ func TestParseDelivery(t *testing.T) { }{ { name: "sent", - line: "2026-07-11T11:55:34 host postfix/smtp[26]: 41E862C00D9E: to=, relay=mx.example.net[203.0.113.9]:25, delay=0.5, dsn=2.0.0, status=sent (250 OK)", + line: "Jul 11 11:55:34 host postfix/smtp[26]: 41E862C00D9E: to=, relay=mx.example.net[203.0.113.9]:25, delay=0.5, dsn=2.0.0, status=sent (250 OK)", wantOK: true, queueID: "41E862C00D9E", recipient: "a@example.net", @@ -460,6 +461,39 @@ func TestFollowTailsAndRotates(t *testing.T) { // would otherwise stay "queued" forever), without re-parsing what it already // read, and must fall back to reading the whole file when the log was rotated // or recreated in the meantime. +// postlogd goes on writing to the renamed file until "postfix reload" ends +// it; the tailer reads that file for a while after it switched to the new +// one, so a line written there in that gap is not lost (assumptions A-33). +// The rename of an open file is what logrotate does on Linux; like +// TestFollowTailsAndRotates this runs on the server. +func TestFollowReadsTheRotatedFileAfterTheSwitch(t *testing.T) { + old := pollInterval + pollInterval = 10 * time.Millisecond + t.Cleanup(func() { pollInterval = old }) + + path := filepath.Join(t.TempDir(), "mail.log") + if err := os.WriteFile(path, nil, 0o644); err != nil { + t.Fatal(err) + } + cs := &captureStore{} + stop := startRun(t, path, cs) + defer stop() + appendLine(t, path, "host postfix/smtp[1]: Q1: to=, relay=x, dsn=2.0.0, status=sent (ok)") + waitFor(t, func() bool { return contains(cs.snapshot(), "Q1|a@example.net|sent") }) + + if err := os.Rename(path, path+".1"); err != nil { + t.Fatal(err) + } + if err := os.WriteFile(path, nil, 0o644); err != nil { + t.Fatal(err) + } + appendLine(t, path, "host postfix/smtp[1]: Q2: to=, relay=x, dsn=2.0.0, status=sent (ok)") + waitFor(t, func() bool { return contains(cs.snapshot(), "Q2|b@example.net|sent") }) + // The switch is made; postlogd has not reloaded yet. + appendLine(t, path+".1", "host postfix/smtp[1]: Q3: to=, relay=x, dsn=2.0.0, status=sent (ok)") + waitFor(t, func() bool { return contains(cs.snapshot(), "Q3|c@example.net|sent") }) +} + func TestFollowResumesAfterRestart(t *testing.T) { old := pollInterval pollInterval = 10 * time.Millisecond @@ -834,22 +868,12 @@ func TestSplitTimestamp(t *testing.T) { stamp, rest string }{ { - name: "RFC 3339, which maillog_file_format selects on Postfix 3.9 and up", - line: "2026-08-03T05:15:52.219218+00:00 mail postfix/smtp[26]: 4A1B2C3D: to=, status=sent (250 OK)", - stamp: "2026-08-03 05:15:52", - rest: "mail postfix/smtp[26]: 4A1B2C3D: to=, status=sent (250 OK)", - }, - { - name: "no fractional seconds, zone as Z", - line: "2026-08-03T05:15:52Z mail postfix/qmgr[10]: 4A1B2C3D: removed", - stamp: "2026-08-03 05:15:52", - rest: "mail postfix/qmgr[10]: 4A1B2C3D: removed", - }, - { - name: "no zone at all", - line: "2026-08-03T05:15:52 mail opendkim[30]: 4A1B2C3D: DKIM-Signature field added", - stamp: "2026-08-03 05:15:52", - rest: "mail opendkim[30]: 4A1B2C3D: DKIM-Signature field added", + // An RFC 3339 stamp is not one Postfix 3.7 writes (assumptions + // A-12): it is not taken off. + name: "RFC 3339 is not a stamp Postfix writes", + line: "2026-08-03T05:15:52.219218+00:00 mail postfix/qmgr[10]: 4A1B2C3D: removed", + stamp: "", + rest: "2026-08-03T05:15:52.219218+00:00 mail postfix/qmgr[10]: 4A1B2C3D: removed", }, { name: "syslog's traditional format, space-padded day", diff --git a/internal/logtail/main_test.go b/internal/logtail/main_test.go new file mode 100644 index 0000000..af6d220 --- /dev/null +++ b/internal/logtail/main_test.go @@ -0,0 +1,17 @@ +package logtail + +import ( + "os" + "testing" + "time" +) + +// TestMain reads mail.log stamps in UTC, whatever the zone of the machine the +// tests run on: Postfix 3.7 writes "%b %d %H:%M:%S" in the logging process's +// local time (src/util/msg_logger.c, msg_logger_print()) and lineTime reads it +// in time.Local, which in the container is the zone the fixtures are written +// in. +func TestMain(m *testing.M) { + time.Local = time.UTC + os.Exit(m.Run()) +} diff --git a/internal/logtail/refusals_test.go b/internal/logtail/refusals_test.go index 10b044f..0efcfd5 100644 --- a/internal/logtail/refusals_test.go +++ b/internal/logtail/refusals_test.go @@ -31,8 +31,8 @@ func (r *refusalProbe) AttachRefusalLine(clientIP, login, from string, _ time.Ti // The mail.log lines in this file are composed by hand, with the e2e stand's // names and addresses (smtpd.c check_milter_reply(), mail_open_stream(); -// cleanup_milter.c cleanup_milter_apply(), Postfix 3.7.11); their ISO stamp -// is not a format Postfix writes (assumptions A-12). +// cleanup_milter.c cleanup_milter_apply(), Postfix 3.7.11), with the stamp +// Postfix 3.7 writes (src/util/msg_logger.c, "%b %d %H:%M:%S"). // // The NOQUEUE line of a refusal at MAIL FROM goes on its row; a line whose // row is not written yet waits and is tried again; port 25's and other @@ -41,14 +41,14 @@ func TestRefusalLines(t *testing.T) { now := time.Date(2026, 10, 14, 12, 0, 0, 0, time.UTC) st := &refusalProbe{} r := &refusalLines{st: st} - limit := `2026-10-14T12:00:00+00:00 mail postfix/smtpd[1149]: NOQUEUE: milter-reject: MAIL from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; from= proto=ESMTP helo= sasl_username=` + limit := `Oct 14 12:00:00 mail postfix/smtpd[1149]: NOQUEUE: milter-reject: MAIL from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; from= proto=ESMTP helo= sasl_username=` for _, other := range []string{ - `2026-10-14T12:00:00+00:00 mail postfix/inbound/smtpd[372]: NOQUEUE: milter-reject: MAIL from unknown[203.0.113.7]: 451 4.7.1 Service unavailable - try again later; from= proto=ESMTP helo=`, - `2026-10-14T12:00:00+00:00 mail postfix/smtpd[11]: NOQUEUE: milter-reject: CONNECT from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; proto=SMTP`, - `2026-10-14T12:00:00+00:00 mail postfix/smtpd[11]: NOQUEUE: reject: RCPT from unknown[10.77.0.1]: 553 5.7.1 : Sender address rejected: not owned by user app1; from= to= proto=ESMTP helo=`, + `Oct 14 12:00:00 mail postfix/inbound/smtpd[372]: NOQUEUE: milter-reject: MAIL from unknown[203.0.113.7]: 451 4.7.1 Service unavailable - try again later; from= proto=ESMTP helo=`, + `Oct 14 12:00:00 mail postfix/smtpd[11]: NOQUEUE: milter-reject: CONNECT from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; proto=SMTP`, + `Oct 14 12:00:00 mail postfix/smtpd[11]: NOQUEUE: reject: RCPT from unknown[10.77.0.1]: 553 5.7.1 : Sender address rejected: not owned by user app1; from= to= proto=ESMTP helo=`, // No login: no application's refusal (the panel down refuses every // session, an unauthenticated one too). - `2026-10-14T12:00:00+00:00 mail postfix/smtpd[12]: NOQUEUE: milter-reject: MAIL from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; from= proto=ESMTP helo=`, + `Oct 14 12:00:00 mail postfix/smtpd[12]: NOQUEUE: milter-reject: MAIL from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; from= proto=ESMTP helo=`, } { r.handle(other, now, Place{}) } @@ -81,8 +81,8 @@ func TestFromRefusalIsRecoveredAfterTheWait(t *testing.T) { now := time.Date(2026, 10, 14, 12, 0, 0, 0, time.UTC) st := &refusalProbe{} r := &refusalLines{st: st} - r.handle(`2026-10-14T12:00:00+00:00 mail postfix/smtpd[11]: E543D3C75DA0: client=unknown[10.77.0.1], sasl_method=PLAIN, sasl_username=app1`, now, Place{}) - r.handle(`2026-10-14T12:00:01+00:00 mail postfix/cleanup[13]: E543D3C75DA0: milter-reject: END-OF-MESSAGE from unknown[10.77.0.1]: 5.7.1 From: "The - Shop" - it names another sender of this server; from= to= proto=ESMTP helo=`, now, Place{}) + r.handle(`Oct 14 12:00:00 mail postfix/smtpd[11]: E543D3C75DA0: client=unknown[10.77.0.1], sasl_method=PLAIN, sasl_username=app1`, now, Place{}) + r.handle(`Oct 14 12:00:01 mail postfix/cleanup[13]: E543D3C75DA0: milter-reject: END-OF-MESSAGE from unknown[10.77.0.1]: 5.7.1 From: "The - Shop" - it names another sender of this server; from= to= proto=ESMTP helo=`, now, Place{}) r.retry(now.Add(time.Second)) if len(st.recovered) != 0 { t.Fatal("recovered before the panel had the time to write the row") @@ -109,8 +109,8 @@ func TestWaitingLinesHoldTheSavedOffset(t *testing.T) { if _, held := r.oldest("fp"); held { t.Fatal("nothing waits, yet the offset is held") } - r.handle(`2026-10-14T12:00:00+00:00 mail postfix/smtpd[11]: Q1: client=unknown[10.77.0.1], sasl_method=PLAIN, sasl_username=app1`, now, Place{FP: "fp", End: 100}) - r.handle(`2026-10-14T12:00:01+00:00 mail postfix/cleanup[13]: Q1: milter-reject: END-OF-MESSAGE from unknown[10.77.0.1]: 5.7.1 From: d@other.example - not an address this application sends as; from= to= proto=ESMTP helo=`, now, Place{FP: "fp", End: 300}) + r.handle(`Oct 14 12:00:00 mail postfix/smtpd[11]: Q1: client=unknown[10.77.0.1], sasl_method=PLAIN, sasl_username=app1`, now, Place{FP: "fp", End: 100}) + r.handle(`Oct 14 12:00:01 mail postfix/cleanup[13]: Q1: milter-reject: END-OF-MESSAGE from unknown[10.77.0.1]: 5.7.1 From: d@other.example - not an address this application sends as; from= to= proto=ESMTP helo=`, now, Place{FP: "fp", End: 300}) if p, held := r.oldest("fp"); !held || p.End != 100 { t.Fatalf("held at %+v %v, want the client= line at 100", p, held) } diff --git a/internal/logtail/sendercheck_test.go b/internal/logtail/sendercheck_test.go index 6d0f964..ea94d4b 100644 --- a/internal/logtail/sendercheck_test.go +++ b/internal/logtail/sendercheck_test.go @@ -46,47 +46,47 @@ func TestDeferredCounter(t *testing.T) { now := time.Date(2026, 10, 12, 18, 0, 0, 0, time.UTC) for _, line := range []string{ // The journal milter's own temporary refusal: no warning, not counted. - `2026-10-12T16:22:13.100000+00:00 mail postfix/smtpd[1149]: connect from unknown[10.77.0.1]`, - `2026-10-12T16:22:13.200000+00:00 mail postfix/smtpd[1149]: NOQUEUE: milter-reject: MAIL from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; from= proto=ESMTP helo= sasl_username=`, + `Oct 12 16:22:13 mail postfix/smtpd[1149]: connect from unknown[10.77.0.1]`, + `Oct 12 16:22:13 mail postfix/smtpd[1149]: NOQUEUE: milter-reject: MAIL from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; from= proto=ESMTP helo= sasl_username=`, // The check does not answer: one connection, counted once. - `2026-10-12T16:22:57.000000+00:00 mail postfix/smtpd[1183]: connect from unknown[10.77.0.1]`, - `2026-10-12T16:22:57.100000+00:00 mail postfix/smtpd[1183]: warning: connect to Milter service unix:/run/selfpost/sender.sock: No such file or directory`, - `2026-10-12T16:22:57.200000+00:00 mail postfix/smtpd[1183]: NOQUEUE: milter-reject: CONNECT from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; proto=SMTP`, - `2026-10-12T16:22:57.300000+00:00 mail postfix/smtpd[1183]: NOQUEUE: milter-reject: EHLO from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; proto=SMTP helo=`, - `2026-10-12T16:22:57.400000+00:00 mail postfix/smtpd[1183]: disconnect from unknown[10.77.0.1] ehlo=1 auth=0/1 quit=1 commands=2/3`, + `Oct 12 16:22:57 mail postfix/smtpd[1183]: connect from unknown[10.77.0.1]`, + `Oct 12 16:22:57 mail postfix/smtpd[1183]: warning: connect to Milter service unix:/run/selfpost/sender.sock: No such file or directory`, + `Oct 12 16:22:57 mail postfix/smtpd[1183]: NOQUEUE: milter-reject: CONNECT from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; proto=SMTP`, + `Oct 12 16:22:57 mail postfix/smtpd[1183]: NOQUEUE: milter-reject: EHLO from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; proto=SMTP helo=`, + `Oct 12 16:22:57 mail postfix/smtpd[1183]: disconnect from unknown[10.77.0.1] ehlo=1 auth=0/1 quit=1 commands=2/3`, // The same process takes another client, and the check answers again: // a level-2 refusal there is not the check's. - `2026-10-12T16:23:30.000000+00:00 mail postfix/smtpd[1183]: connect from unknown[10.77.0.1]`, - `2026-10-12T16:23:30.100000+00:00 mail postfix/smtpd[1183]: NOQUEUE: milter-reject: MAIL from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; from= proto=ESMTP helo=`, + `Oct 12 16:23:30 mail postfix/smtpd[1183]: connect from unknown[10.77.0.1]`, + `Oct 12 16:23:30 mail postfix/smtpd[1183]: NOQUEUE: milter-reject: MAIL from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; from= proto=ESMTP helo=`, // A client that writes the socket's name where Postfix will quote it // in a warning, and then runs into a level-2 refusal: not counted. - `2026-10-12T16:23:40.000000+00:00 mail postfix/smtpd[1190]: connect from unknown[10.77.0.1]`, - `2026-10-12T16:23:40.100000+00:00 mail postfix/smtpd[1190]: warning: Illegal address syntax from unknown[10.77.0.1] in MAIL command: `, - `2026-10-12T16:23:40.200000+00:00 mail postfix/smtpd[1190]: NOQUEUE: milter-reject: MAIL from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; from= proto=ESMTP helo=`, + `Oct 12 16:23:40 mail postfix/smtpd[1190]: connect from unknown[10.77.0.1]`, + `Oct 12 16:23:40 mail postfix/smtpd[1190]: warning: Illegal address syntax from unknown[10.77.0.1] in MAIL command: `, + `Oct 12 16:23:40 mail postfix/smtpd[1190]: NOQUEUE: milter-reject: MAIL from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; from= proto=ESMTP helo=`, // OpenDKIM does not answer: another socket, not counted. - `2026-10-12T16:24:00.000000+00:00 mail postfix/smtpd[1201]: connect from unknown[10.77.0.1]`, - `2026-10-12T16:24:00.100000+00:00 mail postfix/smtpd[1201]: warning: connect to Milter service unix:/run/opendkim/opendkim.sock: Connection refused`, - `2026-10-12T16:24:00.200000+00:00 mail postfix/smtpd[1201]: NOQUEUE: milter-reject: CONNECT from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; proto=SMTP`, + `Oct 12 16:24:00 mail postfix/smtpd[1201]: connect from unknown[10.77.0.1]`, + `Oct 12 16:24:00 mail postfix/smtpd[1201]: warning: connect to Milter service unix:/run/opendkim/opendkim.sock: Connection refused`, + `Oct 12 16:24:00 mail postfix/smtpd[1201]: NOQUEUE: milter-reject: CONNECT from unknown[10.77.0.1]: 451 4.7.1 Service unavailable - try again later; proto=SMTP`, // The check stops answering in the middle of a message, the next day: // cleanup meets it. Two messages through the same cleanup process are // two messages. - `2026-10-13T00:00:05.000000+00:00 mail postfix/smtpd[1300]: connect from unknown[10.77.0.1]`, - `2026-10-13T00:00:35.000000+00:00 mail postfix/cleanup[1339]: warning: milter unix:/run/selfpost/sender.sock: can't read SMFIC_HEADER reply packet header: Connection timed out`, - `2026-10-13T00:00:35.100000+00:00 mail postfix/cleanup[1339]: 7BCAF3C75DA0: milter-reject: END-OF-MESSAGE from unknown[10.77.0.1]: 4.7.1 Service unavailable - try again later; from= to= proto=ESMTP helo=`, - `2026-10-13T00:01:20.000000+00:00 mail postfix/cleanup[1339]: warning: milter unix:/run/selfpost/sender.sock: can't read SMFIC_HEADER reply packet header: Connection timed out`, - `2026-10-13T00:01:20.100000+00:00 mail postfix/cleanup[1339]: 8C1D43C75DA0: milter-reject: END-OF-MESSAGE from unknown[10.77.0.1]: 4.7.1 Service unavailable - try again later; from= to= proto=ESMTP helo=`, + `Oct 13 00:00:05 mail postfix/smtpd[1300]: connect from unknown[10.77.0.1]`, + `Oct 13 00:00:35 mail postfix/cleanup[1339]: warning: milter unix:/run/selfpost/sender.sock: can't read SMFIC_HEADER reply packet header: Connection timed out`, + `Oct 13 00:00:35 mail postfix/cleanup[1339]: 7BCAF3C75DA0: milter-reject: END-OF-MESSAGE from unknown[10.77.0.1]: 4.7.1 Service unavailable - try again later; from= to= proto=ESMTP helo=`, + `Oct 13 00:01:20 mail postfix/cleanup[1339]: warning: milter unix:/run/selfpost/sender.sock: can't read SMFIC_HEADER reply packet header: Connection timed out`, + `Oct 13 00:01:20 mail postfix/cleanup[1339]: 8C1D43C75DA0: milter-reject: END-OF-MESSAGE from unknown[10.77.0.1]: 4.7.1 Service unavailable - try again later; from= to= proto=ESMTP helo=`, // OpenDKIM hung in the middle of a message: another socket. - `2026-10-13T00:01:30.000000+00:00 mail postfix/cleanup[1339]: warning: milter unix:/run/opendkim/opendkim.sock: can't read SMFIC_HEADER reply packet header: Connection timed out`, + `Oct 13 00:01:30 mail postfix/cleanup[1339]: warning: milter unix:/run/opendkim/opendkim.sock: can't read SMFIC_HEADER reply packet header: Connection timed out`, // The check's own verdict is a refusal, not a deferral, and it is // cleanup that writes it. - `2026-10-13T00:01:00.000000+00:00 mail postfix/cleanup[1195]: B6B484831946: milter-reject: END-OF-MESSAGE from unknown[10.77.0.1]: 5.7.1 From: director@other.e2e.test - not an address this application sends as; from= to= proto=ESMTP helo=`, + `Oct 13 00:01:00 mail postfix/cleanup[1195]: B6B484831946: milter-reject: END-OF-MESSAGE from unknown[10.77.0.1]: 5.7.1 From: director@other.e2e.test - not an address this application sends as; from= to= proto=ESMTP helo=`, } { c.handle(line, now, false, Place{}) } @@ -103,11 +103,11 @@ func TestDeferredCounterDoesNotCountALogReadAgain(t *testing.T) { now := time.Date(2026, 10, 12, 18, 0, 0, 0, time.UTC) outage := func(pid, at string) []string { return []string{ - at + `0+00:00 mail postfix/smtpd[` + pid + `]: connect from unknown[10.77.0.1]`, - at + `1+00:00 mail postfix/smtpd[` + pid + `]: warning: connect to Milter service unix:/run/selfpost/sender.sock: Connection refused`, + at + ` mail postfix/smtpd[` + pid + `]: connect from unknown[10.77.0.1]`, + at + ` mail postfix/smtpd[` + pid + `]: warning: connect to Milter service unix:/run/selfpost/sender.sock: Connection refused`, } } - first := append(outage("11", "2026-10-12T16:00:00.00000"), outage("12", "2026-10-12T16:00:05.00000")...) + first := append(outage("11", "Oct 12 16:00:00"), outage("12", "Oct 12 16:00:05")...) c := newDeferredCounter(&SenderCheck{Store: st, Socket: "/run/selfpost/sender.sock"}) for _, line := range first { @@ -119,7 +119,7 @@ func TestDeferredCounterDoesNotCountALogReadAgain(t *testing.T) { // A new run: the same lines again, then what the outage added. c = newDeferredCounter(&SenderCheck{Store: st, Socket: "/run/selfpost/sender.sock"}) - for _, line := range append(first, outage("13", "2026-10-12T16:00:09.00000")...) { + for _, line := range append(first, outage("13", "Oct 12 16:00:09")...) { c.handle(line, now, true, Place{}) } if st.days["2026-10-12"] != 3 { @@ -135,10 +135,10 @@ func TestDeferredCounterRemembersAPlaceNotASecond(t *testing.T) { st := &deferredStore{} now := time.Date(2026, 10, 12, 18, 0, 0, 0, time.UTC) lines := []string{ - `2026-10-12T16:00:00+00:00 mail postfix/smtpd[11]: connect from unknown[10.77.0.1]`, - `2026-10-12T16:00:01+00:00 mail postfix/smtpd[11]: warning: connect to Milter service unix:/run/selfpost/sender.sock: Connection refused`, - `2026-10-12T16:00:01+00:00 mail postfix/smtpd[12]: connect from unknown[10.77.0.1]`, - `2026-10-12T16:00:01+00:00 mail postfix/smtpd[12]: warning: connect to Milter service unix:/run/selfpost/sender.sock: Connection refused`, + `Oct 12 16:00:00 mail postfix/smtpd[11]: connect from unknown[10.77.0.1]`, + `Oct 12 16:00:01 mail postfix/smtpd[11]: warning: connect to Milter service unix:/run/selfpost/sender.sock: Connection refused`, + `Oct 12 16:00:01 mail postfix/smtpd[12]: connect from unknown[10.77.0.1]`, + `Oct 12 16:00:01 mail postfix/smtpd[12]: warning: connect to Milter service unix:/run/selfpost/sender.sock: Connection refused`, } // The place each line ends at, in one file. places := make([]Place, len(lines)) diff --git a/internal/web/handlers/handlers_monitor_test.go b/internal/web/handlers/handlers_monitor_test.go index 09696b8..3a21c0d 100644 --- a/internal/web/handlers/handlers_monitor_test.go +++ b/internal/web/handlers/handlers_monitor_test.go @@ -153,9 +153,9 @@ func TestDeliveryPageMarksAQueuedMessageAsStillWaiting(t *testing.T) { func TestDeliveryPageShowsThisMessagesLogLines(t *testing.T) { h, row := serverWithDelivery(t) h.cfg.MailLogPath = writeMailLog(t, - "2026-08-03T05:15:52.219218+00:00 host postfix/smtpd[20]: 4A1B2C3D: client=mail.example.com[203.0.113.4]", - "2026-08-03T05:15:52.300000+00:00 host postfix/qmgr[10]: 99999999: from=, size=500, nrcpt=1 (queue active)", - "2026-08-03T05:16:03.884210+00:00 host postfix/smtp[26]: 4A1B2C3D: to=, dsn=2.0.0, status=sent (250 OK)", + "Aug 03 05:15:52 host postfix/smtpd[20]: 4A1B2C3D: client=mail.example.com[203.0.113.4]", + "Aug 03 05:15:52 host postfix/qmgr[10]: 99999999: from=, size=500, nrcpt=1 (queue active)", + "Aug 03 05:16:03 host postfix/smtp[26]: 4A1B2C3D: to=, dsn=2.0.0, status=sent (250 OK)", ) out := getBody(t, h.HandleDelivery, "/outbound/log/"+itoa(row.ID)) @@ -163,8 +163,8 @@ func TestDeliveryPageShowsThisMessagesLogLines(t *testing.T) { `
`,
 		// The stamp is split off from the line, without the microseconds and the
 		// offset that make it the widest thing on it.
-		`2026-08-03 05:15:52 host postfix/smtpd[20]: 4A1B2C3D: client=mail.example.com`,
-		`2026-08-03 05:16:03 host postfix/smtp[26]: 4A1B2C3D: to=<public@example.ru>`,
+		`Aug 03 05:15:52 host postfix/smtpd[20]: 4A1B2C3D: client=mail.example.com`,
+		`Aug 03 05:16:03 host postfix/smtp[26]: 4A1B2C3D: to=<public@example.ru>`,
 		"status=sent (250 OK)",
 	} {
 		if !strings.Contains(out, want) {
@@ -196,20 +196,20 @@ func TestDeliveryPageKeepsAnUnstampedLogLineWhole(t *testing.T) {
 func TestDeliveryPageShowsStoredLogLinesAfterRotation(t *testing.T) {
 	h, row := serverWithDelivery(t)
 	h.cfg.RetryPolicy = postfix.DefaultRetryPolicy()
-	h.cfg.MailLogPath = writeMailLog(t, "2026-08-04T00:00:01.000000+00:00 host postfix/qmgr[10]: 99999999: removed")
+	h.cfg.MailLogPath = writeMailLog(t, "Aug 04 00:00:01 host postfix/qmgr[10]: 99999999: removed")
 	if _, err := h.store.InsertSendLogLines([]store.SendLogLine{
-		{QueueID: row.QueueID, At: row.CreatedAt.AddDate(0, 0, -40), Line: "2026-06-24T05:00:00.000000+00:00 host postfix/qmgr[10]: 4A1B2C3D: an earlier message under the same id"},
-		{QueueID: row.QueueID, At: row.CreatedAt.Add(-time.Second), Line: "2026-08-03T05:15:52.219218+00:00 host postfix/smtpd[20]: 4A1B2C3D: client=mail.example.com[203.0.113.4]"},
-		{QueueID: "99999999", At: row.CreatedAt, Line: "2026-08-03T05:15:52.300000+00:00 host postfix/qmgr[10]: 99999999: from=, size=500, nrcpt=1 (queue active)"},
-		{QueueID: row.QueueID, At: row.CreatedAt.Add(11 * time.Second), Line: "2026-08-03T05:16:03.884210+00:00 host postfix/smtp[26]: 4A1B2C3D: to=, dsn=2.0.0, status=sent (250 OK)"},
+		{QueueID: row.QueueID, At: row.CreatedAt.AddDate(0, 0, -40), Line: "Jun 24 05:00:00 host postfix/qmgr[10]: 4A1B2C3D: an earlier message under the same id"},
+		{QueueID: row.QueueID, At: row.CreatedAt.Add(-time.Second), Line: "Aug 03 05:15:52 host postfix/smtpd[20]: 4A1B2C3D: client=mail.example.com[203.0.113.4]"},
+		{QueueID: "99999999", At: row.CreatedAt, Line: "Aug 03 05:15:52 host postfix/qmgr[10]: 99999999: from=, size=500, nrcpt=1 (queue active)"},
+		{QueueID: row.QueueID, At: row.CreatedAt.Add(11 * time.Second), Line: "Aug 03 05:16:03 host postfix/smtp[26]: 4A1B2C3D: to=, dsn=2.0.0, status=sent (250 OK)"},
 	}, false); err != nil {
 		t.Fatalf("InsertSendLogLines: %v", err)
 	}
 
 	out := getBody(t, h.HandleDelivery, "/outbound/log/"+itoa(row.ID))
 	for _, want := range []string{
-		`2026-08-03 05:15:52 host postfix/smtpd[20]: 4A1B2C3D: client=mail.example.com`,
-		`2026-08-03 05:16:03 host postfix/smtp[26]: 4A1B2C3D: to=<public@example.ru>`,
+		`Aug 03 05:15:52 host postfix/smtpd[20]: 4A1B2C3D: client=mail.example.com`,
+		`Aug 03 05:16:03 host postfix/smtp[26]: 4A1B2C3D: to=<public@example.ru>`,
 	} {
 		if !strings.Contains(out, want) {
 			t.Errorf("delivery log is missing %q:\n%s", want, out)
diff --git a/internal/web/handlers/handlers_outbound_log_test.go b/internal/web/handlers/handlers_outbound_log_test.go
index 719fb72..05c81d8 100644
--- a/internal/web/handlers/handlers_outbound_log_test.go
+++ b/internal/web/handlers/handlers_outbound_log_test.go
@@ -159,7 +159,7 @@ func TestMessagePageDrawsTheOutcomeAtItsLevel(t *testing.T) {
 	} {
 		h, row := serverWithDelivery(t)
 		h.cfg.MailLogPath = writeMailLog(t,
-			"2026-08-03T05:16:03.884210+00:00 host postfix/smtp[26]: 4A1B2C3D: to=, status="+tc.status+" (reply)")
+			"Aug 03 05:16:03 host postfix/smtp[26]: 4A1B2C3D: to=, status="+tc.status+" (reply)")
 		if _, err := h.store.UpdateStatus(row.QueueID, row.To, tc.status); err != nil {
 			t.Fatal(err)
 		}
diff --git a/internal/web/handlers/handlers_users_test.go b/internal/web/handlers/handlers_users_test.go
index dc47d39..42957fa 100644
--- a/internal/web/handlers/handlers_users_test.go
+++ b/internal/web/handlers/handlers_users_test.go
@@ -166,7 +166,7 @@ func TestARefusedMessageShowsPostfixsLine(t *testing.T) {
 			t.Fatal(err)
 		}
 		if subject == "with its line" {
-			line := time.Now().UTC().Format("2006-01-02T15:04:05Z") + " mail postfix/smtpd[2131]: NOQUEUE: milter-reject: MAIL from unknown[198.51.100.7]: 451 4.7.1 Service unavailable - try again later; from= proto=ESMTP helo="
+			line := time.Now().Format("Jan 02 15:04:05") + " mail postfix/smtpd[2131]: NOQUEUE: milter-reject: MAIL from unknown[198.51.100.7]: 451 4.7.1 Service unavailable - try again later; from= proto=ESMTP helo="
 			if ok, err := st.AttachRefusalLine("198.51.100.7", "alerts", "alerts@example.org", time.Now(), line); err != nil || !ok {
 				t.Fatalf("attach = %v, %v", ok, err)
 			}