Compare commits
3
Commits
| Author | SHA1 | Date | |
|---|---|---|---|
|
|
e1ddf12744 | ||
|
|
af130e268a | ||
|
|
1ca87f2d1a |
+5
-2
@@ -156,8 +156,11 @@ chmod 2750 /run/opendkim /run/selfpost
|
||||
# A container that was killed leaves its sockets behind, and a file nobody
|
||||
# listens on would satisfy postfix-wrapper.sh's wait: Postfix would start
|
||||
# before the sender check does and defer mail until it is there. The check's
|
||||
# alive mark stays - it is how the downtime of a restart is told.
|
||||
rm -f /run/opendkim/*.sock /run/selfpost/*.sock
|
||||
# alive mark goes too: it tells the downtime of the panel restarting inside a
|
||||
# running container, and a restart of the whole container is not the check's
|
||||
# downtime (guide § Health) - a mark left from before would count the whole
|
||||
# outage when supervisord cannot say since when Postfix runs.
|
||||
rm -f /run/opendkim/*.sock /run/selfpost/*.sock /run/selfpost/*.alive
|
||||
|
||||
# Generate the outbound-relay Postfix configuration from the environment (spec
|
||||
# 5). Kept out of the image build so cert paths, rate limits, hostname and the
|
||||
|
||||
@@ -33,13 +33,21 @@ func serveSenderCheck(ctx context.Context, cfg config, st *store.Store) error {
|
||||
// Statistics are the database's business and supervisord's, and the check
|
||||
// is neither: they are kept beside it, and nothing of them is waited for
|
||||
// before it serves.
|
||||
go func() {
|
||||
now := time.Now()
|
||||
mark := cfg.senderSocket + ".alive"
|
||||
// The mark's age is read before the mark is kept again: asking supervisord
|
||||
// may take half a minute, and the mark must not go stale meanwhile, or a
|
||||
// restart in that half minute would count it as downtime.
|
||||
var markAt time.Time
|
||||
if fi, err := os.Stat(mark); err == nil {
|
||||
markAt = fi.ModTime()
|
||||
}
|
||||
go keepAlive(ctx, mark, st)
|
||||
go func() {
|
||||
if err := st.StartSenderCheckStats(now); err != nil {
|
||||
log.Printf("sender-check: statistics: %v", err)
|
||||
}
|
||||
if down, estimated := senderCheckDowntime(mark, now, postfixStarted); down > 0 {
|
||||
if down, estimated := senderCheckDowntime(markAt, now, postfixStarted); down > 0 {
|
||||
if estimated {
|
||||
log.Printf("sender-check: was not answering for at most %s (supervisord did not say since when Postfix ran)", down.Round(time.Second))
|
||||
} else {
|
||||
@@ -51,7 +59,6 @@ func serveSenderCheck(ctx context.Context, cfg config, st *store.Store) error {
|
||||
}
|
||||
}
|
||||
}
|
||||
keepAlive(ctx, mark, st)
|
||||
}()
|
||||
|
||||
// The two tables the mail path itself goes by: whom Postfix lets send as
|
||||
@@ -69,19 +76,19 @@ type postfixState struct {
|
||||
}
|
||||
|
||||
// senderCheckDowntime is for how long the check was not serving before now
|
||||
// while Postfix was: the time since the mark at path was last set, or since
|
||||
// while Postfix was: the time since the mark was last set (markAt; zero
|
||||
// when there is none), or since
|
||||
// Postfix started if that was later. No mark means the container is new, and
|
||||
// a Postfix that is not running means mail was stopped for another reason -
|
||||
// a rollout, a reboot - and neither is the check's downtime. When supervisord
|
||||
// could not say, the time since the mark is taken and estimated is true: an
|
||||
// upper bound, since Postfix may not have been running all of it (audit
|
||||
// 2026-10-12, stage 2b - until then such a start counted nothing).
|
||||
func senderCheckDowntime(path string, now time.Time, ask func() postfixState) (down time.Duration, estimated bool) {
|
||||
fi, err := os.Stat(path)
|
||||
if err != nil {
|
||||
func senderCheckDowntime(markAt, now time.Time, ask func() postfixState) (down time.Duration, estimated bool) {
|
||||
if markAt.IsZero() {
|
||||
return 0, false
|
||||
}
|
||||
from := fi.ModTime()
|
||||
from := markAt
|
||||
p := ask()
|
||||
switch {
|
||||
case !p.known:
|
||||
|
||||
@@ -1,8 +1,6 @@
|
||||
package main
|
||||
|
||||
import (
|
||||
"os"
|
||||
"path/filepath"
|
||||
"testing"
|
||||
"time"
|
||||
)
|
||||
@@ -13,16 +11,8 @@ import (
|
||||
// that time.
|
||||
func TestSenderCheckDowntime(t *testing.T) {
|
||||
now := time.Date(2026, 10, 12, 18, 0, 0, 0, time.UTC)
|
||||
mark := filepath.Join(t.TempDir(), "sender.sock.alive")
|
||||
set := func(at time.Time) {
|
||||
t.Helper()
|
||||
if err := os.WriteFile(mark, nil, 0o644); err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
if err := os.Chtimes(mark, at, at); err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
}
|
||||
var mark time.Time // the alive mark's time; zero is no mark
|
||||
set := func(at time.Time) { mark = at }
|
||||
postfix := func(started time.Time, running bool) func() postfixState {
|
||||
return func() postfixState { return postfixState{started: started, running: running, known: true} }
|
||||
}
|
||||
|
||||
@@ -422,9 +422,11 @@ judged); the sender check writes it on the row, and the message's page shows
|
||||
the lines stored under it - only those of the minutes around the refusal, since
|
||||
Postfix frees the id at once. A message the journal milter refused at
|
||||
`MAIL FROM` has none: the tailer reads smtpd's `NOQUEUE: milter-reject: MAIL
|
||||
from …; from=<…>` and puts it on the newest refused row of that sender (and
|
||||
login, when the line names it) within two minutes (`send_log.refusal_line`),
|
||||
retrying for 30 s when the row is not written yet. The sender check writes its
|
||||
from <client>[<address>]: …; from=<…>` - it names no login - and puts it on
|
||||
the newest refused row of that client address and sender within two minutes
|
||||
(`send_log.refusal_line`; the milter writes `send_log.client_ip`), retrying
|
||||
for 30 s when the row is not written yet; a line already on a row goes on no
|
||||
other. The sender check writes its
|
||||
row through a buffer after answering 550; a panel stopped in between wrote
|
||||
none. The tailer remembers each queue id's login from smtpd's `client=` line,
|
||||
and 30 s after cleanup's `milter-reject: END-OF-MESSAGE … 5.7.1 From:` line it
|
||||
|
||||
@@ -125,9 +125,9 @@
|
||||
<div class="sp-box-head"><span class="sp-no">02</span><h2>Outbound</h2></div>
|
||||
<div class="sp-help-topic" id="dns"><h3>DNS records</h3><p>DKIM proves the message was signed by this relay, SPF lists the addresses allowed to send for the domain, DMARC tells receivers what to do when both fail and where to report. Publish all three exactly as shown; merge SPF into an existing record rather than adding a second one. A domain's status is the worst of its three records, and results are cached for a few minutes, so use Re-check DNS after publishing. The SPF check is shallow: it looks for this server's address in the record itself and does not follow <code>include:</code> or <code>redirect=</code>, so a record that relies on them is reported as a warning, not a failure. <code>p=none</code> does not affect delivery; tighten to <code>quarantine</code>, then <code>reject</code>, once the reports look clean. A domain's report address is set in its Domain settings.</p></div>
|
||||
<div class="sp-help-topic" id="apps"><h3>Applications</h3><p>An application is one SASL login, unique across all domains. It may send as any address of its domain or only as listed addresses, and, with a list of client IPs set, only from those addresses. The password is shown once at creation or regeneration and is not stored in readable form.</p></div>
|
||||
<div class="sp-help-topic" id="sender-check"><h3>Sender check</h3><p>An application sends only as itself, and that holds for both senders a message has. The envelope sender is held against the login by Postfix. The <code>From:</code> line, the one a mail program shows and the one the DKIM signature is chosen by, is held against it by the panel, under the same rule: an application set to any address of its domain may write any address of that domain, and one with a list of addresses only those. A message with any other <code>From:</code> - another of your domains, the server's own name, an address somewhere else, or none at all - is refused for good with <code>550 5.7.1</code>. It is a rejected row of the Outbound log, and its page says which address was refused. This is what keeps one application from getting mail signed with another domain's key.<br><br>The check is strict. While the panel does not answer, Postfix does not accept mail unchecked: it replies with a temporary error and the application sends again later. Server › Health counts what that costs: for how long the panel did not answer while Postfix itself was running; how many connections Postfix turned away because of it - it refuses from the connection on, before a message is offered, so a client that tries three times is three and a monitor that only connects is one; and how many messages were deferred in the middle, when the panel stopped answering after a message had begun. A time marked ≈ includes a start at which supervisord could not say since when Postfix was running: the time since the panel's last sign of life is counted, at most what Postfix was up. The card warns when a connection was turned away or a message deferred in the last 24 hours. If the numbers stay at nothing, the check is where it should be; if they do not, it belongs in a process of its own.</p></div>
|
||||
<div class="sp-help-topic" id="sender-check"><h3>Sender check</h3><p>An application sends only as itself, and that holds for both senders a message has. The envelope sender is held against the login by Postfix. The <code>From:</code> line, the one a mail program shows and the one the DKIM signature is chosen by, is held against it by the panel, under the same rule: an application set to any address of its domain may write any address of that domain, and one with a list of addresses only those. A message with any other <code>From:</code> - another of your domains, the server's own name, an address somewhere else, or none at all - is refused for good with <code>550 5.7.1</code>. It is a rejected row of the Outbound log, and its page says which address was refused. This is what keeps one application from getting mail signed with another domain's key.<br><br>The check is strict. While the panel does not answer, Postfix does not accept mail unchecked: it replies with a temporary error and the application sends again later. Server › Health counts what that costs: for how long the panel did not answer while Postfix itself was running; how many connections Postfix turned away because of it - it refuses from the connection on, before a message is offered, so a client that tries three times is three and a monitor that only connects is one; and how many messages were deferred in the middle, when the panel stopped answering after a message had begun. A time marked ≈ includes a start at which supervisord could not say since when Postfix was running: the time since the panel's last sign of life is counted, which may be more than Postfix was up. The card warns when a connection was turned away or a message deferred in the last 24 hours. If the numbers stay at nothing, the check is where it should be; if they do not, it belongs in a process of its own.</p></div>
|
||||
<div class="sp-help-topic" id="limits"><h3>Rate limits</h3><p>Level 1 is a per-IP ceiling set in <code>.env</code>. Level 2 is optional, per domain and per application, entered by hand or computed from the last 30 days of sending, and can never exceed level 1. An application's own limit replaces its domain's.</p></div>
|
||||
<div class="sp-help-topic" id="log"><h3>Outbound log</h3><p>One row per message and recipient, with the status Postfix last reported: queued (accepted, nothing reported yet), sent (the receiving server took it; what the mailbox does next is not reported back), deferred (not taken yet, Postfix tries again), bounced (failed for good, or the queue lifetime ran out; or closed by the panel when Postfix no longer held the message and <code>mail.log</code> never said what became of it) and rejected (refused before queueing, so it never reached the queue: under a level-2 rate limit, from a client address the application does not allow, or for a <code>From:</code> line that is not the application's - the message's page says which). A message's page lists these steps and the lines Postfix wrote about it in <code>mail.log</code>, found by queue id. The lines are kept with the row: they stay on the page after that file has rotated, for as long as the row does. A message accepted before version 2.2.0 shows them only while they are still in the current file. Rows are deleted after the retention set in Server › Settings, 90 days by default, and their lines with them. A domain administrator sees only the rows of their own domains.</p></div>
|
||||
<div class="sp-help-topic" id="log"><h3>Outbound log</h3><p>One row per message and recipient, with the status Postfix last reported: queued (accepted, nothing reported yet), sent (the receiving server took it; what the mailbox does next is not reported back), deferred (not taken yet, Postfix tries again), bounced (failed for good, or the queue lifetime ran out; or closed by the panel when Postfix no longer held the message and <code>mail.log</code> never said what became of it) and rejected (refused before queueing, so it never reached the queue: under a level-2 rate limit, from a client address the application does not allow, or for a <code>From:</code> line that is not the application's - the message's page says which). A message's page lists these steps and the lines Postfix wrote about it in <code>mail.log</code>, found by queue id - and for a message refused before it had one, Postfix's one line about the refusal. The lines are kept with the row: they stay on the page after that file has rotated, for as long as the row does. A message accepted before version 2.2.0 shows them only while they are still in the current file. Rows are deleted after the retention set in Server › Settings, 90 days by default, and their lines with them. A domain administrator sees only the rows of their own domains.</p></div>
|
||||
<div class="sp-help-topic" id="queue"><h3>Queue and retries</h3><p>The page lists, as <code>postqueue -p</code> prints it, the messages Postfix has accepted and not yet delivered: mail being sent right now and mail deferred for a later attempt. Only the global role can open it, and it only shows; nothing here deletes or forces a message. A deferred message is tried again after the first retry delay, then at gaps that double up to a cap, until the receiving server takes it or the queue lifetime runs out and it bounces; there is no attempt counter, and the box on the page shows this server's values. A queue that keeps growing means a receiver is refusing or not answering: open the message from the Outbound log to read the reason Postfix logged.</p></div>
|
||||
<div class="sp-help-topic" id="dmarc"><h3>DMARC reports</h3><p>An aggregate report is the summary a receiving provider sends, usually daily, to the <code>rua=</code> address of your DMARC record: which servers sent mail as your domain and whether SPF or DKIM passed for it. A domain's report address is one of three choices, set in its Domain settings: no reports (the default for a new domain), the SelfPost hosted address (an address on this server whose reports are parsed and shown under DMARC reports; offered only while hosted reports are enabled on the server), or an address typed for the domain (an ordinary mailbox that receives the raw XML; a button fills in your own profile e-mail). When the typed address is on another domain than the one sending, that domain must publish a report-authorization record, or providers will not send; the domain's page shows it with the other DNS records and checks it. In the tables pass means SPF or DKIM passed and aligned, fail means neither did, and your own server shows as <em>this relay</em>. A fail from any other source is someone else sending as your domain — a forwarder, an application you forgot, or abuse — so do not tighten <code>p=</code> until that sender is fixed or removed. A domain administrator reads the reports of their own domains.</p></div>
|
||||
</div>
|
||||
|
||||
@@ -59,9 +59,9 @@
|
||||
<div class="sp-box-head"><span class="sp-no">02</span><h2>Outbound</h2></div>
|
||||
<div class="sp-help-topic" id="dns"><h3>DNS records</h3><p>DKIM proves the message was signed by this relay, SPF lists the addresses allowed to send for the domain, DMARC tells receivers what to do when both fail and where to report. Publish all three exactly as shown; merge SPF into an existing record rather than adding a second one. A domain's status is the worst of its three records, and results are cached for a few minutes, so use Re-check DNS after publishing. The SPF check is shallow: it looks for this server's address in the record itself and does not follow <code>include:</code> or <code>redirect=</code>, so a record that relies on them is reported as a warning, not a failure. <code>p=none</code> does not affect delivery; tighten to <code>quarantine</code>, then <code>reject</code>, once the reports look clean. A domain's report address is set in its Domain settings.</p></div>
|
||||
<div class="sp-help-topic" id="apps"><h3>Applications</h3><p>An application is one SASL login, unique across all domains. It may send as any address of its domain or only as listed addresses, and, with a list of client IPs set, only from those addresses. The password is shown once at creation or regeneration and is not stored in readable form.</p></div>
|
||||
<div class="sp-help-topic" id="sender-check"><h3>Sender check</h3><p>An application sends only as itself, and that holds for both senders a message has. The envelope sender is held against the login by Postfix. The <code>From:</code> line, the one a mail program shows and the one the DKIM signature is chosen by, is held against it by the panel, under the same rule: an application set to any address of its domain may write any address of that domain, and one with a list of addresses only those. A message with any other <code>From:</code> - another of your domains, the server's own name, an address somewhere else, or none at all - is refused for good with <code>550 5.7.1</code>. It is a rejected row of the Outbound log, and its page says which address was refused. This is what keeps one application from getting mail signed with another domain's key.<br><br>The check is strict. While the panel does not answer, Postfix does not accept mail unchecked: it replies with a temporary error and the application sends again later. Server › Health counts what that costs: for how long the panel did not answer while Postfix itself was running; how many connections Postfix turned away because of it - it refuses from the connection on, before a message is offered, so a client that tries three times is three and a monitor that only connects is one; and how many messages were deferred in the middle, when the panel stopped answering after a message had begun. A time marked ≈ includes a start at which supervisord could not say since when Postfix was running: the time since the panel's last sign of life is counted, at most what Postfix was up. The card warns when a connection was turned away or a message deferred in the last 24 hours. If the numbers stay at nothing, the check is where it should be; if they do not, it belongs in a process of its own.</p></div>
|
||||
<div class="sp-help-topic" id="sender-check"><h3>Sender check</h3><p>An application sends only as itself, and that holds for both senders a message has. The envelope sender is held against the login by Postfix. The <code>From:</code> line, the one a mail program shows and the one the DKIM signature is chosen by, is held against it by the panel, under the same rule: an application set to any address of its domain may write any address of that domain, and one with a list of addresses only those. A message with any other <code>From:</code> - another of your domains, the server's own name, an address somewhere else, or none at all - is refused for good with <code>550 5.7.1</code>. It is a rejected row of the Outbound log, and its page says which address was refused. This is what keeps one application from getting mail signed with another domain's key.<br><br>The check is strict. While the panel does not answer, Postfix does not accept mail unchecked: it replies with a temporary error and the application sends again later. Server › Health counts what that costs: for how long the panel did not answer while Postfix itself was running; how many connections Postfix turned away because of it - it refuses from the connection on, before a message is offered, so a client that tries three times is three and a monitor that only connects is one; and how many messages were deferred in the middle, when the panel stopped answering after a message had begun. A time marked ≈ includes a start at which supervisord could not say since when Postfix was running: the time since the panel's last sign of life is counted, which may be more than Postfix was up. The card warns when a connection was turned away or a message deferred in the last 24 hours. If the numbers stay at nothing, the check is where it should be; if they do not, it belongs in a process of its own.</p></div>
|
||||
<div class="sp-help-topic" id="limits"><h3>Rate limits</h3><p>Level 1 is a per-IP ceiling set in <code>.env</code>. Level 2 is optional, per domain and per application, entered by hand or computed from the last 30 days of sending, and can never exceed level 1. An application's own limit replaces its domain's.</p></div>
|
||||
<div class="sp-help-topic" id="log"><h3>Outbound log</h3><p>One row per message and recipient, with the status Postfix last reported: queued (accepted, nothing reported yet), sent (the receiving server took it; what the mailbox does next is not reported back), deferred (not taken yet, Postfix tries again), bounced (failed for good, or the queue lifetime ran out; or closed by the panel when Postfix no longer held the message and <code>mail.log</code> never said what became of it) and rejected (refused before queueing, so it never reached the queue: under a level-2 rate limit, from a client address the application does not allow, or for a <code>From:</code> line that is not the application's - the message's page says which). A message's page lists these steps and the lines Postfix wrote about it in <code>mail.log</code>, found by queue id. The lines are kept with the row: they stay on the page after that file has rotated, for as long as the row does. A message accepted before version 2.2.0 shows them only while they are still in the current file. Rows are deleted after the retention set in Server › Settings, 90 days by default, and their lines with them. A domain administrator sees only the rows of their own domains.</p></div>
|
||||
<div class="sp-help-topic" id="log"><h3>Outbound log</h3><p>One row per message and recipient, with the status Postfix last reported: queued (accepted, nothing reported yet), sent (the receiving server took it; what the mailbox does next is not reported back), deferred (not taken yet, Postfix tries again), bounced (failed for good, or the queue lifetime ran out; or closed by the panel when Postfix no longer held the message and <code>mail.log</code> never said what became of it) and rejected (refused before queueing, so it never reached the queue: under a level-2 rate limit, from a client address the application does not allow, or for a <code>From:</code> line that is not the application's - the message's page says which). A message's page lists these steps and the lines Postfix wrote about it in <code>mail.log</code>, found by queue id - and for a message refused before it had one, Postfix's one line about the refusal. The lines are kept with the row: they stay on the page after that file has rotated, for as long as the row does. A message accepted before version 2.2.0 shows them only while they are still in the current file. Rows are deleted after the retention set in Server › Settings, 90 days by default, and their lines with them. A domain administrator sees only the rows of their own domains.</p></div>
|
||||
<div class="sp-help-topic" id="queue"><h3>Queue and retries</h3><p>The page lists, as <code>postqueue -p</code> prints it, the messages Postfix has accepted and not yet delivered: mail being sent right now and mail deferred for a later attempt. Only the global role can open it, and it only shows; nothing here deletes or forces a message. A deferred message is tried again after the first retry delay, then at gaps that double up to a cap, until the receiving server takes it or the queue lifetime runs out and it bounces; there is no attempt counter, and the box on the page shows this server's values. A queue that keeps growing means a receiver is refusing or not answering: open the message from the Outbound log to read the reason Postfix logged.</p></div>
|
||||
<div class="sp-help-topic" id="dmarc"><h3>DMARC reports</h3><p>An aggregate report is the summary a receiving provider sends, usually daily, to the <code>rua=</code> address of your DMARC record: which servers sent mail as your domain and whether SPF or DKIM passed for it. A domain's report address is one of three choices, set in its Domain settings: no reports (the default for a new domain), the SelfPost hosted address (an address on this server whose reports are parsed and shown under DMARC reports; offered only while hosted reports are enabled on the server), or an address typed for the domain (an ordinary mailbox that receives the raw XML; a button fills in your own profile e-mail). When the typed address is on another domain than the one sending, that domain must publish a report-authorization record, or providers will not send; the domain's page shows it with the other DNS records and checks it. In the tables pass means SPF or DKIM passed and aligned, fail means neither did, and your own server shows as <em>this relay</em>. A fail from any other source is someone else sending as your domain — a forwarder, an application you forgot, or abuse — so do not tighten <code>p=</code> until that sender is fixed or removed. A domain administrator reads the reports of their own domains.</p></div>
|
||||
</div>
|
||||
|
||||
@@ -873,6 +873,20 @@ those after it move up one patch number each.
|
||||
shared files of lines (`from-lines-passed.txt`, `from-lines-other.txt`)
|
||||
are kept: the second one's test becomes "never signed for {other}"
|
||||
rather than "refused". - **Opus**
|
||||
- [ ] **What was taken on trust, read in Postfix's source** (owner,
|
||||
2026-10-14: "запиши себе правило не гадать, как работает код, если можно
|
||||
посмотреть в его документацию или исходный код"; then "Есть ли ещё у нас
|
||||
места, где мы угадывали?"). Postfix 3.7.11 - the image's version - read
|
||||
for: (1) when qmgr expires a message against maximal_queue_lifetime - the
|
||||
"+ maximal_backoff" margin of queued_over_lifetime is a guess; (2) whether
|
||||
postlogd goes on writing to the renamed mail.log until the reload - the
|
||||
rotation window the deferred tailer fix is about; (3) why an smtpd from
|
||||
before a reload takes one more connection, and for how long - measured
|
||||
(under 2 s), not understood; (4) the NOQUEUE reject line's fields - two
|
||||
test fixtures carry a sasl_username= that Postfix does not write, one
|
||||
of them presented as seen on the stand; they are corrected. What is read
|
||||
goes into architecture.md with the file it is in; where it contradicts
|
||||
the code, the code is fixed in this stage. - **Opus**
|
||||
- [ ] Docs and wording: help topic sender-check and guide § Who an
|
||||
application may send as (mockup first), security.md § Mail path,
|
||||
CHANGELOG. - **Sonnet**
|
||||
|
||||
+1
-1
@@ -414,7 +414,7 @@ readings, in the order of what stops mail first:
|
||||
is one the panel stopped answering for after it had begun. A time marked ≈
|
||||
is at most what it shows: at that start supervisord could not say since
|
||||
when Postfix ran. Days are UTC days. The card warns when
|
||||
a message was deferred in the last 24 hours. If these numbers do not stay
|
||||
a connection was turned away or a message deferred in the last 24 hours. If these numbers do not stay
|
||||
at nothing, the panel is in the way of your mail more than it should be -
|
||||
report it.
|
||||
- **Hostname and reverse DNS** — compares `SELFPOST_HOSTNAME` against the PTR
|
||||
|
||||
+1
-1
@@ -42,7 +42,7 @@ in `git log` and [CHANGELOG.md](../CHANGELOG.md).
|
||||
| from-header-binding | Hold a message's `From:` header against the application that sends it | shipped `2.4.0` | 9/9 | [plans/from-header-binding.md](plans/from-header-binding.md) |
|
||||
| panel-redesign | Panel redesign (accepted mockups, design contract) | shipped `2.0.0` | 27/27 | [plans/panel-redesign.md](plans/panel-redesign.md) |
|
||||
| schema-squash | Squash SQLite migrations into a 2.x baseline | built in panel-redesign (stage 1) | — | [plans/panel-redesign.md](plans/panel-redesign.md) |
|
||||
| audit-2026-10-12 | Follow-ups of the 2026-10-12 full-tree code audit, seven stages | in progress (stage 0 shipped `2.4.2`, stages 1+2 `2.5.0`; next stage 2b → `2.5.1`) | 30/65 | [audit-2026-10-12.md](audit-2026-10-12.md) |
|
||||
| audit-2026-10-12 | Follow-ups of the 2026-10-12 full-tree code audit, seven stages | in progress (stage 0 shipped `2.4.2`, stages 1+2 `2.5.0`; next stage 2b → `2.5.1`) | 30/66 | [audit-2026-10-12.md](audit-2026-10-12.md) |
|
||||
|
||||
**Recommended order** (not binding; owner, 2026-10-09: feature order follows
|
||||
development convenience): **panel-redesign** shipped as `2.0.0` (2026-10-11) and
|
||||
|
||||
@@ -8,9 +8,12 @@ import (
|
||||
"syscall"
|
||||
)
|
||||
|
||||
// fileID names the file itself - device and inode - which a rename keeps and
|
||||
// a new file does not share. It is part of the log's fingerprint, so two log
|
||||
// files whose first bytes happen to match are still told apart.
|
||||
// fileID names the file itself - its inode - which a rename keeps and a new
|
||||
// file does not share. It is part of the log's fingerprint, so two log files
|
||||
// whose first bytes happen to match are still told apart. The device number
|
||||
// is left out: it can change across a host's reboot (LVM, btrfs, network
|
||||
// file systems), and the same log would then pass for a rotated one (review
|
||||
// of stage 2b).
|
||||
func fileID(f *os.File) string {
|
||||
info, err := f.Stat()
|
||||
if err != nil {
|
||||
@@ -20,5 +23,5 @@ func fileID(f *os.File) string {
|
||||
if !ok {
|
||||
return ""
|
||||
}
|
||||
return fmt.Sprintf("%d.%d", st.Dev, st.Ino)
|
||||
return fmt.Sprintf("%d", st.Ino)
|
||||
}
|
||||
|
||||
@@ -168,7 +168,7 @@ func Run(ctx context.Context, path string, st StatusStore, retention RetentionDa
|
||||
keeper.flush()
|
||||
refusals.retry(time.Now().UTC())
|
||||
}
|
||||
tr := &tracker{st: st, path: path}
|
||||
tr := &tracker{st: st, path: path, hold: refusals.oldest}
|
||||
return follow(ctx, path, tr, caughtUp, flush, func(line string) {
|
||||
// Until the first read reaches end-of-file the lines are those written
|
||||
// while the panel was down - and, after an unclean stop, some it had
|
||||
@@ -187,7 +187,7 @@ func Run(ctx context.Context, path string, st StatusStore, retention RetentionDa
|
||||
deferred.handle(line, now, catchingUp, tr.line)
|
||||
}
|
||||
keeper.add(line, now, catchingUp)
|
||||
refusals.handle(line, now)
|
||||
refusals.handle(line, now, Place{FP: tr.line.FP, End: tr.lineStart})
|
||||
queueID, recipient, status, ok := parseDelivery(line)
|
||||
if !ok {
|
||||
return
|
||||
@@ -647,6 +647,7 @@ func follow(ctx context.Context, path string, tr *tracker, caughtUp chan struct{
|
||||
full := pending + line
|
||||
pending = ""
|
||||
tr.line = Place{FP: tr.fp, End: consumed}
|
||||
tr.lineStart = consumed - int64(len(full))
|
||||
handle(strings.TrimRight(full, "\r\n"))
|
||||
}
|
||||
}
|
||||
|
||||
@@ -47,9 +47,16 @@ type tracker struct {
|
||||
behind bool
|
||||
prev store.LogtailState
|
||||
|
||||
// line is the place of the line being handled: set by follow and
|
||||
// readRotated before each call of handle.
|
||||
// line is the place of the line being handled, lineStart the offset it
|
||||
// starts at: set by follow and readRotated before each call of handle.
|
||||
line Place
|
||||
lineStart int64
|
||||
|
||||
// hold, when set, names the earliest place in a file that something read
|
||||
// from the log still waits on (a refusal's line, a refusal to recover):
|
||||
// no offset past it is saved, so a stop - clean or not - before the wait
|
||||
// is over reads it again (review of stage 2b).
|
||||
hold func(fp string) (Place, bool)
|
||||
}
|
||||
|
||||
// Place is where a line of the log ends: the fingerprint of its file and the
|
||||
@@ -158,6 +165,7 @@ func (t *tracker) readRotated(handle func(string)) bool {
|
||||
r := bufio.NewReader(f)
|
||||
for {
|
||||
line, err := r.ReadString('\n')
|
||||
t.lineStart = end
|
||||
end += int64(len(line))
|
||||
if line != "" {
|
||||
t.line = Place{FP: fp, End: end}
|
||||
@@ -198,6 +206,11 @@ func (t *tracker) adopt(f *os.File) {
|
||||
// record persists offset, at most once per persistInterval unless force is set
|
||||
// (rotation and shutdown, where the write must not be skipped).
|
||||
func (t *tracker) record(f *os.File, offset int64, force bool) {
|
||||
if t.hold != nil {
|
||||
if p, ok := t.hold(t.fp); ok && p.End < offset {
|
||||
offset = p.End
|
||||
}
|
||||
}
|
||||
if offset == t.saved {
|
||||
return
|
||||
}
|
||||
|
||||
@@ -2,6 +2,7 @@ package logtail
|
||||
|
||||
import (
|
||||
"log"
|
||||
"net"
|
||||
"regexp"
|
||||
"strings"
|
||||
"time"
|
||||
@@ -12,13 +13,14 @@ import (
|
||||
// Postfix's line about a message the journal milter refused at MAIL FROM - a
|
||||
// level-2 limit, a client address off the application's list - is put on the
|
||||
// row the milter wrote, so the message's page shows it (audit 2026-10-12,
|
||||
// stage 2b). The refusal has no queue id; the line is matched to its row by
|
||||
// sender, login and time. As the stand writes it:
|
||||
// stage 2b). The refusal has no queue id and the line no login; it is
|
||||
// matched to its row by client address, sender and time. As the stand writes
|
||||
// it:
|
||||
//
|
||||
// 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>
|
||||
//
|
||||
// Port 25's smtpd (postfix/inbound/smtpd) is a stranger's and has no such row.
|
||||
var refusalLineRe = regexp.MustCompile(`^\S+ postfix/(?:([a-z0-9-]+)/)?smtpd\[\d+\]: NOQUEUE: milter-reject: MAIL from \S+: [45]\d\d .*?; from=<([^>]*)>(?:.*? sasl_username=<?([^>\s]*)>?)?`)
|
||||
var refusalLineRe = regexp.MustCompile(`^\S+ postfix/(?:([a-z0-9-]+)/)?smtpd\[\d+\]: NOQUEUE: milter-reject: MAIL from [^\[\s]*\[([^\]]+)\]: [45]\d\d .*?; from=<([^>]*)>`)
|
||||
|
||||
// refusalLineWait is how long a line waits for its row: the milter writes the
|
||||
// row when it refuses, which can be read a moment after the line.
|
||||
@@ -26,7 +28,7 @@ const refusalLineWait = 30 * time.Second
|
||||
|
||||
// RefusalStore is where the lines go. *store.Store satisfies it.
|
||||
type RefusalStore interface {
|
||||
AttachRefusalLine(login, from string, at time.Time, line string) (bool, error)
|
||||
AttachRefusalLine(clientIP, from string, at time.Time, line string) (bool, error)
|
||||
RecoverRefusal(e store.SendLogEntry, at time.Time) (bool, error)
|
||||
}
|
||||
|
||||
@@ -36,8 +38,10 @@ type RefusalStore interface {
|
||||
// postfix/cleanup[1339]: E543D3C75DA0: 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=<e2e-client.e2e.test>
|
||||
//
|
||||
// The From: line as the check printed it runs to the last " - " before the
|
||||
// semicolon; the reason after it holds neither.
|
||||
var fromRefusalRe = regexp.MustCompile(`^\S+ postfix/(?:[a-z0-9-]+/)?cleanup\[\d+\]: ([0-9A-Za-z]+): milter-reject: END-OF-MESSAGE from \S+: 5\.7\.1 From: (.*) - ([^;]*); from=<([^>]*)> to=<([^>]*)>`)
|
||||
// first semicolon; the reason after it holds neither, and the check prints no
|
||||
// ";" of the client's (sender.go printable), so that semicolon is Postfix's
|
||||
// and what follows it - the envelope - is Postfix's own text.
|
||||
var fromRefusalRe = regexp.MustCompile(`^\S+ postfix/(?:[a-z0-9-]+/)?cleanup\[\d+\]: ([0-9A-Za-z]+): milter-reject: END-OF-MESSAGE from \S+: 5\.7\.1 From: ([^;]*) - ([^;]*); from=<([^>]*)> to=<([^>]*)>`)
|
||||
|
||||
// clientLoginRe is smtpd's line naming the login a queue id was submitted
|
||||
// under: "<id>: client=host[addr], sasl_method=PLAIN, sasl_username=<login>".
|
||||
@@ -47,8 +51,9 @@ var clientLoginRe = regexp.MustCompile(`^\S+ postfix/(?:([a-z0-9-]+)/)?smtpd\[\d
|
||||
const refusalLogins = 4096
|
||||
|
||||
type pendingRefusal struct {
|
||||
login, from, line string
|
||||
clientIP, from, line string
|
||||
at, until time.Time
|
||||
start Place // where the line starts in the log
|
||||
}
|
||||
|
||||
// pendingRecovery is a From: refusal whose row is looked for once the panel
|
||||
@@ -56,6 +61,14 @@ type pendingRefusal struct {
|
||||
type pendingRecovery struct {
|
||||
e store.SendLogEntry
|
||||
at, until time.Time
|
||||
start Place // where its client= line - or the refusal - starts
|
||||
}
|
||||
|
||||
// loginLine is the login a queue id was submitted under and where smtpd's
|
||||
// line saying so starts.
|
||||
type loginLine struct {
|
||||
login string
|
||||
start Place
|
||||
}
|
||||
|
||||
// refusalLines puts each refusal line on its row, and keeps for a while the
|
||||
@@ -65,24 +78,49 @@ type refusalLines struct {
|
||||
st RefusalStore
|
||||
pending []pendingRefusal
|
||||
recover []pendingRecovery
|
||||
logins map[string]string // queue id -> login, from smtpd's client= line
|
||||
logins map[string]loginLine // queue id -> login, from smtpd's client= line
|
||||
loginKeys []string
|
||||
}
|
||||
|
||||
// handle looks at one mail.log line.
|
||||
func (r *refusalLines) handle(line string, now time.Time) {
|
||||
// oldest is the earliest place in the file fp a waiting item starts at: the
|
||||
// tracker saves no offset past it, so a stop before the wait is over reads the
|
||||
// lines again - the client= line of a refusal to recover among them.
|
||||
func (r *refusalLines) oldest(fp string) (Place, bool) {
|
||||
var p Place
|
||||
found := false
|
||||
take := func(q Place) {
|
||||
if q.FP == fp && (!found || q.End < p.End) {
|
||||
p, found = q, true
|
||||
}
|
||||
}
|
||||
for _, x := range r.pending {
|
||||
take(x.start)
|
||||
}
|
||||
for _, x := range r.recover {
|
||||
take(x.start)
|
||||
}
|
||||
return p, found
|
||||
}
|
||||
|
||||
// handle looks at one mail.log line, which starts at start.
|
||||
func (r *refusalLines) handle(line string, now time.Time, start Place) {
|
||||
at, rest := lineTime(line, now)
|
||||
if m := clientLoginRe.FindStringSubmatch(rest); m != nil && m[1] != "inbound" {
|
||||
r.remember(m[2], m[3])
|
||||
r.remember(m[2], loginLine{login: m[3], start: start})
|
||||
return
|
||||
}
|
||||
if m := fromRefusalRe.FindStringSubmatch(rest); m != nil {
|
||||
from := start
|
||||
login, ok := r.logins[m[1]]
|
||||
if ok && login.start.FP == start.FP && login.start.End < start.End {
|
||||
from = login.start
|
||||
}
|
||||
r.recover = append(r.recover, pendingRecovery{
|
||||
e: store.SendLogEntry{
|
||||
QueueID: m[1], AppLogin: r.logins[m[1]], From: m[4], To: m[5], Domain: domainOf(m[4]),
|
||||
QueueID: m[1], AppLogin: login.login, From: m[4], To: m[5], Domain: domainOf(m[4]),
|
||||
Reason: store.ReasonFrom, HeaderFrom: m[2],
|
||||
},
|
||||
at: at, until: now.Add(refusalLineWait),
|
||||
at: at, until: now.Add(refusalLineWait), start: from,
|
||||
})
|
||||
return
|
||||
}
|
||||
@@ -90,7 +128,11 @@ func (r *refusalLines) handle(line string, now time.Time) {
|
||||
if m == nil || m[1] == "inbound" {
|
||||
return
|
||||
}
|
||||
p := pendingRefusal{login: m[3], from: m[2], line: line, at: at, until: now.Add(refusalLineWait)}
|
||||
ip := net.ParseIP(strings.TrimPrefix(m[2], "IPv6:"))
|
||||
if ip == nil {
|
||||
return
|
||||
}
|
||||
p := pendingRefusal{clientIP: ip.String(), from: m[3], line: line, at: at, until: now.Add(refusalLineWait), start: start}
|
||||
if !r.attach(p) {
|
||||
r.pending = append(r.pending, p)
|
||||
}
|
||||
@@ -127,9 +169,9 @@ func (r *refusalLines) retry(now time.Time) {
|
||||
|
||||
// remember keeps the login a queue id was submitted under, the oldest going
|
||||
// first beyond refusalLogins.
|
||||
func (r *refusalLines) remember(queueID, login string) {
|
||||
func (r *refusalLines) remember(queueID string, login loginLine) {
|
||||
if r.logins == nil {
|
||||
r.logins = make(map[string]string)
|
||||
r.logins = make(map[string]loginLine)
|
||||
}
|
||||
if _, ok := r.logins[queueID]; !ok {
|
||||
r.loginKeys = append(r.loginKeys, queueID)
|
||||
@@ -150,7 +192,7 @@ func domainOf(addr string) string {
|
||||
}
|
||||
|
||||
func (r *refusalLines) attach(p pendingRefusal) bool {
|
||||
ok, err := r.st.AttachRefusalLine(p.login, p.from, p.at, p.line)
|
||||
ok, err := r.st.AttachRefusalLine(p.clientIP, p.from, p.at, p.line)
|
||||
if err != nil {
|
||||
log.Printf("log-tailer: refusal line: %v", err)
|
||||
return true // not retried: the store said no for its own reason
|
||||
|
||||
@@ -19,13 +19,13 @@ func (r *refusalProbe) RecoverRefusal(e store.SendLogEntry, _ time.Time) (bool,
|
||||
return true, nil
|
||||
}
|
||||
|
||||
func (r *refusalProbe) AttachRefusalLine(login, from string, _ time.Time, line string) (bool, error) {
|
||||
func (r *refusalProbe) AttachRefusalLine(clientIP, from string, _ time.Time, line string) (bool, error) {
|
||||
if r.rows == 0 {
|
||||
return false, nil
|
||||
}
|
||||
r.rows--
|
||||
r.lines = append(r.lines, line)
|
||||
r.who = append(r.who, login+"|"+from)
|
||||
r.who = append(r.who, clientIP+"|"+from)
|
||||
return true, nil
|
||||
}
|
||||
|
||||
@@ -42,23 +42,23 @@ func TestRefusalLines(t *testing.T) {
|
||||
`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 <a@x>: Sender address rejected: not owned by user app1; from=<a@x> to=<b@y> proto=ESMTP helo=<x>`,
|
||||
} {
|
||||
r.handle(other, now)
|
||||
r.handle(other, now, Place{})
|
||||
}
|
||||
if len(r.pending) != 0 {
|
||||
t.Fatalf("lines that are not an application's refusal at MAIL wait: %+v", r.pending)
|
||||
}
|
||||
|
||||
r.handle(limit, now) // its row is not there yet
|
||||
r.handle(limit, now, Place{}) // its row is not there yet
|
||||
if len(r.pending) != 1 {
|
||||
t.Fatalf("pending %d, want the line waiting", len(r.pending))
|
||||
}
|
||||
st.rows = 1 // the milter's row is written
|
||||
r.retry(now.Add(time.Second))
|
||||
if len(r.pending) != 0 || len(st.lines) != 1 || st.who[0] != "l2app|billing@sender.e2e.test" {
|
||||
if len(r.pending) != 0 || len(st.lines) != 1 || st.who[0] != "10.77.0.1|billing@sender.e2e.test" {
|
||||
t.Fatalf("after the retry: pending %d, attached %v", len(r.pending), st.who)
|
||||
}
|
||||
|
||||
r.handle(limit, now) // no row ever comes
|
||||
r.handle(limit, now, Place{}) // no row ever comes
|
||||
r.retry(now.Add(refusalLineWait + time.Second))
|
||||
if len(r.pending) != 0 {
|
||||
t.Fatal("a line kept waiting past its time")
|
||||
@@ -73,8 +73,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)
|
||||
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)
|
||||
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" <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))
|
||||
if len(st.recovered) != 0 {
|
||||
t.Fatal("recovered before the panel had the time to write the row")
|
||||
@@ -90,3 +90,35 @@ func TestFromRefusalIsRecoveredAfterTheWait(t *testing.T) {
|
||||
t.Fatalf("recovered %+v, want %+v", e, want)
|
||||
}
|
||||
}
|
||||
|
||||
// While a line or a recovery waits, the offset saved for its file stays at the
|
||||
// earliest line it needs - for a recovery the client= line that names its
|
||||
// login - so a stop before the wait is over reads them again (review of stage
|
||||
// 2b).
|
||||
func TestWaitingLinesHoldTheSavedOffset(t *testing.T) {
|
||||
now := time.Date(2026, 10, 14, 12, 0, 0, 0, time.UTC)
|
||||
r := &refusalLines{st: &refusalProbe{}}
|
||||
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=<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 {
|
||||
t.Fatalf("held at %+v %v, want the client= line at 100", p, held)
|
||||
}
|
||||
if _, held := r.oldest("another"); held {
|
||||
t.Fatal("a place in another file holds this one")
|
||||
}
|
||||
r.retry(now.Add(refusalLineWait + time.Second))
|
||||
if _, held := r.oldest("fp"); held {
|
||||
t.Fatal("still held after the wait")
|
||||
}
|
||||
|
||||
// The tracker clamps what it saves to the hold.
|
||||
cs := &captureStore{}
|
||||
tr := &tracker{st: cs, path: "x", fp: "fp", hold: func(string) (Place, bool) { return Place{FP: "fp", End: 50}, true }}
|
||||
tr.record(nil, 400, true)
|
||||
if cs.state.Offset != 50 {
|
||||
t.Fatalf("saved %d, want the hold at 50", cs.state.Offset)
|
||||
}
|
||||
}
|
||||
|
||||
@@ -103,6 +103,7 @@ func (s *session) recordRejected(reason string) {
|
||||
AppLogin: s.login,
|
||||
From: s.from,
|
||||
Reason: reason,
|
||||
ClientIP: s.clientIP, // Postfix's line about the refusal names it
|
||||
})
|
||||
if err != nil {
|
||||
log.Printf("journal-milter: record rejected %s: %v", s.from, err)
|
||||
|
||||
@@ -463,6 +463,11 @@ func printable(v string) string {
|
||||
switch {
|
||||
case r == '%' || r < 0x20 || r > 0x7e:
|
||||
sb.WriteByte('?')
|
||||
case r == ';':
|
||||
// Postfix logs the reply and then "; from=<...> to=<...>" of
|
||||
// its own; a ";" of the client's would let its text pass for
|
||||
// Postfix's where the log tailer reads that line.
|
||||
sb.WriteByte(',')
|
||||
default:
|
||||
sb.WriteRune(r)
|
||||
}
|
||||
|
||||
@@ -7,6 +7,12 @@
|
||||
-- headers are judged), and its lines are found by it like any other's.
|
||||
-- DDL only; a row written earlier has '' and says so on its page.
|
||||
ALTER TABLE send_log ADD COLUMN refusal_line TEXT NOT NULL DEFAULT '';
|
||||
-- The client a refusal at MAIL FROM came from, as the milter saw it: Postfix's
|
||||
-- line names the client and the envelope sender and nothing else - no login
|
||||
-- - so the two together are what finds the line's row; the sender alone would
|
||||
-- let one application's line land on another's row of the same sender
|
||||
-- (security review of stage 2b).
|
||||
ALTER TABLE send_log ADD COLUMN client_ip TEXT NOT NULL DEFAULT '';
|
||||
|
||||
-- A refusal row the panel did not get to write - the sender check answers 550
|
||||
-- and writes the row a moment later, and a panel stopped in between wrote
|
||||
|
||||
@@ -1,20 +1,23 @@
|
||||
package store
|
||||
|
||||
import (
|
||||
"fmt"
|
||||
"testing"
|
||||
"time"
|
||||
)
|
||||
|
||||
// Postfix's line about a refusal at MAIL FROM goes on the row of that sender
|
||||
// and login refused about then, the newest without a line; a queued row, a
|
||||
// row of another sender and a row from long ago are not it (audit
|
||||
// 2026-10-12, stage 2b).
|
||||
// Postfix's line about a refusal at MAIL FROM goes on the row of that client
|
||||
// and sender refused about then; a queued row, a row of another client or
|
||||
// sender, and a row from long ago are not it; a line already on a row goes on
|
||||
// no other; and two refusals of one second take one line each, in the order
|
||||
// they were written (security and technical reviews of stage 2b).
|
||||
func TestAttachRefusalLine(t *testing.T) {
|
||||
st := openTestStore(t)
|
||||
now := time.Now().UTC()
|
||||
for _, e := range []SendLogEntry{
|
||||
{AppLogin: "l2app", From: "billing@example.com", Reason: ReasonLimit},
|
||||
{AppLogin: "l2app", From: "other@example.com", Reason: ReasonLimit},
|
||||
{AppLogin: "l2app", From: "billing@example.com", Reason: ReasonLimit, ClientIP: "10.0.0.1"},
|
||||
{AppLogin: "l2app", From: "billing@example.com", Reason: ReasonLimit, ClientIP: "10.0.0.1"},
|
||||
{AppLogin: "other", From: "billing@example.com", Reason: ReasonClient, ClientIP: "10.0.0.2"},
|
||||
} {
|
||||
if err := st.InsertRejected(e); err != nil {
|
||||
t.Fatal(err)
|
||||
@@ -23,33 +26,37 @@ func TestAttachRefusalLine(t *testing.T) {
|
||||
if err := st.InsertQueued(SendLogEntry{QueueID: "Q1", AppLogin: "l2app", From: "billing@example.com", To: "x@example.net"}); err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
line := "Oct 14 12:00:00 mail postfix/smtpd[1]: NOQUEUE: milter-reject: MAIL from unknown[10.77.0.1]: 451 4.7.1 Service unavailable"
|
||||
if ok, err := st.AttachRefusalLine("l2app", "Billing@example.com", now, line); err != nil || !ok {
|
||||
t.Fatalf("attach = %v, %v", ok, err)
|
||||
first := "Oct 14 12:00:00 mail postfix/smtpd[1]: NOQUEUE: milter-reject: MAIL from unknown[10.0.0.1]: 451 4.7.1 first"
|
||||
second := "Oct 14 12:00:00 mail postfix/smtpd[2]: NOQUEUE: milter-reject: MAIL from unknown[10.0.0.1]: 451 4.7.1 second"
|
||||
for _, line := range []string{first, second} {
|
||||
if ok, err := st.AttachRefusalLine("10.0.0.1", "Billing@example.com", now, line); err != nil || !ok {
|
||||
t.Fatalf("attach %q = %v, %v", line, ok, err)
|
||||
}
|
||||
// The row has its line now; a second line finds no row without one.
|
||||
if ok, _ := st.AttachRefusalLine("l2app", "billing@example.com", now, line); ok {
|
||||
t.Fatal("a second line took a row that has one")
|
||||
}
|
||||
if ok, _ := st.AttachRefusalLine("l2app", "other@example.com", now.Add(-time.Hour), line); ok {
|
||||
// Read again after a restart: no row takes it a second time.
|
||||
if ok, _ := st.AttachRefusalLine("10.0.0.1", "billing@example.com", now, first); ok {
|
||||
t.Fatal("a line already on a row took another")
|
||||
}
|
||||
if ok, _ := st.AttachRefusalLine("10.0.0.3", "billing@example.com", now, "a third"); ok {
|
||||
t.Fatal("a line of another client took a row")
|
||||
}
|
||||
if ok, _ := st.AttachRefusalLine("10.0.0.2", "billing@example.com", now.Add(-time.Hour), "an hour off"); ok {
|
||||
t.Fatal("a line an hour off took a row")
|
||||
}
|
||||
if ok, _ := st.AttachRefusalLine("someone", "other@example.com", now, line); ok {
|
||||
t.Fatal("a line of another login took a row")
|
||||
}
|
||||
lines := map[string]string{}
|
||||
rows, _ := st.QuerySendLog(SendLogFilter{AllDomains: true}, 10, 0)
|
||||
got := 0
|
||||
for _, r := range rows {
|
||||
full, _ := st.GetSendLog(r.ID)
|
||||
if full.RefusalLine != "" {
|
||||
got++
|
||||
if full.From != "billing@example.com" || full.Status != StatusRejected {
|
||||
t.Errorf("the line went to %+v", full)
|
||||
lines[fmt.Sprint(full.ID)] = full.RefusalLine
|
||||
}
|
||||
}
|
||||
if len(lines) != 2 {
|
||||
t.Fatalf("lines on rows: %v, want the first two rows", lines)
|
||||
}
|
||||
if got != 1 {
|
||||
t.Fatalf("%d rows have a line, want 1", got)
|
||||
r1, _ := st.GetSendLog(rows[len(rows)-1].ID) // the oldest row
|
||||
if r1.RefusalLine != first {
|
||||
t.Fatalf("the first row has %q, want the first line", r1.RefusalLine)
|
||||
}
|
||||
}
|
||||
|
||||
@@ -113,3 +120,30 @@ func TestRecoverRefusal(t *testing.T) {
|
||||
t.Fatalf("the recovered row: %+v", found)
|
||||
}
|
||||
}
|
||||
|
||||
// A recovered row whose login the tailer did not see is its envelope
|
||||
// domain's, not nobody's (review of stage 2b).
|
||||
func TestRecoverRefusalWithoutALogin(t *testing.T) {
|
||||
st := openTestStore(t)
|
||||
d := addTestDomain(t, st, "sender.example")
|
||||
e := SendLogEntry{QueueID: "NOLOGIN", From: "a@sender.example", To: "r@x", Domain: "sender.example", Reason: ReasonFrom}
|
||||
if wrote, err := st.RecoverRefusal(e, time.Now()); err != nil || !wrote {
|
||||
t.Fatalf("recover = %v, %v", wrote, err)
|
||||
}
|
||||
rows, _ := st.QuerySendLog(SendLogFilter{DomainIDs: []int64{d.ID}}, 10, 0)
|
||||
if len(rows) != 1 {
|
||||
t.Fatalf("the domain's log has %d rows, want the recovered one", len(rows))
|
||||
}
|
||||
}
|
||||
|
||||
// A refused row carries the queue id it was given; a delivery line of a later
|
||||
// message with that id does not touch it.
|
||||
func TestUpdateStatusLeavesARefusalAlone(t *testing.T) {
|
||||
st := openTestStore(t)
|
||||
if err := st.InsertRejected(SendLogEntry{QueueID: "REUSED", To: "a@example.net", Reason: ReasonFrom}); err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
if n, err := st.UpdateStatus("REUSED", "a@example.net", StatusSent); err != nil || n != 0 {
|
||||
t.Fatalf("UpdateStatus = %d, %v; want 0 rows", n, err)
|
||||
}
|
||||
}
|
||||
|
||||
@@ -47,7 +47,7 @@ func TestBaselineSchema(t *testing.T) {
|
||||
"applications": "id domain_id login address_mode auth_ip_restrict auth_allowed_ips created_at",
|
||||
"application_addresses": "id application_id address",
|
||||
"rate_limits": "id scope ref_id max_messages window_seconds mode auto_multiplier auto_updated_at",
|
||||
"send_log": "id queue_id domain app_login from_addr to_addr subject status created_at updated_at reason header_from domain_id refusal_line recovered",
|
||||
"send_log": "id queue_id domain app_login from_addr to_addr subject status created_at updated_at reason header_from domain_id refusal_line client_ip recovered",
|
||||
"logtail_state": "path fingerprint read_offset updated_at",
|
||||
"inbound_domains": "id name recipient_mode created_at",
|
||||
"inbound_transports": "inbound_domain_id host port tls_mode",
|
||||
|
||||
+33
-19
@@ -38,6 +38,9 @@ type SendLogEntry struct {
|
||||
// was refused (Reason*), and for ReasonFrom what its From: line said.
|
||||
Reason string
|
||||
HeaderFrom string
|
||||
// ClientIP is the client a refusal at MAIL FROM came from (InsertRejected
|
||||
// only), which Postfix's line about it names.
|
||||
ClientIP string
|
||||
}
|
||||
|
||||
// loginDomainID is the domain_id a row is written with: the domain of the
|
||||
@@ -73,9 +76,9 @@ func (s *Store) InsertRejected(e SendLogEntry) error {
|
||||
now := time.Now().UTC().Format(time.RFC3339)
|
||||
_, err := s.db.Exec(
|
||||
`INSERT INTO send_log
|
||||
(queue_id, domain, app_login, from_addr, to_addr, subject, status, reason, header_from, created_at, updated_at, domain_id)
|
||||
VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, `+loginDomainID+`)`,
|
||||
e.QueueID, e.Domain, e.AppLogin, e.From, e.To, e.Subject, StatusRejected, e.Reason, e.HeaderFrom, now, now, e.AppLogin,
|
||||
(queue_id, domain, app_login, from_addr, to_addr, subject, status, reason, header_from, client_ip, created_at, updated_at, domain_id)
|
||||
VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, `+loginDomainID+`)`,
|
||||
e.QueueID, e.Domain, e.AppLogin, e.From, e.To, e.Subject, StatusRejected, e.Reason, e.HeaderFrom, e.ClientIP, now, now, e.AppLogin,
|
||||
)
|
||||
if err != nil {
|
||||
return fmt.Errorf("insert rejected send_log: %w", err)
|
||||
@@ -113,7 +116,9 @@ func (s *Store) UpdateStatus(queueID, recipient, status string) (int64, error) {
|
||||
return 0, fmt.Errorf("update send_log status: %w", err)
|
||||
}
|
||||
defer tx.Rollback()
|
||||
const newest = `id = (SELECT MAX(id) FROM send_log WHERE queue_id = ? AND to_addr = ? COLLATE NOCASE)`
|
||||
// A refused row carries the queue id it was given, and that id may be the
|
||||
// next message's: a delivery line is never about a refusal.
|
||||
const newest = `id = (SELECT MAX(id) FROM send_log WHERE queue_id = ? AND to_addr = ? COLLATE NOCASE AND status <> 'rejected')`
|
||||
marked, err := tx.Exec(
|
||||
`UPDATE send_log SET reason = ? WHERE `+newest+` AND reason = ?`,
|
||||
ReasonReconcileContradicted, queueID, recipient, ReasonReconcile,
|
||||
@@ -235,22 +240,27 @@ type SendLogRow struct {
|
||||
|
||||
// AttachRefusalLine puts Postfix's line about a refusal at MAIL FROM on the
|
||||
// row the journal milter wrote for it (audit 2026-10-12, stage 2b). Such a
|
||||
// refusal has no queue id, so the row is found by what the line says: a
|
||||
// refused row of that sender - and login, when the line names one - without a
|
||||
// line yet, written within two minutes of the line's time; the newest when
|
||||
// there are several. It reports whether a row took the line.
|
||||
func (s *Store) AttachRefusalLine(login, from string, at time.Time, line string) (bool, error) {
|
||||
// refusal has no queue id, and the line names no login, so the row is found
|
||||
// by what the line says: a refused row of that client and sender without a
|
||||
// line yet, written within two minutes of the line's time; the nearest in
|
||||
// time, the oldest of equals, when there are several - lines are read in the
|
||||
// order the rows were written, so two refusals of one second take one line
|
||||
// each in turn (review of stage 2b). A line already on a row - read again
|
||||
// after a restart - goes on no other. It reports whether a row took the line.
|
||||
func (s *Store) AttachRefusalLine(clientIP, from string, at time.Time, line string) (bool, error) {
|
||||
res, err := s.db.Exec(
|
||||
`UPDATE send_log SET refusal_line = ? WHERE id = (
|
||||
`UPDATE send_log SET refusal_line = ?1 WHERE id = (
|
||||
SELECT id FROM send_log
|
||||
WHERE status = ? AND queue_id = '' AND refusal_line = ''
|
||||
AND reason IN ('', ?, ?) AND from_addr = ? COLLATE NOCASE
|
||||
AND (? = '' OR app_login = ?)
|
||||
AND created_at BETWEEN ? AND ?
|
||||
ORDER BY id DESC LIMIT 1)`,
|
||||
line, StatusRejected, ReasonLimit, ReasonClient, from, login, login,
|
||||
WHERE status = ?2 AND queue_id = '' AND refusal_line = ''
|
||||
AND reason IN ('', ?3, ?4) AND from_addr = ?5 COLLATE NOCASE AND client_ip = ?6
|
||||
AND created_at BETWEEN ?7 AND ?8
|
||||
ORDER BY ABS(julianday(created_at) - julianday(?9)), id
|
||||
LIMIT 1)
|
||||
AND NOT EXISTS (SELECT 1 FROM send_log WHERE refusal_line = ?1)`,
|
||||
line, StatusRejected, ReasonLimit, ReasonClient, from, clientIP,
|
||||
at.Add(-refusalLineWindow).UTC().Format(time.RFC3339),
|
||||
at.Add(refusalLineWindow).UTC().Format(time.RFC3339),
|
||||
at.UTC().Format(time.RFC3339),
|
||||
)
|
||||
if err != nil {
|
||||
return false, fmt.Errorf("attach refusal line: %w", err)
|
||||
@@ -264,16 +274,20 @@ func (s *Store) AttachRefusalLine(login, from string, at time.Time, line string)
|
||||
// wrote the row itself (audit 2026-10-12, stage 2b): the check answers 550
|
||||
// and writes the row through a buffer a moment later. The message had a queue
|
||||
// id; a refused row with that id from around at means the row was written,
|
||||
// and nothing is. It reports whether it wrote one.
|
||||
// and nothing is. The domain is the login's, or - when the tailer did not see the login, its
|
||||
// client= line read before a restart - the envelope's, so the row is still
|
||||
// its domain's administrator's (review of stage 2b). It reports whether it
|
||||
// wrote one.
|
||||
func (s *Store) RecoverRefusal(e SendLogEntry, at time.Time) (bool, error) {
|
||||
stamp := at.UTC().Format(time.RFC3339)
|
||||
res, err := s.db.Exec(
|
||||
`INSERT INTO send_log
|
||||
(queue_id, domain, app_login, from_addr, to_addr, subject, status, reason, header_from, recovered, created_at, updated_at, domain_id)
|
||||
SELECT ?, ?, ?, ?, ?, '', ?, ?, ?, 1, ?, ?, `+loginDomainID+`
|
||||
SELECT ?, ?, ?, ?, ?, '', ?, ?, ?, 1, ?, ?,
|
||||
COALESCE(`+loginDomainID+`, (SELECT d.id FROM domains d WHERE d.name = ?))
|
||||
WHERE NOT EXISTS (SELECT 1 FROM send_log
|
||||
WHERE queue_id = ? AND status = ? AND created_at BETWEEN ? AND ?)`,
|
||||
e.QueueID, e.Domain, e.AppLogin, e.From, e.To, StatusRejected, e.Reason, e.HeaderFrom, stamp, stamp, e.AppLogin,
|
||||
e.QueueID, e.Domain, e.AppLogin, e.From, e.To, StatusRejected, e.Reason, e.HeaderFrom, stamp, stamp, e.AppLogin, e.Domain,
|
||||
e.QueueID, StatusRejected,
|
||||
at.Add(-refusalLineWindow).UTC().Format(time.RFC3339), at.Add(refusalLineWindow).UTC().Format(time.RFC3339),
|
||||
)
|
||||
|
||||
@@ -273,6 +273,9 @@ func (h *Handlers) deliveryLog(row store.SendLogRow) ([]view.LogLine, string) {
|
||||
return nil, "Could not read the mail log."
|
||||
}
|
||||
}
|
||||
if len(lines) == 0 && row.Status == store.StatusRejected {
|
||||
return nil, "Postfix's lines about this refusal are not stored: the message was refused before version 2.5.1, or the lines were never read."
|
||||
}
|
||||
if len(lines) == 0 {
|
||||
return nil, "Nothing is stored for this queue id and nothing is in the current mail log. Lines are kept with the row since version 2.2.0; a message accepted before that had them only in mail.log, which has since rotated."
|
||||
}
|
||||
|
||||
@@ -162,12 +162,12 @@ func TestARefusedMessageShowsPostfixsLine(t *testing.T) {
|
||||
d, _ := st.AddDomain("example.org", "mail")
|
||||
st.AddApplication(d.ID, "alerts", store.AddressModeWildcard, nil)
|
||||
for _, subject := range []string{"with its line", "from before"} {
|
||||
if err := st.InsertRejected(store.SendLogEntry{Domain: "example.org", AppLogin: "alerts", From: "alerts@example.org", Subject: subject, Reason: store.ReasonLimit}); err != nil {
|
||||
if err := st.InsertRejected(store.SendLogEntry{Domain: "example.org", AppLogin: "alerts", From: "alerts@example.org", Subject: subject, Reason: store.ReasonLimit, ClientIP: "198.51.100.7"}); err != nil {
|
||||
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=<alerts@example.org> proto=ESMTP helo=<app>"
|
||||
if ok, err := st.AttachRefusalLine("alerts", "alerts@example.org", time.Now(), line); err != nil || !ok {
|
||||
if ok, err := st.AttachRefusalLine("198.51.100.7", "alerts@example.org", time.Now(), line); err != nil || !ok {
|
||||
t.Fatalf("attach = %v, %v", ok, err)
|
||||
}
|
||||
}
|
||||
|
||||
@@ -171,14 +171,14 @@ var outboundTopics = []HelpTopic{
|
||||
Code("From:"), " - another of your domains, the server's own name, an address somewhere else, or none at all - is refused for good with ",
|
||||
Code("550 5.7.1"), ". It is a rejected row of the Outbound log, and its page says which address was refused. This is what keeps one application from getting mail signed with another domain's key.",
|
||||
Br(), Br(),
|
||||
"The check is strict. While the panel does not answer, Postfix does not accept mail unchecked: it replies with a temporary error and the application sends again later. Server › Health counts what that costs: for how long the panel did not answer while Postfix itself was running; how many connections Postfix turned away because of it - it refuses from the connection on, before a message is offered, so a client that tries three times is three and a monitor that only connects is one; and how many messages were deferred in the middle, when the panel stopped answering after a message had begun. A time marked ≈ includes a start at which supervisord could not say since when Postfix was running: the time since the panel's last sign of life is counted, at most what Postfix was up. The card warns when a connection was turned away or a message deferred in the last 24 hours. If the numbers stay at nothing, the check is where it should be; if they do not, it belongs in a process of its own."),
|
||||
"The check is strict. While the panel does not answer, Postfix does not accept mail unchecked: it replies with a temporary error and the application sends again later. Server › Health counts what that costs: for how long the panel did not answer while Postfix itself was running; how many connections Postfix turned away because of it - it refuses from the connection on, before a message is offered, so a client that tries three times is three and a monitor that only connects is one; and how many messages were deferred in the middle, when the panel stopped answering after a message had begun. A time marked ≈ includes a start at which supervisord could not say since when Postfix was running: the time since the panel's last sign of life is counted, which may be more than Postfix was up. The card warns when a connection was turned away or a message deferred in the last 24 hours. If the numbers stay at nothing, the check is where it should be; if they do not, it belongs in a process of its own."),
|
||||
}},
|
||||
{ID: HelpLimits, Title: "Rate limits", Body: []Text{
|
||||
Rich("Level 1 is a per-IP ceiling set in ", Code(".env"), ". Level 2 is optional, per domain and per application, entered by hand or computed from the last 30 days of sending, and can never exceed level 1. An application's own limit replaces its domain's."),
|
||||
}},
|
||||
{ID: HelpLog, Title: "Outbound log", Body: []Text{
|
||||
Rich("One row per message and recipient, with the status Postfix last reported: queued (accepted, nothing reported yet), sent (the receiving server took it; what the mailbox does next is not reported back), deferred (not taken yet, Postfix tries again), bounced (failed for good, or the queue lifetime ran out; or closed by the panel when Postfix no longer held the message and ", Code("mail.log"), " never said what became of it) and rejected (refused before queueing, so it never reached the queue: under a level-2 rate limit, from a client address the application does not allow, or for a ", Code("From:"), " line that is not the application's - the message's page says which). A message's page lists these steps and the lines Postfix wrote about it in ",
|
||||
Code("mail.log"), ", found by queue id. The lines are kept with the row: they stay on the page after that file has rotated, for as long as the row does. A message accepted before version 2.2.0 shows them only while they are still in the current file. Rows are deleted after the retention set in Server › Settings, 90 days by default, and their lines with them. A domain administrator sees only the rows of their own domains."),
|
||||
Code("mail.log"), ", found by queue id - and for a message refused before it had one, Postfix's one line about the refusal. The lines are kept with the row: they stay on the page after that file has rotated, for as long as the row does. A message accepted before version 2.2.0 shows them only while they are still in the current file. Rows are deleted after the retention set in Server › Settings, 90 days by default, and their lines with them. A domain administrator sees only the rows of their own domains."),
|
||||
}},
|
||||
{ID: HelpQueue, Title: "Queue and retries", Body: []Text{
|
||||
Rich("The page lists, as ", Code("postqueue -p"), " prints it, the messages Postfix has accepted and not yet delivered: mail being sent right now and mail deferred for a later attempt. Only the global role can open it, and it only shows; nothing here deletes or forces a message. A deferred message is tried again after the first retry delay, then at gaps that double up to a cap, until the receiving server takes it or the queue lifetime runs out and it bounces; there is no attempt counter, and the box on the page shows this server's values. A queue that keeps growing means a receiver is refusing or not answering: open the message from the Outbound log to read the reason Postfix logged."),
|
||||
|
||||
@@ -265,7 +265,7 @@ func NewOutMessage(m Meta, in MessageInput) *OutMessage {
|
||||
facts = append(facts, Fact{Label: "Written", Value: Rich("from ", Code("mail.log"), " after a restart: the panel stopped before it wrote the refusal")})
|
||||
}
|
||||
if in.QueueID != "" {
|
||||
facts = append(facts, Fact{Label: "Queue id", Value: Rich(Mono(in.QueueID), " — given, the message was not queued")})
|
||||
facts = append(facts, Fact{Label: "Queue id", Value: Rich(Mono(in.QueueID), " - given, the message was not queued")})
|
||||
} else {
|
||||
facts = append(facts, Fact{Label: "Queue id", Value: Rich("none - refused at ", Mono("MAIL FROM"), ", before one is given")})
|
||||
delivery.End = Rich("The line from ", Code("mail.log"), " for this refusal")
|
||||
|
||||
@@ -144,7 +144,7 @@ func TestOutMessageRefusedForItsFromLine(t *testing.T) {
|
||||
out := renderSignedIn(t, "out-message", p)
|
||||
pageHas(t, "Message", out, `<span class="tag is-danger is-light">wrong From</span>`,
|
||||
`<dt>From: line</dt><dd class="sp-mono sp-small">director@example.org</dd>`, `<dt>Refused</dt>`,
|
||||
`<span class="sp-mono">7BCAF3C75DA0</span> — given, the message was not queued`, `href="/help#sender-check"`,
|
||||
`<span class="sp-mono">7BCAF3C75DA0</span> - given, the message was not queued`, `href="/help#sender-check"`,
|
||||
`Lines from <code>mail.log</code> with this queue id`, `<span class="sp-e">postfix/cleanup[2120]: 7BCAF3C75DA0: milter-reject`)
|
||||
}
|
||||
|
||||
|
||||
@@ -349,10 +349,18 @@ func testRefusalsShowPostfixsLine(t *testing.T, sc *scenario) {
|
||||
rowRe := regexp.MustCompile(`(?s)<tr>.*?</tr>`)
|
||||
tagRe := regexp.MustCompile(`<span class="tag[^"]*">(wrong From|rate-limited|wrong client)</span>`)
|
||||
linkRe := regexp.MustCompile(`href="(/outbound/log/\d+)[^"]*"`)
|
||||
// Each with the refusal's own sender in Postfix's line: the line of one
|
||||
// application's refusal must not land on another's row (review of
|
||||
// stage 2b; the rate-limited refusals are l2app's, from billing@).
|
||||
want := map[string]string{
|
||||
"wrong From": "milter-reject: END-OF-MESSAGE",
|
||||
"rate-limited": "NOQUEUE: milter-reject: MAIL from",
|
||||
"wrong client": "NOQUEUE: milter-reject: MAIL from",
|
||||
"rate-limited": "NOQUEUE: milter-reject: MAIL from unknown[",
|
||||
"wrong client": "NOQUEUE: milter-reject: MAIL from unknown[",
|
||||
}
|
||||
sender := map[string]string{
|
||||
"wrong From": "",
|
||||
"rate-limited": "from=<billing@" + senderDomain + ">",
|
||||
"wrong client": "from=<alerts@" + senderDomain + ">",
|
||||
}
|
||||
for tag, line := range want {
|
||||
if err := waitFor("the page of a "+tag+" refusal to show Postfix's line", 30*time.Second, time.Second, func() (bool, error) {
|
||||
@@ -370,7 +378,7 @@ func testRefusalsShowPostfixsLine(t *testing.T, sc *scenario) {
|
||||
if err != nil {
|
||||
return false, err
|
||||
}
|
||||
if strings.Contains(page, line) {
|
||||
if strings.Contains(page, line) && strings.Contains(page, sender[tag]) {
|
||||
return true, nil
|
||||
}
|
||||
}
|
||||
@@ -397,6 +405,14 @@ func asPanel(code string, args ...string) (string, error) {
|
||||
// saved place moved back before the message's first line. Started again, the
|
||||
// panel writes the row from mail.log, marked, and once.
|
||||
func testRefusalRecoveredFromTheLog(t *testing.T, sc *scenario) {
|
||||
// A refusal whose row the panel writes as usual: it must not get a second
|
||||
// row from the log once the wait is over.
|
||||
written := uniqueToken("written")
|
||||
if res := attemptSend(sendAttempt{authLogin: sc.appLogin, authPassword: sc.appPassword,
|
||||
from: "alerts@" + senderDomain, headerFrom: "director@" + otherDomain, to: recipient,
|
||||
subject: "e2e " + written, body: "refused, its row written"}); res.refusedAt("DATA", 550, "5.7.1 From:") != nil {
|
||||
t.Fatalf("the written refusal: %v", res.firstErr())
|
||||
}
|
||||
token := uniqueToken("recover")
|
||||
res := attemptSend(sendAttempt{authLogin: sc.appLogin, authPassword: sc.appPassword,
|
||||
from: "alerts@" + senderDomain, headerFrom: "director@" + otherDomain, to: recipient,
|
||||
@@ -454,9 +470,16 @@ print(sqlite3.connect("/data/selfpost.db").execute("select count(*), coalesce(su
|
||||
}); err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
// Once: the next passes over the log write it no more.
|
||||
time.Sleep(3 * time.Second)
|
||||
// Once: past another wait of the tailer's (30 s), the passes over the log
|
||||
// write it no more, and the refusal the panel wrote itself is still one
|
||||
// row, not recovered.
|
||||
time.Sleep(35 * time.Second)
|
||||
if out, _ := count(); out != "(1, 1)" {
|
||||
t.Fatalf("after more passes the rows are %s, want (1, 1)", out)
|
||||
}
|
||||
out, err := asPanel(`import sqlite3,sys
|
||||
print(sqlite3.connect("/data/selfpost.db").execute("select count(*), coalesce(sum(recovered),0) from send_log where subject like ?",("%"+sys.argv[1]+"%",)).fetchone())`, written)
|
||||
if err != nil || out != "(1, 0)" {
|
||||
t.Fatalf("the refusal the panel wrote: rows (count, recovered) = %s, %v; want (1, 0)", out, err)
|
||||
}
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user