diff --git a/modules/mesh-mail/cmd/mesh-mail/outcome_test.go b/modules/mesh-mail/cmd/mesh-mail/outcome_test.go index 367d4dca..f58168d5 100644 --- a/modules/mesh-mail/cmd/mesh-mail/outcome_test.go +++ b/modules/mesh-mail/cmd/mesh-mail/outcome_test.go @@ -186,3 +186,48 @@ func TestRecordOutcomeStillRecordsFailedWhenTheTellsPendingIndexCannotBeWritten( t.Fatalf("emitted %d time(s) despite the index failing", len(emit.calls)) } } + +// review round 1 finding 5: if writing "sent" cannot be kept (even retried on a changed revision), the +// message is never acknowledged and mail.send.sent is never emitted — a mail actually sent is never +// silently announced successful when the record never actually carried it. +func TestRecordOutcomeOnSentDoesNotAckOrEmitWhenTheWriteCannotBeKept(t *testing.T) { + req, claimed, rev, sends := outcomeTestClaim(t, 1) + sends.failKey, sends.failErr = req.ID, errors.New("the store is down") + emit := &memEmit{} + + d, action, _, err := recordOutcome(sends, emit.emit, req, claimed, rev, nil, judgedAt.Add(2*time.Minute)) + if err == nil { + t.Fatalf("the write failure was not reported") + } + if action != actionLeave { + t.Fatalf("action: %v, want actionLeave (left to the bus, never acked)", action) + } + if len(emit.calls) != 0 { + t.Fatalf("emitted mail.send.sent despite the write never being kept: %+v", emit.calls) + } + // The kept record is unaffected: still "sending", as claimQueuedSend originally left it. + kept, _, ok, kerr := getSend(sends, req.ID) + if kerr != nil || !ok || kept.Decided == nil || kept.Decided.Outcome != "sending" { + t.Fatalf("the record changed despite the write failing: %v %v %+v (returned %+v)", kerr, ok, kept.Decided, d) + } +} + +// Same finding, for a failed outcome (refused): the message is left to the bus, never terminated, and +// mail.send.failed is never emitted, when the write itself cannot be kept. +func TestRecordOutcomeOnRefusedDoesNotTerminateOrEmitWhenTheWriteCannotBeKept(t *testing.T) { + req, claimed, rev, sends := outcomeTestClaim(t, 1) + sends.failKey, sends.failErr = req.ID, errors.New("the store is down") + emit := &memEmit{} + + _, action, _, err := recordOutcome(sends, emit.emit, req, claimed, rev, &SendError{Outcome: Refused, Err: errors.New("550 no such mailbox")}, + judgedAt.Add(2*time.Minute)) + if err == nil { + t.Fatalf("the write failure was not reported") + } + if action != actionLeave { + t.Fatalf("action: %v, want actionLeave", action) + } + if len(emit.calls) != 0 { + t.Fatalf("emitted mail.send.failed despite the write never being kept: %+v", emit.calls) + } +} diff --git a/modules/mesh-mail/cmd/mesh-mail/send.go b/modules/mesh-mail/cmd/mesh-mail/send.go index 61b8815a..39a9d7b2 100644 --- a/modules/mesh-mail/cmd/mesh-mail/send.go +++ b/modules/mesh-mail/cmd/mesh-mail/send.go @@ -893,13 +893,18 @@ const MostAttempts = 5 // recordOutcome has written the decision: Ack (sent), NakWithDelay (retrying, not the last attempt yet) or // Term (failed, or not proven — the bus is never asked to redeliver those; a dead letter past the fifth // attempt is still reached by Term, since clause 10 records failed itself rather than waiting for the bus's -// own max-deliveries to notice). +// own max-deliveries to notice). actionLeave is none of these: the record's own write could not be kept +// (even after a retry on a changed revision), so nothing is emitted and the message is left entirely to +// the bus — a later redelivery finds the record still at its previous outcome and reconciles from there, +// never a send silently announced sent, failed or retrying when it was not actually kept that way (novox/hq +// review round 1 finding 5). type msgAction int const ( actionAck msgAction = iota actionRetry actionTerm + actionLeave ) // recordOutcome writes the final decision for one claimed send once SendMail has run (or could not even be @@ -908,7 +913,12 @@ const ( // with the message next. Attempt (req's own, from the claim) decides retrying from failed on a not-taken // failure: the fifth attempt always fails rather than retries again (novox/hq ADR 0436 clauses 10, 11). func recordOutcome(store SendStore, emit Emit, req SendRequest, claimed SendDecision, rev uint64, sendErr error, now time.Time) (SendDecision, msgAction, time.Duration, error) { - write := func(d SendDecision, final, tellWorthy bool) (SendDecision, error) { + // write keeps d, retrying once on a changed revision (re-reading the send and trying again with its + // fresh one) before giving up: kept is false only when the record's own write could not be kept even + // after that retry, in which case the caller emits nothing and leaves the message to the bus entirely — + // never announcing an outcome (sent, failed, retrying) that was not actually recorded (novox/hq review + // round 1 finding 5). + write := func(d SendDecision, final, tellWorthy bool) (result SendDecision, kept bool, outErr error) { var indexErr error if tellWorthy { // Indexed for a tell BEFORE the record carries the outcome that owes it (novox/hq review round @@ -916,11 +926,21 @@ func recordOutcome(store SendStore, emit Emit, req SendRequest, claimed SendDeci // outcome does land; tellSend itself tolerates finding it still sending, queued or retrying. indexErr = addTellPending(store, req.ID) } - result, _, err := settleSend(store, req, rev, d) - if err != nil { - // The attempt (and its SMTP outcome) stand either way; the caller logs this. A redelivery (or the - // sweep, for a send stuck mid-write) finds whatever the real kept state is and reconciles. - return d, errOr(indexErr, err) + curReq, curRev := req, rev + var writeErr error + for attempt := 0; attempt < 2; attempt++ { + result, _, writeErr = settleSend(store, curReq, curRev, d) + if writeErr == nil || !errors.Is(writeErr, stdio.ErrChanged) { + break + } + fresh, freshRev, ok, rerr := getSend(store, req.ID) + if rerr != nil || !ok { + break + } + curReq, curRev = fresh, freshRev + } + if writeErr != nil { + return d, false, errOr(indexErr, fmt.Errorf("the send %s's outcome could not be kept, even retried on a changed revision (%w)", req.ID, writeErr)) } if final { // Only once the outcome is durably recorded is the sender-pending index's entry dropped: from @@ -929,10 +949,13 @@ func recordOutcome(store SendStore, emit Emit, req SendRequest, claimed SendDeci indexErr = errOr(indexErr, fmt.Errorf("dropping %s from the sender-pending index: %w", req.ID, rmErr)) } } - return result, indexErr + return result, true, indexErr } if sendErr == nil { - d, err := write(SendDecision{At: now, Outcome: "sent", Warrant: claimed.Warrant, Attempt: claimed.Attempt}, true, false) + d, kept, err := write(SendDecision{At: now, Outcome: "sent", Warrant: claimed.Warrant, Attempt: claimed.Attempt}, true, false) + if !kept { + return d, actionLeave, 0, err + } _ = emit(MailSendSent, req.ID, OutcomeEvent{Send: req.ID, Account: req.Account, Outcome: d.Outcome}) return d, actionAck, 0, err } @@ -945,25 +968,37 @@ func recordOutcome(store SendStore, emit Emit, req SendRequest, claimed SendDeci } switch se.Outcome { case Refused: - d, err := write(SendDecision{At: now, Outcome: "failed: " + se.Err.Error(), Warrant: claimed.Warrant, + d, kept, err := write(SendDecision{At: now, Outcome: "failed: " + se.Err.Error(), Warrant: claimed.Warrant, Attempt: claimed.Attempt, Error: se.Err.Error()}, true, true) + if !kept { + return d, actionLeave, 0, err + } _ = emit(MailSendFailed, req.ID, OutcomeEvent{Send: req.ID, Account: req.Account, Outcome: d.Outcome}) return d, actionTerm, 0, err case NotProven: - d, err := write(SendDecision{At: now, Outcome: "not proven", Warrant: claimed.Warrant, Attempt: claimed.Attempt, + d, kept, err := write(SendDecision{At: now, Outcome: "not proven", Warrant: claimed.Warrant, Attempt: claimed.Attempt, Error: se.Err.Error()}, true, true) + if !kept { + return d, actionLeave, 0, err + } _ = emit(MailSendFailed, req.ID, OutcomeEvent{Send: req.ID, Account: req.Account, Outcome: d.Outcome}) return d, actionTerm, 0, err default: // NotTaken if claimed.Attempt >= MostAttempts { - d, err := write(SendDecision{At: now, Outcome: "failed: " + se.Err.Error(), Warrant: claimed.Warrant, + d, kept, err := write(SendDecision{At: now, Outcome: "failed: " + se.Err.Error(), Warrant: claimed.Warrant, Attempt: claimed.Attempt, Error: se.Err.Error()}, true, true) + if !kept { + return d, actionLeave, 0, err + } _ = emit(MailSendFailed, req.ID, OutcomeEvent{Send: req.ID, Account: req.Account, Outcome: d.Outcome}) return d, actionTerm, 0, err } delay := RetryDelays[claimed.Attempt-1] - d, err := write(SendDecision{At: now, Outcome: "retrying", Warrant: claimed.Warrant, Attempt: claimed.Attempt, + d, kept, err := write(SendDecision{At: now, Outcome: "retrying", Warrant: claimed.Warrant, Attempt: claimed.Attempt, Error: se.Err.Error(), NextAttempt: now.Add(delay)}, false, false) + if !kept { + return d, actionLeave, 0, err + } return d, actionRetry, delay, err // not a final outcome: no emit (clause 11 names only sent and failed) } } diff --git a/modules/mesh-mail/cmd/mesh-mail/sender.go b/modules/mesh-mail/cmd/mesh-mail/sender.go index 7f376d67..df9880c7 100644 --- a/modules/mesh-mail/cmd/mesh-mail/sender.go +++ b/modules/mesh-mail/cmd/mesh-mail/sender.go @@ -259,6 +259,10 @@ func (h *senderHandler) handle(msg *process.Message) { if err := msg.Term(); err != nil { h.logf("[mesh-mail] send: terminating %s: %v", q.Send, err) } + case actionLeave: + // The outcome's own write could not be kept, even retried on a changed revision (novox/hq review + // round 1 finding 5): nothing was emitted above, and nothing is done to the message either — left + // entirely to the bus, so a later redelivery finds the record still at its previous outcome. } }