diff --git a/internal/commands/connect.go b/internal/commands/connect.go index 6d8afbd31..f8453cbd1 100644 --- a/internal/commands/connect.go +++ b/internal/commands/connect.go @@ -46,7 +46,8 @@ ready. Show prints what setup recorded. Then run the connector on it: basecamp connect -P [--project ]... [--shadow] It runs in the foreground until interrupted. Stdout is a wire of one JSON -object per line (events seen, verdicts, dispatches; never content), and logs +object per line (events seen, verdicts, dispatches, lifecycle messages; +never content), and logs go to stderr. SIGINT and SIGTERM cancel live workers with stop reason shutdown, settle them, and exit 130 and 143. --shadow admits and logs in an isolated state directory and dispatches nothing. macOS and Linux only.`, diff --git a/internal/commands/connect_run.go b/internal/commands/connect_run.go index 07b58fbf1..bfd2d12c8 100644 --- a/internal/commands/connect_run.go +++ b/internal/commands/connect_run.go @@ -123,6 +123,15 @@ func connectSessionsPath(file setup.File) string { return filepath.Join(base, "bcc-"+connector.StateDirName(file.AccountID, file.Agent.PersonID)) } +// connectShutdownFlush bounds how long a stopping connector spends posting +// the completion notices of the attempts it stopped. What it cannot post in +// time stays pending in the outbox and goes out on the next start. +const connectShutdownFlush = 15 * time.Second + +// connectStartBound bounds how long a starting connector spends settling the +// lifecycle messages a previous process left, before intake and dispatch run. +const connectStartBound = 2 * time.Minute + func runConnect(cmd *cobra.Command, f *connectRunFlags) error { if !connectSupportedOS(runtime.GOOS) { return output.ErrUsage("basecamp connect runs on macOS and Linux only: it ends a crashed connector's workers by process group and start time, which only those two can read") @@ -259,8 +268,24 @@ func runConnect(cmd *cobra.Command, f *connectRunFlags) error { return output.ErrUsage(err.Error()) } - var dispatcher *connector.Dispatcher + var ( + dispatcher *connector.Dispatcher + outbox *connector.Outbox + ) if !f.shadow { + // Lifecycle messages: the hooks write each intent in its transition's + // transaction, so they are installed before anything transitions. A + // shadow run installs none: it posts nothing, and a shadow ledger + // promoted later must carry nothing to send. + ledger.SetHooks(connector.LifecycleHooks(ledger, connector.LifecycleOptions{})) + poster, err := connector.NewBasecampPoster(accountClient, agentID) + if err != nil { + return err + } + outbox, err = connector.NewOutbox(connector.OutboxOptions{Ledger: ledger, Poster: poster, Lines: lines, Logger: logger}) + if err != nil { + return err + } exe, err := os.Executable() if err != nil { return fmt.Errorf("locate this binary for the worker's MCP server: %w", err) @@ -277,7 +302,12 @@ func runConnect(cmd *cobra.Command, f *connectRunFlags) error { dispatcher, err = connector.NewDispatcher(connectDispatcherOptions(connectDispatch{ File: file, Buckets: buckets, Ledger: ledger, Driver: worker, Routes: routes.Current, Profile: name, Executable: exe, StateDir: stateDir, SessionsDir: sessions, - Replies: connector.SDKReplies{Client: accountClient, AgentID: agentID}, + // Replies are listed with their words, so the connector's own + // notices are left out even before their receipts are known, and + // no reply is ever adopted from one. That is the whole filter: + // an id-only predicate beside it would ask the ledger again for + // every reply, outside the adoption budget, for nothing. + Replies: connector.LifecycleFilteredReplies{Lister: poster, Ledger: ledger}, Lines: lines, Logger: logger, })) if err != nil { @@ -341,6 +371,20 @@ func runConnect(cmd *cobra.Command, f *connectRunFlags) error { cancel() }) } + if outbox != nil { + // On start, before anything transitions: settle what a previous + // process left sending and send what is due, so no stale notice + // waits behind new work. Bounded, so a slow Basecamp delays the + // connector's start rather than stopping it; what is left, Run + // carries on with. A ledger that cannot settle an intent stops the + // start. + startCtx, stopStart := context.WithTimeout(runCtx, connectStartBound) + err := outbox.Start(startCtx) + stopStart() + if err != nil && runCtx.Err() == nil { + return err + } + } runPart("intake", intake.Run) runPart("admission", func(ctx context.Context) error { return connector.RunAdmission(ctx, connector.AdmissionOptions{Ledger: ledger, Queue: queue, Admitter: admitter, Lines: lines, Logger: logger}) @@ -348,7 +392,19 @@ func runConnect(cmd *cobra.Command, f *connectRunFlags) error { if dispatcher != nil { runPart("dispatch", dispatcher.Run) } + if outbox != nil { + runPart("outbox", outbox.Run) + } wg.Wait() + if outbox != nil { + // The dispatcher has settled every attempt it stopped; their + // completion notices go out now, within a bound. + flushCtx, stopFlush := context.WithTimeout(context.WithoutCancel(ctx), connectShutdownFlush) + if err := outbox.Flush(flushCtx); err != nil { + logger.Warn("connector: posting lifecycle messages on the way out", "error", err) + } + stopFlush() + } mu.Lock() sig := received @@ -450,9 +506,10 @@ type connectDispatch struct { StateDir string SessionsDir string - Replies connector.ReplyLister - Lines *ndjson.Writer - Logger *slog.Logger + Replies connector.ReplyLister + IsLifecycleMessage func(id int64) bool + Lines *ndjson.Writer + Logger *slog.Logger } // connectDispatcherOptions is the dispatcher the run starts: connect.json's @@ -460,18 +517,19 @@ type connectDispatch struct { // MCP server. Built here so what the command wires is what a test can read. func connectDispatcherOptions(d connectDispatch) connector.DispatcherOptions { return connector.DispatcherOptions{ - Ledger: d.Ledger, - Driver: d.Driver, - Routes: d.Routes, - Concurrency: d.File.Concurrency, - Deadline: time.Duration(d.File.Deadline), - Buckets: d.Buckets, - MCP: connector.WorkerMCP{Command: d.Executable, Profile: d.Profile, StateDir: d.StateDir}, - PrivateDir: d.SessionsDir, - Replies: d.Replies, - Lines: d.Lines, - Logger: d.Logger, - StillRunning: connector.DefaultStillRunning, + Ledger: d.Ledger, + Driver: d.Driver, + Routes: d.Routes, + Concurrency: d.File.Concurrency, + Deadline: time.Duration(d.File.Deadline), + Buckets: d.Buckets, + MCP: connector.WorkerMCP{Command: d.Executable, Profile: d.Profile, StateDir: d.StateDir}, + PrivateDir: d.SessionsDir, + Replies: d.Replies, + IsLifecycleMessage: d.IsLifecycleMessage, + Lines: d.Lines, + Logger: d.Logger, + StillRunning: connector.DefaultStillRunning, } } diff --git a/internal/connector/ledger.go b/internal/connector/ledger.go index 4f17364c6..bfa55727f 100644 --- a/internal/connector/ledger.go +++ b/internal/connector/ledger.go @@ -823,6 +823,15 @@ END; // acknowledgement trigger before this branch landed, and a shipped // migration is never renumbered under a ledger that has applied it. migrationTasksAndAttempts, + // Migration 8. The outbox every lifecycle message goes through. See + // outbox.go for the invariants it holds. + // + // This was migration 7 while it sat on #736's head: 6 for the tasks and + // attempts it builds on, 7 for the outbox. Main took 6 for the + // acknowledgement trigger, which pushed the dispatcher's tables to 7 and + // this to 8. The numbers move only because nothing has shipped them yet; + // once a ledger has applied one, its number is fixed. + migrationOutbox, } func (l *Ledger) migrate(ctx context.Context) error { diff --git a/internal/connector/lifecycle.go b/internal/connector/lifecycle.go new file mode 100644 index 000000000..14cd81cff --- /dev/null +++ b/internal/connector/lifecycle.go @@ -0,0 +1,370 @@ +package connector + +import ( + "context" + "database/sql" + "errors" + "fmt" + "html" + "regexp" + "strconv" + "strings" + "time" +) + +// Lifecycle messages are fixed forms. Every word comes from this file; every +// value comes from a ledger record โ€” ids, states, stop reasons, times. None +// comes from content, from a worker or from a model, so a message can be +// rendered again from the records alone and matched against what Basecamp +// holds. + +// GuardAckBody is the guard acknowledgement: a boost on the recording that +// asked. It carries no event id, because a boost is a few characters; two +// guards on one recording are therefore ambiguous to reconciliation, which +// leaves them indeterminate rather than guess. +const GuardAckBody = "๐Ÿ‘€ received" + +// lifecycleSignature ends every comment and chat line the connector posts, so +// a person can tell a notice from the agent's own words. +const lifecycleSignature = "automatic notice from basecamp connect" + +// renderHoldingReply is the reply to a mention or assignment in a project that +// has no route. +func renderHoldingReply(kind MessageKind, eventID int64) string { + lines := []string{ + "I can't start on this here yet: this project has no working directory set up for me on the connector's machine, so nothing was run.", + "Once the project is added to connect.json, a person can run it with: basecamp connect redispatch " + strconv.FormatInt(eventID, 10), + "", + "Event " + strconv.FormatInt(eventID, 10) + " ยท " + lifecycleSignature, + } + return renderLines(kind, lines) +} + +// renderStillRunning is one still-running notice. +func renderStillRunning(kind MessageKind, taskID int64, attemptID string, occurrence int, launchedAt, progressAt time.Time) string { + progress := "No progress has been reported yet." + if !progressAt.IsZero() { + progress = "Last progress at " + clock(progressAt) + "." + } + lines := []string{ + "Still working on this: task " + strconv.FormatInt(taskID, 10) + " started at " + clock(launchedAt) + ". " + progress, + "", + "Attempt " + attemptID + ", update " + strconv.Itoa(occurrence) + " ยท " + lifecycleSignature, + } + return renderLines(kind, lines) +} + +// CompletionNeeded reports whether an attempt's settlement calls for a +// completion notice: an event failed or unknown, succeeded with no reply +// reported, or blocked from a further automatic start. Events that all +// succeeded with replies get none, and neither do events returned to wait for +// a task of their own or withdrawn for their one automatic retry. +func CompletionNeeded(s Settlement) bool { + for _, e := range s.Events { + if completionLine(e) != "" { + return true + } + } + return false +} + +// completionLine is what the notice says about one event; empty when it says +// nothing. +func completionLine(e SettledEvent) string { + id := strconv.FormatInt(e.EventID, 10) + redispatch := " Needs a person: basecamp connect redispatch " + id + switch { + case e.Blocked: + return "Event " + id + ": the worker could not be started." + redispatch + case e.Withdrawn, e.Returned: + return "" + case e.Outcome == OutcomeFailed: + return "Event " + id + ": failed." + redispatch + case e.Outcome == OutcomeUnknown: + return "Event " + id + ": unknown, the worker did not report on it." + redispatch + case e.Outcome == OutcomeSucceeded && e.ReplyID == nil: + return "Event " + id + ": succeeded, with no reply reported." + } + return "" +} + +// stopSentence says how an attempt stopped. +func stopSentence(stop StopReason) string { + switch stop { + case StopFinished: + return "the worker finished" + case StopFailed: + return "the worker failed" + case StopDeadline: + return "the worker was stopped at the task's deadline" + case StopShutdown: + return "the connector shut down and stopped the worker" + case StopLost: + return "the worker was lost" + } + return "the worker stopped" +} + +// renderCompletion is an attempt's completion notice, or "" when the +// settlement calls for none. +func renderCompletion(kind MessageKind, s Settlement) string { + if !CompletionNeeded(s) { + return "" + } + lines := []string{"Task " + strconv.FormatInt(s.TaskID, 10) + " ended: " + stopSentence(s.Stop) + "."} + for _, e := range s.Events { + if line := completionLine(e); line != "" { + lines = append(lines, line) + } + } + lines = append(lines, "", "Attempt "+s.AttemptID+" ยท "+lifecycleSignature) + return renderLines(kind, lines) +} + +// renderLines lays lines out for the message kind: rich text for a comment, +// plain text for a chat line. Every line is escaped, though no line holds +// anything but this file's words and record values. +func renderLines(kind MessageKind, lines []string) string { + if kind == MessageComment { + escaped := make([]string, len(lines)) + for i, line := range lines { + escaped[i] = html.EscapeString(line) + } + return "
" + strings.Join(escaped, "
") + "
" + } + return strings.Join(lines, "\n") +} + +func clock(t time.Time) string { return t.UTC().Format("15:04 UTC") } + +var ( + breakTag = regexp.MustCompile(`(?i)|`) + anyTag = regexp.MustCompile(`<[^>]*>`) + spaceRuns = regexp.MustCompile(`\s+`) +) + +// MessageText is a message reduced to what reconciliation compares: tags +// dropped (a line break is a space), entities decoded, whitespace collapsed. +// Basecamp may wrap or re-attribute rich text it stores; the words stay. +func MessageText(content string) string { + text := breakTag.ReplaceAllString(content, " ") + text = anyTag.ReplaceAllString(text, "") + text = html.UnescapeString(text) + return strings.TrimSpace(spaceRuns.ReplaceAllString(text, " ")) +} + +// destinationKind maps a record's reply kind to the message a comment-shaped +// notice is posted as. +func destinationKind(replyKind string) (MessageKind, bool) { + switch replyKind { + case "comment": + return MessageComment, true + case "chat_line": + return MessageChatLine, true + } + return "", false +} + +// LifecycleOptions tunes the hooks. +type LifecycleOptions struct { + // GuardDelay is how long a worker has to call get_dispatch before the + // guard acknowledges; DefaultGuardDelay when zero. + GuardDelay time.Duration +} + +// DefaultGuardDelay is the guard's wait. +const DefaultGuardDelay = 30 * time.Second + +// LifecycleHooks are the ledger hooks that write the outbox's intents, each in +// its transition's transaction (invariant 1). Install them with +// Ledger.SetHooks. A connector running --shadow installs none: it posts +// nothing, and a shadow ledger promoted later must not carry intents to send. +func LifecycleHooks(l *Ledger, opts LifecycleOptions) Hooks { + if opts.GuardDelay <= 0 { + opts.GuardDelay = DefaultGuardDelay + } + return Hooks{ + VerdictCommitted: func(ctx context.Context, tx Tx, v CommittedVerdict) error { + return verdictIntents(ctx, tx, l.now(), opts.GuardDelay, v) + }, + AttemptEnded: func(ctx context.Context, tx Tx, s Settlement) error { + return completionIntent(ctx, tx, l.now(), s) + }, + StillRunning: func(ctx context.Context, tx Tx, tick StillRunningTick) error { + return stillRunningIntent(ctx, tx, l.now(), tick) + }, + } +} + +// verdictIntents writes the guard for an admitted request and the holding +// reply for an unrouted one. +func verdictIntents(ctx context.Context, tx Tx, now time.Time, guardDelay time.Duration, v CommittedVerdict) error { + if !v.Acknowledge { + // Subscribed and completed are not requests: no guard, no holding + // reply. + return nil + } + var bucketID, recordingID int64 + switch err := tx.QueryRowContext(ctx, `SELECT bucket_id, recording_id FROM events WHERE id = ?`, v.EventID).Scan(&bucketID, &recordingID); { + case errors.Is(err, sql.ErrNoRows): + return fmt.Errorf("connector: lifecycle for event %d: %w", v.EventID, ErrNoSuchRecord) + case err != nil: + return fmt.Errorf("connector: lifecycle for event %d: %w", v.EventID, err) + } + switch { + case v.State == StateAdmitted || v.State == StateQueued: + err := writeIntent(ctx, tx, now, newIntent{ + key: guardKey(v.EventID), + kind: IntentGuardAck, + eventID: v.EventID, + destination: Destination{BucketID: bucketID, Kind: MessageBoost, RecordingID: recordingID}, + body: GuardAckBody, + notBefore: now.Add(guardDelay), + }) + return err + case v.State == StateBlocked && v.Reason == "no_route": + kind, ok := destinationKind(v.ReplyKind) + if !ok || v.ReplyRecordingID <= 0 { + return nil + } + err := writeIntent(ctx, tx, now, newIntent{ + key: holdingKey(v.EventID), + kind: IntentHoldingReply, + eventID: v.EventID, + destination: Destination{BucketID: bucketID, Kind: kind, RecordingID: v.ReplyRecordingID}, + body: renderHoldingReply(kind, v.EventID), + }) + return err + } + return nil +} + +// originDestination is where a task's notices go: the reply destination of +// its originating event. +func originDestination(ctx context.Context, tx Tx, taskID int64) (Destination, bool, error) { + var ( + bucketID, replyRecordingID int64 + replyKind string + ) + err := tx.QueryRowContext(ctx, ` +SELECT e.bucket_id, e.reply_kind, e.reply_recording_id +FROM tasks t JOIN events e ON e.id = t.originating_event_id WHERE t.id = ?`, taskID).Scan(&bucketID, &replyKind, &replyRecordingID) + switch { + case errors.Is(err, sql.ErrNoRows): + return Destination{}, false, nil + case err != nil: + return Destination{}, false, fmt.Errorf("connector: destination of task %d: %w", taskID, err) + } + kind, ok := destinationKind(replyKind) + if !ok || replyRecordingID <= 0 { + return Destination{}, false, nil + } + return Destination{BucketID: bucketID, Kind: kind, RecordingID: replyRecordingID}, true, nil +} + +func completionIntent(ctx context.Context, tx Tx, now time.Time, s Settlement) error { + // The notice is rendered from the rows the settlement wrote, not from the + // Settlement handed to the hook: what is posted is what the ledger says. + settled, err := settlementFromRecords(ctx, tx, s.AttemptID) + if err != nil { + return err + } + dest, ok, err := originDestination(ctx, tx, settled.TaskID) + if err != nil || !ok { + return err + } + // A settlement that calls for no notice renders nothing, and nothing is + // written. + err = writeIntent(ctx, tx, now, newIntent{ + key: completionKey(settled.AttemptID), + kind: IntentCompletion, + taskID: settled.TaskID, + attemptID: settled.AttemptID, + destination: dest, + body: renderCompletion(dest.Kind, settled), + }) + return err +} + +// settlementFromRecords reads an ended attempt's settlement back from the +// ledger: the attempt's stop reason, and each event's delivery, outcome, +// reply and withdrawal on its task. +func settlementFromRecords(ctx context.Context, q Tx, attemptID string) (Settlement, error) { + s := Settlement{AttemptID: attemptID} + var ( + stop string + spawnFailed bool + originating sql.NullInt64 + ) + err := q.QueryRowContext(ctx, ` +SELECT a.task_id, a.stop_reason, a.spawn_failed, t.originating_event_id +FROM attempts a JOIN tasks t ON t.id = a.task_id WHERE a.id = ? AND a.state = 'ended'`, attemptID).Scan(&s.TaskID, &stop, &spawnFailed, &originating) + switch { + case errors.Is(err, sql.ErrNoRows): + return Settlement{}, fmt.Errorf("connector: settlement of %s: %w", attemptID, ErrNoLiveAttempt) + case err != nil: + return Settlement{}, fmt.Errorf("connector: settlement of %s: %w", attemptID, err) + } + s.Stop, s.SpawnFailed, s.OriginatingEventID = StopReason(stop), spawnFailed, originating.Int64 + + rows, err := q.QueryContext(ctx, ` +SELECT te.event_id, te.delivery, te.outcome, te.reply_id, te.withdrawn_at IS NOT NULL, e.state, e.reason +FROM task_events te JOIN events e ON e.id = te.event_id +WHERE te.task_id = ? AND (te.withdrawn_at IS NULL OR te.exposed_attempt_id = ?) +ORDER BY te.event_id`, s.TaskID, attemptID) + if err != nil { + return Settlement{}, fmt.Errorf("connector: settlement of %s: %w", attemptID, err) + } + defer func() { _ = rows.Close() }() + for rows.Next() { + var ( + e SettledEvent + delivery, outcome, state string + reason string + reply sql.NullInt64 + ) + if err := rows.Scan(&e.EventID, &delivery, &outcome, &reply, &e.Withdrawn, &state, &reason); err != nil { + return Settlement{}, fmt.Errorf("connector: settlement of %s: %w", attemptID, err) + } + switch { + case e.Withdrawn: + e.Blocked = RecordState(state) == StateBlocked && reason == ReasonSpawnFailed + case Delivery(delivery) == DeliveryCompleted: + e.Outcome = Outcome(outcome) + e.Reported = e.Outcome != OutcomeUnknown + if reply.Valid { + id := reply.Int64 + e.ReplyID = &id + } + default: + e.Returned = true + } + s.Events = append(s.Events, e) + } + return s, rows.Err() +} + +func stillRunningIntent(ctx context.Context, tx Tx, now time.Time, tick StillRunningTick) error { + dest, ok, err := originDestination(ctx, tx, tick.TaskID) + if err != nil || !ok { + return err + } + var launched string + if err := tx.QueryRowContext(ctx, `SELECT launched_at FROM attempts WHERE id = ?`, tick.AttemptID).Scan(&launched); err != nil { + return fmt.Errorf("connector: still-running for %s: %w", tick.AttemptID, err) + } + launchedAt, err := parseStamp(launched) + if err != nil { + return err + } + err = writeIntent(ctx, tx, now, newIntent{ + key: stillRunningKey(tick.AttemptID, tick.Occurrence), + kind: IntentStillRunning, + taskID: tick.TaskID, + attemptID: tick.AttemptID, + occurrence: tick.Occurrence, + destination: dest, + body: renderStillRunning(dest.Kind, tick.TaskID, tick.AttemptID, tick.Occurrence, launchedAt, tick.ProgressAt), + }) + return err +} diff --git a/internal/connector/lifecycle_test.go b/internal/connector/lifecycle_test.go new file mode 100644 index 000000000..aa202f04a --- /dev/null +++ b/internal/connector/lifecycle_test.go @@ -0,0 +1,267 @@ +package connector + +import ( + "context" + "strconv" + "strings" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + "github.com/basecamp/basecamp-cli/internal/connector/admission" +) + +func id64(v int64) *int64 { return &v } + +// Done when: each template renders from records alone. The body written with +// the intent is the one rendered again from the ledger's rows after commit. +func TestLifecycleTemplatesRenderFromRecordsAlone(t *testing.T) { + t.Run("completion", func(t *testing.T) { + ctx := context.Background() + ledger, clock := obLedger(t) + obAdmit(t, ledger, 1, "recording:10304028989") + l := obLaunch(t, ledger, 1) + obAdmit(t, ledger, 2, "recording:10304028989") + _, err := ledger.JoinConversation(ctx, l.TaskID) + require.NoError(t, err) + clock.Advance(5 * time.Minute) + settlement, err := ledger.EndAttempt(ctx, AttemptEnd{AttemptID: l.AttemptID, Stop: StopDeadline}) + require.NoError(t, err) + + in := obIntent(t, ledger, completionKey(l.AttemptID)) + fromRows, err := settlementFromRecords(ctx, ledger.db, l.AttemptID) + require.NoError(t, err) + assert.Equal(t, in.Body, renderCompletion(in.Destination.Kind, fromRows)) + assert.Equal(t, in.Body, renderCompletion(in.Destination.Kind, settlement), "the ledger and the settlement agree") + assert.Equal(t, Destination{BucketID: adapterBucketID, Kind: MessageComment, RecordingID: obReplyRecording}, in.Destination) + assert.Equal(t, + "
Task "+itoa(l.TaskID)+" ended: the worker was stopped at the task's deadline.
"+ + "Event 1: unknown, the worker did not report on it. Needs a person: basecamp connect redispatch 1
"+ + "
Attempt "+l.AttemptID+" ยท automatic notice from basecamp connect
", + in.Body, "event 2 was never exposed: it waits for a task of its own and is not named") + }) + + t.Run("still running", func(t *testing.T) { + ctx := context.Background() + ledger, clock := obLedger(t) + obAdmit(t, ledger, 1, "recording:10304028989") + l := obLaunch(t, ledger, 1) + clock.Advance(3 * time.Minute) + require.NoError(t, ledger.RecordProgress(ctx, l.AttemptID)) + clock.Advance(7 * time.Minute) + tick, err := ledger.StillRunning(ctx, l.AttemptID) + require.NoError(t, err) + + in := obIntent(t, ledger, stillRunningKey(l.AttemptID, 1)) + assert.Equal(t, IntentStillRunning, in.Kind) + assert.Equal(t, renderStillRunning(MessageComment, l.TaskID, l.AttemptID, 1, l.LaunchedAt, tick.ProgressAt), in.Body) + assert.Equal(t, + "
Still working on this: task "+itoa(l.TaskID)+" started at 12:00 UTC. Last progress at 12:03 UTC.

"+ + "Attempt "+l.AttemptID+", update 1 ยท automatic notice from basecamp connect
", in.Body) + }) + + t.Run("holding reply in a Campfire", func(t *testing.T) { + ctx := context.Background() + ledger, _ := obLedger(t) + seenRecord(t, ledger, 1) + _, err := ledger.Admission().Commit(ctx, obNoRouteVerdict(1, 0, admission.ReplyDestination{Kind: admission.ReplyChatLine, RecordingID: obCampfire})) + require.NoError(t, err) + in := obIntent(t, ledger, holdingKey(1)) + assert.Equal(t, Destination{BucketID: adapterBucketID, Kind: MessageChatLine, RecordingID: obCampfire}, in.Destination) + assert.Equal(t, renderHoldingReply(MessageChatLine, 1), in.Body) + assert.NotContains(t, in.Body, "<", "a chat line is plain text") + assert.True(t, in.NotBefore.Equal(in.CreatedAt), "a holding reply is due at once") + }) + + t.Run("guard", func(t *testing.T) { + ledger, _ := obLedger(t) + obAdmit(t, ledger, 1, "recording:10304028989") + in := obIntent(t, ledger, guardKey(1)) + assert.Equal(t, GuardAckBody, in.Body) + assert.Equal(t, DefaultGuardDelay, in.NotBefore.Sub(in.CreatedAt)) + }) +} + +func itoa(v int64) string { return strconv.FormatInt(v, 10) } + +// No template carries anything a person or worker wrote: the snapshot's +// content never reaches a lifecycle message. +func TestLifecycleMessagesCarryNoContent(t *testing.T) { + ledger, _ := obLedger(t) + ctx := context.Background() + seenRecord(t, ledger, 1) + v := admittedVerdict(1, 0, "recording:10304028989") + v.Snapshot.Title = "SECRET-TITLE" + v.Snapshot.Content = "
SECRET-CONTENT
" + _, err := ledger.Admission().Commit(ctx, v) + require.NoError(t, err) + l := obLaunch(t, ledger, 1) + _, err = ledger.StillRunning(ctx, l.AttemptID) + require.NoError(t, err) + _, err = ledger.EndAttempt(ctx, AttemptEnd{AttemptID: l.AttemptID, Stop: StopFailed}) + require.NoError(t, err) + seenRecord(t, ledger, 2) + _, err = ledger.Admission().Commit(ctx, obNoRouteVerdict(2, 0, obCommentReply)) + require.NoError(t, err) + + intents := obIntents(t, ledger) + require.Len(t, intents, 4) + for _, in := range intents { + assert.NotContains(t, in.Body, "SECRET", in.Key) + assert.NotContains(t, in.Body, "https://", in.Key) + } +} + +// Completion: one notice per attempt, when anything is not succeeded with a +// reply; the notice names what needs redispatch. +func TestCompletionNoticeRule(t *testing.T) { + cases := []struct { + name string + events []SettledEvent + want []string + }{ + {name: "all succeeded with replies", events: []SettledEvent{ + {EventID: 1, Outcome: OutcomeSucceeded, Reported: true, ReplyID: id64(5)}, + {EventID: 2, Outcome: OutcomeSucceeded, Reported: true, ReplyID: id64(6)}, + }}, + {name: "succeeded without a reply", events: []SettledEvent{ + {EventID: 1, Outcome: OutcomeSucceeded, Reported: true}, + }, want: []string{"Event 1: succeeded, with no reply reported."}}, + {name: "failed and unknown need redispatch", events: []SettledEvent{ + {EventID: 1, Outcome: OutcomeSucceeded, Reported: true, ReplyID: id64(5)}, + {EventID: 2, Outcome: OutcomeFailed, Reported: true, ReplyID: id64(6)}, + {EventID: 3, Outcome: OutcomeUnknown}, + }, want: []string{ + "Event 2: failed. Needs a person: basecamp connect redispatch 2", + "Event 3: unknown, the worker did not report on it. Needs a person: basecamp connect redispatch 3", + }}, + {name: "only returned or withdrawn for a retry", events: []SettledEvent{ + {EventID: 1, Withdrawn: true}, + {EventID: 2, Returned: true}, + }}, + {name: "blocked after a second failed start", events: []SettledEvent{ + {EventID: 1, Withdrawn: true, Blocked: true}, + }, want: []string{"Event 1: the worker could not be started. Needs a person: basecamp connect redispatch 1"}}, + } + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + s := Settlement{TaskID: 9, AttemptID: "att_x", Stop: StopFinished, Events: tc.events} + body := renderCompletion(MessageChatLine, s) + assert.Equal(t, len(tc.want) > 0, CompletionNeeded(s)) + if len(tc.want) == 0 { + assert.Empty(t, body) + return + } + assert.Equal(t, "Task 9 ended: the worker finished.\n"+strings.Join(tc.want, "\n")+"\n\nAttempt att_x ยท automatic notice from basecamp connect", body) + }) + } +} + +// Every stop reason reads as itself; a failure is never called a cancel. +func TestCompletionNamesEachStopReason(t *testing.T) { + seen := map[string]bool{} + for _, stop := range []StopReason{StopFinished, StopFailed, StopDeadline, StopShutdown, StopLost} { + sentence := stopSentence(stop) + assert.NotEqual(t, "the worker stopped", sentence, stop) + assert.NotContains(t, sentence, "cancel", stop) + assert.False(t, seen[sentence], stop) + seen[sentence] = true + } +} + +// An attempt whose events all succeeded with replies posts nothing. +func TestCompletionIsNotWrittenWhenEverythingSucceededWithAReply(t *testing.T) { + ledger, _ := obLedger(t) + ctx := context.Background() + obAdmit(t, ledger, 1, "recording:10304028989") + l := obLaunch(t, ledger, 1) + d, err := ledger.Dispatch(ctx, l.Token, adapterAgentID) + require.NoError(t, err) + obPull(t, d, 1) + _, err = d.Complete(ctx, 1, Completion{Outcome: OutcomeSucceeded, ReplyID: id64(4242)}) + require.NoError(t, err) + _, err = ledger.EndAttempt(ctx, AttemptEnd{AttemptID: l.AttemptID, Stop: StopFinished}) + require.NoError(t, err) + for _, in := range obIntents(t, ledger) { + assert.NotEqual(t, IntentCompletion, in.Kind) + } +} + +// Reconciliation compares words, not markup Basecamp may rewrite. +func TestMessageTextComparesWordsNotMarkup(t *testing.T) { + body := renderHoldingReply(MessageComment, 7) + stored := `
` + strings.ReplaceAll(body, "
", "
\n") + `
` + assert.Equal(t, MessageText(body), MessageText(stored)) + assert.Equal(t, MessageText(renderHoldingReply(MessageChatLine, 7)), MessageText(body), "a line and a comment say the same words") + assert.NotEqual(t, MessageText(body), MessageText(renderHoldingReply(MessageComment, 8))) + assert.Equal(t, "a & b", MessageText("

a &\n b

")) +} + +// The dispatch prompt's first instruction for a request is the worker's own +// acknowledgement, before any work, reported through ack_dispatch. +func TestDispatchPromptAcknowledgesFirst(t *testing.T) { + record := Record{ID: 17, Decision: Decision{Trigger: "mentioned", Acknowledge: true, RecordingURL: "https://app.basecamp.com/2914079/buckets/1/recordings/2"}} + prompt := DispatchPrompt(Launch{TaskID: 3}, record) + ack := strings.Index(prompt, "acknowledge first") + work := strings.Index(prompt, "Do the work") + require.Positive(t, ack) + require.Positive(t, work) + assert.Less(t, ack, work) + assert.Contains(t, prompt, "ack_dispatch") + assert.Contains(t, prompt, "guard_acknowledged") +} + +// A second failed start is read back from the ledger as blocked, and named. +func TestOutboxCompletionReadsBlockedBack(t *testing.T) { + ledger, _ := obLedger(t) + ctx := context.Background() + obAdmit(t, ledger, 1, "recording:10304028989") + for range 2 { + l := obLaunch(t, ledger, 1) + _, err := ledger.EndAttempt(ctx, AttemptEnd{AttemptID: l.AttemptID, Stop: StopFailed, SpawnFailed: true}) + require.NoError(t, err) + } + require.Equal(t, StateBlocked, getRecord(t, ledger, 1).State) + completions, err := ledger.Intents(ctx, IntentFilter{Kinds: []IntentKind{IntentCompletion}}) + require.NoError(t, err) + require.Len(t, completions, 1, "the first withdrawal retries quietly; the second needs a person") + assert.Contains(t, completions[0].Body, "Event 1: the worker could not be started. Needs a person: basecamp connect redispatch 1") +} + +// The holding reply answers only a request blocked for want of a route. +func TestOutboxHoldingReplyOnlyForNoRoute(t *testing.T) { + ledger, _ := obLedger(t) + ctx := context.Background() + seenRecord(t, ledger, 1) + v := obNoRouteVerdict(1, 0, obCommentReply) + v.Reason = admission.ReasonReadFailed + _, err := ledger.Admission().Commit(ctx, v) + require.NoError(t, err) + assert.Empty(t, obIntents(t, ledger), "a failed read is not answered") + + _, err = ledger.Admission().Commit(ctx, obNoRouteVerdict(1, getRecord(t, ledger, 1).Revision, obCommentReply)) + require.NoError(t, err) + in := obIntent(t, ledger, holdingKey(1)) + assert.Equal(t, Destination{BucketID: adapterBucketID, Kind: MessageComment, RecordingID: obReplyRecording}, in.Destination) +} + +// The dispatcher's adopted-reply rule never adopts a lifecycle message. +func TestOutboxLifecycleMessagesAreRecognized(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + seenRecord(t, ledger, 1) + _, err := ledger.Admission().Commit(ctx, obNoRouteVerdict(1, 0, obCommentReply)) + require.NoError(t, err) + basecamp := newFakeBasecamp(clock.Now) + ob := obOutbox(t, ledger, basecamp) + require.NoError(t, ob.Flush(ctx)) + receipt := *obIntent(t, ledger, holdingKey(1)).ReceiptID + + assert.True(t, ob.IsLifecycleMessage(receipt)) + assert.False(t, ob.IsLifecycleMessage(receipt+1)) + id, ok := AdoptableReply(AdoptionCandidate{DeliveredAt: clock.Now().Add(-time.Minute)}, + []AgentReply{{ID: receipt, CreatedAt: clock.Now()}}, ob.IsLifecycleMessage) + assert.False(t, ok, "adopted %d", id) +} diff --git a/internal/connector/outbox.go b/internal/connector/outbox.go new file mode 100644 index 000000000..f3f8d6ea3 --- /dev/null +++ b/internal/connector/outbox.go @@ -0,0 +1,574 @@ +package connector + +import ( + "context" + "database/sql" + "errors" + "fmt" + "strconv" + "strings" + "time" +) + +// The outbox: every message the connector itself posts to Basecamp โ€” the +// guard acknowledgement, the holding reply, still-running and the completion +// notice โ€” goes through one table with one rule. +// +// # Invariants +// +// Each is held by the database where SQL can say it, and by a test that fails +// without it (outbox_invariants_test.go). +// +// 1. An intent is written in the transaction of the transition that calls +// for it, through the ledger's hooks, so the two commit or roll back +// together. +// 2. One intent per thing answered for: the key is the guard or holding +// reply per event, the completion per attempt, still-running per attempt +// and occurrence. A second write for a key writes nothing. +// 3. Nothing is sent without a durable sending row. The only path to a +// request claims the intent โ€” pending to sending, committed โ€” first. +// 4. Nothing sending is sent again automatically. A request is made only for +// an intent this process just claimed from pending. A sending intent is +// reconciled by listing the destination, never by posting. +// 5. Reconciliation adopts only an unambiguous candidate: exactly one of the +// agent's messages at the destination since the intent went sending +// matches its body, the message is not a worker's own acknowledgement or +// reply, no other intent owns it, and no other intent at the destination +// whose own message may exist unreceipted โ€” pending, sending, +// indeterminate, or abandoned by a person who could not prove it absent โ€” +// has the same body. Anything else is indeterminate, for a person. +// 6. A receipt belongs to exactly one intent, and once written it never +// changes. A unique index and a trigger. +// 7. States move along the lifecycle's edges only: pending โ†’ sending | +// canceled; sending โ†’ sent | indeterminate, or canceled when Basecamp +// answered the request by refusing it, which creates nothing; and +// indeterminate โ†’ sent | abandoned | pending, those three only by a +// person, as is refused โ†’ pending once a person has fixed the cause. +// 8. get_dispatch cancels the guard: a trigger moves the guard intent from +// pending to canceled in get_dispatch's own transaction, and a guard that +// already went out marks every task event it answers for as fired, so a +// worker is told the connector acknowledged. +// 9. A guard is reported fired from the moment it is claimed, and that is +// final: #736's task_events_guard_settles_once lets a guard move only +// from armed. The claim marks its task events fired in the claim's own +// transaction, so no worker asking while the request is in flight +// acknowledges a second time. If Basecamp then refuses the request, the +// intent is canceled โ€” nothing was created โ€” but its task events stay +// fired, so that task's workers do not acknowledge either: the +// acknowledgement is missing, never doubled, the spec's own preference. +// A later task for the event (a person's redispatch) has its guard armed, +// and the worker acknowledges itself: the intent is canceled, so nothing +// remains to fire that guard, and get_dispatch cancels it. This is the spec's rule: a +// missing acknowledgement costs less than a double one. A refusal here is +// Basecamp refusing the connector's own lifecycle request, recorded on +// the outbox row; a worker's permission refusals are another matter. +// 10. Reconciliation never holds up sending for long. A running connector +// sends a batch, then lists at most one due destination; each listing is +// bounded in time; each failure backs its intent off, doubling, and the +// intent is indeterminate after MaxReconcileFailures, with that count +// recorded. Start is the exception by design: it reconciles everything +// due before it sends, within the bound its caller sets, and stops +// sending at the first send that may not have landed. +const migrationOutbox = ` +CREATE TABLE outbox ( + id INTEGER PRIMARY KEY AUTOINCREMENT, + intent_key TEXT NOT NULL UNIQUE, + kind TEXT NOT NULL CHECK (kind IN ('guard_ack', 'holding_reply', 'still_running', 'completion')), + state TEXT NOT NULL DEFAULT 'pending' + CHECK (state IN ('pending', 'sending', 'sent', 'indeterminate', 'canceled', 'abandoned')), + event_id INTEGER REFERENCES events (id), + task_id INTEGER REFERENCES tasks (id), + attempt_id TEXT REFERENCES attempts (id), + occurrence INTEGER NOT NULL DEFAULT 0, + bucket_id INTEGER NOT NULL, + message_kind TEXT NOT NULL CHECK (message_kind IN ('boost', 'comment', 'chat_line')), + recording_id INTEGER NOT NULL CHECK (recording_id > 0), + body TEXT NOT NULL CHECK (body <> ''), + created_at TEXT NOT NULL, + not_before TEXT NOT NULL, + sending_at TEXT, + finished_at TEXT, + receipt_id INTEGER, + note TEXT NOT NULL DEFAULT '', + resolved_by TEXT NOT NULL DEFAULT '', + -- A reconciliation listing that failed is tried again at reconcile_at, + -- backing off; reconcile_failures counts the failures. + reconcile_failures INTEGER NOT NULL DEFAULT 0, + reconcile_at TEXT, + CHECK ((state = 'sent') = (receipt_id IS NOT NULL)), + CHECK (state IN ('pending', 'canceled') OR sending_at IS NOT NULL) +); +CREATE UNIQUE INDEX outbox_receipt ON outbox (message_kind, receipt_id) WHERE receipt_id IS NOT NULL; +CREATE INDEX outbox_due ON outbox (state, not_before); +CREATE INDEX outbox_destination ON outbox (message_kind, recording_id, state); +CREATE INDEX outbox_event ON outbox (event_id, kind); + +CREATE TRIGGER outbox_state_edges +BEFORE UPDATE OF state ON outbox +WHEN NEW.state <> OLD.state AND NOT ( + (OLD.state = 'pending' AND NEW.state IN ('sending', 'canceled')) + OR (OLD.state = 'sending' AND NEW.state IN ('sent', 'indeterminate', 'canceled')) + OR (OLD.state = 'indeterminate' AND NEW.state IN ('sent', 'abandoned', 'pending')) + OR (OLD.state = 'canceled' AND NEW.state = 'pending' AND OLD.note = 'the request was refused; no message was created') +) +BEGIN + SELECT RAISE(ABORT, 'an outbox intent never moves along that edge'); +END; + +CREATE TRIGGER outbox_receipt_is_final +BEFORE UPDATE OF receipt_id ON outbox +WHEN OLD.receipt_id IS NOT NULL AND (NEW.receipt_id IS NULL OR NEW.receipt_id <> OLD.receipt_id) +BEGIN + SELECT RAISE(ABORT, 'a receipt never changes'); +END; + +CREATE TRIGGER outbox_guard_canceled_by_get_dispatch +AFTER UPDATE OF guard ON task_events +WHEN OLD.guard = 'armed' AND NEW.guard = 'canceled' +BEGIN + UPDATE outbox SET state = 'canceled', note = 'get_dispatch', + finished_at = strftime('%Y-%m-%dT%H:%M:%f000000Z', 'now') + WHERE intent_key = 'guard_ack:event:' || NEW.event_id AND state = 'pending'; +END; + +CREATE TRIGGER outbox_guard_fired_before_task +AFTER INSERT ON task_events +WHEN NEW.guard = 'armed' AND EXISTS ( + SELECT 1 FROM outbox + WHERE intent_key = 'guard_ack:event:' || NEW.event_id AND state IN ('sending', 'sent', 'indeterminate', 'abandoned') +) +BEGIN + UPDATE task_events SET guard = 'fired' WHERE task_id = NEW.task_id AND event_id = NEW.event_id; +END; +` + +// IntentKind is what a lifecycle message answers for. +type IntentKind string + +const ( + // IntentGuardAck is the fixed-form acknowledgement a guard posts when no + // worker called get_dispatch in time. One per event. + IntentGuardAck IntentKind = "guard_ack" + // IntentHoldingReply answers a mention or assignment in a project with no + // route. One per event. + IntentHoldingReply IntentKind = "holding_reply" + // IntentStillRunning is one still-running notice. One per attempt and + // occurrence. + IntentStillRunning IntentKind = "still_running" + // IntentCompletion is an attempt's completion notice. One per attempt. + IntentCompletion IntentKind = "completion" +) + +// IntentState is where an intent is. +type IntentState string + +const ( + // IntentPending is written and not yet asked for. + IntentPending IntentState = "pending" + // IntentSending was claimed for a request; the request may or may not + // have reached Basecamp. + IntentSending IntentState = "sending" + // IntentSent has its receipt. + IntentSent IntentState = "sent" + // IntentIndeterminate could not be reconciled unambiguously. It is never + // sent again automatically; a person decides. + IntentIndeterminate IntentState = "indeterminate" + // IntentCanceled was never sent: nothing called for it any more (a guard + // get_dispatch canceled), or Basecamp refused the request, which creates + // nothing. + IntentCanceled IntentState = "canceled" + // IntentAbandoned is an indeterminate intent a person decided not to + // send. + IntentAbandoned IntentState = "abandoned" +) + +// MessageKind is the kind of Basecamp message an intent posts. +type MessageKind string + +const ( + // MessageBoost is a boost on Destination.RecordingID. + MessageBoost MessageKind = "boost" + // MessageComment is a comment on Destination.RecordingID. + MessageComment MessageKind = "comment" + // MessageChatLine is a line in the Campfire Destination.RecordingID. + MessageChatLine MessageKind = "chat_line" +) + +// Destination is where a lifecycle message goes. +type Destination struct { + BucketID int64 + Kind MessageKind + RecordingID int64 +} + +// Intent is one lifecycle message. +type Intent struct { + ID int64 + Key string + Kind IntentKind + State IntentState + // EventID is the event a guard or holding reply answers for; zero for a + // per-attempt intent. + EventID int64 + // TaskID and AttemptID are set on per-attempt intents. + TaskID int64 + AttemptID string + Occurrence int + + Destination Destination + // Body is the message exactly as it is posted, rendered from records when + // the intent was written. + Body string + + CreatedAt time.Time + NotBefore time.Time + SendingAt *time.Time + FinishedAt *time.Time + ReceiptID *int64 + // Note says why an intent is canceled or indeterminate. + Note string + // ResolvedBy names the person who resolved an indeterminate intent. + ResolvedBy string + // ReconcileFailures counts listings that failed for a sending intent; + // ReconcileAt is when the next is due, nil when none failed. + ReconcileFailures int + ReconcileAt *time.Time +} + +// Intent keys. +func guardKey(eventID int64) string { + return string(IntentGuardAck) + ":event:" + strconv.FormatInt(eventID, 10) +} + +func holdingKey(eventID int64) string { + return string(IntentHoldingReply) + ":event:" + strconv.FormatInt(eventID, 10) +} + +func completionKey(attemptID string) string { + return string(IntentCompletion) + ":attempt:" + attemptID +} + +func stillRunningKey(attemptID string, occurrence int) string { + return string(IntentStillRunning) + ":attempt:" + attemptID + ":" + strconv.Itoa(occurrence) +} + +// Errors from the outbox. +var ( + // ErrNoSuchIntent is an intent id the ledger does not hold. + ErrNoSuchIntent = errors.New("no such outbox intent") + // ErrNotIndeterminate is a person's resolution for an intent that is not + // indeterminate. + ErrNotIndeterminate = errors.New("the intent is not indeterminate") + // ErrReceiptOwned is a receipt another intent already owns. + ErrReceiptOwned = errors.New("the receipt belongs to another intent") +) + +// newIntent is an intent a hook writes. +type newIntent struct { + key string + kind IntentKind + eventID int64 + taskID int64 + attemptID string + occurrence int + destination Destination + body string + notBefore time.Time +} + +// writeIntent inserts an intent in tx unless its key already exists. +func writeIntent(ctx context.Context, tx Tx, now time.Time, in newIntent) error { + if in.destination.RecordingID <= 0 || in.body == "" { + return nil + } + if in.notBefore.IsZero() { + in.notBefore = now + } + _, err := tx.ExecContext(ctx, ` +INSERT INTO outbox (intent_key, kind, event_id, task_id, attempt_id, occurrence, bucket_id, message_kind, recording_id, body, created_at, not_before) +VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) +ON CONFLICT (intent_key) DO NOTHING`, + in.key, string(in.kind), nullableID64(in.eventID), nullableID64(in.taskID), nullableString(in.attemptID), in.occurrence, + in.destination.BucketID, string(in.destination.Kind), in.destination.RecordingID, in.body, stamp(now), stamp(in.notBefore)) + if err != nil { + return fmt.Errorf("connector: write outbox intent %s: %w", in.key, err) + } + return nil +} + +func nullableID64(id int64) any { + if id == 0 { + return nil + } + return id +} + +func nullableString(s string) any { + if s == "" { + return nil + } + return s +} + +const selectIntents = ` +SELECT id, intent_key, kind, state, COALESCE(event_id, 0), COALESCE(task_id, 0), COALESCE(attempt_id, ''), occurrence, + bucket_id, message_kind, recording_id, body, created_at, not_before, sending_at, finished_at, receipt_id, note, resolved_by, + reconcile_failures, reconcile_at +FROM outbox` + +func scanIntents(rows *sql.Rows) ([]Intent, error) { + defer func() { _ = rows.Close() }() + var out []Intent + for rows.Next() { + var ( + in Intent + kind, state, messageKind string + created, notBefore string + sendingAt, finishedAt sql.NullString + reconcileAt sql.NullString + receipt sql.NullInt64 + ) + if err := rows.Scan(&in.ID, &in.Key, &kind, &state, &in.EventID, &in.TaskID, &in.AttemptID, &in.Occurrence, + &in.Destination.BucketID, &messageKind, &in.Destination.RecordingID, &in.Body, &created, ¬Before, + &sendingAt, &finishedAt, &receipt, &in.Note, &in.ResolvedBy, &in.ReconcileFailures, &reconcileAt); err != nil { + return nil, fmt.Errorf("connector: read outbox: %w", err) + } + in.Kind, in.State, in.Destination.Kind = IntentKind(kind), IntentState(state), MessageKind(messageKind) + var err error + if in.CreatedAt, err = parseStamp(created); err != nil { + return nil, err + } + if in.NotBefore, err = parseStamp(notBefore); err != nil { + return nil, err + } + if in.SendingAt, err = parseNullStamp(sendingAt); err != nil { + return nil, err + } + if in.FinishedAt, err = parseNullStamp(finishedAt); err != nil { + return nil, err + } + if in.ReconcileAt, err = parseNullStamp(reconcileAt); err != nil { + return nil, err + } + if receipt.Valid { + id := receipt.Int64 + in.ReceiptID = &id + } + out = append(out, in) + } + return out, rows.Err() +} + +func parseNullStamp(s sql.NullString) (*time.Time, error) { + if !s.Valid { + return nil, nil + } + t, err := parseStamp(s.String) + if err != nil { + return nil, err + } + return &t, nil +} + +// IntentFilter selects intents. Zero values select everything. +type IntentFilter struct { + States []IntentState + Kinds []IntentKind + EventID int64 + // Limit is the most returned, newest first; zero for all. + Limit int +} + +// Intents lists outbox intents, newest first. It only reads. +func (l *Ledger) Intents(ctx context.Context, f IntentFilter) ([]Intent, error) { + var out []Intent + err := retryBusy(func() error { + var err error + out, err = l.intents(ctx, f) + return err + }) + return out, err +} + +func (l *Ledger) intents(ctx context.Context, f IntentFilter) ([]Intent, error) { + var ( + where []string + args []any + ) + if len(f.States) > 0 { + where = append(where, "state IN ("+placeholders(len(f.States))+")") + for _, s := range f.States { + args = append(args, string(s)) + } + } + if len(f.Kinds) > 0 { + where = append(where, "kind IN ("+placeholders(len(f.Kinds))+")") + for _, k := range f.Kinds { + args = append(args, string(k)) + } + } + if f.EventID != 0 { + where = append(where, "event_id = ?") + args = append(args, f.EventID) + } + query := selectIntents + if len(where) > 0 { + query += " WHERE " + strings.Join(where, " AND ") + } + query += " ORDER BY id DESC" + if f.Limit > 0 { + query += " LIMIT ?" + args = append(args, f.Limit) + } + rows, err := l.db.QueryContext(ctx, query, args...) + if err != nil { + return nil, fmt.Errorf("connector: list outbox: %w", err) + } + return scanIntents(rows) +} + +// Intent reads one intent by id. +func (l *Ledger) Intent(ctx context.Context, id int64) (Intent, error) { + var intents []Intent + err := retryBusy(func() error { + rows, err := l.db.QueryContext(ctx, selectIntents+` WHERE id = ?`, id) + if err != nil { + return fmt.Errorf("connector: read outbox intent %d: %w", id, err) + } + intents, err = scanIntents(rows) + return err + }) + if err != nil { + return Intent{}, err + } + if len(intents) == 0 { + return Intent{}, fmt.Errorf("connector: outbox intent %d: %w", id, ErrNoSuchIntent) + } + return intents[0], nil +} + +func placeholders(n int) string { + return strings.TrimSuffix(strings.Repeat("?, ", n), ", ") +} + +// IsLifecycleReceipt reports whether a message id is the receipt of one of the +// connector's own lifecycle messages of that kind. +func (l *Ledger) IsLifecycleReceipt(ctx context.Context, kind MessageKind, id int64) (bool, error) { + var found bool + err := retryBusy(func() error { + return l.db.QueryRowContext(ctx, `SELECT EXISTS (SELECT 1 FROM outbox WHERE message_kind = ? AND receipt_id = ?)`, string(kind), id).Scan(&found) + }) + if err != nil { + return false, fmt.Errorf("connector: lifecycle receipt %d: %w", id, err) + } + return found, nil +} + +// Resolution is a person's decision on an indeterminate intent. +type Resolution string + +const ( + // ResolveSent says the message is in Basecamp: ReceiptID names it. + ResolveSent Resolution = "sent" + // ResolveAbandon says it is not to be sent. + ResolveAbandon Resolution = "abandon" + // ResolveResend authorizes sending it again: the intent returns to + // pending. Only a person may choose this; nothing automatic does. + ResolveResend Resolution = "resend" +) + +// IntentResolution is a person's decision and who made it. +type IntentResolution struct { + Resolution Resolution + // ReceiptID is the message a ResolveSent names. + ReceiptID int64 + // By names who decided, for the record. Required. + By string +} + +// ResolveIntent applies a person's decision to an indeterminate intent. +func (l *Ledger) ResolveIntent(ctx context.Context, id int64, r IntentResolution) error { + if strings.TrimSpace(r.By) == "" { + return errors.New("connector: a resolution records who decided") + } + now := l.timestamp() + var ( + query string + args []any + ) + switch r.Resolution { + case ResolveSent: + if r.ReceiptID <= 0 { + return errors.New("connector: a sent resolution names the message") + } + query = `UPDATE outbox SET state = 'sent', receipt_id = ?, finished_at = ?, resolved_by = ?, note = ? WHERE id = ? AND state = 'indeterminate'` + args = []any{r.ReceiptID, now} + case ResolveAbandon: + query = `UPDATE outbox SET state = 'abandoned', finished_at = ?, resolved_by = ?, note = ? WHERE id = ? AND state = 'indeterminate'` + args = []any{now} + case ResolveResend: + // A refused request created nothing, so a person may send it again + // once the cause is fixed, as they may an indeterminate one. + query = `UPDATE outbox SET state = 'pending', sending_at = NULL, finished_at = NULL, reconcile_failures = 0, reconcile_at = NULL, not_before = ?, resolved_by = ?, note = ? +WHERE id = ? AND (state = 'indeterminate' OR (state = 'canceled' AND note = '` + RefusedNote + `'))` + args = []any{now} + default: + return fmt.Errorf("connector: %q is not a resolution", r.Resolution) + } + return retryBusy(func() error { + res, err := l.db.ExecContext(ctx, query, append(args, r.By, "resolved: "+string(r.Resolution), id)...) + if err != nil { + if isUniqueViolation(err) { + return fmt.Errorf("connector: resolve intent %d: %w", id, ErrReceiptOwned) + } + return fmt.Errorf("connector: resolve intent %d: %w", id, err) + } + n, err := res.RowsAffected() + if err != nil { + return err + } + if n == 0 { + if _, err := l.Intent(ctx, id); err != nil { + return err + } + return fmt.Errorf("connector: resolve intent %d: %w", id, ErrNotIndeterminate) + } + return nil + }) +} + +// RefusedNote is the note on an intent Basecamp refused. +const RefusedNote = "the request was refused; no message was created" + +// refuse settles a sending intent Basecamp refused. The request created +// nothing, so the intent is canceled rather than left uncertain, and no later +// task event is written fired for it. Task events the claim already marked +// fired stay fired (invariant 9). +func (l *Ledger) refuse(ctx context.Context, in Intent, note string) (Intent, error) { + err := retryBusy(func() error { + tx, err := l.db.BeginTx(ctx, nil) + if err != nil { + return fmt.Errorf("connector: begin refusal of %d: %w", in.ID, err) + } + defer func() { _ = tx.Rollback() }() + res, err := tx.ExecContext(ctx, `UPDATE outbox SET state = 'canceled', finished_at = ?, note = ? WHERE id = ? AND state = 'sending'`, + l.timestamp(), note, in.ID) + if err != nil { + return fmt.Errorf("connector: refuse intent %d: %w", in.ID, err) + } + if n, err := res.RowsAffected(); err != nil { + return err + } else if n == 0 { + return fmt.Errorf("connector: refuse intent %d: it is not sending", in.ID) + } + return tx.Commit() + }) + if err != nil { + return Intent{}, err + } + return l.Intent(ctx, in.ID) +} + +func isUniqueViolation(err error) bool { + return err != nil && strings.Contains(err.Error(), "UNIQUE constraint failed") +} diff --git a/internal/connector/outbox_basecamp.go b/internal/connector/outbox_basecamp.go new file mode 100644 index 000000000..28278177e --- /dev/null +++ b/internal/connector/outbox_basecamp.go @@ -0,0 +1,160 @@ +package connector + +import ( + "context" + "errors" + "fmt" + "time" + + "github.com/basecamp/basecamp-sdk/go/pkg/basecamp" +) + +// BasecampPoster posts lifecycle messages through the SDK as the agent: the +// account client must be the agent's own, so every message is the agent's. +// +// A create is not idempotent, and the SDK's generated create path makes one +// attempt at it whatever its retry settings, so Post is one request. (The SDK +// does replay a mutation once after a 401 refreshes the token, which creates +// nothing.) The client given should carry no retries of its own around that. +type BasecampPoster struct { + account *basecamp.AccountClient + agentID int64 +} + +// NewBasecampPoster builds a poster over the agent's account client. agentID +// is the agent's Person id: List answers only its messages. +func NewBasecampPoster(account *basecamp.AccountClient, agentID int64) (*BasecampPoster, error) { + if account == nil { + return nil, errors.New("connector: the poster needs the agent's account client") + } + if agentID <= 0 { + return nil, errors.New("connector: the poster needs the agent's Person id") + } + return &BasecampPoster{account: account, agentID: agentID}, nil +} + +var _ Poster = (*BasecampPoster)(nil) + +// Post creates the message. +func (p *BasecampPoster) Post(ctx context.Context, dest Destination, body string) (int64, error) { + id, err := p.post(ctx, dest, body) + if err == nil { + return id, nil + } + if e := basecamp.AsError(err); e != nil && (e.Code == basecamp.CodeNotFound || e.Code == basecamp.CodeForbidden || e.Code == basecamp.CodeValidation) { + // Basecamp answered, and its answer is that it created nothing. + return 0, fmt.Errorf("connector: post %s at %d: %w: %w", dest.Kind, dest.RecordingID, ErrNotPosted, err) + } + return id, err +} + +func (p *BasecampPoster) post(ctx context.Context, dest Destination, body string) (int64, error) { + switch dest.Kind { + case MessageBoost: + boost, err := p.account.Boosts().CreateRecording(ctx, dest.RecordingID, body) + if err != nil { + return 0, err + } + return boost.ID, nil + case MessageComment: + comment, err := p.account.Comments().Create(ctx, dest.RecordingID, &basecamp.CreateCommentRequest{Content: body}) + if err != nil { + return 0, err + } + return comment.ID, nil + case MessageChatLine: + line, err := p.account.Campfires().CreateLine(ctx, dest.RecordingID, body) + if err != nil { + return 0, err + } + return line.ID, nil + } + return 0, fmt.Errorf("connector: %q is not a message kind", dest.Kind) +} + +// linePageLimit bounds how far back a chat listing pages, for both callers: +// reconciliation, which reaches back to a send made minutes ago, and the +// adopted-reply rule, which reaches back to an acknowledgement a task-length +// ago. A Campfire busier than this leaves the intent unreconciled and the +// reply unadopted โ€” an error, not a shorter answer that would read as +// "nothing was posted". +const linePageLimit = 200 + +// List answers the agent's messages at the destination since the time given. +// Boosts and comments are listed whole; chat lines newest first, page by page, +// until a page reaches back past since. +func (p *BasecampPoster) List(ctx context.Context, dest Destination, since time.Time) ([]PostedMessage, error) { + out, err := p.list(ctx, dest, since) + if err == nil { + return out, nil + } + if e := basecamp.AsError(err); e != nil && (e.Code == basecamp.CodeNotFound || e.Code == basecamp.CodeForbidden) { + return nil, fmt.Errorf("connector: list %s at %d: %w: %w", dest.Kind, dest.RecordingID, ErrUnlistable, err) + } + return out, err +} + +func (p *BasecampPoster) list(ctx context.Context, dest Destination, since time.Time) ([]PostedMessage, error) { + var out []PostedMessage + // Newest-first paging shifts lines across pages as new ones arrive, so + // one line can be served twice; it is one message. + seen := map[int64]bool{} + keep := func(creator *basecamp.Person, id int64, created time.Time, content string) { + if creator != nil && creator.ID == p.agentID && !created.Before(since) && !seen[id] { + seen[id] = true + out = append(out, PostedMessage{ID: id, CreatedAt: created, Content: content}) + } + } + switch dest.Kind { + case MessageBoost: + result, err := p.account.Boosts().ListRecording(ctx, dest.RecordingID, &basecamp.BoostListOptions{Limit: -1}) + if err != nil { + return nil, err + } + if result.Meta.Truncated { + // A truncated listing is the SDK's page cap, which waiting does not + // raise: the same class as a Campfire too deep to page. + return nil, fmt.Errorf("connector: the boost listing was truncated: %w", ErrUnlistable) + } + for _, b := range result.Boosts { + keep(b.Booster, b.ID, b.CreatedAt, b.Content) + } + return out, nil + case MessageComment: + result, err := p.account.Comments().List(ctx, dest.RecordingID, &basecamp.CommentListOptions{Limit: -1}) + if err != nil { + return nil, err + } + if result.Meta.Truncated { + return nil, fmt.Errorf("connector: the comment listing was truncated: %w", ErrUnlistable) + } + for _, c := range result.Comments { + keep(c.Creator, c.ID, c.CreatedAt, c.Content) + } + return out, nil + case MessageChatLine: + for page := 1; page <= linePageLimit; page++ { + result, err := p.account.Campfires().ListLines(ctx, dest.RecordingID, &basecamp.CampfireLineListOptions{ + Sort: "created_at", Direction: "desc", Page: page, + }) + if err != nil { + return nil, err + } + if len(result.Lines) == 0 { + return out, nil + } + reachedBack := false + for _, l := range result.Lines { + keep(l.Creator, l.ID, l.CreatedAt, l.Content) + if l.CreatedAt.Before(since) { + reachedBack = true + } + } + if reachedBack { + return out, nil + } + } + return nil, fmt.Errorf("connector: the Campfire listing did not reach back to %s within %d pages: %w", since.UTC().Format(time.RFC3339), linePageLimit, ErrUnlistable) + } + return nil, fmt.Errorf("connector: %q is not a message kind", dest.Kind) +} diff --git a/internal/connector/outbox_basecamp_test.go b/internal/connector/outbox_basecamp_test.go new file mode 100644 index 000000000..f000abf9f --- /dev/null +++ b/internal/connector/outbox_basecamp_test.go @@ -0,0 +1,365 @@ +package connector + +import ( + "context" + "encoding/json" + "net/http" + "net/http/httptest" + "regexp" + "sort" + "strconv" + "sync" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + "github.com/basecamp/basecamp-sdk/go/pkg/basecamp" +) + +// obServer is enough of Basecamp's API for the poster: boosts and comments on +// a recording, lines in a Campfire, each created by whoever the test says. +type obServer struct { + *httptest.Server + + mu sync.Mutex + nextID int64 + messages map[Destination][]obServerMessage + posts int + // onPost runs after a message is stored and before the answer is + // written; a non-zero status answers with it instead. + onPost func(r *http.Request, id int64) int + // beforeStore runs before a message is stored; a non-zero status answers + // with it and stores nothing. + beforeStore func(r *http.Request) int + pageSize int + pageHook func(page int) + truncated bool +} + +type obServerMessage struct { + ID int64 + Content string + CreatedAt time.Time + Creator int64 +} + +var obServerPath = regexp.MustCompile(`^/999/(recordings|chats)/(\d+)/(boosts|comments|lines)\.json$`) + +func newOBServer(t *testing.T) *obServer { + t.Helper() + s := &obServer{nextID: 70000, messages: map[Destination][]obServerMessage{}, pageSize: 2} + s.Server = httptest.NewServer(http.HandlerFunc(s.serve)) + t.Cleanup(s.Close) + return s +} + +func (s *obServer) serve(w http.ResponseWriter, r *http.Request) { + m := obServerPath.FindStringSubmatch(r.URL.Path) + if m == nil { + http.NotFound(w, r) + return + } + recording, _ := strconv.ParseInt(m[2], 10, 64) + kind := map[string]MessageKind{"boosts": MessageBoost, "comments": MessageComment, "lines": MessageChatLine}[m[3]] + dest := Destination{Kind: kind, RecordingID: recording} + + switch r.Method { + case http.MethodPost: + var body struct { + Content string `json:"content"` + } + if err := json.NewDecoder(r.Body).Decode(&body); err != nil { + http.Error(w, err.Error(), http.StatusBadRequest) + return + } + s.mu.Lock() + s.posts++ + before := s.beforeStore + s.mu.Unlock() + if before != nil { + if status := before(r); status != 0 { + w.WriteHeader(status) + return + } + } + id := s.add(dest, adapterAgentID, body.Content) + s.mu.Lock() + hook := s.onPost + s.mu.Unlock() + if hook != nil { + if status := hook(r, id); status != 0 { + w.WriteHeader(status) + return + } + } + w.Header().Set("Content-Type", "application/json") + w.WriteHeader(http.StatusCreated) + _ = json.NewEncoder(w).Encode(s.render(kind, s.find(dest, id))) + case http.MethodGet: + s.mu.Lock() + all := append([]obServerMessage(nil), s.messages[dest]...) + pageSize, hook := s.pageSize, s.pageHook + s.mu.Unlock() + if hook != nil && kind == MessageChatLine { + page, _ := strconv.Atoi(r.URL.Query().Get("page")) + defer hook(page) + } + if kind == MessageChatLine { + sort.Slice(all, func(i, j int) bool { return all[i].CreatedAt.After(all[j].CreatedAt) }) + page, _ := strconv.Atoi(r.URL.Query().Get("page")) + if page < 1 { + page = 1 + } + start := (page - 1) * pageSize + switch { + case start >= len(all): + all = nil + case start+pageSize < len(all): + all = all[start : start+pageSize] + default: + all = all[start:] + } + } + out := make([]any, 0, len(all)) + for _, msg := range all { + out = append(out, s.render(kind, msg)) + } + s.mu.Lock() + truncated := s.truncated + s.mu.Unlock() + if truncated { + // More pages than the SDK will follow: it answers Truncated. + w.Header().Set("Link", `<`+s.URL+r.URL.Path+`?page=2>; rel="next"`) + } + w.Header().Set("Content-Type", "application/json") + _ = json.NewEncoder(w).Encode(out) + default: + w.WriteHeader(http.StatusMethodNotAllowed) + } +} + +func (s *obServer) setOnPost(fn func(r *http.Request, id int64) int) { + s.mu.Lock() + s.onPost = fn + s.mu.Unlock() +} + +func (s *obServer) setTruncated(v bool) { + s.mu.Lock() + s.truncated = v + s.mu.Unlock() +} + +func (s *obServer) setPageHook(fn func(page int)) { + s.mu.Lock() + s.pageHook = fn + s.mu.Unlock() +} + +func (s *obServer) setPageSize(n int) { + s.mu.Lock() + s.pageSize = n + s.mu.Unlock() +} + +func (s *obServer) add(dest Destination, creator int64, content string) int64 { + return s.addAt(dest, creator, content, time.Now().UTC()) +} + +func (s *obServer) addAt(dest Destination, creator int64, content string, at time.Time) int64 { + s.mu.Lock() + defer s.mu.Unlock() + s.nextID++ + key := Destination{Kind: dest.Kind, RecordingID: dest.RecordingID} + s.messages[key] = append(s.messages[key], obServerMessage{ID: s.nextID, Content: content, CreatedAt: at, Creator: creator}) + return s.nextID +} + +func (s *obServer) find(dest Destination, id int64) obServerMessage { + s.mu.Lock() + defer s.mu.Unlock() + for _, m := range s.messages[Destination{Kind: dest.Kind, RecordingID: dest.RecordingID}] { + if m.ID == id { + return m + } + } + return obServerMessage{} +} + +func (s *obServer) at(dest Destination) []obServerMessage { + s.mu.Lock() + defer s.mu.Unlock() + return append([]obServerMessage(nil), s.messages[Destination{Kind: dest.Kind, RecordingID: dest.RecordingID}]...) +} + +func (s *obServer) postCount() int { + s.mu.Lock() + defer s.mu.Unlock() + return s.posts +} + +func (s *obServer) render(kind MessageKind, m obServerMessage) map[string]any { + person := map[string]any{"id": m.Creator, "name": "Person " + strconv.FormatInt(m.Creator, 10)} + out := map[string]any{"id": m.ID, "content": m.Content, "created_at": m.CreatedAt.Format(time.RFC3339Nano)} + if kind == MessageBoost { + out["booster"] = person + } else { + out["creator"] = person + out["status"] = "active" + } + return out +} + +func (s *obServer) poster(t *testing.T) *BasecampPoster { + t.Helper() + client := basecamp.NewClient(&basecamp.Config{BaseURL: s.URL}, &basecamp.StaticTokenProvider{Token: "test-token-not-real"}) + poster, err := NewBasecampPoster(client.ForAccount("999"), adapterAgentID) + require.NoError(t, err) + return poster +} + +func TestBasecampPosterPostsEachKindAsTheAgent(t *testing.T) { + server := newOBServer(t) + poster := server.poster(t) + ctx := context.Background() + + for _, dest := range []Destination{ + {Kind: MessageBoost, RecordingID: obEventRecording}, + {Kind: MessageComment, RecordingID: obReplyRecording}, + {Kind: MessageChatLine, RecordingID: obCampfire}, + } { + id, err := poster.Post(ctx, dest, "body for "+string(dest.Kind)) + require.NoError(t, err, dest.Kind) + stored := server.at(dest) + require.Len(t, stored, 1, dest.Kind) + assert.Equal(t, stored[0].ID, id) + assert.Equal(t, "body for "+string(dest.Kind), stored[0].Content) + } +} + +// A create is one request: a failed answer is never retried by the SDK, since +// a retry would be a second message. +func TestBasecampPosterMakesOneRequestPerPost(t *testing.T) { + server := newOBServer(t) + server.setOnPost(func(*http.Request, int64) int { return http.StatusServiceUnavailable }) + poster := server.poster(t) + + for _, kind := range []MessageKind{MessageBoost, MessageComment, MessageChatLine} { + before := server.postCount() + _, err := poster.Post(context.Background(), Destination{Kind: kind, RecordingID: 5}, "x") + require.Error(t, err, kind) + assert.Equal(t, before+1, server.postCount(), kind) + } +} + +func TestBasecampPosterListsOnlyTheAgentsMessagesSince(t *testing.T) { + server := newOBServer(t) + poster := server.poster(t) + ctx := context.Background() + since := time.Date(2026, 9, 17, 12, 0, 0, 0, time.UTC) + + for _, kind := range []MessageKind{MessageBoost, MessageComment, MessageChatLine} { + dest := Destination{Kind: kind, RecordingID: 42} + server.addAt(dest, adapterAgentID, "old", since.Add(-time.Hour)) + server.addAt(dest, obOtherPersonID, "someone else", since.Add(time.Minute)) + want := server.addAt(dest, adapterAgentID, "mine", since.Add(2*time.Minute)) + server.addAt(dest, obOtherPersonID, "someone else again", since.Add(3*time.Minute)) + server.addAt(dest, obOtherPersonID, "and again", since.Add(4*time.Minute)) + + listed, err := poster.List(ctx, dest, since) + require.NoError(t, err, kind) + require.Len(t, listed, 1, kind) + assert.Equal(t, want, listed[0].ID, kind) + assert.Equal(t, "mine", listed[0].Content, kind) + } +} + +// A Campfire listing that cannot reach back to the sending time is an error, +// never a shorter answer that would read as "nothing was posted". +func TestBasecampPosterRefusesAShortCampfireListing(t *testing.T) { + server := newOBServer(t) + server.setPageSize(1) + poster := server.poster(t) + dest := Destination{Kind: MessageChatLine, RecordingID: obCampfire} + since := time.Date(2026, 9, 17, 12, 0, 0, 0, time.UTC) + for i := range linePageLimit + 1 { + server.addAt(dest, obOtherPersonID, "chatter", since.Add(time.Duration(i+1)*time.Second)) + } + _, err := poster.List(context.Background(), dest, since) + require.Error(t, err) +} + +// A line served on two pages is one message. +func TestBasecampPosterListsALineOnce(t *testing.T) { + server := newOBServer(t) + server.setPageSize(1) + dest := Destination{Kind: MessageChatLine, RecordingID: obCampfire} + since := time.Date(2026, 9, 17, 12, 0, 0, 0, time.UTC) + server.addAt(dest, obOtherPersonID, "before", since.Add(-time.Minute)) + id := server.addAt(dest, adapterAgentID, "mine", since.Add(time.Minute)) + server.setPageHook(func(page int) { + if page == 1 { + // A line arrives between pages, pushing "mine" onto page 2. + server.addAt(dest, obOtherPersonID, "late", since.Add(2*time.Minute)) + } + }) + listed, err := server.poster(t).List(context.Background(), dest, since) + require.NoError(t, err) + require.Len(t, listed, 1) + assert.Equal(t, id, listed[0].ID) +} + +// A destination that is gone or forbidden is unlistable, not a failure to +// try again. +func TestBasecampPosterMarksAGoneDestinationUnlistable(t *testing.T) { + server := newOBServer(t) + poster := server.poster(t) + _, err := poster.List(context.Background(), Destination{Kind: MessageComment, RecordingID: 1}, time.Now()) + require.NoError(t, err, "an empty listing is an answer") + + gone := httptest.NewServer(http.NotFoundHandler()) + t.Cleanup(gone.Close) + client := basecamp.NewClient(&basecamp.Config{BaseURL: gone.URL}, &basecamp.StaticTokenProvider{Token: "test-token-not-real"}) + p, err := NewBasecampPoster(client.ForAccount("999"), adapterAgentID) + require.NoError(t, err) + _, err = p.List(context.Background(), Destination{Kind: MessageComment, RecordingID: 1}, time.Now()) + require.ErrorIs(t, err, ErrUnlistable) +} + +// Basecamp refusing a create is an answer: the message was not created. +func TestBasecampPosterRefusalIsNotPosted(t *testing.T) { + server := newOBServer(t) + server.beforeStore = func(*http.Request) int { return http.StatusForbidden } + _, err := server.poster(t).Post(context.Background(), Destination{Kind: MessageComment, RecordingID: 5}, "x") + require.ErrorIs(t, err, ErrNotPosted) + + server.beforeStore = func(*http.Request) int { return http.StatusServiceUnavailable } + _, err = server.poster(t).Post(context.Background(), Destination{Kind: MessageComment, RecordingID: 5}, "x") + require.Error(t, err) + assert.NotErrorIs(t, err, ErrNotPosted, "a 503 may or may not have created it") +} + +// A listing the SDK truncated at its page cap will not grow shorter by +// waiting: it is unlistable, not a failure to retry for hours. +func TestBasecampPosterTreatsATruncatedListingAsUnlistable(t *testing.T) { + server := newOBServer(t) + poster := server.poster(t) + since := time.Date(2026, 9, 17, 12, 0, 0, 0, time.UTC) + for _, kind := range []MessageKind{MessageBoost, MessageComment} { + dest := Destination{Kind: kind, RecordingID: 77} + server.setTruncated(true) + _, err := poster.List(context.Background(), dest, since) + require.ErrorIs(t, err, ErrUnlistable, kind) + assert.Contains(t, err.Error(), "truncated", kind) + } +} + +// Basecamp rejecting a create as invalid created nothing, like a 403. +func TestBasecampPosterTreatsAValidationRefusalAsNotPosted(t *testing.T) { + server := newOBServer(t) + server.beforeStore = func(*http.Request) int { return http.StatusUnprocessableEntity } + _, err := server.poster(t).Post(context.Background(), Destination{Kind: MessageComment, RecordingID: 5}, "x") + require.ErrorIs(t, err, ErrNotPosted) +} diff --git a/internal/connector/outbox_fakes_test.go b/internal/connector/outbox_fakes_test.go new file mode 100644 index 000000000..31a64069f --- /dev/null +++ b/internal/connector/outbox_fakes_test.go @@ -0,0 +1,206 @@ +package connector + +import ( + "context" + "errors" + "sort" + "sync" + "testing" + "time" + + "github.com/stretchr/testify/require" + + "github.com/basecamp/basecamp-cli/internal/connector/admission" +) + +// Test fixtures for the outbox. Names carry an "ob" prefix so they never +// collide with the dispatcher's own test helpers. + +const ( + obRoute = "/work/connector" + obEventRecording = int64(10304028972) // testEvent's recording + obReplyRecording = int64(10304028989) // admittedVerdict's reply destination + obCampfire = int64(10304030000) + obOtherPersonID = int64(1001) + obUnreachableNote = "listing refused" +) + +// obClock is a settable clock shared by a ledger. +type obClock struct { + mu sync.Mutex + now time.Time +} + +func (c *obClock) Now() time.Time { + c.mu.Lock() + defer c.mu.Unlock() + return c.now +} + +func (c *obClock) Advance(d time.Duration) { + c.mu.Lock() + c.now = c.now.Add(d) + c.mu.Unlock() +} + +// obLedger is a ledger with the lifecycle hooks installed and a settable +// clock. +func obLedger(t *testing.T) (*Ledger, *obClock) { + t.Helper() + ledger := newTestLedger(t) + clock := &obClock{now: time.Date(2026, 9, 17, 12, 0, 0, 0, time.UTC)} + ledger.now = clock.Now + ledger.SetHooks(LifecycleHooks(ledger, LifecycleOptions{})) + return ledger, clock +} + +func obAdmit(t *testing.T, ledger *Ledger, id int64, key string) { + t.Helper() + seenRecord(t, ledger, id) + _, err := ledger.Admission().Commit(context.Background(), admittedVerdict(id, 0, key)) + require.NoError(t, err) +} + +// obNoRouteVerdict is a mention in a project with no route. +func obNoRouteVerdict(id, revision int64, reply admission.ReplyDestination) admission.Verdict { + v := admittedVerdict(id, revision, "recording:10304028989") + v.State, v.Reason = admission.StateBlocked, admission.ReasonNoRoute + v.Routed, v.Route, v.Class, v.Snapshot = false, "", "", nil + v.Reply = &reply + return v +} + +func obLaunch(t *testing.T, ledger *Ledger, id int64) Launch { + t.Helper() + l, err := ledger.LaunchTask(context.Background(), LaunchSpec{EventID: id, Route: obRoute, Driver: "fake", Deadline: time.Hour}) + require.NoError(t, err) + return l +} + +// obPull is get_dispatch. A worker reports only what it pulled โ€” exposure at +// launch is not the pull โ€” so a test that acknowledges or completes an event +// pulls it first, as a worker does. +func obPull(t *testing.T, d *TaskDispatch, id int64) { + t.Helper() + _, ok, err := d.Get(context.Background(), id) + require.NoError(t, err) + require.True(t, ok) +} + +func obIntent(t *testing.T, ledger *Ledger, key string) Intent { + t.Helper() + intents, err := ledger.Intents(context.Background(), IntentFilter{}) + require.NoError(t, err) + for _, in := range intents { + if in.Key == key { + return in + } + } + t.Fatalf("no intent %s", key) + return Intent{} +} + +func obIntents(t *testing.T, ledger *Ledger) []Intent { + t.Helper() + intents, err := ledger.Intents(context.Background(), IntentFilter{}) + require.NoError(t, err) + return intents +} + +// fakeBasecamp is Basecamp as the outbox sees it: messages at destinations, +// each with its creator. +type fakeBasecamp struct { + mu sync.Mutex + nextID int64 + messages map[Destination][]fakeMessage + posts int + lists int + + // beforePost runs before a message is created; an error fails the post + // with nothing created. + beforePost func(dest Destination, body string) error + // afterPost runs after a message is created; an error fails the post + // with the message already created. + afterPost func(dest Destination, id int64) error + listErr error + clock func() time.Time +} + +type fakeMessage struct { + PostedMessage + creator int64 +} + +func newFakeBasecamp(clock func() time.Time) *fakeBasecamp { + return &fakeBasecamp{nextID: 90000, messages: map[Destination][]fakeMessage{}, clock: clock} +} + +func obKey(d Destination) Destination { return Destination{Kind: d.Kind, RecordingID: d.RecordingID} } + +// add puts a message at a destination as if someone had posted it. +func (f *fakeBasecamp) add(dest Destination, creator int64, content string) int64 { + f.mu.Lock() + defer f.mu.Unlock() + f.nextID++ + f.messages[obKey(dest)] = append(f.messages[obKey(dest)], fakeMessage{ + PostedMessage: PostedMessage{ID: f.nextID, CreatedAt: f.clock(), Content: content}, creator: creator, + }) + return f.nextID +} + +func (f *fakeBasecamp) Post(_ context.Context, dest Destination, body string) (int64, error) { + f.mu.Lock() + f.posts++ + before, after := f.beforePost, f.afterPost + f.mu.Unlock() + if before != nil { + if err := before(dest, body); err != nil { + return 0, err + } + } + id := f.add(dest, adapterAgentID, body) + if after != nil { + if err := after(dest, id); err != nil { + return 0, err + } + } + return id, nil +} + +func (f *fakeBasecamp) List(_ context.Context, dest Destination, since time.Time) ([]PostedMessage, error) { + f.mu.Lock() + defer f.mu.Unlock() + f.lists++ + if f.listErr != nil { + return nil, f.listErr + } + var out []PostedMessage + for _, m := range f.messages[obKey(dest)] { + if m.creator == adapterAgentID && !m.CreatedAt.Before(since) { + out = append(out, m.PostedMessage) + } + } + sort.Slice(out, func(i, j int) bool { return out[i].ID < out[j].ID }) + return out, nil +} + +func (f *fakeBasecamp) at(dest Destination) []fakeMessage { + f.mu.Lock() + defer f.mu.Unlock() + return append([]fakeMessage(nil), f.messages[obKey(dest)]...) +} + +func (f *fakeBasecamp) postCount() int { + f.mu.Lock() + defer f.mu.Unlock() + return f.posts +} + +var errWire = errors.New("connection reset by peer") + +func obOutbox(t *testing.T, ledger *Ledger, poster Poster) *Outbox { + t.Helper() + ob, err := NewOutbox(OutboxOptions{Ledger: ledger, Poster: poster}) + require.NoError(t, err) + return ob +} diff --git a/internal/connector/outbox_invariants_test.go b/internal/connector/outbox_invariants_test.go new file mode 100644 index 000000000..e8d8c7230 --- /dev/null +++ b/internal/connector/outbox_invariants_test.go @@ -0,0 +1,1500 @@ +package connector + +import ( + "context" + "fmt" + "path/filepath" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + "github.com/basecamp/basecamp-cli/internal/connector/admission" +) + +// The outbox's invariants (outbox.go), one test or group each. + +var obCommentReply = admission.ReplyDestination{Kind: admission.ReplyComment, RecordingID: obReplyRecording} + +// Invariant 1: an intent and its transition commit or roll back together. An +// intent that cannot be written takes the verdict down with it. +func TestOutboxIntentRollsBackWithItsTransition(t *testing.T) { + ledger, _ := obLedger(t) + ctx := context.Background() + seenRecord(t, ledger, 1) + _, err := ledger.db.ExecContext(ctx, `CREATE TRIGGER refuse_outbox BEFORE INSERT ON outbox BEGIN SELECT RAISE(ABORT, 'injected'); END`) + require.NoError(t, err) + + _, err = ledger.Admission().Commit(ctx, obNoRouteVerdict(1, 0, obCommentReply)) + require.Error(t, err) + assert.Equal(t, StateSeen, getRecord(t, ledger, 1).State, "the verdict rolled back with its intent") + assert.Empty(t, obIntents(t, ledger)) +} + +// Invariant 1, the other direction: a transition that fails after its intent +// was written leaves no intent. +func TestOutboxIntentRollsBackWhenTheTransitionFails(t *testing.T) { + ledger, _ := obLedger(t) + ctx := context.Background() + obAdmit(t, ledger, 1, "recording:10304028989") + l := obLaunch(t, ledger, 1) + + hooks := LifecycleHooks(ledger, LifecycleOptions{}) + written := hooks.AttemptEnded + hooks.AttemptEnded = func(ctx context.Context, tx Tx, s Settlement) error { + if err := written(ctx, tx, s); err != nil { + return err + } + return errWire + } + ledger.SetHooks(hooks) + _, err := ledger.EndAttempt(ctx, AttemptEnd{AttemptID: l.AttemptID, Stop: StopLost}) + require.Error(t, err) + + for _, in := range obIntents(t, ledger) { + assert.NotEqual(t, IntentCompletion, in.Kind, "the completion rolled back with the settlement") + } + live, err := ledger.LiveAttempts(ctx) + require.NoError(t, err) + assert.Len(t, live, 1) +} + +// Invariant 2: one intent per thing answered for. +func TestOutboxOneIntentPerKey(t *testing.T) { + ledger, _ := obLedger(t) + ctx := context.Background() + + // A no_route record is decided again every time it is retried. + seenRecord(t, ledger, 1) + _, err := ledger.Admission().Commit(ctx, obNoRouteVerdict(1, 0, obCommentReply)) + require.NoError(t, err) + _, err = ledger.Admission().Commit(ctx, obNoRouteVerdict(1, getRecord(t, ledger, 1).Revision, obCommentReply)) + require.NoError(t, err) + + obAdmit(t, ledger, 2, "recording:10304028989") + l := obLaunch(t, ledger, 2) + for range 2 { + _, err := ledger.StillRunning(ctx, l.AttemptID) + require.NoError(t, err) + } + + count := map[IntentKind]int{} + for _, in := range obIntents(t, ledger) { + count[in.Kind]++ + } + assert.Equal(t, 1, count[IntentHoldingReply], "one holding reply per event however often it is decided") + assert.Equal(t, 1, count[IntentGuardAck]) + assert.Equal(t, 2, count[IntentStillRunning], "one per occurrence") + obIntent(t, ledger, stillRunningKey(l.AttemptID, 1)) + obIntent(t, ledger, stillRunningKey(l.AttemptID, 2)) +} + +// sendingChecker is a poster that, when asked to post, reads the intent from a +// second ledger handle: what another process would find if this one died now. +type sendingChecker struct { + *fakeBasecamp + t *testing.T + other *Ledger + states []IntentState +} + +func (s *sendingChecker) Post(ctx context.Context, dest Destination, body string) (int64, error) { + intents, err := s.other.Intents(ctx, IntentFilter{}) + require.NoError(s.t, err) + for _, in := range intents { + if in.Body == body { + s.states = append(s.states, in.State) + } + } + return s.fakeBasecamp.Post(ctx, dest, body) +} + +// Invariant 3: the sending row is durable before the request. +func TestOutboxNothingIsSentWithoutADurableSendingRow(t *testing.T) { + path := filepath.Join(t.TempDir(), "state", "connector.db") + ledger, err := OpenLedger(path) + require.NoError(t, err) + t.Cleanup(func() { _ = ledger.Close() }) + ledger.SetHooks(LifecycleHooks(ledger, LifecycleOptions{})) + ctx := context.Background() + + seenRecord(t, ledger, 1) + _, err = ledger.Admission().Commit(ctx, obNoRouteVerdict(1, 0, obCommentReply)) + require.NoError(t, err) + + other, err := OpenLedger(path) + require.NoError(t, err) + t.Cleanup(func() { _ = other.Close() }) + poster := &sendingChecker{fakeBasecamp: newFakeBasecamp(time.Now), t: t, other: other} + require.NoError(t, obOutbox(t, ledger, poster).Flush(ctx)) + require.Equal(t, []IntentState{IntentSending}, poster.states, "another handle saw the intent sending while the request was made") + assert.Equal(t, IntentSent, obIntent(t, ledger, holdingKey(1)).State) +} + +// Invariant 4: a request that fails leaves the intent sending, and nothing +// automatic posts it again โ€” not the next flush, not a restart. +func TestOutboxNeverResendsASendingIntent(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + seenRecord(t, ledger, 1) + _, err := ledger.Admission().Commit(ctx, obNoRouteVerdict(1, 0, obCommentReply)) + require.NoError(t, err) + + basecamp := newFakeBasecamp(clock.Now) + basecamp.beforePost = func(Destination, string) error { return errWire } + ob := obOutbox(t, ledger, basecamp) + require.NoError(t, ob.Flush(ctx)) + assert.Equal(t, 1, basecamp.postCount()) + assert.Equal(t, IntentSending, obIntent(t, ledger, holdingKey(1)).State) + + basecamp.beforePost = nil + require.NoError(t, ob.Flush(ctx)) + clock.Advance(time.Hour) + require.NoError(t, ob.Flush(ctx)) + restarted := obOutbox(t, ledger, basecamp) + require.NoError(t, restarted.Recover(ctx)) + require.NoError(t, restarted.Flush(ctx)) + + assert.Equal(t, 1, basecamp.postCount(), "one request, ever") + in := obIntent(t, ledger, holdingKey(1)) + assert.Equal(t, IntentIndeterminate, in.State, "nothing matched, so a person decides") + assert.Empty(t, basecamp.at(in.Destination)) +} + +// Invariant 4: a stale sending intent is reconciled by the running process +// too, never posted. +func TestOutboxReconcilesAStaleSendingIntentWithoutPosting(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + seenRecord(t, ledger, 1) + _, err := ledger.Admission().Commit(ctx, obNoRouteVerdict(1, 0, obCommentReply)) + require.NoError(t, err) + + // The request landed, but its answer was lost on the wire. + basecamp := newFakeBasecamp(clock.Now) + basecamp.afterPost = func(Destination, int64) error { return errWire } + ob := obOutbox(t, ledger, basecamp) + require.NoError(t, ob.Flush(ctx)) + require.Equal(t, IntentSending, obIntent(t, ledger, holdingKey(1)).State) + + settled, err := ob.reconcileStale(ctx, ob.opts.ReconcileAfter) + require.NoError(t, err) + assert.Zero(t, settled, "a request just made is given time to land") + + clock.Advance(2 * time.Minute) + settled, err = ob.reconcileStale(ctx, ob.opts.ReconcileAfter) + require.NoError(t, err) + assert.Equal(t, 1, settled) + in := obIntent(t, ledger, holdingKey(1)) + require.Equal(t, IntentSent, in.State) + messages := basecamp.at(in.Destination) + require.Len(t, messages, 1) + assert.Equal(t, messages[0].ID, *in.ReceiptID) + assert.Equal(t, 1, basecamp.postCount()) +} + +// sendingHolding writes a holding reply intent and moves it to sending as a +// crashed process would have left it. +func sendingHolding(t *testing.T, ledger *Ledger, id int64, reply admission.ReplyDestination) Intent { + t.Helper() + ctx := context.Background() + seenRecord(t, ledger, id) + _, err := ledger.Admission().Commit(ctx, obNoRouteVerdict(id, 0, reply)) + require.NoError(t, err) + claimed, ok, err := ledger.claimIntent(ctx) + require.NoError(t, err) + require.True(t, ok) + require.Equal(t, holdingKey(id), claimed.Key) + return claimed +} + +// Invariant 5: reconciliation adopts only an unambiguous candidate. +func TestOutboxReconciliationAdoptsOnlyTheUnambiguous(t *testing.T) { + t.Run("exactly one match is adopted", func(t *testing.T) { + ctx := context.Background() + ledger, clock := obLedger(t) + in := sendingHolding(t, ledger, 1, obCommentReply) + basecamp := newFakeBasecamp(clock.Now) + basecamp.add(in.Destination, adapterAgentID, "
Working on it now
") // the worker's own words + basecamp.add(in.Destination, obOtherPersonID, in.Body) // someone quoting it + posted := basecamp.add(in.Destination, adapterAgentID, `
`+in.Body+`
`) + + require.NoError(t, obOutbox(t, ledger, basecamp).Recover(ctx)) + got := obIntent(t, ledger, in.Key) + require.Equal(t, IntentSent, got.State) + assert.Equal(t, posted, *got.ReceiptID) + assert.Zero(t, basecamp.postCount()) + }) + + t.Run("two matches are indeterminate", func(t *testing.T) { + ctx := context.Background() + ledger, clock := obLedger(t) + in := sendingHolding(t, ledger, 1, obCommentReply) + basecamp := newFakeBasecamp(clock.Now) + basecamp.add(in.Destination, adapterAgentID, in.Body) + basecamp.add(in.Destination, adapterAgentID, in.Body) + + require.NoError(t, obOutbox(t, ledger, basecamp).Recover(ctx)) + got := obIntent(t, ledger, in.Key) + assert.Equal(t, IntentIndeterminate, got.State) + assert.Nil(t, got.ReceiptID) + assert.Zero(t, basecamp.postCount()) + }) + + t.Run("a match another intent owns is not a candidate", func(t *testing.T) { + ctx := context.Background() + ledger, clock := obLedger(t) + // Two guards on one recording: the same boost body, the same + // destination. The first went out and has its receipt. + obAdmit(t, ledger, 1, "recording:10304028989") + obAdmit(t, ledger, 2, "recording:10304028989") + clock.Advance(DefaultGuardDelay) + basecamp := newFakeBasecamp(clock.Now) + first, ok, err := ledger.claimIntent(ctx) + require.NoError(t, err) + require.True(t, ok) + receipt := basecamp.add(first.Destination, adapterAgentID, first.Body) + _, err = ledger.recordReceipt(ctx, first.ID, receipt) + require.NoError(t, err) + second, ok, err := ledger.claimIntent(ctx) + require.NoError(t, err) + require.True(t, ok) + + require.NoError(t, obOutbox(t, ledger, basecamp).Recover(ctx)) + got := obIntent(t, ledger, second.Key) + assert.Equal(t, IntentIndeterminate, got.State, "the only matching boost is the first guard's") + assert.Equal(t, receipt, *obIntent(t, ledger, first.Key).ReceiptID) + }) + + t.Run("a match another unfinished intent could claim is indeterminate", func(t *testing.T) { + ctx := context.Background() + ledger, clock := obLedger(t) + obAdmit(t, ledger, 1, "recording:10304028989") + obAdmit(t, ledger, 2, "recording:10304028989") + clock.Advance(DefaultGuardDelay) + first, ok, err := ledger.claimIntent(ctx) + require.NoError(t, err) + require.True(t, ok) + basecamp := newFakeBasecamp(clock.Now) + basecamp.add(first.Destination, adapterAgentID, first.Body) + + // The second guard is still pending: it could have been the one sent. + ob := obOutbox(t, ledger, basecamp) + _, err = ob.reconcileStale(ctx, 0) + require.NoError(t, err) + assert.Equal(t, IntentIndeterminate, obIntent(t, ledger, first.Key).State) + assert.Zero(t, basecamp.postCount()) + }) + + t.Run("a listing that fails settles nothing", func(t *testing.T) { + ctx := context.Background() + ledger, clock := obLedger(t) + in := sendingHolding(t, ledger, 1, obCommentReply) + basecamp := newFakeBasecamp(clock.Now) + basecamp.add(in.Destination, adapterAgentID, in.Body) + basecamp.listErr = errWire + + require.Error(t, obOutbox(t, ledger, basecamp).Recover(ctx)) + assert.Equal(t, IntentSending, obIntent(t, ledger, in.Key).State, "tried again later, still never posted") + assert.Zero(t, basecamp.postCount()) + }) +} + +// Invariant 6: a receipt belongs to one intent and never changes. +func TestOutboxAReceiptBelongsToOneIntent(t *testing.T) { + ledger, _ := obLedger(t) + ctx := context.Background() + a := sendingHolding(t, ledger, 1, obCommentReply) + b := sendingHolding(t, ledger, 2, obCommentReply) + + _, err := ledger.recordReceipt(ctx, a.ID, 777) + require.NoError(t, err) + _, err = ledger.recordReceipt(ctx, b.ID, 777) + require.ErrorIs(t, err, ErrReceiptOwned) + assert.Equal(t, IntentSending, obIntent(t, ledger, b.Key).State) + + _, err = ledger.db.ExecContext(ctx, `UPDATE outbox SET receipt_id = 778 WHERE id = ?`, a.ID) + require.Error(t, err, "a receipt never changes") +} + +// Invariant 7: states move along the lifecycle's edges only. +func TestOutboxIntentStatesMoveAlongTheirEdges(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + in := sendingHolding(t, ledger, 1, obCommentReply) + + _, err := ledger.db.ExecContext(ctx, `UPDATE outbox SET state = 'pending' WHERE id = ?`, in.ID) + require.Error(t, err, "sending never returns to pending by itself") + + require.NoError(t, obOutbox(t, ledger, newFakeBasecamp(clock.Now)).Recover(ctx)) + require.Equal(t, IntentIndeterminate, obIntent(t, ledger, in.Key).State) + + err = ledger.ResolveIntent(ctx, in.ID, IntentResolution{Resolution: ResolveResend}) + require.Error(t, err, "a resolution names who decided") + require.NoError(t, ledger.ResolveIntent(ctx, in.ID, IntentResolution{Resolution: ResolveAbandon, By: "person:26909558"})) + got := obIntent(t, ledger, in.Key) + assert.Equal(t, IntentAbandoned, got.State) + assert.Equal(t, "person:26909558", got.ResolvedBy) + require.ErrorIs(t, ledger.ResolveIntent(ctx, in.ID, IntentResolution{Resolution: ResolveResend, By: "person:26909558"}), ErrNotIndeterminate) + + // A person's decision reaches an indeterminate intent, and nothing else: + // a sent one is settled, whatever a person says about it. + sent := sendingHolding(t, ledger, 2, obCommentReply) + _, err = ledger.recordReceipt(ctx, sent.ID, 4242) + require.NoError(t, err) + require.ErrorIs(t, ledger.ResolveIntent(ctx, sent.ID, IntentResolution{Resolution: ResolveAbandon, By: "person:26909558"}), ErrNotIndeterminate) + assert.Equal(t, IntentSent, obIntent(t, ledger, sent.Key).State) + _, err = ledger.db.ExecContext(ctx, `UPDATE outbox SET state = 'pending' WHERE id = ?`, in.ID) + require.Error(t, err, "abandoned is final") +} + +// A person's resend is the only way an intent goes out a second time. +func TestOutboxAPersonMayResendAnIndeterminateIntent(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + in := sendingHolding(t, ledger, 1, obCommentReply) + basecamp := newFakeBasecamp(clock.Now) + ob := obOutbox(t, ledger, basecamp) + require.NoError(t, ob.Recover(ctx)) + require.NoError(t, ob.Flush(ctx)) + require.Zero(t, basecamp.postCount()) + + require.NoError(t, ledger.ResolveIntent(ctx, in.ID, IntentResolution{Resolution: ResolveResend, By: "person:26909558"})) + require.NoError(t, ob.Flush(ctx)) + assert.Equal(t, 1, basecamp.postCount()) + assert.Equal(t, IntentSent, obIntent(t, ledger, in.Key).State) +} + +// Invariant 8: get_dispatch within the delay cancels the guard in its own +// transaction, and the guard never posts. +func TestOutboxGetDispatchCancelsTheGuard(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + obAdmit(t, ledger, 1, "recording:10304028989") + l := obLaunch(t, ledger, 1) + basecamp := newFakeBasecamp(clock.Now) + ob := obOutbox(t, ledger, basecamp) + + clock.Advance(20 * time.Second) + require.NoError(t, ob.Flush(ctx)) + require.Zero(t, basecamp.postCount(), "not due yet") + + d, err := ledger.Dispatch(ctx, l.Token, adapterAgentID) + require.NoError(t, err) + instruction, ok, err := d.Get(ctx, 1) + require.NoError(t, err) + require.True(t, ok) + assert.False(t, instruction.GuardAcknowledged) + assert.Equal(t, IntentCanceled, obIntent(t, ledger, guardKey(1)).State, "canceled in get_dispatch's transaction") + + clock.Advance(time.Minute) + require.NoError(t, ob.Flush(ctx)) + assert.Zero(t, basecamp.postCount()) +} + +// Invariant 8: a guard that fired is reported to the worker, whether its task +// existed when it fired or was created after. +func TestOutboxAFiredGuardIsReportedToTheWorker(t *testing.T) { + t.Run("task live when the guard fires", func(t *testing.T) { + ctx := context.Background() + ledger, clock := obLedger(t) + obAdmit(t, ledger, 1, "recording:10304028989") + l := obLaunch(t, ledger, 1) + basecamp := newFakeBasecamp(clock.Now) + clock.Advance(DefaultGuardDelay) + require.NoError(t, obOutbox(t, ledger, basecamp).Flush(ctx)) + require.Equal(t, 1, basecamp.postCount()) + + guard := obIntent(t, ledger, guardKey(1)) + assert.Equal(t, IntentSent, guard.State) + assert.Equal(t, Destination{BucketID: adapterBucketID, Kind: MessageBoost, RecordingID: obEventRecording}, guard.Destination) + d, err := ledger.Dispatch(ctx, l.Token, adapterAgentID) + require.NoError(t, err) + instruction, _, err := d.Get(ctx, 1) + require.NoError(t, err) + assert.True(t, instruction.GuardAcknowledged) + }) + + t.Run("task created after the guard fired", func(t *testing.T) { + ctx := context.Background() + ledger, clock := obLedger(t) + obAdmit(t, ledger, 1, "recording:10304028989") + basecamp := newFakeBasecamp(clock.Now) + clock.Advance(DefaultGuardDelay) + require.NoError(t, obOutbox(t, ledger, basecamp).Flush(ctx)) + require.Equal(t, 1, basecamp.postCount(), "a slow launch is what the guard is for") + + l := obLaunch(t, ledger, 1) + d, err := ledger.Dispatch(ctx, l.Token, adapterAgentID) + require.NoError(t, err) + instruction, _, err := d.Get(ctx, 1) + require.NoError(t, err) + assert.True(t, instruction.GuardAcknowledged) + }) + + t.Run("follow-up joined after its guard fired", func(t *testing.T) { + ctx := context.Background() + ledger, clock := obLedger(t) + obAdmit(t, ledger, 1, "recording:10304028989") + l := obLaunch(t, ledger, 1) + obAdmit(t, ledger, 2, "recording:10304028989") + require.Equal(t, StateQueued, getRecord(t, ledger, 2).State) + d, err := ledger.Dispatch(ctx, l.Token, adapterAgentID) + require.NoError(t, err) + _, _, err = d.Get(ctx, 1) + require.NoError(t, err) + + basecamp := newFakeBasecamp(clock.Now) + clock.Advance(DefaultGuardDelay) + require.NoError(t, obOutbox(t, ledger, basecamp).Flush(ctx)) + require.Equal(t, 1, basecamp.postCount(), "only the follow-up's guard: the first was canceled") + + joined, err := ledger.JoinConversation(ctx, l.TaskID) + require.NoError(t, err) + require.Equal(t, []int64{2}, joined) + instruction, _, err := d.Get(ctx, 2) + require.NoError(t, err) + assert.True(t, instruction.GuardAcknowledged) + }) +} + +// The guard arms only for a request, and stands down for a record that left +// the path to a worker. +func TestOutboxTheGuardArmsOnlyForRequestsStillWaiting(t *testing.T) { + t.Run("no guard for a trigger that is not a request", func(t *testing.T) { + ctx := context.Background() + ledger, _ := obLedger(t) + seenRecord(t, ledger, 1) + v := admittedVerdict(1, 0, "recording:10304028989") + v.Trigger, v.Acknowledge = admission.TriggerCompleted, false + _, err := ledger.Admission().Commit(ctx, v) + require.NoError(t, err) + assert.Empty(t, obIntents(t, ledger)) + }) + + t.Run("a record discarded before the guard is due", func(t *testing.T) { + ctx := context.Background() + ledger, clock := obLedger(t) + obAdmit(t, ledger, 1, "recording:10304028989") + _, err := ledger.db.ExecContext(ctx, `UPDATE events SET state = 'discarded', reason = 'by_operator' WHERE id = 1`) + require.NoError(t, err) + basecamp := newFakeBasecamp(clock.Now) + clock.Advance(DefaultGuardDelay) + require.NoError(t, obOutbox(t, ledger, basecamp).Flush(ctx)) + assert.Zero(t, basecamp.postCount()) + assert.Equal(t, IntentCanceled, obIntent(t, ledger, guardKey(1)).State) + }) +} + +// The hold marker holds sending; what was sent is still reconciled. +func TestOutboxPausedHoldsSending(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + in := sendingHolding(t, ledger, 1, obCommentReply) + seenRecord(t, ledger, 2) + _, err := ledger.Admission().Commit(ctx, obNoRouteVerdict(2, 0, obCommentReply)) + require.NoError(t, err) + + basecamp := newFakeBasecamp(clock.Now) + basecamp.add(in.Destination, adapterAgentID, in.Body) + ob, err := NewOutbox(OutboxOptions{Ledger: ledger, Poster: basecamp, Paused: func(context.Context) (bool, error) { return true, nil }}) + require.NoError(t, err) + require.NoError(t, ob.Recover(ctx)) + require.NoError(t, ob.Flush(ctx)) + assert.Zero(t, basecamp.postCount()) + assert.Equal(t, IntentSent, obIntent(t, ledger, in.Key).State) + assert.Equal(t, IntentPending, obIntent(t, ledger, holdingKey(2)).State) +} + +// Invariant 4, defended in the sender too: should an intent it already +// claimed ever come back as pending within one flush, the flush leaves it for +// the next rather than post it a second time. +func TestOutboxFlushNeverClaimsAnIntentTwice(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + seenRecord(t, ledger, 1) + _, err := ledger.Admission().Commit(ctx, obNoRouteVerdict(1, 0, obCommentReply)) + require.NoError(t, err) + _, err = ledger.db.ExecContext(ctx, `DROP TRIGGER outbox_state_edges`) + require.NoError(t, err) + + basecamp := newFakeBasecamp(clock.Now) + reset := false + basecamp.beforePost = func(Destination, string) error { + if !reset { + // Something outside the rules puts the row back to pending + // mid-send, once. + reset = true + _, err := ledger.db.ExecContext(ctx, `UPDATE outbox SET state = 'pending', sending_at = NULL WHERE intent_key = ?`, holdingKey(1)) + require.NoError(t, err) + } + return errWire + } + require.NoError(t, obOutbox(t, ledger, basecamp).Flush(ctx)) + assert.Equal(t, 1, basecamp.postCount()) + assert.Equal(t, IntentPending, obIntent(t, ledger, holdingKey(1)).State, "left for the next flush, not claimed again in this one") +} + +// A listing that keeps failing backs off, and gives up as indeterminate โ€” +// never a request a second, never a resend. +func TestOutboxAFailingListingBacksOffThenGivesUp(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + in := sendingHolding(t, ledger, 1, obCommentReply) + basecamp := newFakeBasecamp(clock.Now) + basecamp.listErr = errWire + ob := obOutbox(t, ledger, basecamp) + + lists := func() int { basecamp.mu.Lock(); defer basecamp.mu.Unlock(); return basecamp.lists } + require.Error(t, ob.Recover(ctx)) + require.Equal(t, 1, lists()) + for range 5 { + _, _ = ob.reconcileStale(ctx, 0) + } + assert.Equal(t, 1, lists(), "not tried again before its backoff") + got := obIntent(t, ledger, in.Key) + require.Equal(t, IntentSending, got.State) + require.NotNil(t, got.ReconcileAt) + assert.Equal(t, DefaultReconcileBackoff, got.ReconcileAt.Sub(clock.Now())) + + for i := 2; i <= MaxReconcileFailures; i++ { + clock.Advance(MaxReconcileBackoff) + _, _ = ob.reconcileStale(ctx, 0) + assert.Equal(t, i, lists()) + } + got = obIntent(t, ledger, in.Key) + assert.Equal(t, IntentIndeterminate, got.State) + assert.Equal(t, MaxReconcileFailures, got.ReconcileFailures, "the count that gave up is the count recorded") + assert.Zero(t, basecamp.postCount()) +} + +// A destination that cannot be listed settles at once as indeterminate. +func TestOutboxAnUnlistableDestinationIsIndeterminate(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + in := sendingHolding(t, ledger, 1, obCommentReply) + basecamp := newFakeBasecamp(clock.Now) + basecamp.listErr = fmt.Errorf("gone: %w", ErrUnlistable) + require.NoError(t, obOutbox(t, ledger, basecamp).Recover(ctx)) + got := obIntent(t, ledger, in.Key) + assert.Equal(t, IntentIndeterminate, got.State) + assert.Equal(t, "destination cannot be listed", got.Note) + assert.Equal(t, 1, got.ReconcileFailures) +} + +// On start, a sending intent younger than ReconcileAfter is left to land. +func TestOutboxRunLeavesAYoungSendingIntentToLand(t *testing.T) { + ledger, clock := obLedger(t) + in := sendingHolding(t, ledger, 1, obCommentReply) + basecamp := newFakeBasecamp(clock.Now) + ob, err := NewOutbox(OutboxOptions{Ledger: ledger, Poster: basecamp, Tick: time.Millisecond}) + require.NoError(t, err) + ctx, cancel := context.WithTimeout(context.Background(), 50*time.Millisecond) + defer cancel() + require.NoError(t, ob.Run(ctx)) + assert.Zero(t, basecamp.lists) + assert.Equal(t, IntentSending, obIntent(t, ledger, in.Key).State) +} + +// Rivals: an intent left indeterminate or abandoned at the destination with +// the same body may own the only match, so nothing is adopted. +func TestOutboxUnsettledRivalsBlockAdoption(t *testing.T) { + for _, rivalState := range []IntentState{IntentIndeterminate, IntentAbandoned} { + t.Run(string(rivalState), func(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + obAdmit(t, ledger, 1, "recording:10304028989") + obAdmit(t, ledger, 2, "recording:10304028989") + clock.Advance(DefaultGuardDelay) + first, ok, err := ledger.claimIntent(ctx) + require.NoError(t, err) + require.True(t, ok) + basecamp := newFakeBasecamp(clock.Now) + // The first guard's request never got an answer; nothing listed yet. + require.NoError(t, obOutbox(t, ledger, basecamp).Recover(ctx)) + require.Equal(t, IntentIndeterminate, obIntent(t, ledger, first.Key).State) + if rivalState == IntentAbandoned { + require.NoError(t, ledger.ResolveIntent(ctx, first.ID, IntentResolution{Resolution: ResolveAbandon, By: "person:26909558"})) + } + + // The first boost shows up late; the second guard went sending. + second, ok, err := ledger.claimIntent(ctx) + require.NoError(t, err) + require.True(t, ok) + basecamp.add(second.Destination, adapterAgentID, second.Body) + require.NoError(t, obOutbox(t, ledger, basecamp).Recover(ctx)) + assert.Equal(t, IntentIndeterminate, obIntent(t, ledger, second.Key).State) + }) + } +} + +// A lifecycle message whose receipt the ledger does not hold yet is not +// adopted as the worker's reply; it is recognized by its words at its own +// destination, so a notice in flight elsewhere, or one left for a person, +// never hides a reply. +func TestOutboxAnUnreceiptedNoticeIsNeverAdopted(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + in := sendingHolding(t, ledger, 1, obCommentReply) + basecamp := newFakeBasecamp(clock.Now) + since := clock.Now().Add(-time.Minute) + landed := basecamp.add(in.Destination, adapterAgentID, `
`+in.Body+`
`) + reply := basecamp.add(in.Destination, adapterAgentID, "
Done: the fix is on the branch.
") + replies := LifecycleFilteredReplies{Lister: basecamp, Ledger: ledger} + + listed, err := replies.AgentReplies(ctx, adapterBucketID, "comment", obReplyRecording, since) + require.NoError(t, err) + require.Len(t, listed, 1, "the sending notice is left out by its words") + assert.Equal(t, reply, listed[0].ID) + + // Elsewhere, an abandoned notice hides nothing. + other := admission.ReplyDestination{Kind: admission.ReplyComment, RecordingID: 555} + abandoned := sendingHolding(t, ledger, 2, other) + require.NoError(t, obOutbox(t, ledger, newFakeBasecamp(clock.Now)).Recover(ctx)) + require.NoError(t, ledger.ResolveIntent(ctx, abandoned.ID, IntentResolution{Resolution: ResolveAbandon, By: "person:26909558"})) + listed, err = replies.AgentReplies(ctx, adapterBucketID, "comment", obReplyRecording, since) + require.NoError(t, err) + require.Len(t, listed, 1) + + // That recovery listed an empty Basecamp, so the first notice is + // indeterminate too, and still left out by its words. A person then finds + // it and records its receipt, which identifies it from then on. + require.Equal(t, IntentIndeterminate, obIntent(t, ledger, in.Key).State) + require.NoError(t, ledger.ResolveIntent(ctx, in.ID, IntentResolution{Resolution: ResolveSent, ReceiptID: landed, By: "person:26909558"})) + assert.True(t, IsLifecycleMessageIn(ledger)(landed)) + assert.False(t, IsLifecycleMessageIn(ledger)(reply)) + id, ok := AdoptableReply(AdoptionCandidate{DeliveredAt: since}, []AgentReply{{ID: landed, CreatedAt: clock.Now()}}, IsLifecycleMessageIn(ledger)) + assert.False(t, ok, "adopted %d", id) +} + +// blockingPoster answers nothing until its request's context ends. +type blockingPoster struct{ *fakeBasecamp } + +func (b blockingPoster) Post(ctx context.Context, _ Destination, _ string) (int64, error) { + <-ctx.Done() + return 0, ctx.Err() +} + +// A flush with a deadline โ€” the shutdown's โ€” is not held past it by a request, +// and claims nothing it has no time left to send. +func TestOutboxFlushHonoursItsDeadline(t *testing.T) { + ledger, clock := obLedger(t) + for _, id := range []int64{1, 2} { + seenRecord(t, ledger, id) + _, err := ledger.Admission().Commit(context.Background(), obNoRouteVerdict(id, 0, obCommentReply)) + require.NoError(t, err) + } + // The first claim has half a second of slack; once its request is cut off + // at PostTimeout, less than PostTimeout is left, so nothing more is + // claimed. + ob, err := NewOutbox(OutboxOptions{Ledger: ledger, Poster: blockingPoster{newFakeBasecamp(clock.Now)}, PostTimeout: time.Second}) + require.NoError(t, err) + + ctx, cancel := context.WithTimeout(context.Background(), 1500*time.Millisecond) + defer cancel() + started := time.Now() + _ = ob.Flush(ctx) + assert.Less(t, time.Since(started), 5*time.Second) + assert.Equal(t, IntentSending, obIntent(t, ledger, holdingKey(1)).State, "cut off mid-flight: reconciled later, never resent") + assert.Equal(t, IntentPending, obIntent(t, ledger, holdingKey(2)).State, "not claimed with too little time left") +} + +// A person's resend starts the request's reconciliation afresh: the failures +// of the listing before it are not counted against it. +func TestOutboxAResendStartsReconciliationAfresh(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + in := sendingHolding(t, ledger, 1, obCommentReply) + basecamp := newFakeBasecamp(clock.Now) + basecamp.listErr = errWire + ob := obOutbox(t, ledger, basecamp) + for range MaxReconcileFailures { + _, _ = ob.reconcileStale(ctx, 0) + clock.Advance(MaxReconcileBackoff) + } + require.Equal(t, IntentIndeterminate, obIntent(t, ledger, in.Key).State) + + require.NoError(t, ledger.ResolveIntent(ctx, in.ID, IntentResolution{Resolution: ResolveResend, By: "person:26909558"})) + got := obIntent(t, ledger, in.Key) + assert.Zero(t, got.ReconcileFailures) + assert.Nil(t, got.ReconcileAt) + + basecamp.beforePost = func(Destination, string) error { return errWire } + require.NoError(t, ob.Flush(ctx)) + _, _ = ob.reconcileStale(ctx, 0) + assert.Equal(t, IntentSending, obIntent(t, ledger, in.Key).State, "one failed listing is the first of a fresh budget") +} + +// A request that failed โ€” a timeout, say โ€” is given ReconcileAfter from its +// failure to land, not from its claim. +func TestOutboxAFailedPostIsGivenTimeToLand(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + seenRecord(t, ledger, 1) + _, err := ledger.Admission().Commit(ctx, obNoRouteVerdict(1, 0, obCommentReply)) + require.NoError(t, err) + basecamp := newFakeBasecamp(clock.Now) + basecamp.beforePost = func(Destination, string) error { + clock.Advance(DefaultPostTimeout) // the request ran out its whole timeout + return context.DeadlineExceeded + } + ob := obOutbox(t, ledger, basecamp) + require.NoError(t, ob.Flush(ctx)) + _, _ = ob.reconcileStale(ctx, ob.opts.ReconcileAfter) + assert.Zero(t, basecamp.lists, "not listed straight after the failure") + assert.Equal(t, IntentSending, obIntent(t, ledger, holdingKey(1)).State) +} + +// A request claimed with time left is still cut off at the flush's deadline, +// not at its own longer timeout. +func TestOutboxFlushCapsARequestAtItsDeadline(t *testing.T) { + ledger, clock := obLedger(t) + seenRecord(t, ledger, 1) + _, err := ledger.Admission().Commit(context.Background(), obNoRouteVerdict(1, 0, obCommentReply)) + require.NoError(t, err) + ob, err := NewOutbox(OutboxOptions{Ledger: ledger, Poster: blockingPoster{newFakeBasecamp(clock.Now)}, PostTimeout: time.Minute}) + require.NoError(t, err) + + ctx, cancel := context.WithTimeout(context.Background(), MinPostWindow+500*time.Millisecond) + defer cancel() + started := time.Now() + _ = ob.Flush(ctx) + assert.Less(t, time.Since(started), MinPostWindow+5*time.Second) + assert.Equal(t, IntentSending, obIntent(t, ledger, holdingKey(1)).State) +} + +// A queue of intents arriving as fast as they can be sent does not starve +// reconciliation: the running connector sends in batches. +func TestOutboxRunReconcilesWhileSendsKeepArriving(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + stale := sendingHolding(t, ledger, 1, obCommentReply) + basecamp := newFakeBasecamp(clock.Now) + basecamp.add(stale.Destination, adapterAgentID, stale.Body) + + // Every send admits another request, so there is always one more to send. + next := int64(100) + admit := func() { + next++ + seenRecord(t, ledger, next) + _, err := ledger.Admission().Commit(context.Background(), obNoRouteVerdict(next, 0, obCommentReply)) + require.NoError(t, err) + } + basecamp.beforePost = func(Destination, string) error { + admit() + return nil + } + clock.Advance(2 * DefaultReconcileAfter) + seenRecord(t, ledger, 2) + _, err := ledger.Admission().Commit(ctx, obNoRouteVerdict(2, 0, obCommentReply)) + require.NoError(t, err) + + ob, err := NewOutbox(OutboxOptions{Ledger: ledger, Poster: basecamp, Tick: time.Millisecond}) + require.NoError(t, err) + // Cancel without a deadline: a flush with one claims nothing, and this + // run must actually be sending while reconciliation is due. The run is + // stopped once the stale intent settles, or after a bound generous enough + // for a loaded race-detector runner; a drain that starves reconciliation + // never settles it. + runCtx, cancel := context.WithCancel(ctx) + defer cancel() + done := make(chan error, 1) + go func() { done <- ob.Run(runCtx) }() + deadline := time.Now().Add(30 * time.Second) + for time.Now().Before(deadline) { + if in, err := ledger.Intent(ctx, stale.ID); err == nil && in.State != IntentSending { + break + } + time.Sleep(10 * time.Millisecond) + } + cancel() + require.NoError(t, <-done) + assert.Equal(t, IntentSent, obIntent(t, ledger, stale.Key).State, "the stale sending intent was reconciled") +} + +// A holding reply is never posted about work the connector went on to run: it +// stands down when its record leaves blocked(no_route). +func TestOutboxAHoldingReplyStandsDownWhenTheRouteArrives(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + seenRecord(t, ledger, 1) + _, err := ledger.Admission().Commit(ctx, obNoRouteVerdict(1, 0, obCommentReply)) + require.NoError(t, err) + + // connect.json gains the route: the record is decided again and dispatched. + _, err = ledger.Admission().Commit(ctx, admittedVerdict(1, getRecord(t, ledger, 1).Revision, "recording:10304028989")) + require.NoError(t, err) + obLaunch(t, ledger, 1) + + basecamp := newFakeBasecamp(clock.Now) + require.NoError(t, obOutbox(t, ledger, basecamp).Flush(ctx)) + assert.Zero(t, basecamp.postCount()) + got := obIntent(t, ledger, holdingKey(1)) + assert.Equal(t, IntentCanceled, got.State) + assert.Equal(t, "no longer called for", got.Note) +} + +// A message the worker reported as its own acknowledgement or reply is the +// worker's, whatever it says: the guard's fixed form is short enough to +// collide with an acknowledgement in the worker's own words. +func TestOutboxNeverAdoptsAWorkersOwnMessage(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + obAdmit(t, ledger, 1, "recording:10304028989") + l := obLaunch(t, ledger, 1) + clock.Advance(DefaultGuardDelay) + claimed, ok, err := ledger.claimIntent(ctx) + require.NoError(t, err) + require.True(t, ok) + + basecamp := newFakeBasecamp(clock.Now) + workersOwn := basecamp.add(claimed.Destination, adapterAgentID, GuardAckBody) + d, err := ledger.Dispatch(ctx, l.Token, adapterAgentID) + require.NoError(t, err) + obPull(t, d, 1) + _, err = d.Ack(ctx, 1, &workersOwn) + require.NoError(t, err) + + clock.Advance(2 * time.Minute) + require.NoError(t, obOutbox(t, ledger, basecamp).Recover(ctx)) + got := obIntent(t, ledger, guardKey(1)) + assert.Equal(t, IntentIndeterminate, got.State) + assert.Nil(t, got.ReceiptID) +} + +// A request Basecamp refused created nothing, and says so: no listing, no +// backoff, and a note a person can act on. +func TestOutboxARefusedRequestSaysNoMessageExists(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + seenRecord(t, ledger, 1) + _, err := ledger.Admission().Commit(ctx, obNoRouteVerdict(1, 0, obCommentReply)) + require.NoError(t, err) + basecamp := newFakeBasecamp(clock.Now) + basecamp.beforePost = func(Destination, string) error { return fmt.Errorf("404: %w", ErrNotPosted) } + + ob := obOutbox(t, ledger, basecamp) + require.NoError(t, ob.Flush(ctx)) + got := obIntent(t, ledger, holdingKey(1)) + assert.Equal(t, IntentCanceled, got.State, "refused is not uncertain: nothing was created") + assert.Equal(t, "the request was refused; no message was created", got.Note) + assert.Zero(t, basecamp.lists, "nothing to look for") + require.NoError(t, ob.Flush(ctx)) + assert.Equal(t, 1, basecamp.postCount(), "never asked again") +} + +// A reconciliation listing is bounded in time: a destination that pages +// forever cannot hold up the sending of what is due. +func TestOutboxReconciliationListingIsBounded(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + in := sendingHolding(t, ledger, 1, obCommentReply) + basecamp := newFakeBasecamp(clock.Now) + ob, err := NewOutbox(OutboxOptions{Ledger: ledger, Poster: hangingLister{basecamp}, Tick: time.Millisecond}) + require.NoError(t, err) + + started := time.Now() + _, err = ob.reconcileStale(ctx, 0) + require.Error(t, err) + assert.Less(t, time.Since(started), AdoptionScanTimeout+5*time.Second) + assert.Equal(t, IntentSending, obIntent(t, ledger, in.Key).State, "a listing cut short is a failed listing") + assert.NotNil(t, obIntent(t, ledger, in.Key).ReconcileAt) +} + +// hangingLister answers a listing only when its request's context ends. +type hangingLister struct{ *fakeBasecamp } + +func (h hangingLister) List(ctx context.Context, _ Destination, _ time.Time) ([]PostedMessage, error) { + <-ctx.Done() + return nil, ctx.Err() +} + +// A guard or holding reply whose record is gone is canceled, not claimed +// again on every tick behind everything else waiting to be sent. +func TestOutboxAnIntentWithNoRecordIsCanceled(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + seenRecord(t, ledger, 1) + _, err := ledger.Admission().Commit(ctx, obNoRouteVerdict(1, 0, obCommentReply)) + require.NoError(t, err) + _, err = ledger.db.ExecContext(ctx, `PRAGMA foreign_keys = off`) + require.NoError(t, err) + _, err = ledger.db.ExecContext(ctx, `DELETE FROM events WHERE id = 1`) + require.NoError(t, err) + + basecamp := newFakeBasecamp(clock.Now) + require.NoError(t, obOutbox(t, ledger, basecamp).Flush(ctx)) + assert.Equal(t, IntentCanceled, obIntent(t, ledger, holdingKey(1)).State) + assert.Zero(t, basecamp.postCount()) +} + +// A guard Basecamp refused created nothing, so its intent is canceled. Task +// events the claim marked fired stay fired โ€” #736 settles a guard once โ€” so +// the acknowledgement is missing, never doubled; a task created afterwards +// arms afresh. +func TestOutboxARefusedGuardIsMissingNeverDoubled(t *testing.T) { + t.Run("task live when the guard is refused", func(t *testing.T) { + ctx := context.Background() + ledger, clock := obLedger(t) + obAdmit(t, ledger, 1, "recording:10304028989") + l := obLaunch(t, ledger, 1) + basecamp := newFakeBasecamp(clock.Now) + basecamp.beforePost = func(Destination, string) error { return fmt.Errorf("403: %w", ErrNotPosted) } + clock.Advance(DefaultGuardDelay) + require.NoError(t, obOutbox(t, ledger, basecamp).Flush(ctx)) + assert.Equal(t, IntentCanceled, obIntent(t, ledger, guardKey(1)).State) + + d, err := ledger.Dispatch(ctx, l.Token, adapterAgentID) + require.NoError(t, err) + instruction, ok, err := d.Get(ctx, 1) + require.NoError(t, err) + require.True(t, ok) + assert.True(t, instruction.GuardAcknowledged, "settled once: missing rather than doubled") + }) + + t.Run("task created after the guard was refused", func(t *testing.T) { + ctx := context.Background() + ledger, clock := obLedger(t) + obAdmit(t, ledger, 1, "recording:10304028989") + basecamp := newFakeBasecamp(clock.Now) + basecamp.beforePost = func(Destination, string) error { return fmt.Errorf("403: %w", ErrNotPosted) } + clock.Advance(DefaultGuardDelay) + require.NoError(t, obOutbox(t, ledger, basecamp).Flush(ctx)) + + l := obLaunch(t, ledger, 1) + d, err := ledger.Dispatch(ctx, l.Token, adapterAgentID) + require.NoError(t, err) + instruction, _, err := d.Get(ctx, 1) + require.NoError(t, err) + assert.False(t, instruction.GuardAcknowledged, "nothing was acknowledged, so the worker does") + }) +} + +// Slow destinations cannot hold up a guard that is due: the running connector +// lists one destination between sends. +func TestOutboxSlowDestinationsDoNotHoldUpSending(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + for id := int64(1); id <= 3; id++ { + sendingHolding(t, ledger, id, admission.ReplyDestination{Kind: admission.ReplyComment, RecordingID: 900 + id}) + } + clock.Advance(2 * DefaultReconcileAfter) + seenRecord(t, ledger, 9) + _, err := ledger.Admission().Commit(ctx, obNoRouteVerdict(9, 0, obCommentReply)) + require.NoError(t, err) + + lister := &countingHangingLister{fakeBasecamp: newFakeBasecamp(clock.Now)} + ob, err := NewOutbox(OutboxOptions{Ledger: ledger, Poster: lister, Tick: time.Millisecond}) + require.NoError(t, err) + listCtx, cancel := context.WithCancel(ctx) + defer cancel() + lister.cancelAfterFirst = cancel + require.NoError(t, ob.Run(listCtx)) + assert.Equal(t, 1, lister.calls, "one listing per pass") + assert.Equal(t, IntentSent, obIntent(t, ledger, holdingKey(9)).State, "the due intent went out before any listing") +} + +// countingHangingLister fails every listing, and ends the run after the first. +type countingHangingLister struct { + *fakeBasecamp + calls int + cancelAfterFirst func() +} + +func (c *countingHangingLister) List(context.Context, Destination, time.Time) ([]PostedMessage, error) { + c.calls++ + if c.calls == 1 { + c.cancelAfterFirst() + } + return nil, errWire +} + +// A refused request created nothing, so once a person has fixed the cause +// they may send it again; nothing else ever takes a canceled intent back. +func TestOutboxAPersonMayResendARefusedIntent(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + seenRecord(t, ledger, 1) + _, err := ledger.Admission().Commit(ctx, obNoRouteVerdict(1, 0, obCommentReply)) + require.NoError(t, err) + basecamp := newFakeBasecamp(clock.Now) + basecamp.beforePost = func(Destination, string) error { return fmt.Errorf("403: %w", ErrNotPosted) } + ob := obOutbox(t, ledger, basecamp) + require.NoError(t, ob.Flush(ctx)) + in := obIntent(t, ledger, holdingKey(1)) + require.Equal(t, IntentCanceled, in.State) + + basecamp.beforePost = nil + require.NoError(t, ledger.ResolveIntent(ctx, in.ID, IntentResolution{Resolution: ResolveResend, By: "person:26909558"})) + require.NoError(t, ob.Flush(ctx)) + assert.Equal(t, IntentSent, obIntent(t, ledger, holdingKey(1)).State) + assert.Equal(t, 2, basecamp.postCount()) + + // A guard get_dispatch canceled is not refused, and is not resendable. + obAdmit(t, ledger, 2, "recording:10304028989") + l := obLaunch(t, ledger, 2) + d, err := ledger.Dispatch(ctx, l.Token, adapterAgentID) + require.NoError(t, err) + _, _, err = d.Get(ctx, 2) + require.NoError(t, err) + guard := obIntent(t, ledger, guardKey(2)) + require.Equal(t, IntentCanceled, guard.State) + require.ErrorIs(t, ledger.ResolveIntent(ctx, guard.ID, IntentResolution{Resolution: ResolveResend, By: "person:26909558"}), ErrNotIndeterminate) + _, err = ledger.db.ExecContext(ctx, `UPDATE outbox SET state = 'pending' WHERE id = ?`, guard.ID) + require.Error(t, err, "the database refuses it too") +} + +// A person's resend that lands while a flush is still draining waits for the +// next flush: this one never claims the intent again, so it is not left +// sending with no request made. +func TestOutboxAResendDuringAFlushWaitsForTheNext(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + for _, id := range []int64{1, 2} { + seenRecord(t, ledger, id) + _, err := ledger.Admission().Commit(ctx, obNoRouteVerdict(id, 0, obCommentReply)) + require.NoError(t, err) + } + basecamp := newFakeBasecamp(clock.Now) + firstID := obIntent(t, ledger, holdingKey(1)).ID + refused := false + basecamp.beforePost = func(Destination, string) error { + if !refused { + refused = true + return fmt.Errorf("403: %w", ErrNotPosted) + } + // The second intent's request: meanwhile a person resends the first. + require.NoError(t, ledger.ResolveIntent(context.Background(), firstID, IntentResolution{Resolution: ResolveResend, By: "person:26909558"})) + return nil + } + ob := obOutbox(t, ledger, basecamp) + require.NoError(t, ob.Flush(ctx)) + assert.Equal(t, IntentPending, obIntent(t, ledger, holdingKey(1)).State, "not claimed twice in one flush") + + basecamp.beforePost = nil + require.NoError(t, ob.Flush(ctx)) + assert.Equal(t, IntentSent, obIntent(t, ledger, holdingKey(1)).State) + assert.Equal(t, 3, basecamp.postCount()) +} + +// Invariant 9: a worker that asks while a guard is in flight is told the +// connector acknowledged, and that stands if Basecamp then refuses it. +func TestOutboxAGuardIsFiredFromItsClaim(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + obAdmit(t, ledger, 1, "recording:10304028989") + l := obLaunch(t, ledger, 1) + d, err := ledger.Dispatch(ctx, l.Token, adapterAgentID) + require.NoError(t, err) + + basecamp := newFakeBasecamp(clock.Now) + var inFlight Instruction + basecamp.beforePost = func(Destination, string) error { + var err error + inFlight, _, err = d.Get(context.Background(), 1) + require.NoError(t, err) + return fmt.Errorf("404: %w", ErrNotPosted) + } + clock.Advance(DefaultGuardDelay) + require.NoError(t, obOutbox(t, ledger, basecamp).Flush(ctx)) + assert.True(t, inFlight.GuardAcknowledged, "no double acknowledgement while the guard may land") + + after, _, err := d.Get(ctx, 1) + require.NoError(t, err) + assert.True(t, after.GuardAcknowledged, "a guard settles once") +} + +// orderedPoster records the order of listings and posts. +type orderedPoster struct { + *fakeBasecamp + calls []string +} + +func (o *orderedPoster) Post(ctx context.Context, dest Destination, body string) (int64, error) { + o.calls = append(o.calls, "post") + return o.fakeBasecamp.Post(ctx, dest, body) +} + +func (o *orderedPoster) List(ctx context.Context, dest Destination, since time.Time) ([]PostedMessage, error) { + o.calls = append(o.calls, "list") + return o.fakeBasecamp.List(ctx, dest, since) +} + +// On start: what a previous process left sending is reconciled, then what is +// due is sent, all before Start returns and so before anything else runs โ€” +// except an intent that went sending too recently to have landed, which waits. +func TestOutboxStartSettlesWhatAPreviousProcessLeftBeforeSending(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + stale := sendingHolding(t, ledger, 1, admission.ReplyDestination{Kind: admission.ReplyComment, RecordingID: 901}) + basecamp := &orderedPoster{fakeBasecamp: newFakeBasecamp(clock.Now)} + landed := basecamp.add(stale.Destination, adapterAgentID, stale.Body) + + clock.Advance(10 * time.Minute) // the previous process died a while ago + young := sendingHolding(t, ledger, 2, admission.ReplyDestination{Kind: admission.ReplyComment, RecordingID: 902}) + seenRecord(t, ledger, 3) + _, err := ledger.Admission().Commit(ctx, obNoRouteVerdict(3, 0, admission.ReplyDestination{Kind: admission.ReplyComment, RecordingID: 903})) + require.NoError(t, err) + + require.NoError(t, obOutbox(t, ledger, basecamp).Start(ctx)) + got := obIntent(t, ledger, stale.Key) + require.Equal(t, IntentSent, got.State, "reconciled on start") + assert.Equal(t, landed, *got.ReceiptID) + assert.Equal(t, IntentSending, obIntent(t, ledger, young.Key).State, "a request that may still be landing waits") + assert.Equal(t, IntentSent, obIntent(t, ledger, holdingKey(3)).State, "what was due went out on start") + assert.Equal(t, []string{"list", "post"}, basecamp.calls, "reconcile, then send") +} + +// A ledger that cannot settle what a previous process left stops the start: +// nothing is sent past an intent that could not be reconciled. +func TestOutboxStartStopsOnALedgerThatCannotReconcile(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + stale := sendingHolding(t, ledger, 1, admission.ReplyDestination{Kind: admission.ReplyComment, RecordingID: 901}) + basecamp := newFakeBasecamp(clock.Now) + basecamp.add(stale.Destination, adapterAgentID, stale.Body) + clock.Advance(10 * time.Minute) + seenRecord(t, ledger, 2) + _, err := ledger.Admission().Commit(ctx, obNoRouteVerdict(2, 0, obCommentReply)) + require.NoError(t, err) + + // Adoption reads task_events; the ledger now cannot. + _, err = ledger.db.ExecContext(ctx, `ALTER TABLE task_events RENAME TO task_events_gone`) + require.NoError(t, err) + + require.Error(t, obOutbox(t, ledger, basecamp).Start(ctx)) + assert.Zero(t, basecamp.postCount(), "nothing sent past it") + assert.Equal(t, IntentPending, obIntent(t, ledger, holdingKey(2)).State) +} + +// A listing that failed and backed off is not a reason to stop starting: +// Run tries it again, and what is due goes out now. +func TestOutboxStartCarriesOnPastABackedOffListing(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + stale := sendingHolding(t, ledger, 1, admission.ReplyDestination{Kind: admission.ReplyComment, RecordingID: 901}) + clock.Advance(10 * time.Minute) + seenRecord(t, ledger, 2) + _, err := ledger.Admission().Commit(ctx, obNoRouteVerdict(2, 0, obCommentReply)) + require.NoError(t, err) + basecamp := newFakeBasecamp(clock.Now) + basecamp.listErr = errWire + + require.NoError(t, obOutbox(t, ledger, basecamp).Start(ctx)) + got := obIntent(t, ledger, stale.Key) + assert.Equal(t, IntentSending, got.State) + assert.NotNil(t, got.ReconcileAt, "backed off") + assert.Equal(t, IntentSent, obIntent(t, ledger, holdingKey(2)).State) +} + +// The start's sending stops at the first send that may not have landed: the +// next is likely to meet the same Basecamp, and the connector's start should +// not wait out a timeout per notice. Run carries on. +func TestOutboxStartStopsSendingAtTheFirstUncertainSend(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + for _, id := range []int64{1, 2, 3} { + seenRecord(t, ledger, id) + _, err := ledger.Admission().Commit(ctx, obNoRouteVerdict(id, 0, obCommentReply)) + require.NoError(t, err) + } + basecamp := newFakeBasecamp(clock.Now) + basecamp.beforePost = func(Destination, string) error { return context.DeadlineExceeded } + + require.NoError(t, obOutbox(t, ledger, basecamp).Start(ctx)) + assert.Equal(t, 1, basecamp.postCount()) + assert.Equal(t, IntentPending, obIntent(t, ledger, holdingKey(3)).State) +} + +// failingAt fails listings at one destination only. +type failingAt struct { + *fakeBasecamp + recording int64 +} + +func (f failingAt) List(ctx context.Context, dest Destination, since time.Time) ([]PostedMessage, error) { + if dest.RecordingID == f.recording { + return nil, errWire + } + return f.fakeBasecamp.List(ctx, dest, since) +} + +// A hard failure is not hidden behind a listing that merely backed off +// earlier in the same pass. +func TestOutboxStartSeesAHardErrorAfterABackedOffListing(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + sendingHolding(t, ledger, 1, admission.ReplyDestination{Kind: admission.ReplyComment, RecordingID: 901}) + second := sendingHolding(t, ledger, 2, admission.ReplyDestination{Kind: admission.ReplyComment, RecordingID: 902}) + basecamp := newFakeBasecamp(clock.Now) + basecamp.add(second.Destination, adapterAgentID, second.Body) + clock.Advance(10 * time.Minute) + _, err := ledger.db.ExecContext(ctx, `ALTER TABLE task_events RENAME TO task_events_gone`) + require.NoError(t, err) + + require.Error(t, obOutbox(t, ledger, failingAt{basecamp, 901}).Start(ctx)) +} + +// A ledger that cannot record what a send settled โ€” a receipt, or a +// refusal โ€” is an error wherever it happens: a start stops on it and sends +// nothing more, and the intent stays sending for reconciliation to settle. +func TestOutboxALedgerFailureAfterASendStopsTheStart(t *testing.T) { + for _, tc := range []struct { + name string + trigger string + postErr error + }{ + {name: "receipt", trigger: `CREATE TRIGGER refuse_receipt BEFORE UPDATE OF receipt_id ON outbox WHEN NEW.receipt_id IS NOT NULL BEGIN SELECT RAISE(ABORT, 'injected'); END`}, + {name: "refusal", trigger: `CREATE TRIGGER refuse_cancel BEFORE UPDATE OF state ON outbox WHEN NEW.state = 'canceled' BEGIN SELECT RAISE(ABORT, 'injected'); END`, postErr: fmt.Errorf("403: %w", ErrNotPosted)}, + } { + t.Run(tc.name, func(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + for _, id := range []int64{1, 2} { + seenRecord(t, ledger, id) + _, err := ledger.Admission().Commit(ctx, obNoRouteVerdict(id, 0, obCommentReply)) + require.NoError(t, err) + } + _, err := ledger.db.ExecContext(ctx, tc.trigger) + require.NoError(t, err) + basecamp := newFakeBasecamp(clock.Now) + basecamp.beforePost = func(Destination, string) error { return tc.postErr } + + require.Error(t, obOutbox(t, ledger, basecamp).Start(ctx)) + assert.Equal(t, 1, basecamp.postCount(), "nothing sent past the failure") + assert.Equal(t, IntentSending, obIntent(t, ledger, holdingKey(1)).State, "left for reconciliation") + assert.Equal(t, IntentPending, obIntent(t, ledger, holdingKey(2)).State) + }) + } +} + +// hangingAt blocks listings at one destination until ctx ends. +type hangingAt struct { + *fakeBasecamp + recording int64 +} + +func (h hangingAt) List(ctx context.Context, dest Destination, since time.Time) ([]PostedMessage, error) { + if dest.RecordingID == h.recording { + <-ctx.Done() + return nil, ctx.Err() + } + return h.fakeBasecamp.List(ctx, dest, since) +} + +// A ledger failure met during the start's reconciliation stops the start even +// when the start's bound runs out later in the same pass. +func TestOutboxStartStopsOnALedgerFailureWhateverTheBoundDoesAfter(t *testing.T) { + ledger, clock := obLedger(t) + first := sendingHolding(t, ledger, 1, admission.ReplyDestination{Kind: admission.ReplyComment, RecordingID: 902}) + sendingHolding(t, ledger, 2, admission.ReplyDestination{Kind: admission.ReplyComment, RecordingID: 901}) + basecamp := newFakeBasecamp(clock.Now) + basecamp.add(first.Destination, adapterAgentID, first.Body) + clock.Advance(10 * time.Minute) + _, err := ledger.db.ExecContext(context.Background(), `ALTER TABLE task_events RENAME TO task_events_gone`) + require.NoError(t, err) + + ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) + defer cancel() + started := time.Now() + require.Error(t, obOutbox(t, ledger, hangingAt{basecamp, 901}).Start(ctx)) + assert.Less(t, time.Since(started), 2500*time.Millisecond, "the pass stops at the failure rather than spending the bound") +} + +// A ledger that cannot even list what is sending stops the start before +// anything is sent. +func TestOutboxStartStopsWhenTheLedgerCannotListSendingIntents(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + stale := sendingHolding(t, ledger, 1, admission.ReplyDestination{Kind: admission.ReplyComment, RecordingID: 901}) + clock.Advance(10 * time.Minute) + seenRecord(t, ledger, 2) + _, err := ledger.Admission().Commit(ctx, obNoRouteVerdict(2, 0, obCommentReply)) + require.NoError(t, err) + // A row the ledger cannot read back. + _, err = ledger.db.ExecContext(ctx, `UPDATE outbox SET reconcile_at = 'garbage' WHERE id = ?`, stale.ID) + require.NoError(t, err) + + basecamp := newFakeBasecamp(clock.Now) + require.Error(t, obOutbox(t, ledger, basecamp).Start(ctx)) + assert.Zero(t, basecamp.postCount()) +} + +// cancelingLister ends its caller's context as it answers, as a shutdown +// arriving mid-reconciliation would. +type cancelingLister struct { + *fakeBasecamp + cancel func() +} + +func (c cancelingLister) List(ctx context.Context, dest Destination, since time.Time) ([]PostedMessage, error) { + out, err := c.fakeBasecamp.List(ctx, dest, since) + c.cancel() + return out, err +} + +// A ledger failure is marked where it happens: a context that ends at the +// same moment does not hide it from a start. +func TestOutboxALedgerFailureIsNotHiddenByAnEndingContext(t *testing.T) { + ledger, clock := obLedger(t) + stale := sendingHolding(t, ledger, 1, admission.ReplyDestination{Kind: admission.ReplyComment, RecordingID: 901}) + basecamp := newFakeBasecamp(clock.Now) + basecamp.add(stale.Destination, adapterAgentID, stale.Body) + clock.Advance(10 * time.Minute) + _, err := ledger.db.ExecContext(context.Background(), `ALTER TABLE task_events RENAME TO task_events_gone`) + require.NoError(t, err) + + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + require.Error(t, obOutbox(t, ledger, cancelingLister{basecamp, cancel}).Start(ctx)) +} + +// A worker's message is its own by kind as well as by id: a boost id that +// happens to equal some comment's id is a different message, and does not +// stop a guard adopting its own boost. +func TestOutboxAWorkersMessageIsMatchedByKindToo(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + obAdmit(t, ledger, 1, "recording:10304028989") + l := obLaunch(t, ledger, 1) + clock.Advance(DefaultGuardDelay) + claimed, ok, err := ledger.claimIntent(ctx) + require.NoError(t, err) + require.True(t, ok) + + basecamp := newFakeBasecamp(clock.Now) + boost := basecamp.add(claimed.Destination, adapterAgentID, claimed.Body) + // The worker's reply is a comment whose id is the same number as the + // guard's boost. + d, err := ledger.Dispatch(ctx, l.Token, adapterAgentID) + require.NoError(t, err) + obPull(t, d, 1) + _, err = d.Complete(ctx, 1, Completion{Outcome: OutcomeSucceeded, ReplyID: &boost}) + require.NoError(t, err) + + clock.Advance(2 * time.Minute) + require.NoError(t, obOutbox(t, ledger, basecamp).Recover(ctx)) + got := obIntent(t, ledger, claimed.Key) + require.Equal(t, IntentSent, got.State, "a comment id is not a boost id") + assert.Equal(t, boost, *got.ReceiptID) +} + +// A still-running notice says the worker is still working. If its attempt has +// ended before the notice goes out, it is not sent: the connector's last word +// on finished work is never "still working on this". +func TestOutboxAStillRunningNoticeIsNotPostedAfterTheAttemptEnded(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + obAdmit(t, ledger, 1, "recording:10304028989") + l := obLaunch(t, ledger, 1) + _, err := ledger.StillRunning(ctx, l.AttemptID) + require.NoError(t, err) + + // The worker finishes and reports before the notice is sent, so the + // settlement calls for no completion notice either. + d, err := ledger.Dispatch(ctx, l.Token, adapterAgentID) + require.NoError(t, err) + obPull(t, d, 1) + _, err = d.Complete(ctx, 1, Completion{Outcome: OutcomeSucceeded, ReplyID: id64(4242)}) + require.NoError(t, err) + _, err = ledger.EndAttempt(ctx, AttemptEnd{AttemptID: l.AttemptID, Stop: StopFinished}) + require.NoError(t, err) + + basecamp := newFakeBasecamp(clock.Now) + require.NoError(t, obOutbox(t, ledger, basecamp).Flush(ctx)) + assert.Zero(t, basecamp.postCount(), "nothing says the worker is still working") + got := obIntent(t, ledger, stillRunningKey(l.AttemptID, 1)) + assert.Equal(t, IntentCanceled, got.State) + assert.Equal(t, "the attempt ended before the notice went out", got.Note) +} + +// A still-running notice whose attempt is not in the ledger at all is +// canceled too, as a holding reply is when its record is gone. +func TestOutboxAStillRunningNoticeWithNoAttemptIsCanceled(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + obAdmit(t, ledger, 1, "recording:10304028989") + l := obLaunch(t, ledger, 1) + _, err := ledger.StillRunning(ctx, l.AttemptID) + require.NoError(t, err) + _, err = ledger.db.ExecContext(ctx, `PRAGMA foreign_keys = off`) + require.NoError(t, err) + _, err = ledger.db.ExecContext(ctx, `DELETE FROM attempts WHERE id = ?`, l.AttemptID) + require.NoError(t, err) + + basecamp := newFakeBasecamp(clock.Now) + require.NoError(t, obOutbox(t, ledger, basecamp).Flush(ctx)) + assert.Zero(t, basecamp.postCount()) + assert.Equal(t, IntentCanceled, obIntent(t, ledger, stillRunningKey(l.AttemptID, 1)).State) +} + +// A ledger failure while sending stops the start even when the start's bound +// runs out in the same breath. +func TestOutboxALedgerFailureWhileSendingIsNotHiddenByAnEndingBound(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + for _, id := range []int64{1, 2} { + seenRecord(t, ledger, id) + _, err := ledger.Admission().Commit(ctx, obNoRouteVerdict(id, 0, obCommentReply)) + require.NoError(t, err) + } + _, err := ledger.db.ExecContext(ctx, `CREATE TRIGGER refuse_receipt BEFORE UPDATE OF receipt_id ON outbox WHEN NEW.receipt_id IS NOT NULL BEGIN SELECT RAISE(ABORT, 'injected'); END`) + require.NoError(t, err) + + startCtx, cancel := context.WithCancel(ctx) + defer cancel() + basecamp := newFakeBasecamp(clock.Now) + basecamp.afterPost = func(Destination, int64) error { + cancel() // the start's bound runs out as the request is answered + return nil + } + require.Error(t, obOutbox(t, ledger, basecamp).Start(startCtx)) +} + +// A canceled intent posted nothing, so its words do not hide a worker's reply +// that happens to read the same. +func TestOutboxACanceledNoticeDoesNotHideAReply(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + seenRecord(t, ledger, 1) + _, err := ledger.Admission().Commit(ctx, obNoRouteVerdict(1, 0, obCommentReply)) + require.NoError(t, err) + in := obIntent(t, ledger, holdingKey(1)) + basecamp := newFakeBasecamp(clock.Now) + basecamp.beforePost = func(Destination, string) error { return fmt.Errorf("403: %w", ErrNotPosted) } + require.NoError(t, obOutbox(t, ledger, basecamp).Flush(ctx)) + require.Equal(t, IntentCanceled, obIntent(t, ledger, in.Key).State) + + // A worker's reply that reads exactly like the notice nobody posted. + since := clock.Now().Add(-time.Minute) + reply := basecamp.add(in.Destination, adapterAgentID, in.Body) + listed, err := LifecycleFilteredReplies{Lister: basecamp, Ledger: ledger}. + AgentReplies(ctx, adapterBucketID, "comment", obReplyRecording, since) + require.NoError(t, err) + require.Len(t, listed, 1, "nothing of ours is there to hide it") + assert.Equal(t, reply, listed[0].ID) +} + +// A receipt identifies the connector's message whatever its intent's state, +// and since the dispatcher is given no id-only predicate beside this filter, +// that is the whole of the spec's "not one of the connector's own lifecycle +// messages" for a notice the ledger has a receipt for. +func TestOutboxASentNoticeIsLeftOutByItsReceipt(t *testing.T) { + ledger, clock := obLedger(t) + ctx := context.Background() + in := sendingHolding(t, ledger, 1, obCommentReply) + basecamp := newFakeBasecamp(clock.Now) + since := clock.Now().Add(-time.Minute) + landed := basecamp.add(in.Destination, adapterAgentID, `
`+in.Body+`
`) + reply := basecamp.add(in.Destination, adapterAgentID, "
Done: the fix is on the branch.
") + _, err := ledger.recordReceipt(ctx, in.ID, landed) + require.NoError(t, err) + require.Equal(t, IntentSent, obIntent(t, ledger, in.Key).State) + + listed, err := LifecycleFilteredReplies{Lister: basecamp, Ledger: ledger}. + AgentReplies(ctx, adapterBucketID, "comment", obReplyRecording, since) + require.NoError(t, err) + require.Len(t, listed, 1, "the sent notice is left out by its receipt") + assert.Equal(t, reply, listed[0].ID) +} diff --git a/internal/connector/outbox_kill_unix_test.go b/internal/connector/outbox_kill_unix_test.go new file mode 100644 index 000000000..3739dc307 --- /dev/null +++ b/internal/connector/outbox_kill_unix_test.go @@ -0,0 +1,173 @@ +//go:build unix + +package connector + +import ( + "context" + "net/http" + "os" + "os/exec" + "path/filepath" + "syscall" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + "github.com/basecamp/basecamp-sdk/go/pkg/basecamp" +) + +// Done when: a kill between sending and the receipt, then a restart, yields +// exactly one message or an indeterminate intent โ€” with a real process, +// killed by SIGKILL, not a simulated error. + +const ( + obKillHelperEnv = "BASECAMP_CONNECT_OUTBOX_KILL_HELPER" + obKillLedgerEnv = "BASECAMP_CONNECT_OUTBOX_KILL_LEDGER" + obKillServerEnv = "BASECAMP_CONNECT_OUTBOX_KILL_SERVER" + obKillMarkerEnv = "BASECAMP_CONNECT_OUTBOX_KILL_MARKER" +) + +// TestOutboxKillHelperProcess is the process that gets killed. It does +// nothing unless started by the kill test. +func TestOutboxKillHelperProcess(t *testing.T) { + if os.Getenv(obKillHelperEnv) == "" { + t.Skip("helper process for the outbox kill test") + } + ledger, err := OpenLedger(os.Getenv(obKillLedgerEnv)) + require.NoError(t, err) + client := basecamp.NewClient(&basecamp.Config{BaseURL: os.Getenv(obKillServerEnv)}, &basecamp.StaticTokenProvider{Token: "test-token-not-real"}) + poster, err := NewBasecampPoster(client.ForAccount("999"), adapterAgentID) + require.NoError(t, err) + + var p Poster = poster + if marker := os.Getenv(obKillMarkerEnv); marker != "" { + // Stop between the committed sending row and the request. + p = stallingPoster{Poster: poster, marker: marker} + } + ob, err := NewOutbox(OutboxOptions{Ledger: ledger, Poster: p}) + require.NoError(t, err) + _ = ob.Flush(context.Background()) + select {} // never exits on its own: it is killed +} + +type stallingPoster struct { + Poster + marker string +} + +func (s stallingPoster) Post(context.Context, Destination, string) (int64, error) { + _ = os.WriteFile(s.marker, []byte("sending"), 0o600) + select {} +} + +func TestOutboxKillBetweenSendingAndReceipt(t *testing.T) { + cases := []struct { + name string + // landed: the request reached Basecamp before the kill. + landed bool + }{ + {name: "the request landed", landed: true}, + {name: "the request never left", landed: false}, + } + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + ctx := context.Background() + path := filepath.Join(t.TempDir(), "state", "connector.db") + ledger, err := OpenLedger(path) + require.NoError(t, err) + t.Cleanup(func() { _ = ledger.Close() }) + ledger.SetHooks(LifecycleHooks(ledger, LifecycleOptions{})) + seenRecord(t, ledger, 1) + _, err = ledger.Admission().Commit(ctx, obNoRouteVerdict(1, 0, obCommentReply)) + require.NoError(t, err) + + server := newOBServer(t) + stored := make(chan struct{}, 1) + release := make(chan struct{}) + server.setOnPost(func(r *http.Request, _ int64) int { + // Answer nothing until the client is gone: the receipt never + // reaches the process. + stored <- struct{}{} + select { + case <-r.Context().Done(): + case <-release: + } + return http.StatusServiceUnavailable + }) + t.Cleanup(func() { close(release) }) + + marker := filepath.Join(t.TempDir(), "sending") + cmd := exec.CommandContext(context.WithoutCancel(ctx), os.Args[0], "-test.run=^TestOutboxKillHelperProcess$", "-test.count=1") + cmd.Env = []string{ + obKillHelperEnv + "=1", + obKillLedgerEnv + "=" + path, + obKillServerEnv + "=" + server.URL, + "HOME=" + os.Getenv("HOME"), + "PATH=" + os.Getenv("PATH"), + } + if !tc.landed { + cmd.Env = append(cmd.Env, obKillMarkerEnv+"="+marker) + } + require.NoError(t, cmd.Start()) + // Signaled through os.Process, which refuses a process already + // reaped: the pid is never signaled after it could be reused. + t.Cleanup(func() { _ = cmd.Process.Kill(); _ = cmd.Wait() }) + + deadline := time.After(30 * time.Second) + if tc.landed { + select { + case <-stored: + case <-deadline: + t.Fatal("the helper never made its request") + } + } else { + for { + if _, err := os.Stat(marker); err == nil { + break + } + select { + case <-deadline: + t.Fatal("the helper never reached its request") + case <-time.After(10 * time.Millisecond): + } + } + } + // The helper is between its durable sending row and a receipt. + require.Equal(t, IntentSending, obIntent(t, ledger, holdingKey(1)).State) + require.NoError(t, cmd.Process.Signal(syscall.SIGKILL)) + waitErr := cmd.Wait() + var exitErr *exec.ExitError + require.ErrorAs(t, waitErr, &exitErr) + require.Equal(t, syscall.SIGKILL, exitErr.Sys().(syscall.WaitStatus).Signal()) + + // Restart: a fresh ledger handle, opened after the killed process + // is gone โ€” as a restarted connector would โ€” and a fresh outbox + // on it, Basecamp answering normally now. Every assertion below + // reads through this handle. + require.NoError(t, ledger.Close()) + ledger, err = OpenLedger(path) + require.NoError(t, err) + t.Cleanup(func() { _ = ledger.Close() }) + server.setOnPost(nil) + postsBefore := server.postCount() + restarted, err := NewOutbox(OutboxOptions{Ledger: ledger, Poster: server.poster(t)}) + require.NoError(t, err) + require.NoError(t, restarted.Recover(ctx)) + require.NoError(t, restarted.Flush(ctx)) + + assert.Equal(t, postsBefore, server.postCount(), "the restart posted nothing") + in := obIntent(t, ledger, holdingKey(1)) + messages := server.at(in.Destination) + if tc.landed { + require.Len(t, messages, 1, "exactly one message") + require.Equal(t, IntentSent, in.State) + assert.Equal(t, messages[0].ID, *in.ReceiptID) + } else { + assert.Empty(t, messages) + assert.Equal(t, IntentIndeterminate, in.State, "never resent: a person decides") + } + }) + } +} diff --git a/internal/connector/outbox_run.go b/internal/connector/outbox_run.go new file mode 100644 index 000000000..6092a44c8 --- /dev/null +++ b/internal/connector/outbox_run.go @@ -0,0 +1,902 @@ +package connector + +import ( + "context" + "database/sql" + "errors" + "fmt" + "log/slog" + "strconv" + "sync" + "time" + + "github.com/basecamp/basecamp-cli/internal/connector/ndjson" +) + +// Poster is how the outbox reaches Basecamp, as the agent. +type Poster interface { + // Post creates one message and returns its id. It makes at most one + // request: a retry is a second message. + Post(ctx context.Context, dest Destination, body string) (int64, error) + // List returns every message of dest.Kind the agent created at dest since + // since, exhaustively: a listing that could not reach back that far is an + // error, never a shorter answer. An error wrapping ErrUnlistable says no + // later listing will answer either. + List(ctx context.Context, dest Destination, since time.Time) ([]PostedMessage, error) +} + +// errLedger marks a reconciliation that failed in the ledger, not at +// Basecamp: a start never proceeds past one. +var errLedger = errors.New("the ledger could not settle a lifecycle message") + +// errBackedOff marks a listing failure whose backoff was recorded: the intent +// is tried again later, and nothing about the ledger is wrong. +var errBackedOff = errors.New("listing failed; backed off") + +// ErrNotPosted is a request Basecamp answered by refusing it: the message was +// not created, so there is nothing to find and nothing to resend without a +// person. +var ErrNotPosted = errors.New("the message was not created") + +// ErrUnlistable is a destination that cannot be listed and will not become +// listable by waiting: gone, forbidden, or too busy to reach back to the +// sending time. An intent whose destination is unlistable is indeterminate. +var ErrUnlistable = errors.New("the destination cannot be listed") + +// PostedMessage is one of the agent's messages at a destination. +type PostedMessage struct { + ID int64 + CreatedAt time.Time + Content string +} + +// Outbox defaults. +const ( + DefaultOutboxTick = time.Second + // DefaultReconcileAfter is how long a sending intent this process is not + // sending is left before it is reconciled: long enough for a request that + // failed on the wire to have landed, if it was going to. + DefaultReconcileAfter = time.Minute + // DefaultReconcileSlack widens a reconciliation listing back past the + // sending time, for clock skew between this machine and Basecamp. + DefaultReconcileSlack = 2 * time.Minute + // DefaultPostTimeout bounds one request. + DefaultPostTimeout = time.Minute + // A listing that fails is tried again after DefaultReconcileBackoff, + // doubling up to MaxReconcileBackoff, and after MaxReconcileFailures the + // intent is indeterminate. + DefaultReconcileBackoff = 30 * time.Second + MaxReconcileBackoff = 30 * time.Minute + MaxReconcileFailures = 10 + // MinPostWindow is the least time a flush with a deadline needs left to + // claim another intent. + MinPostWindow = 5 * time.Second + // RunBatch is how many intents a running connector sends between + // reconciliation passes, and RunReconcileBatch how many destinations it + // lists in one pass. + RunBatch = 16 + RunReconcileBatch = 1 +) + +// OutboxOptions configures the outbox's sender. +type OutboxOptions struct { + Ledger *Ledger + Poster Poster + // Paused, when set and true, holds sending (the hold marker). Reconciling + // what was already sent goes on, since it only reads and adopts. + Paused func(ctx context.Context) (bool, error) + + Lines *ndjson.Writer + Logger *slog.Logger + + Tick time.Duration + ReconcileAfter time.Duration + ReconcileSlack time.Duration + PostTimeout time.Duration +} + +// Outbox sends lifecycle intents and reconciles the ones a request left +// uncertain. One Outbox per ledger. +type Outbox struct { + opts OutboxOptions + ledger *Ledger + log *slog.Logger + + // mu serializes sending and reconciling, so an intent this process is + // sending is never reconciled under it. + mu sync.Mutex +} + +// OutboxLine is the stdout line for an intent's transitions: ids and states, +// never a body. +type OutboxLine struct { + Type string `json:"type"` + IntentID int64 `json:"intent_id"` + Kind string `json:"kind"` + State string `json:"state"` + EventID int64 `json:"event_id,omitempty"` + AttemptID string `json:"attempt_id,omitempty"` + ReceiptID int64 `json:"receipt_id,omitempty"` +} + +// NewOutbox builds the sender. +func NewOutbox(opts OutboxOptions) (*Outbox, error) { + switch { + case opts.Ledger == nil: + return nil, errors.New("connector: the outbox needs the ledger") + case opts.Poster == nil: + return nil, errors.New("connector: the outbox needs a poster") + } + if opts.Logger == nil { + opts.Logger = slog.New(slog.DiscardHandler) + } + if opts.Tick <= 0 { + opts.Tick = DefaultOutboxTick + } + if opts.ReconcileAfter <= 0 { + opts.ReconcileAfter = DefaultReconcileAfter + } + if opts.ReconcileSlack <= 0 { + opts.ReconcileSlack = DefaultReconcileSlack + } + if opts.PostTimeout <= 0 { + opts.PostTimeout = DefaultPostTimeout + } + return &Outbox{opts: opts, ledger: opts.Ledger, log: opts.Logger}, nil +} + +// Run sends due intents and reconciles sending ones until ctx ends. On start +// every sending intent is a previous process's; each is reconciled once it is +// ReconcileAfter old, so a request that was still landing when that process +// died has landed. It does not flush on the way out: call Flush once whatever +// settles attempts on shutdown is done, so their completion notices go out. +func (o *Outbox) Run(ctx context.Context) error { + ticker := time.NewTicker(o.opts.Tick) + defer ticker.Stop() + for { + if err := o.flushSome(ctx, RunBatch, false); err != nil && ctx.Err() == nil { + o.log.Warn("connector: outbox", "error", err) + } + if ctx.Err() != nil { + return nil + } + if _, err := o.reconcileSome(ctx, o.opts.ReconcileAfter, RunReconcileBatch); err != nil && ctx.Err() == nil { + o.log.Warn("connector: outbox reconciliation", "error", err) + } + select { + case <-ctx.Done(): + return nil + case <-ticker.C: + } + } +} + +// Start is the outbox's part of a connector's start, run before anything else +// transitions: every sending intent a previous process left is reconciled, +// then due pending intents are sent. +// +// An error Start returns is one the connector must not start past: the ledger +// could not read or settle an intent. Everything else is left to Run, which +// carries on from where Start stopped: +// - a listing that failed has backed its intent off; +// - a send that may or may not have landed ends the start's sending, since +// the next is likely to meet the same Basecamp; +// - a ctx that ends โ€” a bound the caller sets, or shutdown โ€” ends Start. +// +// One wait a start cannot skip: an intent that went sending less than +// ReconcileAfter ago may still be landing, and listing it now could only make +// it indeterminate for want of patience. A supervisor that restarts a crashed +// connector within the minute meets exactly this case; Run reconciles the +// intent once it comes of age. +func (o *Outbox) Start(ctx context.Context) error { + if _, err := o.reconcileStale(ctx, o.opts.ReconcileAfter); err != nil { + if errors.Is(err, errLedger) { + return fmt.Errorf("connector: reconcile lifecycle messages on start: %w", err) + } + // A listing that backed off, or one the bound or shutdown cut short: + // Run carries on with it. + if ctx.Err() != nil { + return nil //nolint:nilerr // not a failure of the ledger + } + o.log.Warn("connector: a lifecycle message's listing failed on start; it is tried again", "error", err) + } + if err := o.flushSome(ctx, 0, true); err != nil && (errors.Is(err, errLedger) || ctx.Err() == nil) { + // A ledger failure stops the start whenever it happened, even if the + // bound ran out in the same breath. + return fmt.Errorf("connector: send lifecycle messages on start: %w", err) + } + return nil +} + +// Recover reconciles every sending intent whose listing is due, whatever its +// age. A connector does not call it on start โ€” Start does, honoring the wait +// for a request still landing. It is here for a caller that knows the wait +// has already passed: a test with a killed process, say. +func (o *Outbox) Recover(ctx context.Context) error { + _, err := o.reconcileStale(ctx, 0) + return err +} + +// Flush sends every intent that is due, one at a time, and returns when none +// is left or ctx ends. One flush claims an intent at most once: an intent a +// person sent back to pending while the flush drains waits for the next one. +func (o *Outbox) Flush(ctx context.Context) error { return o.flushSome(ctx, 0, false) } + +// flushSome sends at most limit intents, or every due one when limit is zero. +// The running connector sends in batches so that a queue arriving as fast as +// it can be posted cannot starve reconciliation; only the shutdown flush +// drains. +func (o *Outbox) flushSome(ctx context.Context, limit int, stopWhenUncertain bool) error { + claimed := map[int64]bool{} + for ctx.Err() == nil { + if limit > 0 && len(claimed) >= limit { + return nil + } + if o.opts.Paused != nil { + paused, err := o.opts.Paused(ctx) + if err != nil { + return err + } + if paused { + return nil + } + } + if deadline, ok := ctx.Deadline(); ok && time.Until(deadline) < min(MinPostWindow, o.opts.PostTimeout) { + // Too little time left for a request to be answered: a claim now + // would only leave the intent for a person. It stays pending and + // goes out on the next start. + return nil + } + id, uncertain, err := o.sendNext(ctx, claimed) + if err != nil { + return err + } + if id == 0 || (uncertain && stopWhenUncertain) { + return nil + } + } + return nil +} + +// sendNext claims the oldest due intent and sends it. It returns the id it +// claimed, zero when none was due. +func (o *Outbox) sendNext(ctx context.Context, claimed map[int64]bool) (int64, bool, error) { + o.mu.Lock() + defer o.mu.Unlock() + skip := make([]int64, 0, len(claimed)) + for id := range claimed { + skip = append(skip, id) + } + intent, ok, err := o.ledger.claimIntent(ctx, skip...) + if err != nil || !ok { + return 0, false, err + } + if claimed[intent.ID] { + // Unreachable while the claim's query skips these ids; kept so a + // broken query stops the flush rather than sending twice. + return 0, false, fmt.Errorf("connector: outbox intent %d was claimed twice in one flush; not sending it again", intent.ID) + } + claimed[intent.ID] = true + o.line(intent) + if intent.State != IntentSending { + // Claiming canceled it. + return intent.ID, false, nil + } + + // Invariant 3: the sending row is committed; only now is a request made. + // A request is not abandoned because ctx ends mid-flight โ€” its answer is + // the receipt โ€” but it is bounded, and never outlives a deadline ctx + // carries (the shutdown flush's). + timeout := o.opts.PostTimeout + if deadline, ok := ctx.Deadline(); ok { + timeout = min(timeout, time.Until(deadline)) + } + postCtx, cancel := context.WithTimeout(context.WithoutCancel(ctx), timeout) + receipt, postErr := o.opts.Poster.Post(postCtx, intent.Destination, intent.Body) + cancel() + if errors.Is(postErr, ErrNotPosted) { + // Basecamp refused the request, so no message exists to find: nothing + // to reconcile. The intent is canceled (invariant 9). + settled, err := o.ledger.refuse(context.WithoutCancel(ctx), intent, RefusedNote) + if err != nil { + // The ledger failed, not Basecamp: either the refusal was not + // written, and the intent stays sending for reconciliation to + // settle, finding nothing; or it was written and could not be read + // back. Either way it is an error wherever it happens, so a start + // stops on it. + return intent.ID, false, fmt.Errorf("%w: record or read back the refusal of lifecycle message %d: %w", errLedger, intent.ID, err) + } + o.log.Warn("connector: a lifecycle message was refused", "intent_id", intent.ID, "kind", string(intent.Kind), "error", postErr) + o.line(settled) + return intent.ID, false, nil + } + if postErr != nil { + // The request may have reached Basecamp. The intent stays sending and + // is reconciled once it has had time to land โ€” counted from now, not + // from the claim, since a request that timed out may land later + // still; it is never posted again (invariant 4). + o.ledger.deferReconcile(context.WithoutCancel(ctx), intent.ID, o.opts.ReconcileAfter) + o.log.Warn("connector: a lifecycle message may not have been posted; it will be reconciled, not resent", + "intent_id", intent.ID, "kind", string(intent.Kind), "error", postErr) + return intent.ID, true, nil + } + if receipt <= 0 { + o.log.Warn("connector: a lifecycle message was posted without an id; it will be reconciled", "intent_id", intent.ID) + return intent.ID, true, nil + } + recorded, err := o.ledger.recordReceipt(context.WithoutCancel(ctx), intent.ID, receipt) + if err != nil { + // The message exists. Either the receipt was not written, and + // reconciliation will find the message by its body, or it was written + // and could not be read back. The ledger failed either way: that is an + // error wherever it happens, so a start stops on it. + return intent.ID, false, fmt.Errorf("%w: record or read back the receipt of lifecycle message %d: %w", errLedger, intent.ID, err) + } + o.line(recorded) + return intent.ID, false, nil +} + +// claimIntent moves the oldest due pending intent to sending and commits, or, +// for a guard that no longer applies, to canceled. It is the only way to +// sending. +func (l *Ledger) claimIntent(ctx context.Context, skip ...int64) (Intent, bool, error) { + var ( + out Intent + ok bool + ) + err := retryBusy(func() error { + tx, err := l.db.BeginTx(ctx, nil) + if err != nil { + return fmt.Errorf("connector: begin outbox claim: %w", err) + } + defer func() { _ = tx.Rollback() }() + now := l.timestamp() + // A flush never claims an intent it already claimed: one a person sent + // back to pending meanwhile waits for the next flush rather than being + // claimed, marked sending, and left with no request. + query, args := selectIntents+` WHERE state = 'pending' AND not_before <= ?`, []any{now} + if len(skip) > 0 { + query += ` AND id NOT IN (` + placeholders(len(skip)) + `)` + for _, id := range skip { + args = append(args, id) + } + } + rows, err := tx.QueryContext(ctx, query+` ORDER BY not_before, id LIMIT 1`, args...) + if err != nil { + return fmt.Errorf("connector: outbox claim: %w", err) + } + intents, err := scanIntents(rows) + if err != nil { + return err + } + if len(intents) == 0 { + ok = false + return nil + } + in := intents[0] + + next, note := IntentSending, "" + if in.Kind == IntentHoldingReply { + // The reply answers a record with no route. If the route arrived + // and the record moved on โ€” it may be running now โ€” the answer is + // wrong, so it is never sent. + var stillBlocked bool + switch err := tx.QueryRowContext(ctx, `SELECT state = 'blocked' AND reason = 'no_route' FROM events WHERE id = ?`, in.EventID).Scan(&stillBlocked); { + case errors.Is(err, sql.ErrNoRows): + // No record, nothing to answer for. Canceled rather than + // left to be claimed again on every tick. + stillBlocked = false + case err != nil: + return fmt.Errorf("connector: outbox claim holding reply %d: %w", in.ID, err) + } + if !stillBlocked { + next, note = IntentCanceled, "no longer called for" + } + } + if in.Kind == IntentStillRunning { + // The notice says the worker is still working. If its attempt has + // ended in the meantime โ€” behind a slow send, or a listing in + // front of it โ€” that is no longer true, and the completion notice, + // if the settlement called for one, is the connector's last word. + // A crashed process's attempt is not ended yet when a start + // flushes: the dispatcher's recovery settles it just after, and + // that settlement's notice follows this one. + var live bool + switch err := tx.QueryRowContext(ctx, `SELECT state <> 'ended' FROM attempts WHERE id = ?`, in.AttemptID).Scan(&live); { + case errors.Is(err, sql.ErrNoRows): + live = false + case err != nil: + return fmt.Errorf("connector: outbox claim still-running %d: %w", in.ID, err) + } + if !live { + next, note = IntentCanceled, "the attempt ended before the notice went out" + } + } + if in.Kind == IntentGuardAck { + var stillCalledFor bool + switch err := tx.QueryRowContext(ctx, ` +SELECT e.acknowledge = 1 AND e.state IN ('admitted', 'queued', 'dispatched') + AND NOT EXISTS (SELECT 1 FROM task_events te + WHERE te.event_id = e.id AND (te.guard = 'canceled' OR te.delivery IN ('delivered', 'completed'))) +FROM events e WHERE e.id = ?`, in.EventID).Scan(&stillCalledFor); { + case errors.Is(err, sql.ErrNoRows): + stillCalledFor = false + case err != nil: + return fmt.Errorf("connector: outbox claim guard %d: %w", in.ID, err) + } + if !stillCalledFor { + next, note = IntentCanceled, "no longer called for" + } else if _, err := tx.ExecContext(ctx, `UPDATE task_events SET guard = 'fired' WHERE event_id = ? AND guard = 'armed'`, in.EventID); err != nil { + return fmt.Errorf("connector: outbox claim guard %d: %w", in.ID, err) + } + } + var res sql.Result + if next == IntentSending { + res, err = tx.ExecContext(ctx, `UPDATE outbox SET state = 'sending', sending_at = ? WHERE id = ? AND state = 'pending'`, now, in.ID) + } else { + res, err = tx.ExecContext(ctx, `UPDATE outbox SET state = 'canceled', finished_at = ?, note = ? WHERE id = ? AND state = 'pending'`, now, note, in.ID) + } + if err != nil { + return fmt.Errorf("connector: outbox claim %d: %w", in.ID, err) + } + // The select and this update share one immediate transaction, so the + // row cannot have moved; checked rather than reasoned, because + // invariant 3 rests on it. + if n, err := res.RowsAffected(); err != nil { + return err + } else if n == 0 { + ok = false + return nil + } + if err := tx.Commit(); err != nil { + return fmt.Errorf("connector: commit outbox claim %d: %w", in.ID, err) + } + in.State, in.Note = next, note + if next == IntentSending { + t, _ := parseStamp(now) + in.SendingAt = &t + } + out, ok = in, true + return nil + }) + return out, ok, err +} + +// recordReceipt moves a sending intent to sent with its receipt. +func (l *Ledger) recordReceipt(ctx context.Context, id, receipt int64) (Intent, error) { + err := retryBusy(func() error { + res, err := l.db.ExecContext(ctx, `UPDATE outbox SET state = 'sent', receipt_id = ?, finished_at = ? WHERE id = ? AND state = 'sending'`, + receipt, l.timestamp(), id) + if err != nil { + if isUniqueViolation(err) { + return fmt.Errorf("connector: receipt %d for intent %d: %w", receipt, id, ErrReceiptOwned) + } + return fmt.Errorf("connector: receipt for intent %d: %w", id, err) + } + if n, err := res.RowsAffected(); err != nil { + return err + } else if n == 0 { + return fmt.Errorf("connector: receipt for intent %d: it is not sending", id) + } + return nil + }) + if err != nil { + return Intent{}, err + } + return l.Intent(ctx, id) +} + +// reconcileStale reconciles every sending intent whose sending time is at +// least age ago. It returns how many it settled. +func (o *Outbox) reconcileStale(ctx context.Context, age time.Duration) (int, error) { + return o.reconcileSome(ctx, age, 0) +} + +// reconcileSome reconciles at most limit due sending intents โ€” every one when +// limit is zero โ€” and returns how many it settled. Each listing is bounded, +// but sending waits for the pass, so the running connector lists one +// destination per tick: a guard due in thirty seconds waits at most one +// listing, however many destinations are slow. A listing that fails backs +// its intent off, so the next tick reaches the next one. +func (o *Outbox) reconcileSome(ctx context.Context, age time.Duration, limit int) (int, error) { + o.mu.Lock() + defer o.mu.Unlock() + intents, err := o.ledger.Intents(ctx, IntentFilter{States: []IntentState{IntentSending}}) + if err != nil { + if ctx.Err() != nil { + return 0, err + } + return 0, fmt.Errorf("%w: %w", errLedger, err) + } + now := o.ledger.now() + cutoff := now.Add(-age) + settled, listed := 0, 0 + var firstErr, hardErr error + for i := len(intents) - 1; i >= 0; i-- { + if limit > 0 && listed >= limit { + break + } + in := intents[i] + if in.SendingAt != nil && in.SendingAt.After(cutoff) { + continue + } + if in.ReconcileAt != nil && in.ReconcileAt.After(now) { + continue + } + listed++ + done, err := o.reconcile(ctx, in) + if err != nil { + o.log.Warn("connector: reconciling a lifecycle message", "intent_id", in.ID, "error", err) + if firstErr == nil { + firstErr = err + } + if errors.Is(err, errLedger) { + // The ledger failed. The pass stops here: nothing it does + // afterwards โ€” nor a bound running out meanwhile โ€” may hide + // that from a start. The intent is put back a little, best + // effort, so a running connector does not list the same + // destination on every tick while the ledger recovers. + o.ledger.deferReconcile(context.WithoutCancel(ctx), in.ID, DefaultReconcileBackoff) + hardErr = err + break + } + continue + } + if done { + settled++ + } + } + if hardErr != nil { + return settled, hardErr + } + return settled, firstErr +} + +// reconcile settles one sending intent by listing its destination (invariant +// 5). A listing that fails leaves it sending, to try again; a listing that +// answers settles it as sent or indeterminate. +func (o *Outbox) reconcile(ctx context.Context, in Intent) (bool, error) { + since := in.CreatedAt + if in.SendingAt != nil { + since = *in.SendingAt + } + since = since.Add(-o.opts.ReconcileSlack) + // Bounded like every other listing: Run sends and reconciles in one + // sequence, and a Campfire deep enough to page for minutes would hold up + // a guard that is due in thirty seconds. A listing cut short is a failed + // listing, which backs off. + listCtx, cancel := context.WithTimeout(ctx, AdoptionScanTimeout) + defer cancel() + listed, err := o.opts.Poster.List(listCtx, in.Destination, since) + // From here on the ledger is written without ctx: a listing that answered + // is settled even as shutdown begins, and so every error below is the + // ledger's own, marked where it happens rather than guessed from ctx. + ledgerCtx := context.WithoutCancel(ctx) + if err != nil { + if ctx.Err() != nil { + // Cut short by the bound or shutdown: not a failure of Basecamp's + // nor the ledger's, and nothing is recorded. + return false, err + } + updated, settled, recErr := o.ledger.listingFailed(ledgerCtx, in, err) + if recErr != nil { + return false, fmt.Errorf("%w: %w", errLedger, recErr) + } + if settled { + o.line(updated) + return true, nil + } + return false, fmt.Errorf("%w: %w", errBackedOff, err) + } + candidate, note, err := o.ledger.adoptable(ledgerCtx, in, listed) + if err != nil { + return false, fmt.Errorf("%w: %w", errLedger, err) + } + updated, err := o.ledger.settleReconciled(ledgerCtx, in.ID, candidate, note) + if err != nil { + return false, fmt.Errorf("%w: %w", errLedger, err) + } + o.line(updated) + return true, nil +} + +// deferReconcile makes a sending intent's first reconciliation due after wait +// from now. Best effort: without it the intent is reconciled a little early, +// which can only make it indeterminate, never send it. +func (l *Ledger) deferReconcile(ctx context.Context, id int64, wait time.Duration) { + _ = retryBusy(func() error { + _, err := l.db.ExecContext(ctx, `UPDATE outbox SET reconcile_at = ? WHERE id = ? AND state = 'sending'`, stamp(l.now().Add(wait)), id) + return err + }) +} + +// listingFailed records a failed listing: the next is due after a backoff, +// and an unlistable destination or too many failures make the intent +// indeterminate. It reports whether the intent was settled. +func (l *Ledger) listingFailed(ctx context.Context, in Intent, listErr error) (Intent, bool, error) { + failures := in.ReconcileFailures + 1 + if errors.Is(listErr, ErrUnlistable) || failures >= MaxReconcileFailures { + note := "listing failed " + strconv.Itoa(failures) + " times" + if errors.Is(listErr, ErrUnlistable) { + note = "destination cannot be listed" + } + updated, err := l.giveUpReconciling(ctx, in.ID, failures, note) + return updated, err == nil, err + } + backoff := DefaultReconcileBackoff << (failures - 1) + if backoff <= 0 || backoff > MaxReconcileBackoff { + backoff = MaxReconcileBackoff + } + err := retryBusy(func() error { + _, err := l.db.ExecContext(ctx, `UPDATE outbox SET reconcile_failures = ?, reconcile_at = ? WHERE id = ? AND state = 'sending'`, + failures, stamp(l.now().Add(backoff)), in.ID) + return err + }) + return Intent{}, false, err +} + +// adoptable picks the one message a sending intent may adopt, or says why +// there is none. +func (l *Ledger) adoptable(ctx context.Context, in Intent, listed []PostedMessage) (int64, string, error) { + want := MessageText(in.Body) + var matches []int64 + seen := map[int64]bool{} + for _, m := range listed { + if seen[m.ID] || MessageText(m.Content) != want { + continue + } + seen[m.ID] = true + owned, err := l.receiptOwnedByOther(ctx, in.ID, in.Destination.Kind, m.ID) + if err != nil { + return 0, "", err + } + if owned { + continue + } + // A worker's own acknowledgement or reply is the worker's, however + // alike the words: the guard's fixed form is short enough to collide. + workers, err := l.workerMessage(ctx, in.Destination.Kind, m.ID) + if err != nil { + return 0, "", err + } + if !workers { + matches = append(matches, m.ID) + } + } + if len(matches) != 1 { + return 0, strconv.Itoa(len(matches)) + " matching messages at the destination", nil + } + rivals, err := l.unsettledAt(ctx, in.Destination) + if err != nil { + return 0, "", err + } + for _, r := range rivals { + if r.ID != in.ID && MessageText(r.Body) == want { + return 0, "intent " + strconv.FormatInt(r.ID, 10) + " could claim the same message", nil + } + } + return matches[0], "", nil +} + +// workerMessage reports whether a message id is one a worker reported as its +// own acknowledgement or reply. +func (l *Ledger) workerMessage(ctx context.Context, kind MessageKind, id int64) (bool, error) { + // Scoped by kind, as receipt ownership is: a boost id and a comment id + // are different numbers in different spaces, and a worker acknowledges + // with either while its reply is always a comment or a line. + query := `SELECT EXISTS (SELECT 1 FROM task_events WHERE ack_id = ?)` + if kind != MessageBoost { + query = `SELECT EXISTS (SELECT 1 FROM task_events WHERE ack_id = ? OR reply_id = ? OR adopted_reply_id = ?)` + } + args := []any{id} + if kind != MessageBoost { + args = append(args, id, id) + } + var found bool + err := retryBusy(func() error { + return l.db.QueryRowContext(ctx, query, args...).Scan(&found) + }) + return found, err +} + +// unsettledAt lists the intents at a destination whose message may exist +// without a receipt: not yet sent, sending, or never settled โ€” abandoned +// included, since a person abandoning one did not prove it absent. +func (l *Ledger) unsettledAt(ctx context.Context, dest Destination) ([]Intent, error) { + var out []Intent + err := retryBusy(func() error { + rows, err := l.db.QueryContext(ctx, selectIntents+` +WHERE message_kind = ? AND recording_id = ? AND state IN ('pending', 'sending', 'indeterminate', 'abandoned')`, + string(dest.Kind), dest.RecordingID) + if err != nil { + return fmt.Errorf("connector: intents at %d: %w", dest.RecordingID, err) + } + out, err = scanIntents(rows) + return err + }) + return out, err +} + +func (l *Ledger) receiptOwnedByOther(ctx context.Context, id int64, kind MessageKind, receipt int64) (bool, error) { + var owned bool + err := retryBusy(func() error { + return l.db.QueryRowContext(ctx, `SELECT EXISTS (SELECT 1 FROM outbox WHERE message_kind = ? AND receipt_id = ? AND id <> ?)`, + string(kind), receipt, id).Scan(&owned) + }) + return owned, err +} + +// giveUpReconciling settles a sending intent indeterminate after its last +// failed listing, recording that failure in the same write so the count a +// person reads is the count that gave up. +func (l *Ledger) giveUpReconciling(ctx context.Context, id int64, failures int, note string) (Intent, error) { + err := retryBusy(func() error { + res, err := l.db.ExecContext(ctx, ` +UPDATE outbox SET state = 'indeterminate', finished_at = ?, note = ?, reconcile_failures = ?, reconcile_at = NULL +WHERE id = ? AND state = 'sending'`, l.timestamp(), note, failures, id) + if err != nil { + return fmt.Errorf("connector: give up reconciling intent %d: %w", id, err) + } + if n, err := res.RowsAffected(); err != nil { + return err + } else if n == 0 { + return fmt.Errorf("connector: give up reconciling intent %d: it is no longer sending", id) + } + return nil + }) + if err != nil { + return Intent{}, err + } + return l.Intent(ctx, id) +} + +// settleReconciled writes a reconciliation's answer onto a still-sending +// intent: sent with the adopted receipt, or indeterminate with why. +func (l *Ledger) settleReconciled(ctx context.Context, id, receipt int64, note string) (Intent, error) { + err := retryBusy(func() error { + var ( + res sql.Result + err error + ) + now := l.timestamp() + if receipt > 0 { + res, err = l.db.ExecContext(ctx, `UPDATE outbox SET state = 'sent', receipt_id = ?, finished_at = ?, note = 'adopted by reconciliation' WHERE id = ? AND state = 'sending'`, + receipt, now, id) + } else { + res, err = l.db.ExecContext(ctx, `UPDATE outbox SET state = 'indeterminate', finished_at = ?, note = ? WHERE id = ? AND state = 'sending'`, + now, note, id) + } + if err != nil { + if isUniqueViolation(err) { + return fmt.Errorf("connector: reconcile intent %d: %w", id, ErrReceiptOwned) + } + return fmt.Errorf("connector: reconcile intent %d: %w", id, err) + } + if n, err := res.RowsAffected(); err != nil { + return err + } else if n == 0 { + return fmt.Errorf("connector: reconcile intent %d: it is no longer sending", id) + } + return nil + }) + if err != nil { + return Intent{}, err + } + return l.Intent(ctx, id) +} + +// IsLifecycleMessage says whether a comment or chat line id is the receipt of +// one of the connector's own lifecycle messages, for the adopted-reply rule. +// A notice whose receipt the ledger does not hold yet is recognized by its +// words instead, where the replies are listed: LifecycleFilteredReplies. An +// error answers yes: a reply is not adopted on a guess. +func (o *Outbox) IsLifecycleMessage(id int64) bool { + return IsLifecycleMessageIn(o.ledger)(id) +} + +// IsLifecycleMessageIn is IsLifecycleMessage over a ledger, for a dispatcher +// built without a sender. +func IsLifecycleMessageIn(l *Ledger) func(id int64) bool { + return func(id int64) bool { + ctx := context.Background() + for _, kind := range []MessageKind{MessageComment, MessageChatLine} { + found, err := l.IsLifecycleReceipt(ctx, kind, id) + if err != nil || found { + return true + } + } + return false + } +} + +// LifecycleFilteredReplies lists the agent's replies at a destination for the +// adopted-reply rule, without the connector's own notices: a message is left +// out when its id is a lifecycle receipt, or when its words are those of a +// comment or chat line intent at the same destination that has no receipt โ€” +// one still sending, say, or left for a person. Notice bodies name their event +// or attempt, so the match is exact and scoped to the destination; a notice in +// flight elsewhere never hides a reply here. +type LifecycleFilteredReplies struct { + // Lister lists the agent's messages with their content (a Poster does). + Lister interface { + List(ctx context.Context, dest Destination, since time.Time) ([]PostedMessage, error) + } + Ledger *Ledger +} + +var _ ReplyLister = LifecycleFilteredReplies{} + +// AgentReplies implements ReplyLister. +func (r LifecycleFilteredReplies) AgentReplies(ctx context.Context, bucketID int64, kind string, recordingID int64, since time.Time) ([]AgentReply, error) { + messageKind, ok := destinationKind(kind) + if !ok { + return nil, fmt.Errorf("connector: no reply listing for %q", kind) + } + dest := Destination{BucketID: bucketID, Kind: messageKind, RecordingID: recordingID} + // The bound is the listing's alone: the ledger read that follows is + // short, and a listing that used nearly all of it must not leave the + // ledger no time and be reported as a listing that failed. + listCtx, cancel := context.WithTimeout(ctx, AdoptionScanTimeout) + defer cancel() + listed, err := r.Lister.List(listCtx, dest, since) + if err != nil { + return nil, err + } + receipts := map[int64]bool{} + unreceipted := map[string]bool{} + if err := retryBusy(func() error { + clear(receipts) + clear(unreceipted) + // A receipt names the connector's message whatever state its intent + // is in. A body stands in for a message only while one may exist + // unreceipted: a canceled intent posted nothing, so its words are the + // worker's if they appear. + rows, err := r.Ledger.db.QueryContext(ctx, ` +SELECT receipt_id, body, state IN ('pending', 'sending', 'indeterminate', 'abandoned') +FROM outbox WHERE message_kind = ? AND recording_id = ?`, string(messageKind), recordingID) + if err != nil { + return err + } + defer func() { _ = rows.Close() }() + for rows.Next() { + var ( + receipt sql.NullInt64 + body string + unsettled bool + ) + if err := rows.Scan(&receipt, &body, &unsettled); err != nil { + return err + } + switch { + case receipt.Valid: + receipts[receipt.Int64] = true + case unsettled: + unreceipted[MessageText(body)] = true + } + } + return rows.Err() + }); err != nil { + return nil, fmt.Errorf("connector: lifecycle messages at %d: %w", recordingID, err) + } + out := make([]AgentReply, 0, len(listed)) + for _, m := range listed { + if receipts[m.ID] || unreceipted[MessageText(m.Content)] { + continue + } + out = append(out, AgentReply{ID: m.ID, CreatedAt: m.CreatedAt}) + } + return out, nil +} + +func (o *Outbox) line(in Intent) { + if o.opts.Lines == nil { + return + } + line := OutboxLine{Type: "outbox", IntentID: in.ID, Kind: string(in.Kind), State: string(in.State), EventID: in.EventID, AttemptID: in.AttemptID} + if in.ReceiptID != nil { + line.ReceiptID = *in.ReceiptID + } + if err := o.opts.Lines.WriteLine(line); err != nil { + o.log.Warn("connector: outbox line", "error", err) + } +}