package logtail import ( "context" "os" "path/filepath" "strings" "testing" "time" ) // The mail.log lines in this file are composed by hand. "postfix/submission/ // smtpd" is a tag this image never writes (build/postfix-config.sh sets // syslog_name on port 25 only); it stands for any "-o syslog_name" listener. // // Which lines are kept for a message's page, and under which queue id: the id // at the head of the line and nothing the far end wrote further along it. func TestQueueLineHead(t *testing.T) { cases := []struct { name, rest, want string }{ {"delivery", "mail postfix/smtp[26]: 41E862C00D9E: to=, relay=mx.example.net[203.0.113.9]:25, dsn=2.0.0, status=sent (250 OK)", "41E862C00D9E"}, {"submission smtpd opens the id", "mail postfix/submission/smtpd[10]: 41E862C00D9E: client=unknown[203.0.113.7], sasl_method=PLAIN, sasl_username=app", "41E862C00D9E"}, {"port-25 smtpd", "mail postfix/inbound/smtpd[41]: 4A1B2C3D: client=mx.example.net[203.0.113.9]", "4A1B2C3D"}, {"cleanup", "mail postfix/cleanup[52]: 41E862C00D9E: message-id=<1@example.com>", "41E862C00D9E"}, {"qmgr removes it", "mail postfix/qmgr[10]: 41E862C00D9E: removed", "41E862C00D9E"}, // Postfix 3.10.13: src/cleanup/cleanup_api.c, cleanup_flush(), "%s: // removed (%s)"; src/smtpd/smtpd.c, smtpd_proto(), "%s: %s after %s // (%lu bytes) from %s" with the queue id or "NOQUEUE". {"cleanup removes an unqueued message", "mail postfix/cleanup[52]: 41E862C00D9E: removed (canceled)", "41E862C00D9E"}, {"a connection lost in DATA", "mail postfix/submission/smtpd[10]: 41E862C00D9E: lost connection after DATA (5420 bytes) from unknown[203.0.113.7]", "41E862C00D9E"}, {"a connection lost before a queue id", "mail postfix/smtpd[10]: NOQUEUE: lost connection after EHLO from unknown[203.0.113.7]", ""}, // The same function's "%s: %s after %s from %s" for the other reasons. {"too many errors with a queue id", "mail postfix/submission/smtpd[10]: 41E862C00D9E: too many errors after RCPT from unknown[203.0.113.7]", "41E862C00D9E"}, {"a timeout before a queue id", "mail postfix/smtpd[10]: NOQUEUE: timeout after MAIL from unknown[203.0.113.7]", ""}, {"a bounce is sent: the id at the head, not the new message's", "mail postfix/bounce[30]: 41E862C00D9E: sender non-delivery notification: 5F00AA12", "41E862C00D9E"}, {"long queue id", "mail postfix/qmgr[10]: 3sJ8Xh2Cgqz4Xy1: removed", "3sJ8Xh2Cgqz4Xy1"}, {"refused before queueing", "mail postfix/inbound/smtpd[41]: NOQUEUE: reject: RCPT from mx.example.net[203.0.113.9]: 550 5.1.1 : Recipient address rejected; from= to= proto=ESMTP helo=", ""}, {"a warning", "mail postfix/smtpd[10]: warning: hostname mx.example.net does not resolve to address 203.0.113.9", ""}, {"a connection", "mail postfix/smtpd[10]: connect from unknown[203.0.113.7]", ""}, {"no program", "preexisting line, ignored on start", ""}, { // The reply is the receiving server's text. One that spells the head // of a line is still the tail of this one: the line is the message's // it was written about, and no other's. "a reply that quotes a line head", "mail postfix/smtp[26]: 9F1A2C00D9E: to=, relay=mx.example.net[203.0.113.9]:25, dsn=5.1.1, status=bounced (host said: 550 mail postfix/smtp[1]: 41E862C00D9E: to=, status=sent)", "9F1A2C00D9E", }, } for _, c := range cases { got := "" if m := queueLineRe.FindStringSubmatch(c.rest); m != nil { got = m[2] } if got != c.want { t.Errorf("%s: queue id %q, want %q", c.name, got, c.want) } } } // A line is dated by its own stamp, not by when the tailer got to it, and is // kept as the log has it. Nothing is written until the pass over the log ends. func TestLineKeeperDatesByTheLine(t *testing.T) { cs := &captureStore{} k := newLineKeeper(cs) now := time.Date(2026, 10, 12, 18, 0, 0, 0, time.UTC) line := "Oct 12 09:00:00 mail postfix/qmgr[7]: 41E862C00D9E: removed" k.add(line, now, false) k.add("Oct 12 09:00:01 mail postfix/smtpd[7]: connect from unknown[203.0.113.7]", now, false) if len(cs.lines) != 0 { t.Fatalf("written before the pass ended: %v", cs.kept()) } k.flush() if len(cs.lines) != 1 { t.Fatalf("kept %d lines, want 1: %v", len(cs.lines), cs.kept()) } got := cs.lines[0] if got.QueueID != "41E862C00D9E" || got.Line != line { t.Errorf("kept %q under %q", got.Line, got.QueueID) } if want := time.Date(2026, 10, 12, 9, 0, 0, 0, time.Local).UTC(); !got.At.Equal(want) { t.Errorf("dated %v, want %v", got.At, want) } } // A backlog is written in batches of lineBatch, not held whole, and a pass // that changes from catching up to following does not write the later lines // under the earlier rule. func TestLineKeeperWritesInBatches(t *testing.T) { cs := &captureStore{} k := newLineKeeper(cs) now := time.Date(2026, 10, 12, 18, 0, 0, 0, time.UTC) line := func(i int) string { return "host postfix/qmgr[7]: 41E862C00D9E: from=, size=" + itoa(i) + ", nrcpt=1 (queue active)" } for i := 0; i < lineBatch+10; i++ { k.add(line(i), now, true) } if len(cs.lines) != lineBatch || cs.batches != 1 { t.Fatalf("after %d lines: %d written in %d batches, want %d in 1", lineBatch+10, len(cs.lines), cs.batches, lineBatch) } // The same line again, now as one read while following: it is a new line, // and the ten still held from the catch-up are written first, under theirs. k.add(line(0), now, false) k.flush() if got, want := len(cs.lines), lineBatch+11; got != want { t.Errorf("%d lines written, want %d", got, want) } if cs.batches != 3 { t.Errorf("%d batches, want 3", cs.batches) } } // Mail that comes in on port 25 is a stranger's and never gets a send-log row: // none of its lines are kept, from the smtpd that opened the queue id to // qmgr's "removed". The id is then anybody's again. func TestLineKeeperLeavesOutPort25Mail(t *testing.T) { cs := &captureStore{} k := newLineKeeper(cs) now := time.Date(2026, 10, 12, 18, 0, 0, 0, time.UTC) const ( outClient = "host postfix/submission/smtpd[10]: 41E862C00D9E: client=app.example.com[203.0.113.7], sasl_method=PLAIN, sasl_username=app" outSent = "host postfix/smtp[26]: 41E862C00D9E: to=, relay=mx.example.net[203.0.113.9]:25, dsn=2.0.0, status=sent (250 OK)" reused = "host postfix/submission/smtpd[10]: 4A1B2C3D: client=app.example.com[203.0.113.7], sasl_method=PLAIN, sasl_username=app" bounce = "host postfix/cleanup[52]: 5F00AA12: message-id=<20261012180000.5F00AA12@mail.example.com>" ) for _, line := range []string{ "host postfix/inbound/smtpd[41]: 4A1B2C3D: client=mx.example.net[198.51.100.9]", outClient, "host postfix/cleanup[52]: 4A1B2C3D: message-id=", "host postfix/qmgr[10]: 4A1B2C3D: from=, size=900, nrcpt=1 (queue active)", outSent, "host postfix/smtp[27]: 4A1B2C3D: to=, relay=upstream.example.com[192.0.2.1]:25, dsn=2.0.0, status=sent (250 OK)", "host postfix/qmgr[10]: 4A1B2C3D: removed", // The id comes round again for a submitted message, and a bounce has no // smtpd at all: both are kept. reused, bounce, } { k.add(line, now, false) } k.flush() want := []string{"41E862C00D9E|" + outClient, "41E862C00D9E|" + outSent, "4A1B2C3D|" + reused, "5F00AA12|" + bounce} if got := cs.kept(); strings.Join(got, "\n") != strings.Join(want, "\n") { t.Errorf("kept:\n%s\nwant:\n%s", strings.Join(got, "\n"), strings.Join(want, "\n")) } // A port-25 id that a submission listener opens before qmgr's "removed" was // seen (the line was lost, the panel restarted) is the submitted message's. k.add("host postfix/inbound/smtpd[41]: 6C00BB34: client=mx.example.net[198.51.100.9]", now, false) again := "host postfix/smtps/smtpd[11]: 6C00BB34: client=app.example.com[203.0.113.7], sasl_method=PLAIN, sasl_username=app" k.add(again, now, false) k.flush() if got := cs.kept(); got[len(got)-1] != "6C00BB34|"+again { t.Errorf("a reused port-25 id was not kept for the submitted message: %v", got[len(got)-1]) } // What is remembered of port 25 has a ceiling. for i := 0; i < port25IDs+50; i++ { k.rememberPort25("7D" + itoa(100000+i)) } if len(k.port25) > port25IDs { t.Errorf("%d port-25 ids remembered, ceiling is %d", len(k.port25), port25IDs) } } // A port-25 message that is never queued - refused at end-of-message, or its // client gone in DATA - ends with cleanup's "removed (canceled)" rather than // qmgr's "removed", and its id is anybody's again from there. Postfix 3.10.13: // src/smtpd/smtpd.c, smtpd_proto(), logs the lost connection before // mail_reset() closes the cleanup stream; src/cleanup/cleanup_api.c, // cleanup_flush(), logs "%s: removed (%s)" after the milter verdict. The // lines are composed from those formats. func TestLineKeeperForgetsPort25AtCleanupRemoval(t *testing.T) { cs := &captureStore{} k := newLineKeeper(cs) now := time.Date(2026, 10, 12, 18, 0, 0, 0, time.UTC) const bounce = "host postfix/cleanup[52]: 4A1B2C3D: message-id=<20261012180000.4A1B2C3D@mail.example.com>" for _, line := range []string{ "host postfix/inbound/smtpd[41]: 4A1B2C3D: client=mx.example.net[198.51.100.9]", "host postfix/inbound/smtpd[41]: 4A1B2C3D: lost connection after DATA (5420 bytes) from mx.example.net[198.51.100.9]", "host postfix/cleanup[52]: 4A1B2C3D: removed (canceled)", // The id comes round for a bounce Postfix generates, which has no smtpd. bounce, } { k.add(line, now, false) } k.flush() if got := cs.kept(); len(got) != 1 || got[0] != "4A1B2C3D|"+bounce { t.Errorf("kept %v, want only the bounce's line", got) } if len(k.port25) != 0 { t.Errorf("port-25 ids still remembered: %v", k.port25) } } // The tailer keeps queue-id lines as it follows the log, and after an unclean // stop - its saved place lies before lines it had already read - it does not // keep them a second time. func TestRunKeepsQueueLinesOnce(t *testing.T) { old := pollInterval pollInterval = 10 * time.Millisecond t.Cleanup(func() { pollInterval = old }) dir := t.TempDir() path := filepath.Join(dir, "mail.log") // Longer than a fingerprint, so the file is recognised across the restart. seed := strings.Repeat("host postfix/smtpd[1]: connect from unknown[203.0.113.7]\n", 20) if err := os.WriteFile(path, []byte(seed), 0o644); err != nil { t.Fatalf("seed log: %v", err) } const ( client = "host postfix/submission/smtpd[1]: 41E862C00D9E: client=unknown[203.0.113.7]" sent = "host postfix/smtp[1]: 41E862C00D9E: to=, relay=x, dsn=2.0.0, status=sent (ok)" later = "host postfix/qmgr[1]: 41E862C00D9E: removed" ) cs := &captureStore{} stop := startRun(t, path, cs) appendLine(t, path, client) appendLine(t, path, "host postfix/smtpd[1]: disconnect from unknown[203.0.113.7]") appendLine(t, path, sent) waitFor(t, func() bool { return len(cs.kept()) == 2 }) stop() // The process died before it saved its place: what it has is the place it // was at before those lines. cs.mu.Lock() cs.state.Offset = int64(len(seed)) cs.mu.Unlock() appendLine(t, path, later) stop = startRun(t, path, cs) waitFor(t, func() bool { return len(cs.kept()) >= 3 }) stop() want := []string{"41E862C00D9E|" + client, "41E862C00D9E|" + sent, "41E862C00D9E|" + later} if got := cs.kept(); strings.Join(got, "\n") != strings.Join(want, "\n") { t.Errorf("kept:\n%s\nwant:\n%s", strings.Join(got, "\n"), strings.Join(want, "\n")) } } // Lines without a send-log row are removed at the start and after every // send-log sweep, and only once they are old enough for the row to have been // written. func TestRetentionLoopPrunesLines(t *testing.T) { old := retentionInterval retentionInterval = 20 * time.Millisecond t.Cleanup(func() { retentionInterval = old }) cs := &captureStore{} ctx, cancel := context.WithCancel(context.Background()) defer cancel() go retentionLoop(ctx, cs, func() int { return 90 }) waitFor(t, func() bool { return cs.prunes() >= 3 }) cs.mu.Lock() defer cs.mu.Unlock() for _, cutoff := range cs.pruned { if age := time.Since(cutoff); age < lineGrace || age > lineGrace+time.Minute { t.Errorf("prune cutoff %v ago, want %v", age, lineGrace) } } }