added email queue

This commit is contained in:
2026-08-21 04:46:46 +01:00
parent 2d2b749c54
commit 5b2936cf9d
14 changed files with 747 additions and 67 deletions
+6 -1
View File
@@ -78,11 +78,16 @@ func (d *DB) MessageVolumeByHour(hours int) ([]VolumeBucket, error) {
// DeliveryStats totals per-recipient delivery outcomes over the last `hours` hours —
// success is a recipient actually delivered/quarantined-but-accepted; failed is
// everything else (hard rejects, relay failures).
// DeliveryStats reports success vs. failed recipient counts within the window — a
// recipient still 'queued' for the background relay-queue worker (see
// internal/relay/queue.go) counts as neither: it's not a delivery failure, it just
// hasn't been attempted yet, so including it in "failed" would understate the real
// success rate for every message still in flight.
func (d *DB) DeliveryStats(hours int) (success, failed int, err error) {
since := time.Now().UTC().Add(-time.Duration(hours) * time.Hour)
err = d.QueryRow(`
SELECT COALESCE(SUM(CASE WHEN r.status = 'success' THEN 1 ELSE 0 END), 0),
COALESCE(SUM(CASE WHEN r.status != 'success' THEN 1 ELSE 0 END), 0)
COALESCE(SUM(CASE WHEN r.status NOT IN ('success', 'queued') THEN 1 ELSE 0 END), 0)
FROM esrv_email_recipient_logs r
JOIN esrv_email_logs l ON l.id = r.email_log_id
WHERE l.timestamp >= ?`, since).Scan(&success, &failed)
+117
View File
@@ -0,0 +1,117 @@
package db
import (
"encoding/json"
"time"
)
// RelayQueueRecipient is one entry of a RelayQueueItem's recipients_json — mirrors
// relay.Result's Recipient/RecipientType shape closely enough to round-trip without
// internal/db needing to import internal/relay (which would be a cycle: relay already
// imports db).
type RelayQueueRecipient struct {
Recipient string `json:"recipient"`
Type string `json:"type"`
}
// RelayQueueItem is one recipient-domain-group of in-flight outbound relay work — see
// schema.go's esrv_relay_queue comment.
type RelayQueueItem struct {
ID int64
EmailLogID int64
MailFrom string
Domain string
Recipients []RelayQueueRecipient
Content string
Status string
Attempts int
NextAttemptAt time.Time
LastError string
CreatedAt time.Time
}
// InsertRelayQueueItem queues one recipient-domain-group for delivery, due at
// nextAttemptAt (normally time.Now() for a fresh message — the worker's next tick
// picks it up promptly).
func (d *DB) InsertRelayQueueItem(emailLogID int64, mailFrom, domain string, recipients []RelayQueueRecipient, content string, nextAttemptAt time.Time) (int64, error) {
recipientsJSON, err := json.Marshal(recipients)
if err != nil {
return 0, err
}
res, err := d.Exec(`INSERT INTO esrv_relay_queue
(email_log_id, mail_from, domain, recipients_json, content, next_attempt_at)
VALUES (?, ?, ?, ?, ?, ?)`,
emailLogID, mailFrom, domain, string(recipientsJSON), content, nextAttemptAt)
if err != nil {
return 0, err
}
return res.LastInsertId()
}
// ClaimDueRelayQueueItems selects up to limit rows that are due (status='pending' and
// next_attempt_at in the past) and immediately flips them to status='sending' so a
// second worker tick can't pick the same row up again — a plain select-then-update,
// not a single atomic statement, but safe here: sqlDB.SetMaxOpenConns(1) (schema.go)
// already serializes every DB access app-wide through one connection, so there's no
// real cross-goroutine race to guard against, only "don't process the same row twice
// within one process," which this already prevents.
func (d *DB) ClaimDueRelayQueueItems(limit int) ([]RelayQueueItem, error) {
rows, err := d.Query(`SELECT id, email_log_id, mail_from, domain, recipients_json, content, attempts, next_attempt_at, created_at
FROM esrv_relay_queue WHERE status = 'pending' AND next_attempt_at <= ? ORDER BY next_attempt_at LIMIT ?`,
time.Now(), limit)
if err != nil {
return nil, err
}
var items []RelayQueueItem
for rows.Next() {
var it RelayQueueItem
var recipientsJSON, nextAttemptAt, createdAt string
if err := rows.Scan(&it.ID, &it.EmailLogID, &it.MailFrom, &it.Domain, &recipientsJSON, &it.Content, &it.Attempts, &nextAttemptAt, &createdAt); err != nil {
rows.Close()
return nil, err
}
if err := json.Unmarshal([]byte(recipientsJSON), &it.Recipients); err != nil {
rows.Close()
return nil, err
}
it.NextAttemptAt, _ = parseTime(nextAttemptAt)
it.CreatedAt, _ = parseTime(createdAt)
it.Status = "sending"
items = append(items, it)
}
if err := rows.Err(); err != nil {
rows.Close()
return nil, err
}
rows.Close()
for _, it := range items {
if _, err := d.Exec(`UPDATE esrv_relay_queue SET status = 'sending' WHERE id = ?`, it.ID); err != nil {
return nil, err
}
}
return items, nil
}
// RescheduleRelayQueueItem records a failed delivery attempt and puts the row back to
// 'pending' at the given next attempt time (retry backoff — see
// internal/relay/queue.go's retrySchedule).
func (d *DB) RescheduleRelayQueueItem(id int64, nextAttemptAt time.Time, lastError string) error {
_, err := d.Exec(`UPDATE esrv_relay_queue SET status = 'pending', attempts = attempts + 1, next_attempt_at = ?, last_error = ? WHERE id = ?`,
nextAttemptAt, lastError, id)
return err
}
func (d *DB) DeleteRelayQueueItem(id int64) error {
_, err := d.Exec(`DELETE FROM esrv_relay_queue WHERE id = ?`, id)
return err
}
// CountPendingRelayQueueItemsForEmailLog reports how many domain-groups for one
// message are still unresolved — the worker uses this to know when it's the one
// finalizing an email_log's overall status (all groups either delivered or given up).
func (d *DB) CountPendingRelayQueueItemsForEmailLog(emailLogID int64) (int, error) {
var n int
err := d.QueryRow(`SELECT COUNT(*) FROM esrv_relay_queue WHERE email_log_id = ?`, emailLogID).Scan(&n)
return n, err
}
+23
View File
@@ -24,6 +24,29 @@ func (d *DB) InsertEmailRecipientLog(l EmailRecipientLog) error {
return err
}
// UpdateEmailRecipientLogStatus resolves a placeholder "queued" recipient row (written
// at accept time, before the relay queue worker has actually attempted delivery) to
// its real outcome — matched by (email_log_id, recipient), not a stored row id, since
// EnqueueForDelivery never needs to thread individual recipient-log ids through the
// queue table. The status='queued' guard means this can never overwrite an
// already-resolved (e.g. local-delivery) row for the same address.
func (d *DB) UpdateEmailRecipientLogStatus(emailLogID int64, recipient, status, errorCode, errorMessage, serverResponse string) error {
_, err := d.Exec(`UPDATE esrv_email_recipient_logs
SET status = ?, error_code = ?, error_message = ?, server_response = ?
WHERE email_log_id = ? AND recipient = ? AND status = 'queued'`,
status, errorCode, errorMessage, serverResponse, emailLogID, recipient)
return err
}
// UpdateEmailLogStatus overwrites the parent esrv_email_logs row's stored overall
// status — called by the relay queue worker once a domain group resolves, so
// dashboard.html's "Recent Email Activity" (which reads this stored snapshot, not a
// live recompute) reflects the outcome instead of staying "queued" forever.
func (d *DB) UpdateEmailLogStatus(id int64, status string) error {
_, err := d.Exec(`UPDATE esrv_email_logs SET status = ? WHERE id = ?`, status, id)
return err
}
// InsertEmailAttachment mirrors one EmailAttachment row creation.
func (d *DB) InsertEmailAttachment(a EmailAttachment) error {
_, err := d.Exec(`INSERT INTO esrv_email_attachments
+26
View File
@@ -127,6 +127,32 @@ CREATE TABLE IF NOT EXISTS esrv_email_recipient_logs (
server_response TEXT
);
-- In-flight outbound relay work — one row per recipient-domain-group (matching how
-- RelayEmailAsync/EnqueueForDelivery already batch same-domain recipients into a
-- single SMTP transaction), so a slow/unreachable domain never holds a client's SMTP
-- session open (see internal/relay/queue.go). Purely transient: a row is deleted the
-- moment its group reaches a terminal outcome (success, or retries exhausted) —
-- esrv_email_recipient_logs is already the permanent historical record, this table is
-- operational state only, not a second copy of history.
CREATE TABLE IF NOT EXISTS esrv_relay_queue (
id INTEGER PRIMARY KEY AUTOINCREMENT,
email_log_id INTEGER NOT NULL REFERENCES esrv_email_logs(id),
mail_from TEXT NOT NULL,
domain TEXT NOT NULL,
-- JSON array of {"recipient":"...","type":"to|cc|bcc"} for this domain group.
recipients_json TEXT NOT NULL,
-- The full signed message content for this group — stored directly here (not a
-- new blob-storage subsystem) matching how esrv_email_logs.message_body already
-- stores raw content directly; rows are short-lived under normal operation.
content TEXT NOT NULL,
status TEXT NOT NULL DEFAULT 'pending', -- pending | sending
attempts INTEGER NOT NULL DEFAULT 0,
next_attempt_at DATETIME NOT NULL,
last_error TEXT NOT NULL DEFAULT '',
created_at DATETIME DEFAULT CURRENT_TIMESTAMP
);
CREATE INDEX IF NOT EXISTS idx_relay_queue_due ON esrv_relay_queue(status, next_attempt_at);
CREATE TABLE IF NOT EXISTS esrv_auth_logs (
id INTEGER PRIMARY KEY AUTOINCREMENT,
auth_type TEXT NOT NULL,
+19 -7
View File
@@ -52,24 +52,36 @@ func (r *Relay) LogEmail(cfg *ini.File, peerIP, mailFrom, toAddress, ccAddresses
return logID, nil
}
// overallStatus derives one summary status from a message's per-recipient results.
// "queued" (a relay recipient enqueued for later delivery by the background worker —
// see EnqueueForDelivery) counts as neither a success nor a failure on its own: a
// message with only queued and successful recipients isn't done yet, but nothing has
// gone wrong either, so it's "queued" rather than "partial". Once the worker resolves
// those recipients to a real outcome, UpdateEmailLogStatus overwrites this with a
// re-run of the same logic against the now-fully-resolved results.
func overallStatus(results []Result) string {
if len(results) == 0 {
return "failed"
}
success, failed := 0, 0
success, failed, queued := 0, 0, 0
for _, res := range results {
if res.Status == "success" {
switch res.Status {
case "success":
success++
} else {
case "queued":
queued++
default:
failed++
}
}
switch {
case success > 0 && failed > 0:
case failed > 0 && (success > 0 || queued > 0):
return "partial"
case success > 0:
return "relayed"
default:
case failed > 0:
return "failed"
case queued > 0:
return "queued"
default:
return "relayed"
}
}
+129
View File
@@ -0,0 +1,129 @@
package relay
import (
"sync"
"time"
"mailgoserver/internal/db"
)
// retrySchedule is the fixed backoff between delivery attempts (five tries total, ~17h
// worst case before giving up) — fixed, not admin-configurable, matching the
// auto-reply loop-prevention window's own "fixed, keeps this simple" precedent
// elsewhere in this codebase.
var retrySchedule = []time.Duration{time.Minute, 15 * time.Minute, time.Hour, 4 * time.Hour, 12 * time.Hour}
// ProcessQueueOnce claims up to maxBatch due esrv_relay_queue rows and attempts
// delivery for each with up to maxConcurrent goroutines running at once — bounded so a
// large backlog can never spawn unbounded outbound connections. Meant to be called on
// a ticker (see main.go's runRelayQueueWorker); a no-op when nothing is due.
func (r *Relay) ProcessQueueOnce(maxConcurrent, maxBatch int) {
items, err := r.DB.ClaimDueRelayQueueItems(maxBatch)
if err != nil {
r.Logger.Error("relay queue: claim due items: %v", err)
return
}
if len(items) == 0 {
return
}
sem := make(chan struct{}, maxConcurrent)
var wg sync.WaitGroup
for _, item := range items {
wg.Add(1)
sem <- struct{}{}
go func(item db.RelayQueueItem) {
defer wg.Done()
defer func() { <-sem }()
r.processQueueItem(item)
}(item)
}
wg.Wait()
}
// processQueueItem attempts one recipient-domain-group's delivery via the existing
// deliverToDomain (same MX-iteration/STARTTLS/MTA-STS logic RelayEmailAsync's
// synchronous path already uses — this is the only new call site, not a duplicate
// implementation). On success or final failure, updates the placeholder "queued"
// recipient-log rows (written by Session.Data at accept time) to their real outcome
// and removes the queue row. On a failure with retries remaining, reschedules instead.
func (r *Relay) processQueueItem(item db.RelayQueueItem) {
rcpts := make([]string, len(item.Recipients))
for i, rec := range item.Recipients {
rcpts[i] = rec.Recipient
}
status, serverResp, errCode, errMsg := r.deliverToDomain(item.Domain, item.MailFrom, rcpts, item.Content)
if status == "success" {
for _, rec := range item.Recipients {
if err := r.DB.UpdateEmailRecipientLogStatus(item.EmailLogID, rec.Recipient, "success", "", "", serverResp); err != nil {
r.Logger.Error("relay queue: update recipient log for %s: %v", rec.Recipient, err)
}
}
if err := r.DB.DeleteRelayQueueItem(item.ID); err != nil {
r.Logger.Error("relay queue: delete item %d: %v", item.ID, err)
}
r.finalizeEmailLogStatusIfDone(item.EmailLogID)
return
}
if item.Attempts < len(retrySchedule) {
next := time.Now().Add(retrySchedule[item.Attempts])
if err := r.DB.RescheduleRelayQueueItem(item.ID, next, errMsg); err != nil {
r.Logger.Error("relay queue: reschedule item %d: %v", item.ID, err)
}
return
}
// Retries exhausted — final failure. Resolve the recipient rows, drop the queue
// row, and bounce back to the original sender (skipped for a null sender, the
// same rule Session.Data's own immediate-bounce path already follows — replying
// to a bounce is the classic loop bug). Unlike that synchronous path, there's no
// live peer connection here to gate the bounce on IsIPBlacklisted — by the time
// retries are exhausted (minutes to hours later), this is no longer a live
// mailbox-enumeration oracle the way an instant response would be.
var failedResults []Result
for _, rec := range item.Recipients {
if err := r.DB.UpdateEmailRecipientLogStatus(item.EmailLogID, rec.Recipient, "failed", errCode, errMsg, serverResp); err != nil {
r.Logger.Error("relay queue: update recipient log for %s: %v", rec.Recipient, err)
}
failedResults = append(failedResults, Result{Recipient: rec.Recipient, RecipientType: rec.Type, Status: "failed", ErrorCode: errCode, ErrorMessage: errMsg, ServerResponse: serverResp})
}
if err := r.DB.DeleteRelayQueueItem(item.ID); err != nil {
r.Logger.Error("relay queue: delete item %d: %v", item.ID, err)
}
if item.MailFrom != "" {
if err := r.SendBounce(item.MailFrom, "", "", failedResults); err != nil {
r.Logger.Error("relay queue: send bounce to %s: %v", item.MailFrom, err)
}
}
r.finalizeEmailLogStatusIfDone(item.EmailLogID)
}
// finalizeEmailLogStatusIfDone recomputes and stores the parent email_log's overall
// status once every domain-group for it has resolved (no esrv_relay_queue rows left
// referencing it) — recomputed from the now-current recipient-log rows via the same
// overallStatus logic LogEmail used at accept time, so a message that started
// "queued" naturally settles into relayed/partial/failed once nothing's left pending.
func (r *Relay) finalizeEmailLogStatusIfDone(emailLogID int64) {
pending, err := r.DB.CountPendingRelayQueueItemsForEmailLog(emailLogID)
if err != nil {
r.Logger.Error("relay queue: count pending for email_log %d: %v", emailLogID, err)
return
}
if pending > 0 {
return
}
recipients, err := r.DB.ListRecipientLogsForEmail(emailLogID)
if err != nil {
r.Logger.Error("relay queue: list recipients for email_log %d: %v", emailLogID, err)
return
}
results := make([]Result, len(recipients))
for i, rec := range recipients {
results[i] = Result{Status: rec.Status}
}
if err := r.DB.UpdateEmailLogStatus(emailLogID, overallStatus(results)); err != nil {
r.Logger.Error("relay queue: update email_log %d status: %v", emailLogID, err)
}
}
+192
View File
@@ -0,0 +1,192 @@
package relay
import (
"net"
"os"
"testing"
"time"
"mailgoserver/internal/db"
"mailgoserver/internal/toolbox"
)
// testDB opens a fresh temp-file sqlite DB with the full schema applied — same
// pattern smtpserver's newTestBackend uses (db.Open runs schema.go's CREATE TABLE
// statements, including esrv_relay_queue).
func testDB(t *testing.T) *db.DB {
t.Helper()
f, err := os.CreateTemp("", "relay-queue-test-*.db")
if err != nil {
t.Fatal(err)
}
f.Close()
t.Cleanup(func() { os.Remove(f.Name()) })
database, err := db.Open(f.Name())
if err != nil {
t.Fatal(err)
}
t.Cleanup(func() { database.Close() })
return database
}
// fixedMXLookup resolves any domain to 127.0.0.1 — combined with Relay.port
// (overriding the real MX port 25), this points deliverToDomain at a local
// stand-in MTA regardless of what domain is being "relayed" to.
func fixedMXLookup(domain string) ([]*net.MX, error) {
return []*net.MX{{Host: "127.0.0.1.", Pref: 10}}, nil
}
// failingMXLookup simulates every MX lookup failing (e.g. an unreachable/nonexistent
// domain) — deliverToDomain fails immediately, no connection ever attempted.
func failingMXLookup(domain string) ([]*net.MX, error) {
return nil, &net.DNSError{Err: "no such host", Name: domain, IsNotFound: true}
}
func TestProcessQueueOnceDeliversSuccessfully(t *testing.T) {
cert, caPool := genTestCert(t)
port, received, _ := startTestMTA(t, cert)
database := testDB(t)
r := &Relay{
DB: database, Hostname: "sender.example.com", Timeout: 5 * time.Second,
Logger: toolbox.GetLogger("relay_test"), port: port, rootCAs: caPool, mxLookup: fixedMXLookup,
}
logID, err := database.InsertEmailLog(db.EmailLog{MailFrom: "from@example.com", ToAddress: "to@dest.example", Status: "queued"})
if err != nil {
t.Fatal(err)
}
if err := database.InsertEmailRecipientLog(db.EmailRecipientLog{EmailLogID: logID, Recipient: "to@dest.example", RecipientType: "to", Status: "queued"}); err != nil {
t.Fatal(err)
}
if err := r.EnqueueForDelivery(logID, "from@example.com", []string{"to@dest.example"}, []string{"to"}, "Subject: hi\r\n\r\nbody"); err != nil {
t.Fatal(err)
}
r.ProcessQueueOnce(5, 10)
select {
case <-received:
case <-time.After(2 * time.Second):
t.Fatal("expected the test MTA to receive the queued message")
}
recipients, err := database.ListRecipientLogsForEmail(logID)
if err != nil {
t.Fatal(err)
}
if len(recipients) != 1 || recipients[0].Status != "success" {
t.Fatalf("expected recipient status success, got %+v", recipients)
}
pending, err := database.CountPendingRelayQueueItemsForEmailLog(logID)
if err != nil {
t.Fatal(err)
}
if pending != 0 {
t.Fatalf("expected the queue row to be gone after delivery, got %d pending", pending)
}
log, err := database.GetEmailLogByID(logID)
if err != nil {
t.Fatal(err)
}
if log.Status != "relayed" {
t.Errorf("expected email_log status 'relayed', got %q", log.Status)
}
}
func TestProcessQueueOnceReschedulesOnFailure(t *testing.T) {
database := testDB(t)
r := &Relay{
DB: database, Hostname: "sender.example.com", Timeout: 5 * time.Second,
Logger: toolbox.GetLogger("relay_test"), mxLookup: failingMXLookup,
}
logID, err := database.InsertEmailLog(db.EmailLog{MailFrom: "from@example.com", ToAddress: "to@dest.example", Status: "queued"})
if err != nil {
t.Fatal(err)
}
if err := database.InsertEmailRecipientLog(db.EmailRecipientLog{EmailLogID: logID, Recipient: "to@dest.example", RecipientType: "to", Status: "queued"}); err != nil {
t.Fatal(err)
}
if err := r.EnqueueForDelivery(logID, "from@example.com", []string{"to@dest.example"}, []string{"to"}, "Subject: hi\r\n\r\nbody"); err != nil {
t.Fatal(err)
}
r.ProcessQueueOnce(5, 10)
pending, err := database.CountPendingRelayQueueItemsForEmailLog(logID)
if err != nil {
t.Fatal(err)
}
if pending != 1 {
t.Fatalf("expected the queue row to still exist (rescheduled, not exhausted), got %d", pending)
}
recipients, err := database.ListRecipientLogsForEmail(logID)
if err != nil {
t.Fatal(err)
}
if recipients[0].Status != "queued" {
t.Errorf("expected recipient to remain 'queued' pending retry, got %q", recipients[0].Status)
}
}
// TestProcessQueueOnceExhaustsRetriesAndBounces short-circuits retrySchedule so the
// test doesn't wait real hours — after every scheduled attempt fails, the queue row
// should be dropped, the recipient marked failed, and a bounce delivered back to the
// original sender's own inbox (via SendBounce's relay-out path, using the same
// always-fails mxLookup — proving the bounce attempt doesn't crash even when it too
// can't be delivered, matching real MTA behavior of just logging the failed bounce).
func TestProcessQueueOnceExhaustsRetriesAndBounces(t *testing.T) {
orig := retrySchedule
retrySchedule = []time.Duration{0, 0}
t.Cleanup(func() { retrySchedule = orig })
database := testDB(t)
r := &Relay{
DB: database, Hostname: "sender.example.com", Timeout: 5 * time.Second,
Logger: toolbox.GetLogger("relay_test"), mxLookup: failingMXLookup,
}
logID, err := database.InsertEmailLog(db.EmailLog{MailFrom: "from@example.com", ToAddress: "to@dest.example", Status: "queued"})
if err != nil {
t.Fatal(err)
}
if err := database.InsertEmailRecipientLog(db.EmailRecipientLog{EmailLogID: logID, Recipient: "to@dest.example", RecipientType: "to", Status: "queued"}); err != nil {
t.Fatal(err)
}
if err := r.EnqueueForDelivery(logID, "from@example.com", []string{"to@dest.example"}, []string{"to"}, "Subject: hi\r\n\r\nbody"); err != nil {
t.Fatal(err)
}
// One tick per scheduled retry, plus one for the initial attempt — each due
// immediately since the schedule above is all-zero backoff.
for i := 0; i <= len(retrySchedule); i++ {
r.ProcessQueueOnce(5, 10)
}
pending, err := database.CountPendingRelayQueueItemsForEmailLog(logID)
if err != nil {
t.Fatal(err)
}
if pending != 0 {
t.Fatalf("expected the queue row to be gone once retries are exhausted, got %d pending", pending)
}
recipients, err := database.ListRecipientLogsForEmail(logID)
if err != nil {
t.Fatal(err)
}
if recipients[0].Status != "failed" {
t.Errorf("expected recipient status 'failed' after exhausting retries, got %q", recipients[0].Status)
}
log, err := database.GetEmailLogByID(logID)
if err != nil {
t.Fatal(err)
}
if log.Status != "failed" {
t.Errorf("expected email_log status 'failed', got %q", log.Status)
}
}
+71 -39
View File
@@ -68,6 +68,10 @@ type Relay struct {
// outbound HTTPS call. nil (the normal, non-test case) means "use the real
// mtaSTSEnforced, which does a live HTTPS lookup."
mtaSTSCheck func(domain string) bool
// mxLookup overrides net.LookupMX for tests only — lets a test point deliverToDomain
// at a local stand-in MTA (combined with port above) without a real DNS MX record.
// nil (the normal, non-test case) means "use net.LookupMX".
mxLookup func(domain string) ([]*net.MX, error)
}
func (r *Relay) targetPort() int {
@@ -116,66 +120,90 @@ func prepareEmailForRecipient(content string) string {
return strings.Join(kept, "\r\n") + "\r\n\r\n" + body
}
// RelayEmailAsync mirrors email_relay.relay_email_async: TO/CC recipients are grouped
// by domain and delivered in one shared SMTP transaction per domain; each BCC recipient
// gets its own transaction. MX hosts are tried once each, in preference order, with
// opportunistic STARTTLS.
func (r *Relay) RelayEmailAsync(mailFrom string, rcptTos []string, content string, recipientTypes []string) []Result {
// recipientEntry pairs a recipient address with its to/cc/bcc envelope role.
type recipientEntry struct {
Recipient string
Type string // "to" | "cc" | "bcc"
}
// groupRecipientsByDomain groups rcptTos by recipient domain, mirroring
// email_relay.relay_email_async: to/cc recipients on the same domain share one group
// (and so, later, one SMTP transaction); each bcc recipient gets its own
// single-entry group (keyed distinctly so it never merges with a to/cc group on the
// same domain) — bcc must never appear in a shared transaction's visible recipient
// list. Shared by RelayEmailAsync and EnqueueForDelivery so the two paths can't drift
// on this grouping logic.
func groupRecipientsByDomain(rcptTos, recipientTypes []string) map[string][]recipientEntry {
if len(recipientTypes) != len(rcptTos) {
recipientTypes = make([]string, len(rcptTos))
for i := range recipientTypes {
recipientTypes[i] = "to"
}
}
type group struct{ to, cc []string }
domainGroups := map[string]*group{}
var bccList []string
groups := map[string][]recipientEntry{}
for i, rcpt := range rcptTos {
typ := recipientTypes[i]
if typ == "bcc" {
bccList = append(bccList, rcpt)
groups["bcc:"+rcpt] = []recipientEntry{{Recipient: rcpt, Type: "bcc"}}
continue
}
domain := domainOf(rcpt)
g, ok := domainGroups[domain]
if !ok {
g = &group{}
domainGroups[domain] = g
}
if typ == "cc" {
g.cc = append(g.cc, rcpt)
} else {
g.to = append(g.to, rcpt)
}
groups[domain] = append(groups[domain], recipientEntry{Recipient: rcpt, Type: typ})
}
return groups
}
var results []Result
// RelayEmailAsync mirrors email_relay.relay_email_async: TO/CC recipients are grouped
// by domain and delivered in one shared SMTP transaction per domain; each BCC recipient
// gets its own transaction. MX hosts are tried once each, in preference order, with
// opportunistic STARTTLS. Delivers synchronously — this call blocks until every group
// has been attempted. Used for forwarding, auto-reply, and SendBounce's own relay-out
// path, all low-volume and already fire-and-forget from their own callers; the main
// inbound-relay path uses EnqueueForDelivery below instead, precisely to avoid this
// synchronous-until-every-domain-answers behavior blocking a client's SMTP session.
func (r *Relay) RelayEmailAsync(mailFrom string, rcptTos []string, content string, recipientTypes []string) []Result {
groups := groupRecipientsByDomain(rcptTos, recipientTypes)
prepared := prepareEmailForRecipient(content)
for domain, g := range domainGroups {
all := append(append([]string{}, g.to...), g.cc...)
if len(all) == 0 {
continue
var results []Result
for _, entries := range groups {
all := make([]string, len(entries))
for i, e := range entries {
all[i] = e.Recipient
}
status, serverResp, errCode, errMsg := r.deliverToDomain(domain, mailFrom, all, prepared)
for _, rcpt := range g.to {
results = append(results, Result{Recipient: rcpt, RecipientType: "to", Status: status, ErrorCode: errCode, ErrorMessage: errMsg, ServerResponse: serverResp})
}
for _, rcpt := range g.cc {
results = append(results, Result{Recipient: rcpt, RecipientType: "cc", Status: status, ErrorCode: errCode, ErrorMessage: errMsg, ServerResponse: serverResp})
targetDomain := domainOf(entries[0].Recipient)
status, serverResp, errCode, errMsg := r.deliverToDomain(targetDomain, mailFrom, all, prepared)
for _, e := range entries {
results = append(results, Result{Recipient: e.Recipient, RecipientType: e.Type, Status: status, ErrorCode: errCode, ErrorMessage: errMsg, ServerResponse: serverResp})
}
}
for _, bcc := range bccList {
status, serverResp, errCode, errMsg := r.deliverToDomain(domainOf(bcc), mailFrom, []string{bcc}, prepared)
results = append(results, Result{Recipient: bcc, RecipientType: "bcc", Status: status, ErrorCode: errCode, ErrorMessage: errMsg, ServerResponse: serverResp})
}
return results
}
// EnqueueForDelivery groups rcptTos by recipient domain (same grouping RelayEmailAsync
// uses) and inserts one esrv_relay_queue row per group, due immediately — actual
// delivery happens later, in the background worker (queue.go's ProcessQueueOnce), not
// inline here. Returns as soon as the rows are written, so the caller (Session.Data)
// can respond to the client right away regardless of how slow or unreachable the
// destination domains turn out to be.
func (r *Relay) EnqueueForDelivery(emailLogID int64, mailFrom string, rcptTos, recipientTypes []string, content string) error {
groups := groupRecipientsByDomain(rcptTos, recipientTypes)
prepared := prepareEmailForRecipient(content)
now := time.Now()
for _, entries := range groups {
targetDomain := domainOf(entries[0].Recipient)
queueRecipients := make([]db.RelayQueueRecipient, len(entries))
for i, e := range entries {
queueRecipients[i] = db.RelayQueueRecipient{Recipient: e.Recipient, Type: e.Type}
}
if _, err := r.DB.InsertRelayQueueItem(emailLogID, mailFrom, targetDomain, queueRecipients, prepared, now); err != nil {
return err
}
}
return nil
}
func domainOf(address string) string {
if i := strings.LastIndex(address, "@"); i >= 0 {
return strings.ToLower(address[i+1:])
@@ -186,7 +214,11 @@ func domainOf(address string) string {
// deliverToDomain resolves MX hosts for domain and tries each in preference order once,
// mirroring the MX-iteration loop in relay_email_async.
func (r *Relay) deliverToDomain(domain, mailFrom string, rcpts []string, content string) (status, serverResponse, errorCode, errorMessage string) {
mxRecords, err := net.LookupMX(domain)
lookupMX := r.mxLookup
if lookupMX == nil {
lookupMX = net.LookupMX
}
mxRecords, err := lookupMX(domain)
if err != nil || len(mxRecords) == 0 {
return "failed", "", "MX", fmt.Sprintf("MX lookup failed for %s: %v", domain, err)
}
+99
View File
@@ -0,0 +1,99 @@
package smtpserver
import (
"net/smtp"
"testing"
"time"
)
// TestRelayRecipientGetsImmediateResponseAndQueuesForDelivery proves the async relay
// queue's core promise: a client sending to a non-local recipient gets its DATA
// response right away, without the session blocking on real MX resolution/delivery —
// the message is enqueued (esrv_relay_queue) and the email_log is left "queued"
// rather than relayed inline. elsewhere.example has no real MX record (RFC 2606
// reserved, confirmed to fail DNS lookup in well under a second), so under the old
// synchronous RelayEmailAsync path this same transaction would have blocked on that
// failed lookup before responding — here it must not.
func TestRelayRecipientGetsImmediateResponseAndQueuesForDelivery(t *testing.T) {
backend, _ := newTestBackendWithMailbox(t)
addr := startTestServer(t, backend)
c, err := smtp.Dial(addr)
if err != nil {
t.Fatal(err)
}
defer c.Close()
if err := c.Auth(smtp.PlainAuth("", "test@example.com", "testpass123", "127.0.0.1")); err != nil {
t.Fatalf("auth: %v", err)
}
if err := c.Mail("test@example.com"); err != nil {
t.Fatalf("MAIL FROM: %v", err)
}
if err := c.Rcpt("someone@elsewhere.example"); err != nil {
t.Fatalf("RCPT: %v", err)
}
w, err := c.Data()
if err != nil {
t.Fatal(err)
}
w.Write([]byte("Subject: hi\r\n\r\nhi"))
start := time.Now()
if err := w.Close(); err != nil {
t.Fatalf("expected DATA to be accepted (queued for later delivery), got: %v", err)
}
if elapsed := time.Since(start); elapsed > 2*time.Second {
t.Errorf("expected an immediate response decoupled from relay delivery, took %v", elapsed)
}
var logID int64
var status string
if err := backend.DB.QueryRow(`SELECT id, status FROM esrv_email_logs ORDER BY id DESC LIMIT 1`).Scan(&logID, &status); err != nil {
t.Fatal(err)
}
if status != "queued" {
t.Errorf("expected email_log status 'queued' immediately after accept, got %q", status)
}
var recipientStatus string
if err := backend.DB.QueryRow(`SELECT status FROM esrv_email_recipient_logs WHERE email_log_id = ?`, logID).Scan(&recipientStatus); err != nil {
t.Fatal(err)
}
if recipientStatus != "queued" {
t.Errorf("expected recipient log status 'queued', got %q", recipientStatus)
}
var pending int
if err := backend.DB.QueryRow(`SELECT COUNT(*) FROM esrv_relay_queue WHERE email_log_id = ?`, logID).Scan(&pending); err != nil {
t.Fatal(err)
}
if pending != 1 {
t.Fatalf("expected exactly one esrv_relay_queue row for this message, got %d", pending)
}
// Now run the background worker directly (main.go normally does this on a ticker).
// elsewhere.example has no MX, so the first attempt fails — with retries
// remaining (see internal/relay/queue.go's retrySchedule), that's a reschedule,
// not an immediate bounce: the row stays, attempts increments, and the email_log
// stays "queued" rather than settling to "failed" on the very first try. Full
// exhaustion-to-bounce behavior is covered by internal/relay's own
// TestProcessQueueOnceExhaustsRetriesAndBounces.
backend.Relay.ProcessQueueOnce(5, 10)
var attempts int
if err := backend.DB.QueryRow(`SELECT COUNT(*), COALESCE(MAX(attempts), 0) FROM esrv_relay_queue WHERE email_log_id = ?`, logID).Scan(&pending, &attempts); err != nil {
t.Fatal(err)
}
if pending != 1 {
t.Fatalf("expected the queue row to still exist (rescheduled), got %d pending", pending)
}
if attempts != 1 {
t.Errorf("expected one recorded attempt after the worker's first pass, got %d", attempts)
}
if err := backend.DB.QueryRow(`SELECT status FROM esrv_email_logs WHERE id = ?`, logID).Scan(&status); err != nil {
t.Fatal(err)
}
if status != "queued" {
t.Errorf("expected email_log status to remain 'queued' pending retry, got %q", status)
}
}
+22 -3
View File
@@ -364,26 +364,40 @@ func (s *Session) Data(r io.Reader) error {
}
}
// Relay recipients are never delivered inline here — that would block this client's
// DATA response on however long the recipient domain's MX takes to answer (the
// concurrency/load issue this queue exists to fix). Instead a "queued" placeholder
// Result is recorded now and the real attempt happens later via EnqueueForDelivery
// (below, once logID exists) + the background worker in internal/relay/queue.go.
var results []relay.Result
if len(relayRcpts) > 0 {
if limited, err := s.domainSendRateLimited(senderDomain); err != nil {
s.backend.Logger.Error("send-rate-limit check for domain %s: %v", senderDomain, err)
results = s.backend.Relay.RelayEmailAsync(s.mailFrom, relayRcpts, signedContent, relayTypes)
for i, rcpt := range relayRcpts {
results = append(results, relay.Result{Recipient: rcpt, RecipientType: relayTypes[i], Status: "queued"})
}
} else if limited {
for i, rcpt := range relayRcpts {
results = append(results, relay.Result{Recipient: rcpt, RecipientType: relayTypes[i], Status: "failed", ErrorCode: "450", ErrorMessage: "Sending rate limit exceeded for domain " + senderDomain + ", try again later"})
}
relayRcpts, relayTypes = nil, nil
} else {
results = s.backend.Relay.RelayEmailAsync(s.mailFrom, relayRcpts, signedContent, relayTypes)
for i, rcpt := range relayRcpts {
results = append(results, relay.Result{Recipient: rcpt, RecipientType: relayTypes[i], Status: "queued"})
}
}
}
if len(localRcpts) > 0 {
results = append(results, s.deliverLocally(localRcpts, localTypes, signedContent, messageID, subject, fromHeader)...)
}
// "queued" is neither a known success nor a known failure yet — the worker resolves
// it later (and bounces then, on genuine final failure). Only count actual failures
// here so the immediate bounce-on-partial-failure block below doesn't fire for a
// message that's simply still in flight.
var failed []relay.Result
for _, res := range results {
if res.Status != "success" {
if res.Status != "success" && res.Status != "queued" {
failed = append(failed, res)
}
}
@@ -448,6 +462,11 @@ func (s *Session) Data(r io.Reader) error {
s.backend.Logger.Error("Failed to record attachment %s: %v", a.Filename, err)
}
}
if len(relayRcpts) > 0 {
if err := s.backend.Relay.EnqueueForDelivery(logID, s.mailFrom, relayRcpts, relayTypes, signedContent); err != nil {
s.backend.Logger.Error("Failed to enqueue relay delivery: %v", err)
}
}
}
if allSucceeded {
+23 -13
View File
@@ -71,7 +71,7 @@ func (a *App) funcMap() template.FuncMap {
}
return "?"
},
"dotToDash": func(s string) string { return strings.ReplaceAll(s, ".", "-") },
"dotToDash": func(s string) string { return strings.ReplaceAll(s, ".", "-") },
// daysSince is a key/cert's age in whole days, for the DKIM admin page's
// rotation-due badge — 0 for a zero-value/future time rather than negative.
"daysSince": func(t time.Time) int {
@@ -84,8 +84,8 @@ func (a *App) funcMap() template.FuncMap {
}
return d
},
"add": func(a, b int) int { return a + b },
"sub": func(a, b int) int { return a - b },
"add": func(a, b int) int { return a + b },
"sub": func(a, b int) int { return a - b },
// pct is part/total as a 0-100 int, 0 when total is 0 (avoids a div-by-zero
// NaN%-width bar on the monitoring page when a bucket/domain/mailbox has no
// data yet). Accepts int or int64 for either argument — the monitoring page
@@ -98,7 +98,7 @@ func (a *App) funcMap() template.FuncMap {
}
return int(p * 100 / t)
},
"eq2": func(a, b any) bool { return fmt.Sprint(a) == fmt.Sprint(b) },
"eq2": func(a, b any) bool { return fmt.Sprint(a) == fmt.Sprint(b) },
// dget looks up an optional map key, returning "" if absent — mirrors Jinja's
// `x if x is defined else ''` pattern used for context vars only some pages set
// (e.g. sidebar badge counts, which only dashboard passes).
@@ -111,24 +111,34 @@ func (a *App) funcMap() template.FuncMap {
"list": func(items ...string) []string { return items },
"isStandardFolder": isStandardFolder,
"folderIcon": folderIcon,
// emailOverallStatus mirrors the delivered/failed selectattr computation
// dashboard.html and logs.html both do in the Python templates.
// emailOverallStatus mirrors internal/relay/log.go's overallStatus (kept as a
// separate copy since this one recomputes live from current recipient rows at
// render time, not from a stored snapshot — so a message whose relay portion
// was still "queued" when logged naturally shows its resolved outcome here
// once the background relay-queue worker updates those rows, no extra
// plumbing needed). "queued" (a relay recipient not yet attempted) counts as
// neither delivered nor failed on its own.
"emailOverallStatus": func(recipients []db.EmailRecipientLog) string {
delivered, failed := 0, 0
delivered, failed, queued := 0, 0, 0
for _, r := range recipients {
if r.Status == "success" {
switch r.Status {
case "success":
delivered++
} else {
case "queued":
queued++
default:
failed++
}
}
switch {
case delivered > 0 && failed > 0:
case failed > 0 && (delivered > 0 || queued > 0):
return "partial"
case delivered > 0:
return "relayed"
default:
case failed > 0:
return "failed"
case queued > 0:
return "queued"
default:
return "relayed"
}
},
}
+2
View File
@@ -172,6 +172,8 @@
<span class="badge bg-success"><i class="bi bi-check-circle me-1"></i>Sent</span>
{{else if eq .Status "partial"}}
<span class="badge bg-warning text-dark"><i class="bi bi-exclamation-triangle me-1"></i>Partial Fail</span>
{{else if eq .Status "queued"}}
<span class="badge bg-info text-dark"><i class="bi bi-clock-history me-1"></i>Queued</span>
{{else}}
<span class="badge bg-danger"><i class="bi bi-x-circle me-1"></i>Failed</span>
{{end}}
+5 -4
View File
@@ -8,6 +8,7 @@
.log-success { border-left-color: #198754; }
.log-failed { border-left-color: #dc3545; }
.log-partial { border-left-color: #fd7e14; }
.log-queued { border-left-color: #0dcaf0; }
</style>
{{end}}
@@ -47,7 +48,7 @@
{{if eq .type "email"}}
{{$log := .data}}
{{$overall := emailOverallStatus .recipients}}
<div class="log-entry log-email log-{{if eq $overall "relayed"}}success{{else if eq $overall "partial"}}partial{{else}}failed{{end}}">
<div class="log-entry log-email log-{{if eq $overall "relayed"}}success{{else if eq $overall "partial"}}partial{{else if eq $overall "queued"}}queued{{else}}failed{{end}}">
<div class="d-flex justify-content-between align-items-start mb-2">
<div>
<span class="badge bg-primary me-2">EMAIL</span>
@@ -58,7 +59,7 @@
<small class="text-muted">{{strftime "%Y-%m-%d %H:%M:%S" $log.Timestamp}}</small>
</div>
<div class="row">
<div class="col-md-6"><strong>Status:</strong> {{if eq $overall "relayed"}}<span class="text-success">Sent Successfully</span>{{else if eq $overall "partial"}}<span class="text-warning">Partial Fail</span>{{else}}<span class="text-danger">Failed</span>{{end}}</div>
<div class="col-md-6"><strong>Status:</strong> {{if eq $overall "relayed"}}<span class="text-success">Sent Successfully</span>{{else if eq $overall "partial"}}<span class="text-warning">Partial Fail</span>{{else if eq $overall "queued"}}<span class="text-info">Queued</span>{{else}}<span class="text-danger">Failed</span>{{end}}</div>
<div class="col-md-6"><strong>Message ID:</strong> <code>{{$log.MessageID}}</code></div>
</div>
{{if $log.Subject}}<div class="mt-2"><strong>Subject:</strong> {{$log.Subject}}</div>{{end}}
@@ -101,7 +102,7 @@
<small class="text-muted">{{strftime "%Y-%m-%d %H:%M:%S" .Timestamp}}</small>
</div>
<div class="row">
<div class="col-md-3"><strong>Status:</strong> {{if eq $overall "relayed"}}<span class="text-success">Sent</span>{{else if eq $overall "partial"}}<span class="text-warning">Partial Fail</span>{{else}}<span class="text-danger">Failed</span>{{end}}</div>
<div class="col-md-3"><strong>Status:</strong> {{if eq $overall "relayed"}}<span class="text-success">Sent</span>{{else if eq $overall "partial"}}<span class="text-warning">Partial Fail</span>{{else if eq $overall "queued"}}<span class="text-info">Queued</span>{{else}}<span class="text-danger">Failed</span>{{end}}</div>
<div class="col-md-3"><strong>Peer:</strong> <code>{{.PeerIP}}</code></div>
<div class="col-md-6"><strong>Message ID:</strong> <code>{{.MessageID}}</code></div>
</div>
@@ -111,7 +112,7 @@
<ul class="list-group">
{{range $recs}}
<li class="list-group-item d-flex justify-content-between align-items-center">
<span><strong>{{upper .RecipientType}}:</strong> {{.Recipient}} {{if eq .Status "success"}}<span class="badge bg-success ms-2">Delivered</span>{{else}}<span class="badge bg-danger ms-2">Failed</span>{{end}}</span>
<span><strong>{{upper .RecipientType}}:</strong> {{.Recipient}} {{if eq .Status "success"}}<span class="badge bg-success ms-2">Delivered</span>{{else if eq .Status "queued"}}<span class="badge bg-info text-dark ms-2">Queued</span>{{else}}<span class="badge bg-danger ms-2">Failed</span>{{end}}</span>
{{if or .ErrorCode .ErrorMessage}}<span class="text-danger ms-2">{{.ErrorCode}} {{.ErrorMessage}}</span>{{end}}
</li>
{{end}}
+13
View File
@@ -451,6 +451,19 @@ func main() {
}
go runGlobalDKIMRotation()
// Delivers messages accepted onto esrv_relay_queue by Session.Data (see
// internal/relay/queue.go) — a 5s tick keeps delivery prompt without polling too
// aggressively; 10 concurrent deliveries / 50 per tick are fixed, not config, same
// "keeps this simple" precedent as retrySchedule.
runRelayQueueWorker := func() {
ticker := time.NewTicker(5 * time.Second)
defer ticker.Stop()
for range ticker.C {
relayer.ProcessQueueOnce(10, 50)
}
}
go runRelayQueueWorker()
// Shared by both the -smtp-only branch below and the full-server path at the
// bottom of main: waits for SIGINT/SIGTERM, then shuts down whatever server
// handles it's given (nil-safe — a branch that never started a given server just