Compare commits
2
Commits
| Author | SHA1 | Date | |
|---|---|---|---|
|
|
463d4ff3fe | ||
|
|
e174537512 |
@@ -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
|
message forced to expire (`postsuper -e`, `#` in the queue listing) is
|
||||||
still counted as held (audit 2026-10-12, stage 2c; assumptions A-8,
|
still counted as held (audit 2026-10-12, stage 2c; assumptions A-8,
|
||||||
B-PQ1).
|
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
|
- **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
|
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
|
panel and three days to Postfix; `1h7m` was 67 minutes to the panel and
|
||||||
@@ -68,6 +74,18 @@ Format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/); version
|
|||||||
as `bounced`. The row now holds the recipient as Postfix logs it, once,
|
as `bounced`. The row now holds the recipient as Postfix logs it, once,
|
||||||
and is found under `orig_to=` when Postfix rewrote it (assumptions B-G5,
|
and is found under `orig_to=` when Postfix rewrote it (assumptions B-G5,
|
||||||
A-9, A-31, D-S20).
|
A-9, A-31, D-S20).
|
||||||
|
- **Inbound mail between 10 MB and the port's limit is accepted.** Port 25
|
||||||
|
said it took messages up to `INBOUND_MESSAGE_SIZE_LIMIT` (25 MiB by
|
||||||
|
default), but Postfix writes the message to its queue under a limit of
|
||||||
|
its own, main.cf's, never set and so 10240000 bytes: a larger message was
|
||||||
|
taken through `DATA` and then refused with 552. That limit now follows
|
||||||
|
port 25's when it is larger; 465 and 587 keep theirs (assumptions
|
||||||
|
C-P31).
|
||||||
|
- **Mail to an address literal of the container is refused, not delivered
|
||||||
|
locally.** An empty `mydestination` left one way to local delivery:
|
||||||
|
`user@[127.0.0.1]` and the container's other addresses. Local delivery is
|
||||||
|
now Postfix's refusal, and Postfix refuses such a recipient at `RCPT TO`:
|
||||||
|
`550 5.1.1 ... local mail delivery is disabled` (assumptions C-P8).
|
||||||
- **A bounce is judged by the filter lists as the panel counts it.**
|
- **A bounce is judged by the filter lists as the panel counts it.**
|
||||||
rspamd's sender rules took a bounce's `From:` header when the envelope
|
rspamd's sender rules took a bounce's `From:` header when the envelope
|
||||||
sender was empty, so a bounce could be refused or allowed by an entry the
|
sender was empty, so a bounce could be refused or allowed by an entry the
|
||||||
|
|||||||
+25
-2
@@ -170,6 +170,10 @@ DMARC_RELAY_DOMAINS_MAP="${POSTFIX_DMARC_RELAY_DOMAINS:-/data/postfix/dmarc_rela
|
|||||||
# directory and the file with the ownership postlogd writes and the panel reads.
|
# directory and the file with the ownership postlogd writes and the panel reads.
|
||||||
MAIL_LOG_PATH="${MAIL_LOG:-/data/log/mail.log}"
|
MAIL_LOG_PATH="${MAIL_LOG:-/data/log/mail.log}"
|
||||||
|
|
||||||
|
# /etc/postfix outlives a restart of the container, so a cleanup limit set for
|
||||||
|
# port 25 before is taken back here and set again below when it still applies.
|
||||||
|
postconf -PX "cleanup/unix/message_size_limit" 2>/dev/null || true
|
||||||
|
|
||||||
# --- main.cf -----------------------------------------------------------------
|
# --- main.cf -----------------------------------------------------------------
|
||||||
# maillog_file lives under the persistent /data bind mount (architecture.md §
|
# maillog_file lives under the persistent /data bind mount (architecture.md §
|
||||||
# Log tailer). Postfix's default maillog_file_prefixes are only /var and
|
# Log tailer). Postfix's default maillog_file_prefixes are only /var and
|
||||||
@@ -199,11 +203,18 @@ postconf -e \
|
|||||||
postconf -M "postlog/unix-dgram=postlog unix-dgram n - n - 1 postlogd"
|
postconf -M "postlog/unix-dgram=postlog unix-dgram n - n - 1 postlogd"
|
||||||
|
|
||||||
# This is an outbound relay: no local delivery, no per-user aliases. Empty
|
# This is an outbound relay: no local delivery, no per-user aliases. Empty
|
||||||
# these so a misfiled recipient never gets delivered locally.
|
# these so a misfiled recipient never gets delivered locally. An empty
|
||||||
|
# mydestination is not enough: an address literal of an interface the
|
||||||
|
# container listens on - x@[127.0.0.1] - is local too (Postfix 3.7.11,
|
||||||
|
# src/global/resolve_local.c, resolve_local(), own_inet_addr()), so local(8)
|
||||||
|
# itself is replaced by a refusal, as Postfix's null-client example does
|
||||||
|
# (README_FILES/STANDARD_CONFIGURATION_README, "local_transport = error:local
|
||||||
|
# mail delivery is disabled"; assumptions C-P8).
|
||||||
postconf -e \
|
postconf -e \
|
||||||
"local_recipient_maps=" \
|
"local_recipient_maps=" \
|
||||||
"alias_maps=" \
|
"alias_maps=" \
|
||||||
"alias_database="
|
"alias_database=" \
|
||||||
|
"local_transport=error:local mail delivery is disabled"
|
||||||
|
|
||||||
# Outbound delivery: straight to the recipient MX, opportunistic TLS.
|
# Outbound delivery: straight to the recipient MX, opportunistic TLS.
|
||||||
postconf -e \
|
postconf -e \
|
||||||
@@ -563,6 +574,18 @@ if [ "${INBOUND_RELAY_ENABLE}" = "true" ] || [ "${DMARC_REPORTS_ENABLE}" = "true
|
|||||||
"smtp/inet/message_size_limit=${PORT25_SIZE}"
|
"smtp/inet/message_size_limit=${PORT25_SIZE}"
|
||||||
master_cf_set_smtp_inet_o smtpd_recipient_restrictions "${RECIPIENT_RESTRICTIONS}"
|
master_cf_set_smtp_inet_o smtpd_recipient_restrictions "${RECIPIENT_RESTRICTIONS}"
|
||||||
master_cf_set_smtp_inet_o smtpd_milters "${INBOUND_MILTERS}"
|
master_cf_set_smtp_inet_o smtpd_milters "${INBOUND_MILTERS}"
|
||||||
|
|
||||||
|
# smtpd's -o limit is not the whole of it: cleanup writes the queue file
|
||||||
|
# under its own message_size_limit, main.cf's, which is never set here and
|
||||||
|
# so is 10240000 (Postfix 3.7.11, src/cleanup/cleanup_init.c,
|
||||||
|
# cleanup_post_jail(), set_file_limit(); src/global/mail_params.h,
|
||||||
|
# DEF_MESSAGE_LIMIT), and a larger message is refused 552 after DATA
|
||||||
|
# (assumptions C-P31). cleanup gets port 25's limit when it is larger;
|
||||||
|
# smtpd on 465 and 587 still holds its own, main.cf's (src/smtpd/smtpd.c,
|
||||||
|
# the DATA and BDAT size checks).
|
||||||
|
if [ "${PORT25_SIZE}" -gt "$(postconf -h message_size_limit)" ]; then
|
||||||
|
postconf -P "cleanup/unix/message_size_limit=${PORT25_SIZE}"
|
||||||
|
fi
|
||||||
else
|
else
|
||||||
postconf -MX "smtp/inet" 2>/dev/null || true
|
postconf -MX "smtp/inet" 2>/dev/null || true
|
||||||
postconf -MX "dmarc-ingest/unix" 2>/dev/null || true
|
postconf -MX "dmarc-ingest/unix" 2>/dev/null || true
|
||||||
|
|||||||
@@ -269,13 +269,6 @@ func printable(s string, max int) string {
|
|||||||
// process has the container's zone (TZ is in import_environment,
|
// 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.
|
// src/global/mail_params.h). A line with no readable stamp is dated now.
|
||||||
func lineTime(line string, now time.Time) (time.Time, string) {
|
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 {
|
if m := syslogStampRe.FindStringSubmatch(line); m != nil {
|
||||||
rest := strings.TrimSpace(line[len(m[0]):])
|
rest := strings.TrimSpace(line[len(m[0]):])
|
||||||
stamp := strings.Join(strings.Fields(m[1]), " ")
|
stamp := strings.Join(strings.Fields(m[1]), " ")
|
||||||
|
|||||||
@@ -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
|
// 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
|
// 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
|
// cleanup_milter_apply() (Postfix 3.7.11), with the stamp Postfix 3.7 writes
|
||||||
// Postfix writes (assumptions A-12); TestLineTime has the syslog one.
|
// (src/util/msg_logger.c, "%b %d %H:%M:%S").
|
||||||
const (
|
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 <nobody@in.example.com>: Recipient address rejected: User unknown in relay recipient table; from=<a@example.net> to=<nobody@in.example.com> proto=ESMTP helo=<mx.example.net>"
|
unknownRcp = head + "postfix/inbound/smtpd[41]: NOQUEUE: reject: RCPT from mx.example.net[203.0.113.9]: 550 5.1.1 <nobody@in.example.com>: Recipient address rejected: User unknown in relay recipient table; from=<a@example.net> to=<nobody@in.example.com> proto=ESMTP helo=<mx.example.net>"
|
||||||
)
|
)
|
||||||
|
|
||||||
@@ -74,7 +74,7 @@ func TestInboundRejectByPostfix(t *testing.T) {
|
|||||||
From: "a@example.net", To: "nobody@in.example.com",
|
From: "a@example.net", To: "nobody@in.example.com",
|
||||||
Decision: store.SpamDecisionReject, Engine: store.SpamEnginePostfix,
|
Decision: store.SpamDecisionReject, Engine: store.SpamEnginePostfix,
|
||||||
Detail: "550 5.1.1 <nobody@in.example.com>: Recipient address rejected: User unknown in relay recipient table",
|
Detail: "550 5.1.1 <nobody@in.example.com>: 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 {
|
if st.rows[0] != want {
|
||||||
t.Errorf("row = %+v\nwant %+v", 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
|
want time.Time
|
||||||
rest string
|
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"},
|
{"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.
|
// 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"},
|
{"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"},
|
||||||
|
|||||||
+89
-29
@@ -581,41 +581,28 @@ func isQueueIDByte(b byte) bool {
|
|||||||
return b >= '0' && b <= '9' || b >= 'A' && b <= 'Z' || b >= 'a' && b <= 'z'
|
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
|
// syslogStampRe is the timestamp at the head of a mail.log line (maillog_file
|
||||||
// build/postfix-config.sh): the one format postlogd writes, and an ISO one.
|
// in build/postfix-config.sh), the one format Postfix 3.7 writes. Postfix 3.7.11,
|
||||||
//
|
|
||||||
// syslogStampRe is the one that matches. Postfix 3.7.11,
|
|
||||||
// src/util/msg_logger.c, msg_logger_print(): every record is stamped
|
// 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
|
// 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
|
// 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
|
// 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,
|
// year and no zone, so the stamp shown is a wall clock and nothing more,
|
||||||
// which is all this column claims to be.
|
// 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
|
||||||
// isoStampRe was written for an RFC 3339 format said to come with a
|
// 3.9; there is none in 3.7.11, nor in the 3.12 snapshot of 2026-09-25
|
||||||
// maillog_file_format parameter of Postfix 3.9. No such parameter exists in
|
// (proto/postconf.proto; msg_logger.c keeps the strftime) - assumptions A-12.
|
||||||
// 3.7.11, nor in the 3.12 snapshot of 2026-09-25 (postconf.proto, and
|
var syslogStampRe = regexp.MustCompile(`^([A-Z][a-z]{2}\s+\d{1,2} \d{2}:\d{2}:\d{2})\s`)
|
||||||
// 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`)
|
|
||||||
)
|
|
||||||
|
|
||||||
// SplitTimestamp separates the timestamp at the head of a mail.log line from
|
// 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
|
// 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
|
// is the log's own wall clock, not converted: what is on the page is what is
|
||||||
// places of microsecond are the widest part of the column and the least worth
|
// in the file.
|
||||||
// reading — but is otherwise 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
|
// 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
|
// rest, with an empty stamp. Nothing is ever dropped: the point of showing the
|
||||||
// log is that it says what it says.
|
// log is that it says what it says.
|
||||||
func SplitTimestamp(line string) (stamp, rest string) {
|
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 {
|
if m := syslogStampRe.FindStringSubmatch(line); m != nil {
|
||||||
return m[1], strings.TrimSpace(line[len(m[0]):])
|
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,
|
// consumed is the offset just past what the reader has handed over,
|
||||||
// pending included: where a complete line ends.
|
// pending included: where a complete line ends.
|
||||||
consumed int64
|
consumed int64
|
||||||
|
// old is the file rotated away, still read for rotatedGrace.
|
||||||
|
old *rotatedTail
|
||||||
)
|
)
|
||||||
openAt := func(offset int64, whence int) error {
|
openAt := func(offset int64, whence int) error {
|
||||||
nf, err := os.Open(path)
|
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))
|
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
|
var once sync.Once
|
||||||
blind := &blindness{add: tr.st.AddTailerBlind}
|
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
|
tr.record(f, read(), true) // shutdown: the next start resumes here
|
||||||
return nil
|
return nil
|
||||||
case <-ticker.C:
|
case <-ticker.C:
|
||||||
|
drainOld(time.Now())
|
||||||
drain()
|
drain()
|
||||||
once.Do(func() { close(caughtUp) })
|
once.Do(func() { close(caughtUp) })
|
||||||
ni, err := os.Stat(path)
|
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
|
// Rotated away or truncated: the old (renamed) inode may have
|
||||||
// gained lines between the drain() above and this check, since
|
// gained lines between the drain() above and this check, since
|
||||||
// Postfix keeps writing to it until it reloads. Drain it once
|
// Postfix keeps writing to it until it reloads. Drain it once
|
||||||
// more before switching so nothing in that gap is lost.
|
// more before switching, and - renamed, not truncated - go on
|
||||||
// Postfix 3.7.11, src/postlogd/postlogd.c, pre_jail_init():
|
// reading it for rotatedGrace after the switch, for what
|
||||||
// maillog_file is opened once per postlogd process, which ends
|
// postlogd writes there until the reload (assumptions A-33).
|
||||||
// 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.
|
|
||||||
drain()
|
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 err := openAt(0, io.SeekStart); err != nil {
|
||||||
|
if renamed {
|
||||||
|
f, r = prev.f, prev.r
|
||||||
|
}
|
||||||
log.Printf("log-tailer: reopen %s: %v", path, err)
|
log.Printf("log-tailer: reopen %s: %v", path, err)
|
||||||
blind.see(time.Now(), true)
|
blind.see(time.Now(), true)
|
||||||
continue
|
continue
|
||||||
}
|
}
|
||||||
|
if renamed {
|
||||||
|
old = prev
|
||||||
|
}
|
||||||
blind.see(time.Now(), false)
|
blind.see(time.Now(), false)
|
||||||
tr.adopt(f)
|
tr.adopt(f)
|
||||||
continue
|
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
|
// blindness measures the stretches in which follow cannot read mail.log - the
|
||||||
// file gone, reopening it failing - for delivery_log_days. A stretch is
|
// 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
|
// stored when it ends, and every minute while it lasts, so a long one is not
|
||||||
|
|||||||
@@ -16,9 +16,10 @@ import (
|
|||||||
|
|
||||||
// The mail.log lines in this file are composed by hand, after the formats the
|
// 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
|
// 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:
|
// comment says where one was seen; some carry no stamp, which the parsers
|
||||||
// ISO stamps (msg_logger.c writes "%b %d %H:%M:%S" - A-12), and opendkim
|
// take as they come. One shape Postfix does not write here: opendkim lines in
|
||||||
// lines in mail.log (build/opendkim.conf has Syslog no).
|
// 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'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
|
// 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
|
// sender"); composed by hand after that format. The sender is the client's
|
||||||
@@ -89,7 +90,7 @@ func TestParseDelivery(t *testing.T) {
|
|||||||
}{
|
}{
|
||||||
{
|
{
|
||||||
name: "sent",
|
name: "sent",
|
||||||
line: "2026-07-11T11:55:34 host postfix/smtp[26]: 41E862C00D9E: to=<a@example.net>, 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=<a@example.net>, relay=mx.example.net[203.0.113.9]:25, delay=0.5, dsn=2.0.0, status=sent (250 OK)",
|
||||||
wantOK: true,
|
wantOK: true,
|
||||||
queueID: "41E862C00D9E",
|
queueID: "41E862C00D9E",
|
||||||
recipient: "a@example.net",
|
recipient: "a@example.net",
|
||||||
@@ -460,6 +461,39 @@ func TestFollowTailsAndRotates(t *testing.T) {
|
|||||||
// would otherwise stay "queued" forever), without re-parsing what it already
|
// 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
|
// read, and must fall back to reading the whole file when the log was rotated
|
||||||
// or recreated in the meantime.
|
// 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=<a@example.net>, 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=<b@example.net>, 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=<c@example.net>, 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) {
|
func TestFollowResumesAfterRestart(t *testing.T) {
|
||||||
old := pollInterval
|
old := pollInterval
|
||||||
pollInterval = 10 * time.Millisecond
|
pollInterval = 10 * time.Millisecond
|
||||||
@@ -834,22 +868,12 @@ func TestSplitTimestamp(t *testing.T) {
|
|||||||
stamp, rest string
|
stamp, rest string
|
||||||
}{
|
}{
|
||||||
{
|
{
|
||||||
name: "RFC 3339, which maillog_file_format selects on Postfix 3.9 and up",
|
// An RFC 3339 stamp is not one Postfix 3.7 writes (assumptions
|
||||||
line: "2026-08-03T05:15:52.219218+00:00 mail postfix/smtp[26]: 4A1B2C3D: to=<a@example.net>, status=sent (250 OK)",
|
// A-12): it is not taken off.
|
||||||
stamp: "2026-08-03 05:15:52",
|
name: "RFC 3339 is not a stamp Postfix writes",
|
||||||
rest: "mail postfix/smtp[26]: 4A1B2C3D: to=<a@example.net>, status=sent (250 OK)",
|
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: "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",
|
|
||||||
},
|
},
|
||||||
{
|
{
|
||||||
name: "syslog's traditional format, space-padded day",
|
name: "syslog's traditional format, space-padded day",
|
||||||
|
|||||||
@@ -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())
|
||||||
|
}
|
||||||
@@ -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
|
// 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();
|
// names and addresses (smtpd.c check_milter_reply(), mail_open_stream();
|
||||||
// cleanup_milter.c cleanup_milter_apply(), Postfix 3.7.11); their ISO stamp
|
// cleanup_milter.c cleanup_milter_apply(), Postfix 3.7.11), with the stamp
|
||||||
// is not a format Postfix writes (assumptions A-12).
|
// 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
|
// 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
|
// 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)
|
now := time.Date(2026, 10, 14, 12, 0, 0, 0, time.UTC)
|
||||||
st := &refusalProbe{}
|
st := &refusalProbe{}
|
||||||
r := &refusalLines{st: st}
|
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=<billing@sender.e2e.test> proto=ESMTP helo=<e2e-client.e2e.test> sasl_username=<l2app>`
|
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=<billing@sender.e2e.test> proto=ESMTP helo=<e2e-client.e2e.test> sasl_username=<l2app>`
|
||||||
for _, other := range []string{
|
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=<a@stranger.example> proto=ESMTP helo=<x>`,
|
`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=<a@stranger.example> proto=ESMTP helo=<x>`,
|
||||||
`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`,
|
`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`,
|
||||||
`2026-10-14T12:00:00+00:00 mail postfix/smtpd[11]: NOQUEUE: reject: RCPT from unknown[10.77.0.1]: 553 5.7.1 <a@x>: Sender address rejected: not owned by user app1; from=<a@x> to=<b@y> proto=ESMTP helo=<x>`,
|
`Oct 14 12:00:00 mail postfix/smtpd[11]: NOQUEUE: reject: RCPT from unknown[10.77.0.1]: 553 5.7.1 <a@x>: Sender address rejected: not owned by user app1; from=<a@x> to=<b@y> proto=ESMTP helo=<x>`,
|
||||||
// No login: no application's refusal (the panel down refuses every
|
// No login: no application's refusal (the panel down refuses every
|
||||||
// session, an unauthenticated one too).
|
// 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=<billing@sender.e2e.test> proto=ESMTP helo=<x>`,
|
`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=<billing@sender.e2e.test> proto=ESMTP helo=<x>`,
|
||||||
} {
|
} {
|
||||||
r.handle(other, now, Place{})
|
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)
|
now := time.Date(2026, 10, 14, 12, 0, 0, 0, time.UTC)
|
||||||
st := &refusalProbe{}
|
st := &refusalProbe{}
|
||||||
r := &refusalLines{st: st}
|
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(`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(`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" <director@other.e2e.test> - it names another sender of this server; from=<alerts@sender.e2e.test> to=<rcpt@sink.e2e.test> proto=ESMTP helo=<x>`, 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" <director@other.e2e.test> - it names another sender of this server; from=<alerts@sender.e2e.test> to=<rcpt@sink.e2e.test> proto=ESMTP helo=<x>`, now, Place{})
|
||||||
r.retry(now.Add(time.Second))
|
r.retry(now.Add(time.Second))
|
||||||
if len(st.recovered) != 0 {
|
if len(st.recovered) != 0 {
|
||||||
t.Fatal("recovered before the panel had the time to write the row")
|
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 {
|
if _, held := r.oldest("fp"); held {
|
||||||
t.Fatal("nothing waits, yet the offset is 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(`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(`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=<a@sender.example> to=<r@x> proto=ESMTP helo=<x>`, now, Place{FP: "fp", End: 300})
|
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=<a@sender.example> to=<r@x> proto=ESMTP helo=<x>`, now, Place{FP: "fp", End: 300})
|
||||||
if p, held := r.oldest("fp"); !held || p.End != 100 {
|
if p, held := r.oldest("fp"); !held || p.End != 100 {
|
||||||
t.Fatalf("held at %+v %v, want the client= line at 100", p, held)
|
t.Fatalf("held at %+v %v, want the client= line at 100", p, held)
|
||||||
}
|
}
|
||||||
|
|||||||
@@ -46,47 +46,47 @@ func TestDeferredCounter(t *testing.T) {
|
|||||||
now := time.Date(2026, 10, 12, 18, 0, 0, 0, time.UTC)
|
now := time.Date(2026, 10, 12, 18, 0, 0, 0, time.UTC)
|
||||||
for _, line := range []string{
|
for _, line := range []string{
|
||||||
// The journal milter's own temporary refusal: no warning, not counted.
|
// 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]`,
|
`Oct 12 16:22:13 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]: 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.
|
// 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]`,
|
`Oct 12 16:22:57 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`,
|
`Oct 12 16:22:57 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`,
|
`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`,
|
||||||
`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>`,
|
`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>`,
|
||||||
`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]: 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:
|
// The same process takes another client, and the check answers again:
|
||||||
// a level-2 refusal there is not the check's.
|
// 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]`,
|
`Oct 12 16:23:30 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]: 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
|
// 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.
|
// 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]`,
|
`Oct 12 16:23:40 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>`,
|
`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>`,
|
||||||
`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]: 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.
|
// 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]`,
|
`Oct 12 16:24: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`,
|
`Oct 12 16:24: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]: 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:
|
// The check stops answering in the middle of a message, the next day:
|
||||||
// cleanup meets it. Two messages through the same cleanup process are
|
// cleanup meets it. Two messages through the same cleanup process are
|
||||||
// two messages.
|
// two messages.
|
||||||
`2026-10-13T00:00:05.000000+00:00 mail postfix/smtpd[1300]: connect from unknown[10.77.0.1]`,
|
`Oct 13 00:00:05 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`,
|
`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`,
|
||||||
`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>`,
|
`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>`,
|
||||||
`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`,
|
`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`,
|
||||||
`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: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.
|
// 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
|
// The check's own verdict is a refusal, not a deferral, and it is
|
||||||
// cleanup that writes it.
|
// 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{})
|
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)
|
now := time.Date(2026, 10, 12, 18, 0, 0, 0, time.UTC)
|
||||||
outage := func(pid, at string) []string {
|
outage := func(pid, at string) []string {
|
||||||
return []string{
|
return []string{
|
||||||
at + `0+00:00 mail postfix/smtpd[` + pid + `]: connect from unknown[10.77.0.1]`,
|
at + ` 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 + `]: 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"})
|
c := newDeferredCounter(&SenderCheck{Store: st, Socket: "/run/selfpost/sender.sock"})
|
||||||
for _, line := range first {
|
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.
|
// A new run: the same lines again, then what the outage added.
|
||||||
c = newDeferredCounter(&SenderCheck{Store: st, Socket: "/run/selfpost/sender.sock"})
|
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{})
|
c.handle(line, now, true, Place{})
|
||||||
}
|
}
|
||||||
if st.days["2026-10-12"] != 3 {
|
if st.days["2026-10-12"] != 3 {
|
||||||
@@ -135,10 +135,10 @@ func TestDeferredCounterRemembersAPlaceNotASecond(t *testing.T) {
|
|||||||
st := &deferredStore{}
|
st := &deferredStore{}
|
||||||
now := time.Date(2026, 10, 12, 18, 0, 0, 0, time.UTC)
|
now := time.Date(2026, 10, 12, 18, 0, 0, 0, time.UTC)
|
||||||
lines := []string{
|
lines := []string{
|
||||||
`2026-10-12T16:00:00+00:00 mail postfix/smtpd[11]: connect from unknown[10.77.0.1]`,
|
`Oct 12 16: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`,
|
`Oct 12 16:00:01 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]`,
|
`Oct 12 16:00:01 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: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.
|
// The place each line ends at, in one file.
|
||||||
places := make([]Place, len(lines))
|
places := make([]Place, len(lines))
|
||||||
|
|||||||
@@ -153,9 +153,9 @@ func TestDeliveryPageMarksAQueuedMessageAsStillWaiting(t *testing.T) {
|
|||||||
func TestDeliveryPageShowsThisMessagesLogLines(t *testing.T) {
|
func TestDeliveryPageShowsThisMessagesLogLines(t *testing.T) {
|
||||||
h, row := serverWithDelivery(t)
|
h, row := serverWithDelivery(t)
|
||||||
h.cfg.MailLogPath = writeMailLog(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]",
|
"Aug 03 05:15:52 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=<other@example.ru>, size=500, nrcpt=1 (queue active)",
|
"Aug 03 05:15:52 host postfix/qmgr[10]: 99999999: from=<other@example.ru>, size=500, nrcpt=1 (queue active)",
|
||||||
"2026-08-03T05:16:03.884210+00:00 host postfix/smtp[26]: 4A1B2C3D: to=<public@example.ru>, dsn=2.0.0, status=sent (250 OK)",
|
"Aug 03 05:16:03 host postfix/smtp[26]: 4A1B2C3D: to=<public@example.ru>, dsn=2.0.0, status=sent (250 OK)",
|
||||||
)
|
)
|
||||||
|
|
||||||
out := getBody(t, h.HandleDelivery, "/outbound/log/"+itoa(row.ID))
|
out := getBody(t, h.HandleDelivery, "/outbound/log/"+itoa(row.ID))
|
||||||
@@ -163,8 +163,8 @@ func TestDeliveryPageShowsThisMessagesLogLines(t *testing.T) {
|
|||||||
`<pre class="sp-log">`,
|
`<pre class="sp-log">`,
|
||||||
// The stamp is split off from the line, without the microseconds and the
|
// The stamp is split off from the line, without the microseconds and the
|
||||||
// offset that make it the widest thing on it.
|
// offset that make it the widest thing on it.
|
||||||
`<span class="sp-d">2026-08-03 05:15:52</span> host postfix/smtpd[20]: 4A1B2C3D: client=mail.example.com`,
|
`<span class="sp-d">Aug 03 05:15:52</span> host postfix/smtpd[20]: 4A1B2C3D: client=mail.example.com`,
|
||||||
`<span class="sp-d">2026-08-03 05:16:03</span> host postfix/smtp[26]: 4A1B2C3D: to=<public@example.ru>`,
|
`<span class="sp-d">Aug 03 05:16:03</span> host postfix/smtp[26]: 4A1B2C3D: to=<public@example.ru>`,
|
||||||
"status=sent (250 OK)",
|
"status=sent (250 OK)",
|
||||||
} {
|
} {
|
||||||
if !strings.Contains(out, want) {
|
if !strings.Contains(out, want) {
|
||||||
@@ -196,20 +196,20 @@ func TestDeliveryPageKeepsAnUnstampedLogLineWhole(t *testing.T) {
|
|||||||
func TestDeliveryPageShowsStoredLogLinesAfterRotation(t *testing.T) {
|
func TestDeliveryPageShowsStoredLogLinesAfterRotation(t *testing.T) {
|
||||||
h, row := serverWithDelivery(t)
|
h, row := serverWithDelivery(t)
|
||||||
h.cfg.RetryPolicy = postfix.DefaultRetryPolicy()
|
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{
|
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.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: "2026-08-03T05:15:52.219218+00:00 host postfix/smtpd[20]: 4A1B2C3D: client=mail.example.com[203.0.113.4]"},
|
{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: "2026-08-03T05:15:52.300000+00:00 host postfix/qmgr[10]: 99999999: from=<other@example.ru>, size=500, nrcpt=1 (queue active)"},
|
{QueueID: "99999999", At: row.CreatedAt, Line: "Aug 03 05:15:52 host postfix/qmgr[10]: 99999999: from=<other@example.ru>, 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=<public@example.ru>, dsn=2.0.0, status=sent (250 OK)"},
|
{QueueID: row.QueueID, At: row.CreatedAt.Add(11 * time.Second), Line: "Aug 03 05:16:03 host postfix/smtp[26]: 4A1B2C3D: to=<public@example.ru>, dsn=2.0.0, status=sent (250 OK)"},
|
||||||
}, false); err != nil {
|
}, false); err != nil {
|
||||||
t.Fatalf("InsertSendLogLines: %v", err)
|
t.Fatalf("InsertSendLogLines: %v", err)
|
||||||
}
|
}
|
||||||
|
|
||||||
out := getBody(t, h.HandleDelivery, "/outbound/log/"+itoa(row.ID))
|
out := getBody(t, h.HandleDelivery, "/outbound/log/"+itoa(row.ID))
|
||||||
for _, want := range []string{
|
for _, want := range []string{
|
||||||
`<span class="sp-d">2026-08-03 05:15:52</span> host postfix/smtpd[20]: 4A1B2C3D: client=mail.example.com`,
|
`<span class="sp-d">Aug 03 05:15:52</span> host postfix/smtpd[20]: 4A1B2C3D: client=mail.example.com`,
|
||||||
`<span class="sp-d">2026-08-03 05:16:03</span> host postfix/smtp[26]: 4A1B2C3D: to=<public@example.ru>`,
|
`<span class="sp-d">Aug 03 05:16:03</span> host postfix/smtp[26]: 4A1B2C3D: to=<public@example.ru>`,
|
||||||
} {
|
} {
|
||||||
if !strings.Contains(out, want) {
|
if !strings.Contains(out, want) {
|
||||||
t.Errorf("delivery log is missing %q:\n%s", want, out)
|
t.Errorf("delivery log is missing %q:\n%s", want, out)
|
||||||
|
|||||||
@@ -159,7 +159,7 @@ func TestMessagePageDrawsTheOutcomeAtItsLevel(t *testing.T) {
|
|||||||
} {
|
} {
|
||||||
h, row := serverWithDelivery(t)
|
h, row := serverWithDelivery(t)
|
||||||
h.cfg.MailLogPath = writeMailLog(t,
|
h.cfg.MailLogPath = writeMailLog(t,
|
||||||
"2026-08-03T05:16:03.884210+00:00 host postfix/smtp[26]: 4A1B2C3D: to=<public@example.ru>, status="+tc.status+" (reply)")
|
"Aug 03 05:16:03 host postfix/smtp[26]: 4A1B2C3D: to=<public@example.ru>, status="+tc.status+" (reply)")
|
||||||
if _, err := h.store.UpdateStatus(row.QueueID, row.To, tc.status); err != nil {
|
if _, err := h.store.UpdateStatus(row.QueueID, row.To, tc.status); err != nil {
|
||||||
t.Fatal(err)
|
t.Fatal(err)
|
||||||
}
|
}
|
||||||
|
|||||||
@@ -166,7 +166,7 @@ func TestARefusedMessageShowsPostfixsLine(t *testing.T) {
|
|||||||
t.Fatal(err)
|
t.Fatal(err)
|
||||||
}
|
}
|
||||||
if subject == "with its line" {
|
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=<alerts@example.org> proto=ESMTP helo=<app>"
|
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=<alerts@example.org> proto=ESMTP helo=<app>"
|
||||||
if ok, err := st.AttachRefusalLine("198.51.100.7", "alerts", "alerts@example.org", time.Now(), line); err != nil || !ok {
|
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)
|
t.Fatalf("attach = %v, %v", ok, err)
|
||||||
}
|
}
|
||||||
|
|||||||
@@ -181,3 +181,23 @@ print("; ".join(r[0]+" "+r[1] for r in rows))`, token)
|
|||||||
t.Fatal(err)
|
t.Fatal(err)
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
|
// testAddressLiteralIsNotLocal: an address literal of an interface the
|
||||||
|
// container listens on is a local destination to Postfix even with an empty
|
||||||
|
// mydestination (Postfix 3.7.11, src/global/resolve_local.c,
|
||||||
|
// resolve_local()). Local delivery is Postfix's refusal now
|
||||||
|
// (local_transport=error:..., assumptions C-P8), and smtpd refuses such a
|
||||||
|
// recipient at RCPT with its text: smtpd_reject_unlisted_recipient (on by
|
||||||
|
// default) runs check_rcpt_maps(), which rejects whatever resolves to the
|
||||||
|
// error transport (src/smtpd/smtpd_check.c). Before, the message was
|
||||||
|
// accepted and handed to local(8).
|
||||||
|
func testAddressLiteralIsNotLocal(t *testing.T, sc *scenario) {
|
||||||
|
res := attemptSend(sendAttempt{
|
||||||
|
authLogin: sc.appLogin, authPassword: sc.appPassword,
|
||||||
|
from: "alerts@" + senderDomain, headerFrom: "alerts@" + senderDomain,
|
||||||
|
to: "probe@[127.0.0.1]", subject: "e2e " + uniqueToken("literal"), body: "to an address literal of the container",
|
||||||
|
})
|
||||||
|
if err := res.refusedAt("RCPT", 550, "local mail delivery is disabled"); err != nil {
|
||||||
|
t.Fatalf("to probe@[127.0.0.1]: %v", err)
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|||||||
@@ -348,6 +348,9 @@ func TestE2E(t *testing.T) {
|
|||||||
run("recipients_as_postfix_logs_them", func(t *testing.T) {
|
run("recipients_as_postfix_logs_them", func(t *testing.T) {
|
||||||
testRecipientsAsPostfixLogsThem(t, sc)
|
testRecipientsAsPostfixLogsThem(t, sc)
|
||||||
})
|
})
|
||||||
|
run("address_literal_is_not_local", func(t *testing.T) {
|
||||||
|
testAddressLiteralIsNotLocal(t, sc)
|
||||||
|
})
|
||||||
run("expired_message_is_closed", func(t *testing.T) {
|
run("expired_message_is_closed", func(t *testing.T) {
|
||||||
testExpiredMessageIsClosed(t, sc)
|
testExpiredMessageIsClosed(t, sc)
|
||||||
})
|
})
|
||||||
|
|||||||
@@ -268,6 +268,21 @@ func testInboundRelay(t *testing.T, sc *scenario) {
|
|||||||
t.Fatalf("mail for the inbound domain never reached its upstream: %v\n%s", err, mailLogTail(h, "postfix/"))
|
t.Fatalf("mail for the inbound domain never reached its upstream: %v\n%s", err, mailLogTail(h, "postfix/"))
|
||||||
}
|
}
|
||||||
|
|
||||||
|
// Port 25's limit is the whole limit: a 12 MB message - over the
|
||||||
|
// 10240000 bytes cleanup would hold it to on its own, under the 25 MiB the
|
||||||
|
// listener says - is accepted and passed on (Postfix 3.7.11,
|
||||||
|
// src/cleanup/cleanup_init.c, cleanup_post_jail(); assumptions C-P31).
|
||||||
|
big := uniqueToken("inbound-12mb")
|
||||||
|
line := "0123456789abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789ab\r\n"
|
||||||
|
bigBody := strings.Repeat(line, 12*1000*1000/len(line))
|
||||||
|
if res := deliverPort25("someone@stranger.e2e.test", inboundRecipient,
|
||||||
|
strings.Replace(message(inboundRecipient, big), "mail for the inbound domain\r\n", bigBody, 1)); !res.ok() {
|
||||||
|
t.Fatalf("port 25 refused a 12 MB message: %v\n%s", res.firstErr(), mailLogTail(h, "postfix/"))
|
||||||
|
}
|
||||||
|
if _, err := findSinkMessage(h.stageDir, big, 60*time.Second); err != nil {
|
||||||
|
t.Fatalf("the 12 MB message never reached the upstream: %v\n%s", err, mailLogTail(h, "postfix/"))
|
||||||
|
}
|
||||||
|
|
||||||
// The filter lists exist as files from the first start with the relay on,
|
// The filter lists exist as files from the first start with the relay on,
|
||||||
// readable by a filter that is another user in another container. Nothing
|
// readable by a filter that is another user in another container. Nothing
|
||||||
// is on them until someone adds an entry.
|
// is on them until someone adds an entry.
|
||||||
@@ -335,7 +350,8 @@ func testInboundRelay(t *testing.T, sc *scenario) {
|
|||||||
return ""
|
return ""
|
||||||
}
|
}
|
||||||
|
|
||||||
rows := logRows("e2e " + token)
|
rows := logRows("e2e " + big)
|
||||||
|
rowWith(rows, "user@<wbr>"+inboundDomain, "e2e "+big, `class="tag is-success is-light" popovertarget="why-`)
|
||||||
rowWith(rows,
|
rowWith(rows,
|
||||||
"someone@<wbr>stranger.e2e.test", "user@<wbr>"+inboundDomain, "e2e "+token,
|
"someone@<wbr>stranger.e2e.test", "user@<wbr>"+inboundDomain, "e2e "+token,
|
||||||
`class="tag is-success is-light" popovertarget="why-`, `<th>Decided by</th><td>selfpost</td>`,
|
`class="tag is-success is-light" popovertarget="why-`, `<th>Decided by</th><td>selfpost</td>`,
|
||||||
@@ -343,8 +359,8 @@ func testInboundRelay(t *testing.T, sc *scenario) {
|
|||||||
`href="/inbound/filter-lists?list=deny&kind=address&value=someone%40stranger.e2e.test">Deny sender</a>`)
|
`href="/inbound/filter-lists?list=deny&kind=address&value=someone%40stranger.e2e.test">Deny sender</a>`)
|
||||||
// A report mailed to the server's own name earlier in the run came through
|
// A report mailed to the server's own name earlier in the run came through
|
||||||
// the same listener and is not the relay's mail.
|
// the same listener and is not the relay's mail.
|
||||||
if len(rows) != 1 {
|
if len(rows) != 2 {
|
||||||
t.Fatalf("the Inbound log holds %d rows, want the relayed message alone:\n%s", len(rows), strings.Join(rows, "\n"))
|
t.Fatalf("the Inbound log holds %d rows, want the two relayed messages alone:\n%s", len(rows), strings.Join(rows, "\n"))
|
||||||
}
|
}
|
||||||
|
|
||||||
// Postfix 3.7.11, src/smtpd/smtpd_check.c: "User unknown in relay recipient
|
// Postfix 3.7.11, src/smtpd/smtpd_check.c: "User unknown in relay recipient
|
||||||
@@ -377,8 +393,8 @@ func testInboundRelay(t *testing.T, sc *scenario) {
|
|||||||
if strings.Contains(refused, "sender</a>") {
|
if strings.Contains(refused, "sender</a>") {
|
||||||
t.Fatalf("the refused row offers a way into the filter lists:\n%s", refused)
|
t.Fatalf("the refused row offers a way into the filter lists:\n%s", refused)
|
||||||
}
|
}
|
||||||
if len(rows) != 2 {
|
if len(rows) != 3 {
|
||||||
t.Fatalf("the Inbound log holds %d rows, want the relayed message and one refusal:\n%s", len(rows), strings.Join(rows, "\n"))
|
t.Fatalf("the Inbound log holds %d rows, want the two relayed messages and one refusal:\n%s", len(rows), strings.Join(rows, "\n"))
|
||||||
}
|
}
|
||||||
|
|
||||||
// The filter lists: an entry added in the panel is in the map file the
|
// The filter lists: an entry added in the panel is in the map file the
|
||||||
|
|||||||
Reference in New Issue
Block a user