test / test (push) Canceled after 0s
The sender check answers 550 5.7.1 and writes the refused row through a
buffer a moment later; a panel stopped in between (a rollout, a kill) left
an application refused and a log that did not know it. A refusal at MAIL
FROM needs nothing: the journal milter writes its row before it answers.
- logtail.refusalLines remembers each queue id's login from smtpd's
"<id>: client=..., sasl_username=<login>" (4096 ids at most) and, on
cleanup's "<id>: milter-reject: END-OF-MESSAGE ...: 5.7.1 From: <line> -
<why>; from=<...> to=<...>", waits 30 s and hands it to
store.RecoverRefusal - an INSERT ... WHERE NOT EXISTS a refused row of that
queue id within two minutes: the row the panel wrote, or one recovered
before, means nothing is written. It is read from the saved offset on, so
a kill is covered as well as a clean stop - which a flush of the buffer at
shutdown would not.
- Migration 0009 (not deployed yet) gains send_log.recovered; the row is
written with the line's time, the login's domain id, reason "from", the
From: line as the check printed it (to the last " - " before ";").
- The message page: a fact "Written: from mail.log after a restart: the
panel stopped before it wrote the refusal".
Tests: store (not written when the panel wrote it; written once however
often); logtail (the login from client=, the From: line with a " - " in it,
nothing before the wait is over); view (the fact). e2e
refusal_recovered_from_the_log: a From: refusal, the panel stopped, its row
deleted and the tailer's saved place moved before the message's first line
(python3 in the container, as the panel's user - a kill cannot be timed to
that moment from outside); started again, the row is back, recovered, once.
Also fixed: handlers TestMessagePageOfARefusedMessage still expected the
old sentence; it failed on the server after e166a2e, whose run showed only
the schema failures - now it wants the new one.
schema-migrations row 9, CHANGELOG [Unreleased], audit plan line ticked,
roadmap 26/62.
Evidence on the test server for this tree but the handler-test fix: make e2e
exit 0 (the new case 37 s); go test 22/23 ok, the 23rd that test - fixed,
passes locally; the full run follows before the push.
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
116 lines
4.3 KiB
Go
116 lines
4.3 KiB
Go
package store
|
|
|
|
import (
|
|
"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).
|
|
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},
|
|
} {
|
|
if err := st.InsertRejected(e); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
}
|
|
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)
|
|
}
|
|
// 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 {
|
|
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")
|
|
}
|
|
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)
|
|
}
|
|
}
|
|
}
|
|
if got != 1 {
|
|
t.Fatalf("%d rows have a line, want 1", got)
|
|
}
|
|
}
|
|
|
|
// A refused message's lines are those of a few minutes around the refusal:
|
|
// its queue id was freed at once, and a later message with the same id lends
|
|
// it nothing.
|
|
func TestSendLogLinesOfARefusalAreItsOwn(t *testing.T) {
|
|
st := openTestStore(t)
|
|
if err := st.InsertRejected(SendLogEntry{QueueID: "7BCAF3C75DA0", AppLogin: "shop", From: "shop@shop.example", Reason: ReasonFrom}); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
now := time.Now().UTC()
|
|
if _, err := st.InsertSendLogLines([]SendLogLine{
|
|
{QueueID: "7BCAF3C75DA0", At: now.Add(-time.Second), Line: "its own refusal"},
|
|
{QueueID: "7BCAF3C75DA0", At: now.Add(20 * time.Minute), Line: "a later message with the id"},
|
|
}, false); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
rows, _ := st.QuerySendLog(SendLogFilter{AllDomains: true}, 1, 0)
|
|
lines, err := st.SendLogLines(rows[0], 5*24*time.Hour, 10)
|
|
if err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
if len(lines) != 1 || lines[0].Line != "its own refusal" {
|
|
t.Fatalf("lines = %+v, want its own alone", lines)
|
|
}
|
|
}
|
|
|
|
// A From: refusal's row is written from the log only when the panel wrote
|
|
// none for that queue id about then; once, however often the line is read.
|
|
func TestRecoverRefusal(t *testing.T) {
|
|
st := openTestStore(t)
|
|
d := addTestDomain(t, st, "sender.example")
|
|
if _, err := st.AddApplication(d.ID, "app1", AddressModeWildcard, nil); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
now := time.Now().UTC()
|
|
// The panel wrote this one itself.
|
|
if err := st.InsertRejected(SendLogEntry{QueueID: "WRITTEN", AppLogin: "app1", From: "a@sender.example", Reason: ReasonFrom}); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
e := SendLogEntry{QueueID: "WRITTEN", AppLogin: "app1", From: "a@sender.example", To: "r@x", Domain: "sender.example", Reason: ReasonFrom, HeaderFrom: "x@y"}
|
|
if wrote, err := st.RecoverRefusal(e, now); err != nil || wrote {
|
|
t.Fatalf("a refusal the panel wrote was written again: %v, %v", wrote, err)
|
|
}
|
|
e.QueueID = "LOST"
|
|
for i := 0; i < 2; i++ {
|
|
wrote, err := st.RecoverRefusal(e, now)
|
|
if err != nil || wrote != (i == 0) {
|
|
t.Fatalf("recovery %d: wrote %v, %v", i, wrote, err)
|
|
}
|
|
}
|
|
rows, _ := st.QuerySendLog(SendLogFilter{DomainIDs: []int64{d.ID}}, 10, 0)
|
|
var found SendLogRow
|
|
for _, r := range rows {
|
|
if r.QueueID == "LOST" {
|
|
found, _ = st.GetSendLog(r.ID)
|
|
}
|
|
}
|
|
if !found.Recovered || found.Status != StatusRejected || found.Reason != ReasonFrom || found.HeaderFrom != "x@y" || found.DomainID != d.ID {
|
|
t.Fatalf("the recovered row: %+v", found)
|
|
}
|
|
}
|