Compare commits
2
Commits
| Author | SHA1 | Date | |
|---|---|---|---|
|
|
65d916f26a | ||
|
|
e166a2ebd6 |
@@ -22,6 +22,25 @@ Format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/); version
|
|||||||
`mail.log` stamps whole seconds, so a second warning of that second was
|
`mail.log` stamps whole seconds, so a second warning of that second was
|
||||||
passed over too. It now remembers the place in the log, saved with the
|
passed over too. It now remembers the place in the log, saved with the
|
||||||
count in one transaction (audit 2026-10-12, stage 2b).
|
count in one transaction (audit 2026-10-12, stage 2b).
|
||||||
|
- **A refused message's page shows what Postfix wrote.** Its Delivery log
|
||||||
|
box said Postfix wrote nothing about it, which was untrue. A message
|
||||||
|
refused for its `From:` line had a queue id, given before its headers were
|
||||||
|
judged; the row now keeps it and the page shows the message's lines, the
|
||||||
|
refusal among them - only those of the minutes around the refusal, since
|
||||||
|
Postfix frees the id at once. A message refused at `MAIL FROM` (a level-2
|
||||||
|
limit, a client address off the list) has no queue id; the log tailer puts
|
||||||
|
Postfix's `NOQUEUE: milter-reject` line on its row (migration `0009`) and
|
||||||
|
the page shows it. A row refused before this says the line was not kept.
|
||||||
|
A refusal's line is red for a permanent reply, amber for a temporary one
|
||||||
|
(audit 2026-10-12, stage 2b).
|
||||||
|
- **A refusal the panel did not get to write is written from the log.** The
|
||||||
|
sender check answers 550 and writes the row a moment later; a panel that
|
||||||
|
stopped in between - a rollout, a crash - left an application refused and
|
||||||
|
a log that did not know it. When the log tailer reads cleanup's refusal
|
||||||
|
line and, after giving the panel half a minute, finds no row for that
|
||||||
|
queue id, it writes the row from the line, marked on its page as written
|
||||||
|
from `mail.log` after a restart. A refusal at `MAIL FROM` needs no such
|
||||||
|
thing: its row is written before Postfix is answered.
|
||||||
|
|
||||||
## [2.5.0] - 2026-10-14
|
## [2.5.0] - 2026-10-14
|
||||||
|
|
||||||
|
|||||||
@@ -764,7 +764,7 @@ order - each stands on the one before.
|
|||||||
place must stay true across a rotated file. A test that stops the tailer
|
place must stay true across a rotated file. A test that stops the tailer
|
||||||
between two warnings of one second and finds both counted, once each.
|
between two warnings of one second and finds both counted, once each.
|
||||||
- **Opus**
|
- **Opus**
|
||||||
- [ ] **A refused message's page shows what Postfix wrote** (owner,
|
- [x] **A refused message's page shows what Postfix wrote** (owner,
|
||||||
2026-10-13: "the log box is required" - the box is the reason
|
2026-10-13: "the log box is required" - the box is the reason
|
||||||
delivery-log-storage was built, and its absence from the picture he
|
delivery-log-storage was built, and its absence from the picture he
|
||||||
approved for 2.4.0 was an oversight, not a decision). Today every
|
approved for 2.4.0 was an oversight, not a decision). Today every
|
||||||
@@ -793,7 +793,7 @@ order - each stands on the one before.
|
|||||||
`mail.log` never said what became of it, so the panel closed it as a
|
`mail.log` never said what became of it, so the panel closed it as a
|
||||||
failure. Wording in the mockup `out-message` first (`design:` commit),
|
failure. Wording in the mockup `out-message` first (`design:` commit),
|
||||||
with the box of the step above. - **Sonnet**
|
with the box of the step above. - **Sonnet**
|
||||||
- [ ] **A refusal the panel did not get to write is written from
|
- [x] **A refusal the panel did not get to write is written from
|
||||||
`mail.log`** (owner, 2026-10-13, from the Not done list of
|
`mail.log`** (owner, 2026-10-13, from the Not done list of
|
||||||
from-header-binding; built on the step above). The check answers 550 and
|
from-header-binding; built on the step above). The check answers 550 and
|
||||||
writes the row a moment later, through a buffer; a panel that stops in
|
writes the row a moment later, through a buffer; a panel that stops in
|
||||||
|
|||||||
+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) |
|
| 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) |
|
| 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) |
|
| 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`) | 24/62 | [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`) | 26/62 | [audit-2026-10-12.md](audit-2026-10-12.md) |
|
||||||
|
|
||||||
**Recommended order** (not binding; owner, 2026-10-09: feature order follows
|
**Recommended order** (not binding; owner, 2026-10-09: feature order follows
|
||||||
development convenience): **panel-redesign** shipped as `2.0.0` (2026-10-11) and
|
development convenience): **panel-redesign** shipped as `2.0.0` (2026-10-11) and
|
||||||
|
|||||||
@@ -17,8 +17,8 @@ When you add or review a migration, update this file in the same change.
|
|||||||
|
|
||||||
| Field | Value |
|
| Field | Value |
|
||||||
|---|---|
|
|---|---|
|
||||||
| Chain head | `user_version = 8` |
|
| Chain head | `user_version = 9` |
|
||||||
| Files | `0001_init.sql` (the 2.0 baseline), `0002_inbound_spam_log.sql`, `0003_send_log_lines.sql`, `0004_notifications.sql`, `0005_send_log_rejected_index.sql`, `0006_sender_check.sql`, `0007_delivery_log_days.sql`, `0008_tenant_boundary.sql` |
|
| Files | `0001_init.sql` (the 2.0 baseline), `0002_inbound_spam_log.sql`, `0003_send_log_lines.sql`, `0004_notifications.sql`, `0005_send_log_rejected_index.sql`, `0006_sender_check.sql`, `0007_delivery_log_days.sql`, `0008_tenant_boundary.sql`, `0009_refusal_line.sql` |
|
||||||
| File mark | `PRAGMA application_id = 0x53503230` ("SP20") |
|
| File mark | `PRAGMA application_id = 0x53503230` ("SP20") |
|
||||||
| Database file | `/data/selfpost.db` (bind mount) |
|
| Database file | `/data/selfpost.db` (bind mount) |
|
||||||
| Compatibility | 2.x MINOR releases must boot a `2.0.0` data directory. **Nothing is carried over from 1.x.** |
|
| Compatibility | 2.x MINOR releases must boot a `2.0.0` data directory. **Nothing is carried over from 1.x.** |
|
||||||
@@ -83,6 +83,7 @@ audit (`2.5.0`).
|
|||||||
| 6 | `0006_sender_check.sql` | 2.4.0 | DDL | `send_log.reason` and `send_log.header_from` (both default `''`: a row refused earlier keeps no reason), and `sender_check_days` |
|
| 6 | `0006_sender_check.sql` | 2.4.0 | DDL | `send_log.reason` and `send_log.header_from` (both default `''`: a row refused earlier keeps no reason), and `sender_check_days` |
|
||||||
| 7 | `0007_delivery_log_days.sql` | 2.5.0 | DDL | `delivery_log_days`: what the reconcile sweep and the log tailer did, a row per UTC day, kept a year, shown nowhere - the measurement that decides the sweep's fate (audit 2026-10-12, stage 1). `send_log.reason` gains the values `reconcile` and `reconcile-contradicted` without a schema change |
|
| 7 | `0007_delivery_log_days.sql` | 2.5.0 | DDL | `delivery_log_days`: what the reconcile sweep and the log tailer did, a row per UTC day, kept a year, shown nowhere - the measurement that decides the sweep's fate (audit 2026-10-12, stage 1). `send_log.reason` gains the values `reconcile` and `reconcile-contradicted` without a schema change |
|
||||||
| 8 | `0008_tenant_boundary.sql` | 2.5.0 | DDL + data | `idx_applications_login_nocase`: an application login is unique without regard to case (audit 2026-10-12, H4). `send_log.domain_id` and `inbound_spam_log.inbound_domain_id` (`ON DELETE SET NULL`), each with an index, filled once by name from the registry as it was then: a row belongs to a domain by id, and a domain deleted and added again starts with an empty log (L12) |
|
| 8 | `0008_tenant_boundary.sql` | 2.5.0 | DDL + data | `idx_applications_login_nocase`: an application login is unique without regard to case (audit 2026-10-12, H4). `send_log.domain_id` and `inbound_spam_log.inbound_domain_id` (`ON DELETE SET NULL`), each with an index, filled once by name from the registry as it was then: a row belongs to a domain by id, and a domain deleted and added again starts with an empty log (L12) |
|
||||||
|
| 9 | `0009_refusal_line.sql` | 2.5.1 | DDL | `send_log.refusal_line`: Postfix's line about a refusal at MAIL FROM (a level-2 limit, a client address off the list), which has no queue id; the log tailer puts it on the row; and `send_log.recovered`, a refusal row the tailer wrote from `mail.log` because the panel stopped before writing it (audit 2026-10-12, stage 2b) |
|
||||||
|
|
||||||
**Kind:** *DDL* — schema only; *data* — `INSERT`/`UPDATE` that must stay correct
|
**Kind:** *DDL* — schema only; *data* — `INSERT`/`UPDATE` that must stay correct
|
||||||
for operators upgrading from older 2.x images.
|
for operators upgrading from older 2.x images.
|
||||||
|
|||||||
@@ -39,6 +39,7 @@ type StatusStore interface {
|
|||||||
CountQueuedOlderThan(cutoff time.Time) (int64, error)
|
CountQueuedOlderThan(cutoff time.Time) (int64, error)
|
||||||
SetQueuedOverLifetime(at time.Time, n int64) error
|
SetQueuedOverLifetime(at time.Time, n int64) error
|
||||||
PruneDeliveryLogDays(now time.Time) error
|
PruneDeliveryLogDays(now time.Time) error
|
||||||
|
RefusalStore
|
||||||
DeleteSendLogBefore(cutoff time.Time) (int64, error)
|
DeleteSendLogBefore(cutoff time.Time) (int64, error)
|
||||||
InsertSendLogLines(lines []store.SendLogLine, once bool) (int, error)
|
InsertSendLogLines(lines []store.SendLogLine, once bool) (int, error)
|
||||||
PruneSendLogLines(cutoff time.Time) (int64, error)
|
PruneSendLogLines(cutoff time.Time) (int64, error)
|
||||||
@@ -162,8 +163,13 @@ func Run(ctx context.Context, path string, st StatusStore, retention RetentionDa
|
|||||||
}
|
}
|
||||||
|
|
||||||
keeper := newLineKeeper(st)
|
keeper := newLineKeeper(st)
|
||||||
|
refusals := &refusalLines{st: st}
|
||||||
|
flush := func() {
|
||||||
|
keeper.flush()
|
||||||
|
refusals.retry(time.Now().UTC())
|
||||||
|
}
|
||||||
tr := &tracker{st: st, path: path}
|
tr := &tracker{st: st, path: path}
|
||||||
return follow(ctx, path, tr, caughtUp, keeper.flush, func(line string) {
|
return follow(ctx, path, tr, caughtUp, flush, func(line string) {
|
||||||
// Until the first read reaches end-of-file the lines are those written
|
// 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
|
// while the panel was down - and, after an unclean stop, some it had
|
||||||
// read already.
|
// read already.
|
||||||
@@ -181,6 +187,7 @@ func Run(ctx context.Context, path string, st StatusStore, retention RetentionDa
|
|||||||
deferred.handle(line, now, catchingUp, tr.line)
|
deferred.handle(line, now, catchingUp, tr.line)
|
||||||
}
|
}
|
||||||
keeper.add(line, now, catchingUp)
|
keeper.add(line, now, catchingUp)
|
||||||
|
refusals.handle(line, now)
|
||||||
queueID, recipient, status, ok := parseDelivery(line)
|
queueID, recipient, status, ok := parseDelivery(line)
|
||||||
if !ok {
|
if !ok {
|
||||||
return
|
return
|
||||||
|
|||||||
@@ -283,6 +283,10 @@ func (c *captureStore) AddReconcileMissed(_ time.Time, n int64) error {
|
|||||||
return nil
|
return nil
|
||||||
}
|
}
|
||||||
func (c *captureStore) AddTailerBlind(time.Time, time.Duration) error { return nil }
|
func (c *captureStore) AddTailerBlind(time.Time, time.Duration) error { return nil }
|
||||||
|
func (c *captureStore) AttachRefusalLine(string, string, time.Time, string) (bool, error) {
|
||||||
|
return true, nil
|
||||||
|
}
|
||||||
|
func (c *captureStore) RecoverRefusal(store.SendLogEntry, time.Time) (bool, error) { return false, nil }
|
||||||
func (c *captureStore) CountQueuedOlderThan(time.Time) (int64, error) {
|
func (c *captureStore) CountQueuedOlderThan(time.Time) (int64, error) {
|
||||||
c.mu.Lock()
|
c.mu.Lock()
|
||||||
defer c.mu.Unlock()
|
defer c.mu.Unlock()
|
||||||
|
|||||||
@@ -0,0 +1,159 @@
|
|||||||
|
package logtail
|
||||||
|
|
||||||
|
import (
|
||||||
|
"log"
|
||||||
|
"regexp"
|
||||||
|
"strings"
|
||||||
|
"time"
|
||||||
|
|
||||||
|
"github.com/mixeme/selfpost/internal/store"
|
||||||
|
)
|
||||||
|
|
||||||
|
// 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:
|
||||||
|
//
|
||||||
|
// 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]*)>?)?`)
|
||||||
|
|
||||||
|
// 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.
|
||||||
|
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)
|
||||||
|
RecoverRefusal(e store.SendLogEntry, at time.Time) (bool, error)
|
||||||
|
}
|
||||||
|
|
||||||
|
// fromRefusalRe is cleanup's line about a message the sender check refused
|
||||||
|
// for its From: line, as the stand writes it:
|
||||||
|
//
|
||||||
|
// 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=<([^>]*)>`)
|
||||||
|
|
||||||
|
// clientLoginRe is smtpd's line naming the login a queue id was submitted
|
||||||
|
// under: "<id>: client=host[addr], sasl_method=PLAIN, sasl_username=<login>".
|
||||||
|
var clientLoginRe = regexp.MustCompile(`^\S+ postfix/(?:([a-z0-9-]+)/)?smtpd\[\d+\]: ([0-9A-Za-z]+): client=.*?, sasl_username=(\S+)`)
|
||||||
|
|
||||||
|
// refusalLogins bounds the queue ids whose login is remembered.
|
||||||
|
const refusalLogins = 4096
|
||||||
|
|
||||||
|
type pendingRefusal struct {
|
||||||
|
login, from, line string
|
||||||
|
at, until time.Time
|
||||||
|
}
|
||||||
|
|
||||||
|
// pendingRecovery is a From: refusal whose row is looked for once the panel
|
||||||
|
// has had the time to write it.
|
||||||
|
type pendingRecovery struct {
|
||||||
|
e store.SendLogEntry
|
||||||
|
at, until time.Time
|
||||||
|
}
|
||||||
|
|
||||||
|
// refusalLines puts each refusal line on its row, and keeps for a while the
|
||||||
|
// lines whose row is not there yet. It also writes, from cleanup's line, the
|
||||||
|
// row of a From: refusal the panel did not get to write.
|
||||||
|
type refusalLines struct {
|
||||||
|
st RefusalStore
|
||||||
|
pending []pendingRefusal
|
||||||
|
recover []pendingRecovery
|
||||||
|
logins map[string]string // 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) {
|
||||||
|
at, rest := lineTime(line, now)
|
||||||
|
if m := clientLoginRe.FindStringSubmatch(rest); m != nil && m[1] != "inbound" {
|
||||||
|
r.remember(m[2], m[3])
|
||||||
|
return
|
||||||
|
}
|
||||||
|
if m := fromRefusalRe.FindStringSubmatch(rest); m != nil {
|
||||||
|
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]),
|
||||||
|
Reason: store.ReasonFrom, HeaderFrom: m[2],
|
||||||
|
},
|
||||||
|
at: at, until: now.Add(refusalLineWait),
|
||||||
|
})
|
||||||
|
return
|
||||||
|
}
|
||||||
|
m := refusalLineRe.FindStringSubmatch(rest)
|
||||||
|
if m == nil || m[1] == "inbound" {
|
||||||
|
return
|
||||||
|
}
|
||||||
|
p := pendingRefusal{login: m[3], from: m[2], line: line, at: at, until: now.Add(refusalLineWait)}
|
||||||
|
if !r.attach(p) {
|
||||||
|
r.pending = append(r.pending, p)
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
||||||
|
// retry tries the waiting lines again and lets go of those that waited long
|
||||||
|
// enough; and writes, once their wait is over, the rows of From: refusals the
|
||||||
|
// panel did not write.
|
||||||
|
func (r *refusalLines) retry(now time.Time) {
|
||||||
|
kept := r.pending[:0]
|
||||||
|
for _, p := range r.pending {
|
||||||
|
if r.attach(p) || now.After(p.until) {
|
||||||
|
continue
|
||||||
|
}
|
||||||
|
kept = append(kept, p)
|
||||||
|
}
|
||||||
|
r.pending = kept
|
||||||
|
|
||||||
|
waiting := r.recover[:0]
|
||||||
|
for _, p := range r.recover {
|
||||||
|
if !now.After(p.until) {
|
||||||
|
waiting = append(waiting, p)
|
||||||
|
continue
|
||||||
|
}
|
||||||
|
wrote, err := r.st.RecoverRefusal(p.e, p.at)
|
||||||
|
if err != nil {
|
||||||
|
log.Printf("log-tailer: recover refusal: %v", err)
|
||||||
|
} else if wrote {
|
||||||
|
log.Printf("log-tailer: wrote the refusal of %s (%s) from mail.log: the panel had not written it", p.e.QueueID, p.e.From)
|
||||||
|
}
|
||||||
|
}
|
||||||
|
r.recover = waiting
|
||||||
|
}
|
||||||
|
|
||||||
|
// remember keeps the login a queue id was submitted under, the oldest going
|
||||||
|
// first beyond refusalLogins.
|
||||||
|
func (r *refusalLines) remember(queueID, login string) {
|
||||||
|
if r.logins == nil {
|
||||||
|
r.logins = make(map[string]string)
|
||||||
|
}
|
||||||
|
if _, ok := r.logins[queueID]; !ok {
|
||||||
|
r.loginKeys = append(r.loginKeys, queueID)
|
||||||
|
if len(r.loginKeys) > refusalLogins {
|
||||||
|
delete(r.logins, r.loginKeys[0])
|
||||||
|
r.loginKeys = r.loginKeys[1:]
|
||||||
|
}
|
||||||
|
}
|
||||||
|
r.logins[queueID] = login
|
||||||
|
}
|
||||||
|
|
||||||
|
// domainOf is the domain of an address, lower-cased; "" without one.
|
||||||
|
func domainOf(addr string) string {
|
||||||
|
if i := strings.LastIndexByte(addr, '@'); i >= 0 {
|
||||||
|
return strings.ToLower(addr[i+1:])
|
||||||
|
}
|
||||||
|
return ""
|
||||||
|
}
|
||||||
|
|
||||||
|
func (r *refusalLines) attach(p pendingRefusal) bool {
|
||||||
|
ok, err := r.st.AttachRefusalLine(p.login, 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
|
||||||
|
}
|
||||||
|
return ok
|
||||||
|
}
|
||||||
@@ -0,0 +1,92 @@
|
|||||||
|
package logtail
|
||||||
|
|
||||||
|
import (
|
||||||
|
"testing"
|
||||||
|
"time"
|
||||||
|
|
||||||
|
"github.com/mixeme/selfpost/internal/store"
|
||||||
|
)
|
||||||
|
|
||||||
|
type refusalProbe struct {
|
||||||
|
rows int // rows waiting for a line
|
||||||
|
lines []string
|
||||||
|
who []string
|
||||||
|
recovered []store.SendLogEntry
|
||||||
|
}
|
||||||
|
|
||||||
|
func (r *refusalProbe) RecoverRefusal(e store.SendLogEntry, _ time.Time) (bool, error) {
|
||||||
|
r.recovered = append(r.recovered, e)
|
||||||
|
return true, nil
|
||||||
|
}
|
||||||
|
|
||||||
|
func (r *refusalProbe) AttachRefusalLine(login, 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)
|
||||||
|
return true, nil
|
||||||
|
}
|
||||||
|
|
||||||
|
// 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
|
||||||
|
// lines are not refusals of an application.
|
||||||
|
func TestRefusalLines(t *testing.T) {
|
||||||
|
now := time.Date(2026, 10, 14, 12, 0, 0, 0, time.UTC)
|
||||||
|
st := &refusalProbe{}
|
||||||
|
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>`
|
||||||
|
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>`,
|
||||||
|
`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)
|
||||||
|
}
|
||||||
|
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
|
||||||
|
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" {
|
||||||
|
t.Fatalf("after the retry: pending %d, attached %v", len(r.pending), st.who)
|
||||||
|
}
|
||||||
|
|
||||||
|
r.handle(limit, now) // 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")
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
||||||
|
// cleanup's line about a From: refusal is the row's, written by the panel; once
|
||||||
|
// the panel has had the time to, the line is handed to RecoverRefusal, which
|
||||||
|
// writes the row only if it is missing - with the login smtpd named for the
|
||||||
|
// queue id, the sender, the recipient and the From: line as printed.
|
||||||
|
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.retry(now.Add(time.Second))
|
||||||
|
if len(st.recovered) != 0 {
|
||||||
|
t.Fatal("recovered before the panel had the time to write the row")
|
||||||
|
}
|
||||||
|
r.retry(now.Add(refusalLineWait + time.Second))
|
||||||
|
if len(st.recovered) != 1 {
|
||||||
|
t.Fatalf("recovered %d, want 1", len(st.recovered))
|
||||||
|
}
|
||||||
|
e := st.recovered[0]
|
||||||
|
want := store.SendLogEntry{QueueID: "E543D3C75DA0", AppLogin: "app1", From: "alerts@sender.e2e.test", To: "rcpt@sink.e2e.test",
|
||||||
|
Domain: "sender.e2e.test", Reason: store.ReasonFrom, HeaderFrom: `"The - Shop" <director@other.e2e.test>`}
|
||||||
|
if e != want {
|
||||||
|
t.Fatalf("recovered %+v, want %+v", e, want)
|
||||||
|
}
|
||||||
|
}
|
||||||
@@ -98,3 +98,11 @@ func TestRetentionLoopUsesUpdatedValue(t *testing.T) {
|
|||||||
age := time.Since(st.lastCutoff())
|
age := time.Since(st.lastCutoff())
|
||||||
t.Fatalf("second prune cutoff age %v, want about 7 days", age)
|
t.Fatalf("second prune cutoff age %v, want about 7 days", age)
|
||||||
}
|
}
|
||||||
|
|
||||||
|
func (s *retentionProbeStore) AttachRefusalLine(string, string, time.Time, string) (bool, error) {
|
||||||
|
return true, nil
|
||||||
|
}
|
||||||
|
|
||||||
|
func (s *retentionProbeStore) RecoverRefusal(store.SendLogEntry, time.Time) (bool, error) {
|
||||||
|
return false, nil
|
||||||
|
}
|
||||||
|
|||||||
@@ -268,7 +268,10 @@ func (s *senderSession) Headers(h textproto.MIMEHeader, m *milter.Modifier) (mil
|
|||||||
return milter.RespContinue, nil
|
return milter.RespContinue, nil
|
||||||
}
|
}
|
||||||
log.Printf("sender-check: application %q refused: %s (From: %s)", s.login, why, shown)
|
log.Printf("sender-check: application %q refused: %s (From: %s)", s.login, why, shown)
|
||||||
s.record(shown)
|
// cleanup has given the message a queue id by the end of its headers
|
||||||
|
// (milter_end_of_header_macros has {i}); Postfix's lines about it - the
|
||||||
|
// refusal among them - are found by it on the message's page.
|
||||||
|
s.record(shown, macro(m, "i"))
|
||||||
// A reply code of its own, so that the application is told what is wrong
|
// A reply code of its own, so that the application is told what is wrong
|
||||||
// and, the refusal being permanent, does not send the message again.
|
// and, the refusal being permanent, does not send the message again.
|
||||||
return milter.NewResponseStr('y', "550 5.7.1 From: "+shown+" - "+why), nil
|
return milter.NewResponseStr('y', "550 5.7.1 From: "+shown+" - "+why), nil
|
||||||
@@ -352,7 +355,7 @@ func (s *senderSession) judge() (shown, why string, err error) {
|
|||||||
// each recipient as an accepted message has: nothing was sent to anybody, and
|
// each recipient as an accepted message has: nothing was sent to anybody, and
|
||||||
// a refused message with a thousand recipients would otherwise be a thousand
|
// a refused message with a thousand recipients would otherwise be a thousand
|
||||||
// rows at the price of one.
|
// rows at the price of one.
|
||||||
func (s *senderSession) record(shown string) {
|
func (s *senderSession) record(shown, queueID string) {
|
||||||
if s.refused == nil {
|
if s.refused == nil {
|
||||||
return
|
return
|
||||||
}
|
}
|
||||||
@@ -364,6 +367,7 @@ func (s *senderSession) record(shown string) {
|
|||||||
to += fmt.Sprintf(" and %d more", more)
|
to += fmt.Sprintf(" and %d more", more)
|
||||||
}
|
}
|
||||||
e := store.SendLogEntry{
|
e := store.SendLogEntry{
|
||||||
|
QueueID: queueID,
|
||||||
Domain: s.domain(),
|
Domain: s.domain(),
|
||||||
AppLogin: s.login,
|
AppLogin: s.login,
|
||||||
From: s.from,
|
From: s.from,
|
||||||
|
|||||||
@@ -63,7 +63,8 @@ func offer(t *testing.T, bind *Bindings, login, envelope string, headers ...[2]s
|
|||||||
t.Fatal(err)
|
t.Fatal(err)
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
resp, err := s.Headers(nil, mods(nil))
|
// cleanup has given the message its queue id by the end of the headers.
|
||||||
|
resp, err := s.Headers(nil, mods(map[string]string{"i": "7BCAF3C75DA0"}))
|
||||||
if err != nil {
|
if err != nil {
|
||||||
t.Fatal(err)
|
t.Fatal(err)
|
||||||
}
|
}
|
||||||
@@ -153,7 +154,7 @@ func TestSenderCheck(t *testing.T) {
|
|||||||
t.Fatalf("the reason %q names %s", reason, other)
|
t.Fatalf("the reason %q names %s", reason, other)
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
if len(rows) != 1 || rows[0].Reason != store.ReasonFrom || rows[0].To != "someone@elsewhere.example" || rows[0].AppLogin != c.login {
|
if len(rows) != 1 || rows[0].Reason != store.ReasonFrom || rows[0].To != "someone@elsewhere.example" || rows[0].AppLogin != c.login || rows[0].QueueID != "7BCAF3C75DA0" {
|
||||||
t.Fatalf("log rows: %+v", rows)
|
t.Fatalf("log rows: %+v", rows)
|
||||||
}
|
}
|
||||||
})
|
})
|
||||||
|
|||||||
@@ -0,0 +1,15 @@
|
|||||||
|
-- What Postfix wrote about a refusal (audit 2026-10-12, stage 2b). A message
|
||||||
|
-- the journal milter refuses at MAIL FROM - a level-2 limit, a client address
|
||||||
|
-- off the application's list - has no queue id, and Postfix's one line about
|
||||||
|
-- it, "NOQUEUE: milter-reject: MAIL from ...", was nowhere the message's page
|
||||||
|
-- could find it. The log tailer puts it on the row it belongs to. A message
|
||||||
|
-- refused for its From: line has a queue id (cleanup gives one before the
|
||||||
|
-- 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 '';
|
||||||
|
|
||||||
|
-- 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
|
||||||
|
-- none - is written by the log tailer from Postfix's line about it, and marked
|
||||||
|
-- so: recovered = 1.
|
||||||
|
ALTER TABLE send_log ADD COLUMN recovered INTEGER NOT NULL DEFAULT 0;
|
||||||
@@ -0,0 +1,115 @@
|
|||||||
|
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)
|
||||||
|
}
|
||||||
|
}
|
||||||
@@ -47,7 +47,7 @@ func TestBaselineSchema(t *testing.T) {
|
|||||||
"applications": "id domain_id login address_mode auth_ip_restrict auth_allowed_ips created_at",
|
"applications": "id domain_id login address_mode auth_ip_restrict auth_allowed_ips created_at",
|
||||||
"application_addresses": "id application_id address",
|
"application_addresses": "id application_id address",
|
||||||
"rate_limits": "id scope ref_id max_messages window_seconds mode auto_multiplier auto_updated_at",
|
"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",
|
"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",
|
||||||
"logtail_state": "path fingerprint read_offset updated_at",
|
"logtail_state": "path fingerprint read_offset updated_at",
|
||||||
"inbound_domains": "id name recipient_mode created_at",
|
"inbound_domains": "id name recipient_mode created_at",
|
||||||
"inbound_transports": "inbound_domain_id host port tls_mode",
|
"inbound_transports": "inbound_domain_id host port tls_mode",
|
||||||
@@ -115,8 +115,8 @@ func TestBaselineSchema(t *testing.T) {
|
|||||||
}
|
}
|
||||||
|
|
||||||
var version, appID int64
|
var version, appID int64
|
||||||
if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 8 {
|
if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 9 {
|
||||||
t.Errorf("user_version = %d, %v; want 8", version, err)
|
t.Errorf("user_version = %d, %v; want 9", version, err)
|
||||||
}
|
}
|
||||||
if err := st.db.QueryRow("PRAGMA application_id").Scan(&appID); err != nil || appID != applicationID {
|
if err := st.db.QueryRow("PRAGMA application_id").Scan(&appID); err != nil || appID != applicationID {
|
||||||
t.Errorf("application_id = %#x, %v; want %#x", appID, err, applicationID)
|
t.Errorf("application_id = %#x, %v; want %#x", appID, err, applicationID)
|
||||||
@@ -192,8 +192,8 @@ func TestOpenMigratesA20Database(t *testing.T) {
|
|||||||
}
|
}
|
||||||
defer st.Close()
|
defer st.Close()
|
||||||
var version int
|
var version int
|
||||||
if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 8 {
|
if err := st.db.QueryRow("PRAGMA user_version").Scan(&version); err != nil || version != 9 {
|
||||||
t.Errorf("user_version = %d, %v; want 8", version, err)
|
t.Errorf("user_version = %d, %v; want 9", version, err)
|
||||||
}
|
}
|
||||||
if ok, err := st.UserExists(); err != nil || !ok {
|
if ok, err := st.UserExists(); err != nil || !ok {
|
||||||
t.Errorf("the user of the 2.0 database: exists = %v, %v", ok, err)
|
t.Errorf("the user of the 2.0 database: exists = %v, %v", ok, err)
|
||||||
|
|||||||
@@ -221,12 +221,74 @@ type SendLogRow struct {
|
|||||||
// Reason and HeaderFrom: see SendLogEntry.
|
// Reason and HeaderFrom: see SendLogEntry.
|
||||||
Reason string
|
Reason string
|
||||||
HeaderFrom string
|
HeaderFrom string
|
||||||
CreatedAt time.Time
|
// RefusalLine is Postfix's line about a refusal that has no queue id
|
||||||
|
// (migration 0009); "" for every other row, and for one refused before.
|
||||||
|
RefusalLine string
|
||||||
|
// Recovered is a refusal row the log tailer wrote from mail.log because
|
||||||
|
// the panel stopped before it wrote the row itself.
|
||||||
|
Recovered bool
|
||||||
|
CreatedAt time.Time
|
||||||
// UpdatedAt is when the status last changed — the log-tailer's report of
|
// UpdatedAt is when the status last changed — the log-tailer's report of
|
||||||
// the delivery attempt. It equals CreatedAt while a row is still queued.
|
// the delivery attempt. It equals CreatedAt while a row is still queued.
|
||||||
UpdatedAt time.Time
|
UpdatedAt time.Time
|
||||||
}
|
}
|
||||||
|
|
||||||
|
// 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) {
|
||||||
|
res, err := s.db.Exec(
|
||||||
|
`UPDATE send_log SET refusal_line = ? 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,
|
||||||
|
at.Add(-refusalLineWindow).UTC().Format(time.RFC3339),
|
||||||
|
at.Add(refusalLineWindow).UTC().Format(time.RFC3339),
|
||||||
|
)
|
||||||
|
if err != nil {
|
||||||
|
return false, fmt.Errorf("attach refusal line: %w", err)
|
||||||
|
}
|
||||||
|
n, _ := res.RowsAffected()
|
||||||
|
return n > 0, nil
|
||||||
|
}
|
||||||
|
|
||||||
|
// RecoverRefusal writes the row of a message the sender check refused for its
|
||||||
|
// From: line, from Postfix's line about it, when the panel stopped before it
|
||||||
|
// 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.
|
||||||
|
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+`
|
||||||
|
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, StatusRejected,
|
||||||
|
at.Add(-refusalLineWindow).UTC().Format(time.RFC3339), at.Add(refusalLineWindow).UTC().Format(time.RFC3339),
|
||||||
|
)
|
||||||
|
if err != nil {
|
||||||
|
return false, fmt.Errorf("recover refusal %s: %w", e.QueueID, err)
|
||||||
|
}
|
||||||
|
n, _ := res.RowsAffected()
|
||||||
|
return n > 0, nil
|
||||||
|
}
|
||||||
|
|
||||||
|
// refusalLineWindow is how far apart a refusal's row and its log line may be
|
||||||
|
// dated: the milter writes the row at MAIL FROM, Postfix the line a moment
|
||||||
|
// later, and the log's stamps are whole seconds.
|
||||||
|
const refusalLineWindow = 2 * time.Minute
|
||||||
|
|
||||||
// ErrSendLogNotFound is returned by GetSendLog for an id that no longer exists.
|
// ErrSendLogNotFound is returned by GetSendLog for an id that no longer exists.
|
||||||
// Send-log rows are pruned on the retention window, so a bookmarked delivery
|
// Send-log rows are pruned on the retention window, so a bookmarked delivery
|
||||||
// disappearing is expected, not a fault.
|
// disappearing is expected, not a fault.
|
||||||
@@ -240,10 +302,10 @@ func (s *Store) GetSendLog(id int64) (SendLogRow, error) {
|
|||||||
createdAt, updatedAt string
|
createdAt, updatedAt string
|
||||||
)
|
)
|
||||||
err := s.db.QueryRow(
|
err := s.db.QueryRow(
|
||||||
`SELECT id, queue_id, domain, COALESCE(domain_id, 0), app_login, from_addr, to_addr, subject, status, reason, header_from, created_at, updated_at
|
`SELECT id, queue_id, domain, COALESCE(domain_id, 0), app_login, from_addr, to_addr, subject, status, reason, header_from, refusal_line, recovered, created_at, updated_at
|
||||||
FROM send_log WHERE id = ?`, id,
|
FROM send_log WHERE id = ?`, id,
|
||||||
).Scan(&row.ID, &row.QueueID, &row.Domain, &row.DomainID, &row.AppLogin, &row.From, &row.To,
|
).Scan(&row.ID, &row.QueueID, &row.Domain, &row.DomainID, &row.AppLogin, &row.From, &row.To,
|
||||||
&row.Subject, &row.Status, &row.Reason, &row.HeaderFrom, &createdAt, &updatedAt)
|
&row.Subject, &row.Status, &row.Reason, &row.HeaderFrom, &row.RefusalLine, &row.Recovered, &createdAt, &updatedAt)
|
||||||
if errors.Is(err, sql.ErrNoRows) {
|
if errors.Is(err, sql.ErrNoRows) {
|
||||||
return SendLogRow{}, ErrSendLogNotFound
|
return SendLogRow{}, ErrSendLogNotFound
|
||||||
}
|
}
|
||||||
|
|||||||
@@ -93,10 +93,19 @@ func (s *Store) InsertSendLogLines(lines []SendLogLine, once bool) (int, error)
|
|||||||
// A line is the row's when it is dated from shortly before the row was written
|
// A line is the row's when it is dated from shortly before the row was written
|
||||||
// to lifetime after it; lifetime is how long Postfix may keep working on a
|
// to lifetime after it; lifetime is how long Postfix may keep working on a
|
||||||
// message, with a margin, and the caller's to state (postfix.RetryPolicy).
|
// message, with a margin, and the caller's to state (postfix.RetryPolicy).
|
||||||
|
//
|
||||||
|
// A refused message - one refused for its From: line has a queue id, given
|
||||||
|
// before the headers were judged - is over in a moment, and Postfix frees the
|
||||||
|
// id at once: its lines are those of a few minutes around the refusal, so
|
||||||
|
// that the next message to get the id lends it none of its own.
|
||||||
func (s *Store) SendLogLines(row SendLogRow, lifetime time.Duration, n int) ([]SendLogLine, error) {
|
func (s *Store) SendLogLines(row SendLogRow, lifetime time.Duration, n int) ([]SendLogLine, error) {
|
||||||
if row.QueueID == "" || n <= 0 {
|
if row.QueueID == "" || n <= 0 {
|
||||||
return nil, nil
|
return nil, nil
|
||||||
}
|
}
|
||||||
|
before := sendLogLineBefore
|
||||||
|
if row.Status == StatusRejected {
|
||||||
|
before, lifetime = refusedLinesBefore, refusedLinesAfter
|
||||||
|
}
|
||||||
rows, err := s.db.Query(
|
rows, err := s.db.Query(
|
||||||
`SELECT logged_at, line FROM (
|
`SELECT logged_at, line FROM (
|
||||||
SELECT id, logged_at, line FROM send_log_lines
|
SELECT id, logged_at, line FROM send_log_lines
|
||||||
@@ -104,7 +113,7 @@ func (s *Store) SendLogLines(row SendLogRow, lifetime time.Duration, n int) ([]S
|
|||||||
ORDER BY id DESC LIMIT ?)
|
ORDER BY id DESC LIMIT ?)
|
||||||
ORDER BY id`,
|
ORDER BY id`,
|
||||||
row.QueueID,
|
row.QueueID,
|
||||||
row.CreatedAt.Add(-sendLogLineBefore).UTC().Format(time.RFC3339),
|
row.CreatedAt.Add(-before).UTC().Format(time.RFC3339),
|
||||||
row.CreatedAt.Add(lifetime).UTC().Format(time.RFC3339),
|
row.CreatedAt.Add(lifetime).UTC().Format(time.RFC3339),
|
||||||
n,
|
n,
|
||||||
)
|
)
|
||||||
@@ -150,3 +159,10 @@ func (s *Store) PruneSendLogLines(cutoff time.Time) (int64, error) {
|
|||||||
n, _ := res.RowsAffected()
|
n, _ := res.RowsAffected()
|
||||||
return n, nil
|
return n, nil
|
||||||
}
|
}
|
||||||
|
|
||||||
|
// The lines of a refused message: from its connection - a slow client may
|
||||||
|
// take minutes to reach the end of its headers - to just after the refusal.
|
||||||
|
const (
|
||||||
|
refusedLinesBefore = 10 * time.Minute
|
||||||
|
refusedLinesAfter = time.Minute
|
||||||
|
)
|
||||||
|
|||||||
@@ -104,7 +104,7 @@ func (h *Handlers) HandleDelivery(w http.ResponseWriter, r *http.Request) {
|
|||||||
in := view.MessageInput{
|
in := view.MessageInput{
|
||||||
ID: row.ID, QueueID: row.QueueID, Domain: row.Domain, App: row.AppLogin,
|
ID: row.ID, QueueID: row.QueueID, Domain: row.Domain, App: row.AppLogin,
|
||||||
From: row.From, To: row.To, Subject: row.Subject, Status: row.Status,
|
From: row.From, To: row.To, Subject: row.Subject, Status: row.Status,
|
||||||
Reason: row.Reason, HeaderFrom: row.HeaderFrom,
|
Reason: row.Reason, HeaderFrom: row.HeaderFrom, Recovered: row.Recovered,
|
||||||
Accepted: row.CreatedAt, Reported: row.UpdatedAt,
|
Accepted: row.CreatedAt, Reported: row.UpdatedAt,
|
||||||
// Where the row came from, so the way back returns to the page and filters
|
// Where the row came from, so the way back returns to the page and filters
|
||||||
// the operator was looking at rather than the top of an unfiltered log.
|
// the operator was looking at rather than the top of an unfiltered log.
|
||||||
@@ -241,6 +241,12 @@ const deliveryLogMargin = 24 * time.Hour
|
|||||||
// reported as a fault, and that one is logged for the operator as well.
|
// reported as a fault, and that one is logged for the operator as well.
|
||||||
func (h *Handlers) deliveryLog(row store.SendLogRow) ([]view.LogLine, string) {
|
func (h *Handlers) deliveryLog(row store.SendLogRow) ([]view.LogLine, string) {
|
||||||
if row.QueueID == "" {
|
if row.QueueID == "" {
|
||||||
|
if row.RefusalLine != "" {
|
||||||
|
return logLines([]string{row.RefusalLine}), ""
|
||||||
|
}
|
||||||
|
if row.Status == store.StatusRejected {
|
||||||
|
return nil, "Postfix's line about this refusal is not stored: the message was refused before version 2.5.1, or the line was never read."
|
||||||
|
}
|
||||||
return nil, "This message never reached the queue, so Postfix wrote no delivery lines for it."
|
return nil, "This message never reached the queue, so Postfix wrote no delivery lines for it."
|
||||||
}
|
}
|
||||||
stored, err := h.store.SendLogLines(row, h.cfg.RetryPolicy.LongestLifetime()+deliveryLogMargin, deliveryLogLines)
|
stored, err := h.store.SendLogLines(row, h.cfg.RetryPolicy.LongestLifetime()+deliveryLogMargin, deliveryLogLines)
|
||||||
@@ -252,7 +258,9 @@ func (h *Handlers) deliveryLog(row store.SendLogRow) ([]view.LogLine, string) {
|
|||||||
for i, l := range stored {
|
for i, l := range stored {
|
||||||
lines[i] = l.Line
|
lines[i] = l.Line
|
||||||
}
|
}
|
||||||
if len(lines) == 0 {
|
// A refused message's id was freed at once and may be another's by now:
|
||||||
|
// what was not stored with the row is not looked for in the log.
|
||||||
|
if len(lines) == 0 && row.Status != store.StatusRejected {
|
||||||
lines, err = logtail.QueueLines(h.cfg.MailLogPath, row.QueueID, deliveryLogLines)
|
lines, err = logtail.QueueLines(h.cfg.MailLogPath, row.QueueID, deliveryLogLines)
|
||||||
if err != nil && !errors.Is(err, fs.ErrNotExist) {
|
if err != nil && !errors.Is(err, fs.ErrNotExist) {
|
||||||
logf("panel: delivery log %s: %v", row.QueueID, err)
|
logf("panel: delivery log %s: %v", row.QueueID, err)
|
||||||
@@ -262,6 +270,11 @@ func (h *Handlers) deliveryLog(row store.SendLogRow) ([]view.LogLine, string) {
|
|||||||
if len(lines) == 0 {
|
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."
|
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."
|
||||||
}
|
}
|
||||||
|
return logLines(lines), ""
|
||||||
|
}
|
||||||
|
|
||||||
|
// logLines are lines of mail.log as the delivery log box shows them.
|
||||||
|
func logLines(lines []string) []view.LogLine {
|
||||||
out := make([]view.LogLine, len(lines))
|
out := make([]view.LogLine, len(lines))
|
||||||
for i, line := range lines {
|
for i, line := range lines {
|
||||||
// A line whose head is not a timestamp the log format recognises keeps its
|
// A line whose head is not a timestamp the log format recognises keeps its
|
||||||
@@ -269,7 +282,7 @@ func (h *Handlers) deliveryLog(row store.SendLogRow) ([]view.LogLine, string) {
|
|||||||
stamp, rest := logtail.SplitTimestamp(line)
|
stamp, rest := logtail.SplitTimestamp(line)
|
||||||
out[i] = view.LogLine{Time: stamp, Text: rest, Level: view.LogLineLevel(rest)}
|
out[i] = view.LogLine{Time: stamp, Text: rest, Level: view.LogLineLevel(rest)}
|
||||||
}
|
}
|
||||||
return out, ""
|
return out
|
||||||
}
|
}
|
||||||
|
|
||||||
// deliveriesBackURL rebuilds the delivery-log URL a detail page was opened
|
// deliveriesBackURL rebuilds the delivery-log URL a detail page was opened
|
||||||
|
|||||||
@@ -176,8 +176,9 @@ func TestMessagePageDrawsTheOutcomeAtItsLevel(t *testing.T) {
|
|||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
// A message the milter refused never reached the queue: it has no queue id and
|
// A message the milter refused never reached the queue: it has no queue id,
|
||||||
// no lines to show, and says why instead of showing an empty log.
|
// and a row from before Postfix's line about it was kept says so instead of
|
||||||
|
// showing an empty log.
|
||||||
func TestMessagePageOfARefusedMessage(t *testing.T) {
|
func TestMessagePageOfARefusedMessage(t *testing.T) {
|
||||||
h, _ := serverWithDelivery(t)
|
h, _ := serverWithDelivery(t)
|
||||||
if err := h.store.InsertRejected(store.SendLogEntry{
|
if err := h.store.InsertRejected(store.SendLogEntry{
|
||||||
@@ -190,7 +191,7 @@ func TestMessagePageOfARefusedMessage(t *testing.T) {
|
|||||||
t.Fatalf("query: %v (%d rows)", err, len(rows))
|
t.Fatalf("query: %v (%d rows)", err, len(rows))
|
||||||
}
|
}
|
||||||
body := getBody(t, h.HandleDelivery, "/outbound/log/"+itoa(rows[0].ID))
|
body := getBody(t, h.HandleDelivery, "/outbound/log/"+itoa(rows[0].ID))
|
||||||
has(t, "refused message", body, `Refused before queueing`, `class="sp-fail"`, `never reached the queue`, `<span class="tag is-light">rejected</span>`)
|
has(t, "refused message", body, `Refused before queueing`, `class="sp-fail"`, `the line was never read`, `<span class="tag is-light">rejected</span>`)
|
||||||
lacks(t, "refused message", body, `<pre`)
|
lacks(t, "refused message", body, `<pre`)
|
||||||
}
|
}
|
||||||
|
|
||||||
|
|||||||
@@ -5,6 +5,7 @@ import (
|
|||||||
"net/url"
|
"net/url"
|
||||||
"strings"
|
"strings"
|
||||||
"testing"
|
"testing"
|
||||||
|
"time"
|
||||||
|
|
||||||
"github.com/mixeme/selfpost/internal/store"
|
"github.com/mixeme/selfpost/internal/store"
|
||||||
"github.com/mixeme/selfpost/internal/web/auth"
|
"github.com/mixeme/selfpost/internal/web/auth"
|
||||||
@@ -150,3 +151,38 @@ func TestADomainAddedAgainShowsItsAssigneeNothingOld(t *testing.T) {
|
|||||||
t.Errorf("the global log is missing a row")
|
t.Errorf("the global log is missing a row")
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
|
// A refused message's page shows what Postfix wrote about the refusal: the
|
||||||
|
// NOQUEUE line put on the row of a refusal at MAIL FROM, or, for a row from
|
||||||
|
// before that line was kept, a sentence that says so (audit 2026-10-12,
|
||||||
|
// stage 2b).
|
||||||
|
func TestARefusedMessageShowsPostfixsLine(t *testing.T) {
|
||||||
|
h, st := inboundHandlers(t)
|
||||||
|
root := userWith(t, st, "root", store.RoleGlobal, store.Reach{})
|
||||||
|
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 {
|
||||||
|
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 {
|
||||||
|
t.Fatalf("attach = %v, %v", ok, err)
|
||||||
|
}
|
||||||
|
}
|
||||||
|
}
|
||||||
|
rows, _ := st.QuerySendLog(store.SendLogFilter{AllDomains: true}, 10, 0)
|
||||||
|
for _, r := range rows {
|
||||||
|
body := send(h.HandleDelivery, &root, "GET", "/outbound/log/"+idStr(r.ID), map[string]string{"id": idStr(r.ID)}, nil).Body.String()
|
||||||
|
if r.Subject == "with its line" {
|
||||||
|
if !strings.Contains(body, `<span class="sp-w">mail postfix/smtpd[2131]: NOQUEUE: milter-reject: MAIL from unknown[198.51.100.7]: 451 4.7.1`) {
|
||||||
|
t.Errorf("the page of a refusal with its line lacks it:\n%s", body)
|
||||||
|
}
|
||||||
|
continue
|
||||||
|
}
|
||||||
|
if !strings.Contains(body, "the message was refused before version 2.5.1, or the line was never read") {
|
||||||
|
t.Errorf("the page of a refusal without its line does not say why")
|
||||||
|
}
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|||||||
@@ -12,6 +12,7 @@ package view
|
|||||||
|
|
||||||
import (
|
import (
|
||||||
"net/url"
|
"net/url"
|
||||||
|
"regexp"
|
||||||
"strconv"
|
"strconv"
|
||||||
"strings"
|
"strings"
|
||||||
"time"
|
"time"
|
||||||
@@ -172,8 +173,11 @@ type MessageInput struct {
|
|||||||
// (store.Reason*) and, for its From: line, what that line said.
|
// (store.Reason*) and, for its From: line, what that line said.
|
||||||
Reason string
|
Reason string
|
||||||
HeaderFrom string
|
HeaderFrom string
|
||||||
Accepted time.Time
|
// Recovered is a refused row the log tailer wrote from mail.log: the
|
||||||
Reported time.Time
|
// panel stopped before it wrote the row itself.
|
||||||
|
Recovered bool
|
||||||
|
Accepted time.Time
|
||||||
|
Reported time.Time
|
||||||
// BackHref is the log the message was opened from, filters and page kept.
|
// BackHref is the log the message was opened from, filters and page kept.
|
||||||
BackHref string
|
BackHref string
|
||||||
}
|
}
|
||||||
@@ -246,15 +250,26 @@ func NewOutMessage(m Meta, in MessageInput) *OutMessage {
|
|||||||
{Label: "Application", Value: value(in.App, in.AppHref), Mono: true},
|
{Label: "Application", Value: value(in.App, in.AppHref), Mono: true},
|
||||||
}
|
}
|
||||||
history := Box{No: "02", Title: "History", Help: topicLink(HelpLog, "What the statuses mean")}
|
history := Box{No: "02", Title: "History", Help: topicLink(HelpLog, "What the statuses mean")}
|
||||||
|
delivery := Box{No: "03", Title: "Delivery log", End: Rich("Lines from ", Code("mail.log"), " with this queue id")}
|
||||||
if in.Status == "rejected" {
|
if in.Status == "rejected" {
|
||||||
// A refused message was never accepted and never queued: its one date
|
// A refused message was never accepted and never queued: its one date
|
||||||
// is the refusal, and it has no queue id to look anything up by.
|
// is the refusal. One refused for its From: line was given a queue id
|
||||||
|
// before its headers were judged; one refused at MAIL FROM was not,
|
||||||
|
// and its box holds Postfix's one line about the refusal.
|
||||||
facts = append(facts, Fact{Label: "Refused", Value: Plain(formatStamp(in.Accepted))})
|
facts = append(facts, Fact{Label: "Refused", Value: Plain(formatStamp(in.Accepted))})
|
||||||
if in.Reason == "from" {
|
if in.Reason == "from" {
|
||||||
facts = append(facts, Fact{Label: "From: line", Value: Plain(orDash(in.HeaderFrom)), Mono: true, Small: true})
|
facts = append(facts, Fact{Label: "From: line", Value: Plain(orDash(in.HeaderFrom)), Mono: true, Small: true})
|
||||||
history.Help = topicLink(HelpSenderCheck, "What an application may write in From:")
|
history.Help = topicLink(HelpSenderCheck, "What an application may write in From:")
|
||||||
}
|
}
|
||||||
facts = append(facts, Fact{Label: "Queue id", Value: Plain("none - never queued")})
|
if in.Recovered {
|
||||||
|
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")})
|
||||||
|
} 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")
|
||||||
|
}
|
||||||
} else {
|
} else {
|
||||||
facts = append(facts,
|
facts = append(facts,
|
||||||
Fact{Label: "Accepted", Value: Plain(formatStamp(in.Accepted))},
|
Fact{Label: "Accepted", Value: Plain(formatStamp(in.Accepted))},
|
||||||
@@ -276,7 +291,7 @@ func NewOutMessage(m Meta, in MessageInput) *OutMessage {
|
|||||||
Message: Box{No: "01", Title: "Message"},
|
Message: Box{No: "01", Title: "Message"},
|
||||||
Facts: facts,
|
Facts: facts,
|
||||||
History: history,
|
History: history,
|
||||||
Delivery: Box{No: "03", Title: "Delivery log", End: Rich("Lines from ", Code("mail.log"), " with this queue id")},
|
Delivery: delivery,
|
||||||
LogEmpty: EmptyState{Icon: "ti-file-text"},
|
LogEmpty: EmptyState{Icon: "ti-file-text"},
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
@@ -330,5 +345,17 @@ func LogLineLevel(text string) string {
|
|||||||
case strings.Contains(text, "status=deferred"), strings.Contains(text, " warning:"):
|
case strings.Contains(text, "status=deferred"), strings.Contains(text, " warning:"):
|
||||||
return "warn"
|
return "warn"
|
||||||
}
|
}
|
||||||
|
// A refusal is as permanent as its reply: "550"/"5.7.1" red, "451" amber.
|
||||||
|
if m := rejectCodeRe.FindStringSubmatch(text); m != nil {
|
||||||
|
if m[1] == "5" {
|
||||||
|
return "error"
|
||||||
|
}
|
||||||
|
return "warn"
|
||||||
|
}
|
||||||
return ""
|
return ""
|
||||||
}
|
}
|
||||||
|
|
||||||
|
// rejectCodeRe finds the reply of a refusal Postfix logged: the code or the
|
||||||
|
// enhanced status after "reject: <stage> from <client>[<address>]:", from
|
||||||
|
// smtpd ("reject:") and cleanup ("milter-reject:") alike.
|
||||||
|
var rejectCodeRe = regexp.MustCompile(`reject: \S+ from [^\]]*\]: ([45])(?:\d\d|\.\d+\.\d+) `)
|
||||||
|
|||||||
@@ -124,23 +124,38 @@ func TestOutMessageWithoutSubjectOrRecipient(t *testing.T) {
|
|||||||
out := renderSignedIn(t, "out-message", p)
|
out := renderSignedIn(t, "out-message", p)
|
||||||
pageHas(t, "Message", out, `<h1 class="title is-4">(no subject)</h1>`, `<span>—</span><i class="ti ti-arrow-right sp-muted"></i><span>—</span>`,
|
pageHas(t, "Message", out, `<h1 class="title is-4">(no subject)</h1>`, `<span>—</span><i class="ti ti-arrow-right sp-muted"></i><span>—</span>`,
|
||||||
`<span class="tag is-light">rejected</span>`, `href="/outbound/log?domain=gone.example&p=2"`,
|
`<span class="tag is-light">rejected</span>`, `href="/outbound/log?domain=gone.example&p=2"`,
|
||||||
`<dd>gone.example</dd>`, `<dd class="sp-mono">old</dd>`, `<dt>Refused</dt>`, `<dd>none - never queued</dd>`,
|
`<dd>gone.example</dd>`, `<dd class="sp-mono">old</dd>`, `<dt>Refused</dt>`,
|
||||||
`never reached the queue`)
|
`<dd>none - refused at <span class="sp-mono">MAIL FROM</span>, before one is given</dd>`,
|
||||||
|
`The line from <code>mail.log</code> for this refusal`, `never reached the queue`)
|
||||||
pageLacks(t, "Message", out, `<pre`, `<a href="/outbound/domains/`, `Status reported`, `From: line`)
|
pageLacks(t, "Message", out, `<pre`, `<a href="/outbound/domains/`, `Status reported`, `From: line`)
|
||||||
}
|
}
|
||||||
|
|
||||||
// A row refused for its From: line says so in its tag, shows what the line
|
// A row refused for its From: line says so in its tag, shows what the line
|
||||||
// said, and its History links to the topic that explains the rule.
|
// said, and its History links to the topic that explains the rule. The
|
||||||
|
// message had a queue id - cleanup gives one before the headers are judged -
|
||||||
|
// and its box shows Postfix's lines by it, the refusal red.
|
||||||
func TestOutMessageRefusedForItsFromLine(t *testing.T) {
|
func TestOutMessageRefusedForItsFromLine(t *testing.T) {
|
||||||
at := time.Date(2026, 9, 21, 13, 40, 55, 0, time.UTC)
|
at := time.Date(2026, 9, 21, 13, 40, 55, 0, time.UTC)
|
||||||
p := NewOutMessage(admin(), MessageInput{ID: 184231, Domain: "shop.example.org", App: "shop",
|
p := NewOutMessage(admin(), MessageInput{ID: 184231, QueueID: "7BCAF3C75DA0", Domain: "shop.example.org", App: "shop",
|
||||||
From: "shop@shop.example.org", To: "k.berg@web.de", Subject: "A message from the director",
|
From: "shop@shop.example.org", To: "k.berg@web.de", Subject: "A message from the director",
|
||||||
Status: "rejected", Reason: "from", HeaderFrom: "director@example.org", Accepted: at, Reported: at}).
|
Status: "rejected", Reason: "from", HeaderFrom: "director@example.org", Accepted: at, Reported: at}).
|
||||||
WithDeliveryLog(nil, "This message never reached the queue, so Postfix wrote no delivery lines for it.")
|
WithDeliveryLog([]LogLine{{Time: "13:40:55", Text: "postfix/cleanup[2120]: 7BCAF3C75DA0: milter-reject: END-OF-MESSAGE from unknown[198.51.100.7]: 5.7.1 From: director@example.org - not an address this application sends as",
|
||||||
|
Level: LogLineLevel("postfix/cleanup[2120]: 7BCAF3C75DA0: milter-reject: END-OF-MESSAGE from unknown[198.51.100.7]: 5.7.1 From: director@example.org - not an address this application sends as")}}, "")
|
||||||
out := renderSignedIn(t, "out-message", p)
|
out := renderSignedIn(t, "out-message", p)
|
||||||
pageHas(t, "Message", out, `<span class="tag is-danger is-light">wrong From</span>`,
|
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>`,
|
`<dt>From: line</dt><dd class="sp-mono sp-small">director@example.org</dd>`, `<dt>Refused</dt>`,
|
||||||
`<dd>none - never queued</dd>`, `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`)
|
||||||
|
}
|
||||||
|
|
||||||
|
// A refused row the log tailer wrote from mail.log says so.
|
||||||
|
func TestOutMessageRecoveredFromTheLog(t *testing.T) {
|
||||||
|
at := time.Date(2026, 9, 21, 13, 40, 55, 0, time.UTC)
|
||||||
|
p := NewOutMessage(admin(), MessageInput{ID: 184232, QueueID: "E543D3C75DA0", Domain: "shop.example.org", App: "shop",
|
||||||
|
From: "shop@shop.example.org", To: "k.berg@web.de", Status: "rejected", Reason: "from", HeaderFrom: "director@example.org",
|
||||||
|
Recovered: true, Accepted: at, Reported: at}).WithDeliveryLog(nil, "")
|
||||||
|
out := renderSignedIn(t, "out-message", p)
|
||||||
|
pageHas(t, "Message", out, `<dt>Written</dt>`, `after a restart: the panel stopped before it wrote the refusal`)
|
||||||
}
|
}
|
||||||
|
|
||||||
func TestSendLogTag(t *testing.T) {
|
func TestSendLogTag(t *testing.T) {
|
||||||
@@ -184,12 +199,15 @@ func TestStepLevelAndLogLineLevel(t *testing.T) {
|
|||||||
}
|
}
|
||||||
}
|
}
|
||||||
for text, want := range map[string]string{
|
for text, want := range map[string]string{
|
||||||
"postfix/smtp[1]: Q1: to=<a@b>, status=sent (250 OK)": "",
|
"postfix/smtp[1]: Q1: to=<a@b>, status=sent (250 OK)": "",
|
||||||
"postfix/smtp[1]: Q1: to=<a@b>, status=deferred (try later)": "warn",
|
"postfix/smtp[1]: Q1: to=<a@b>, status=deferred (try later)": "warn",
|
||||||
"postfix/smtp[1]: Q1: to=<a@b>, status=bounced (no such user)": "error",
|
"postfix/smtp[1]: Q1: to=<a@b>, status=bounced (no such user)": "error",
|
||||||
"postfix/qmgr[1]: Q1: status=expired, returned to sender": "error",
|
"postfix/qmgr[1]: Q1: status=expired, returned to sender": "error",
|
||||||
"postfix/smtp[1]: warning: TLS library problem": "warn",
|
"postfix/smtp[1]: warning: TLS library problem": "warn",
|
||||||
"opendkim[1]: Q1: DKIM-Signature field added": "",
|
"opendkim[1]: Q1: DKIM-Signature field added": "",
|
||||||
|
"postfix/cleanup[1]: Q1: milter-reject: END-OF-MESSAGE from unknown[10.77.0.1]: 5.7.1 From: x - no": "error",
|
||||||
|
"postfix/smtpd[1]: NOQUEUE: milter-reject: MAIL from unknown[10.77.0.1]: 451 4.7.1 Service unavailable": "warn",
|
||||||
|
"postfix/smtpd[1]: NOQUEUE: reject: RCPT from unknown[2001:db8::1]: 554 5.7.1 <a@b>: Relay access denied": "error",
|
||||||
} {
|
} {
|
||||||
if got := LogLineLevel(text); got != want {
|
if got := LogLineLevel(text); got != want {
|
||||||
t.Errorf("LogLineLevel(%q) = %q, want %q", text, got, want)
|
t.Errorf("LogLineLevel(%q) = %q, want %q", text, got, want)
|
||||||
|
|||||||
@@ -313,6 +313,12 @@ func TestE2E(t *testing.T) {
|
|||||||
run("passed_from_lines_signed_for_their_domain_only", func(t *testing.T) {
|
run("passed_from_lines_signed_for_their_domain_only", func(t *testing.T) {
|
||||||
testSignedForItsDomainOnly(t, sc)
|
testSignedForItsDomainOnly(t, sc)
|
||||||
})
|
})
|
||||||
|
run("refusals_show_postfixs_line", func(t *testing.T) {
|
||||||
|
testRefusalsShowPostfixsLine(t, sc)
|
||||||
|
})
|
||||||
|
run("refusal_recovered_from_the_log", func(t *testing.T) {
|
||||||
|
testRefusalRecoveredFromTheLog(t, sc)
|
||||||
|
})
|
||||||
run("lines_naming_another_sender_never_signed_for_it", func(t *testing.T) {
|
run("lines_naming_another_sender_never_signed_for_it", func(t *testing.T) {
|
||||||
testNeverSignedForAnother(t, sc)
|
testNeverSignedForAnother(t, sc)
|
||||||
})
|
})
|
||||||
|
|||||||
@@ -5,8 +5,10 @@ import (
|
|||||||
"errors"
|
"errors"
|
||||||
"fmt"
|
"fmt"
|
||||||
"net"
|
"net"
|
||||||
|
"net/http"
|
||||||
"net/smtp"
|
"net/smtp"
|
||||||
"net/textproto"
|
"net/textproto"
|
||||||
|
"net/url"
|
||||||
"regexp"
|
"regexp"
|
||||||
"strconv"
|
"strconv"
|
||||||
"strings"
|
"strings"
|
||||||
@@ -311,3 +313,148 @@ func testPanelHungMidMessage(t *testing.T, sc *scenario) {
|
|||||||
t.Fatal(err)
|
t.Fatal(err)
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
|
// testRefusalsShowPostfixsLine: the page of each of the three refusals shows
|
||||||
|
// what Postfix wrote about it (audit 2026-10-12, stage 2b) - for a message
|
||||||
|
// refused for its From: line, cleanup's line under the queue id the message
|
||||||
|
// had; for one refused at MAIL FROM under a level-2 limit or for its client
|
||||||
|
// address, smtpd's NOQUEUE line the log tailer put on the row. The first two
|
||||||
|
// refusals were made by earlier steps; the third is made here.
|
||||||
|
func testRefusalsShowPostfixsLine(t *testing.T, sc *scenario) {
|
||||||
|
login, password, err := sc.panel.addApplication(sc.domainID, "clientapp", "wildcard", "")
|
||||||
|
if err != nil {
|
||||||
|
t.Fatal(err)
|
||||||
|
}
|
||||||
|
if err := waitForSenderMap(login, password, "alerts@"+senderDomain); err != nil {
|
||||||
|
t.Fatal(err)
|
||||||
|
}
|
||||||
|
appID, err := sc.panel.applicationID(sc.domainID, login)
|
||||||
|
if err != nil {
|
||||||
|
t.Fatal(err)
|
||||||
|
}
|
||||||
|
resp, body, err := sc.panel.postForm("/outbound/domains/"+sc.domainID+"/applications/"+appID, url.Values{
|
||||||
|
"mode": {"wildcard"}, "auth_ip_restrict": {"1"}, "auth_allowed_ips": {"192.0.2.1"},
|
||||||
|
})
|
||||||
|
if err != nil || resp.StatusCode != http.StatusOK {
|
||||||
|
t.Fatalf("restrict the client addresses: %v %d\n%.600s", err, resp.StatusCode, body)
|
||||||
|
}
|
||||||
|
res := attemptSend(sendAttempt{authLogin: login, authPassword: password,
|
||||||
|
from: "alerts@" + senderDomain, to: recipient, subject: "e2e " + uniqueToken("client"), body: "x"})
|
||||||
|
if err := res.refusedAt("MAIL", 451, "4.7.1"); err != nil {
|
||||||
|
t.Fatalf("a client off the list: %v", err)
|
||||||
|
}
|
||||||
|
|
||||||
|
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+)[^"]*"`)
|
||||||
|
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",
|
||||||
|
}
|
||||||
|
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) {
|
||||||
|
rows, err := sc.panel.sendLogRows(senderDomain, "")
|
||||||
|
if err != nil {
|
||||||
|
return false, err
|
||||||
|
}
|
||||||
|
for _, row := range rowRe.FindAllString(rows, -1) {
|
||||||
|
m := tagRe.FindStringSubmatch(row)
|
||||||
|
l := linkRe.FindStringSubmatch(row)
|
||||||
|
if m == nil || m[1] != tag || l == nil {
|
||||||
|
continue
|
||||||
|
}
|
||||||
|
_, page, err := sc.panel.get(l[1])
|
||||||
|
if err != nil {
|
||||||
|
return false, err
|
||||||
|
}
|
||||||
|
if strings.Contains(page, line) {
|
||||||
|
return true, nil
|
||||||
|
}
|
||||||
|
}
|
||||||
|
return false, fmt.Errorf("no %s row whose page shows %q", tag, line)
|
||||||
|
}); err != nil {
|
||||||
|
t.Error(err)
|
||||||
|
}
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
||||||
|
// asPanel runs python3 code inside the container as the panel's user, so the
|
||||||
|
// database's WAL files stay the panel's.
|
||||||
|
func asPanel(code string, args ...string) (string, error) {
|
||||||
|
full := append([]string{"exec", "-T", "-u", "panel", "selfpost", "python3", "-c", code}, args...)
|
||||||
|
out, err := h.compose(full...)
|
||||||
|
return strings.TrimSpace(string(out)), err
|
||||||
|
}
|
||||||
|
|
||||||
|
// testRefusalRecoveredFromTheLog: the sender check answers 550 and writes the
|
||||||
|
// row a moment later; a panel stopped in between leaves a refusal the log
|
||||||
|
// knows and the panel does not (audit 2026-10-12, stage 2b). The stop cannot
|
||||||
|
// be timed to that moment from outside, so what it leaves is made by hand: a
|
||||||
|
// From: refusal, then - the panel stopped - its row deleted and the tailer's
|
||||||
|
// 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) {
|
||||||
|
token := uniqueToken("recover")
|
||||||
|
res := attemptSend(sendAttempt{authLogin: sc.appLogin, authPassword: sc.appPassword,
|
||||||
|
from: "alerts@" + senderDomain, headerFrom: "director@" + otherDomain, to: recipient,
|
||||||
|
subject: "e2e " + token, body: "refused, and its row lost"})
|
||||||
|
if err := res.refusedAt("DATA", 550, "5.7.1 From:"); err != nil {
|
||||||
|
t.Fatal(err)
|
||||||
|
}
|
||||||
|
var queueID string
|
||||||
|
if err := waitFor("the refused row", 15*time.Second, 300*time.Millisecond, func() (bool, error) {
|
||||||
|
out, err := asPanel(`import sqlite3,sys
|
||||||
|
r=sqlite3.connect("/data/selfpost.db").execute("select queue_id from send_log where subject like ?",("%"+sys.argv[1]+"%",)).fetchone()
|
||||||
|
print(r[0] if r else "")`, token)
|
||||||
|
queueID = out
|
||||||
|
return err == nil && out != "", err
|
||||||
|
}); err != nil {
|
||||||
|
t.Fatal(err)
|
||||||
|
}
|
||||||
|
supervisorctl := func(verb string) {
|
||||||
|
if _, err := h.execIn("selfpost", "supervisorctl", "-c", "/etc/supervisor/supervisord.conf", verb, "panel"); err != nil {
|
||||||
|
t.Fatalf("%s panel: %v", verb, err)
|
||||||
|
}
|
||||||
|
}
|
||||||
|
supervisorctl("stop")
|
||||||
|
t.Cleanup(func() {
|
||||||
|
_, _ = h.execIn("selfpost", "supervisorctl", "-c", "/etc/supervisor/supervisord.conf", "start", "panel")
|
||||||
|
})
|
||||||
|
if out, err := asPanel(`import sqlite3,sys
|
||||||
|
q=sys.argv[1]
|
||||||
|
data=open("/data/log/mail.log","rb").read()
|
||||||
|
pos=data.find((q+": client=").encode())
|
||||||
|
if pos < 0: sys.exit("no client= line for "+q)
|
||||||
|
start=data.rfind(b"\n",0,pos)+1
|
||||||
|
c=sqlite3.connect("/data/selfpost.db")
|
||||||
|
c.execute("delete from send_log where queue_id=?",(q,))
|
||||||
|
c.execute("update logtail_state set read_offset=?",(start,))
|
||||||
|
c.commit()
|
||||||
|
print(start)`, queueID); err != nil {
|
||||||
|
t.Fatalf("lose the row: %v %s", err, out)
|
||||||
|
}
|
||||||
|
supervisorctl("start")
|
||||||
|
if err := waitFor("panel HTTP to answer again", 30*time.Second, 300*time.Millisecond, func() (bool, error) {
|
||||||
|
_, err := sc.panel.status()
|
||||||
|
return err == nil, err
|
||||||
|
}); err != nil {
|
||||||
|
t.Fatal(err)
|
||||||
|
}
|
||||||
|
|
||||||
|
count := func() (string, error) {
|
||||||
|
return asPanel(`import sqlite3,sys
|
||||||
|
print(sqlite3.connect("/data/selfpost.db").execute("select count(*), coalesce(sum(recovered),0) from send_log where queue_id=? and status='rejected'",(sys.argv[1],)).fetchone())`, queueID)
|
||||||
|
}
|
||||||
|
if err := waitFor("the refusal written from mail.log", 90*time.Second, time.Second, func() (bool, error) {
|
||||||
|
out, err := count()
|
||||||
|
return err == nil && out == "(1, 1)", fmt.Errorf("rows (count, recovered) = %s, %v", out, err)
|
||||||
|
}); err != nil {
|
||||||
|
t.Fatal(err)
|
||||||
|
}
|
||||||
|
// Once: the next passes over the log write it no more.
|
||||||
|
time.Sleep(3 * time.Second)
|
||||||
|
if out, _ := count(); out != "(1, 1)" {
|
||||||
|
t.Fatalf("after more passes the rows are %s, want (1, 1)", out)
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|||||||
Reference in New Issue
Block a user