mix/selfpost
1
0
Fork 0
Code Issues Pull Requests Actions 21 Packages Projects Releases Wiki Activity

log tailer: the rotated mail.log read until postlogd lets it go
test / test (push) Canceled after 0s
Details

Browse Source 
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 <noreply@anthropic.com>
This commit is contained in:
mix
2026-10-14 23:12:37 +03:00
co-authored by Claude Opus 5.5
parent e174537512
commit 463d4ff3fe
11 changed files with 216 additions and 116 deletions
Download Patch File Download Diff File Expand all files Collapse all files
internal/logtail/sendercheck_test.go
+30 -30
View File
@@ -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=<billing@sender.e2e.test> proto=ESMTP helo=<e2e-client.e2e.test> sasl_username=<l2app>`,
`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=<billing@sender.e2e.test> proto=ESMTP helo=<e2e-client.e2e.test> sasl_username=<l2app>`,
// 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=<e2e-client.e2e.test>`,
`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=<e2e-client.e2e.test>`,
`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=<a@sender.e2e.test> proto=ESMTP helo=<x>`,
`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=<a@sender.e2e.test> proto=ESMTP helo=<x>`,
// 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: <warning: connect to Milter service unix:/run/selfpost/sender.sock: milter>`,
`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=<a@sender.e2e.test> proto=ESMTP helo=<x>`,
`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: <warning: connect to Milter service unix:/run/selfpost/sender.sock: milter>`,
`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=<a@sender.e2e.test> proto=ESMTP helo=<x>`,
// 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=<alerts@sender.e2e.test> to=<rcpt@sink.e2e.test> proto=ESMTP helo=<e2e-client.e2e.test>`,
`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=<alerts@sender.e2e.test> to=<rcpt@sink.e2e.test> proto=ESMTP helo=<e2e-client.e2e.test>`,
`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=<alerts@sender.e2e.test> to=<rcpt@sink.e2e.test> proto=ESMTP helo=<e2e-client.e2e.test>`,
`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=<alerts@sender.e2e.test> to=<rcpt@sink.e2e.test> proto=ESMTP helo=<e2e-client.e2e.test>`,
// 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=<alerts@sender.e2e.test> to=<rcpt@sink.e2e.test> proto=ESMTP helo=<x>`,
`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=<alerts@sender.e2e.test> to=<rcpt@sink.e2e.test> proto=ESMTP helo=<x>`,
} {
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))