diff --git a/go.mod b/go.mod index 56e121233..a66172eca 100644 --- a/go.mod +++ b/go.mod @@ -8,7 +8,7 @@ require ( charm.land/bubbles/v2 v2.2.1 charm.land/bubbletea/v2 v2.1.0 charm.land/lipgloss/v2 v2.0.6 - github.com/basecamp/basecamp-sdk/go v0.28.1 + github.com/basecamp/basecamp-sdk/go v0.29.1 github.com/basecamp/cli v0.2.2-0.20261023171439-c9bce8206df9 github.com/basecamp/mcp v0.0.0-20260828100356-2d6f44b51e9d github.com/basecamp/surfguard/go v0.1.0 diff --git a/go.sum b/go.sum index 6a424c50b..7aa92ed2c 100644 --- a/go.sum +++ b/go.sum @@ -89,8 +89,8 @@ github.com/aymerick/douceur v0.2.0 h1:Mv+mAeH1Q+n9Fr+oyamOlAkUNPWPlA8PPGR0QAaYuP github.com/aymerick/douceur v0.2.0/go.mod h1:wlT5vV2O3h55X9m7iVYN0TBM0NH/MmbLnd30/FjWUq4= github.com/basecamp/actioncable-go v1.2.0 h1:t0MxlfMTcmaGXZ5ztgKRs7ZiY1MwXtBRwSSSAh1ofVg= github.com/basecamp/actioncable-go v1.2.0/go.mod h1:ezaV5z1GXQAsqyejqTs6wCFl2D8Wj+COLQkHc/kwoRs= -github.com/basecamp/basecamp-sdk/go v0.28.1 h1:DX3zukDnqZXo5lAOjuFg11Tinv0SYIp8/ddsuHDB6BA= -github.com/basecamp/basecamp-sdk/go v0.28.1/go.mod h1:mUm/MQGMyg1E1cddyxdG7tQHiq0NsYee2zUeAUT5VjU= +github.com/basecamp/basecamp-sdk/go v0.29.1 h1:zYEtED8WnEKcfRXKujKHqYqbFc3h2DbE9Z+scHuH1J8= +github.com/basecamp/basecamp-sdk/go v0.29.1/go.mod h1:mUm/MQGMyg1E1cddyxdG7tQHiq0NsYee2zUeAUT5VjU= github.com/basecamp/cli v0.2.2-0.20261023171439-c9bce8206df9 h1:3NfGs+zx23Tp6cf+97+UewrJHlzZMLzmvEXOmOJyQAk= github.com/basecamp/cli v0.2.2-0.20261023171439-c9bce8206df9/go.mod h1:iTBTaWvsPEFIcZfkxQHEfISyJ6sZ7036K6bNx0RY3EE= github.com/basecamp/mcp v0.0.0-20260828100356-2d6f44b51e9d h1:zEQVGq1x1nhKMZ2TudFAcSJ32CHT8richI1vQakIKz4= diff --git a/internal/connector/intake.go b/internal/connector/intake.go index d881c63fe..a09b0d59f 100644 --- a/internal/connector/intake.go +++ b/internal/connector/intake.go @@ -755,6 +755,25 @@ func (in *Intake) observer(ctx context.Context) eventfeed.Observer { BufferOverflow: func(dropped int) { in.log.Warn("live buffer overflowed", "dropped", dropped) }, + // In-band renewal. A server that bounds the stream by its token's + // expiry advertises the deadline in the welcome, and the package + // renews the socket before it. Nothing here decides anything: a + // renewal that gives up leaves the socket to the server's lease, and + // the reconnect after that `remote` close is the ordinary one. The + // lines are what tell that close apart from an unexplained one. + StreamDeadline: func(expiresAt time.Time) { + in.log.Info("feed stream deadline advertised; renewing in band before it", "expires_at", expiresAt.UTC()) + }, + Renewed: func(expiresAt time.Time) { + in.log.Info("feed stream renewed in band", "expires_at", expiresAt.UTC()) + }, + RenewFailed: func(kind eventfeed.RenewFailure, retrying bool) { + msg := "feed stream renewal failed; retrying" + if !retrying { + msg = "feed stream renewal gave up; the server closes the socket at its deadline, and the connector reconnects and catches up" + } + in.log.Warn(msg, "kind", kind.String()) + }, } } diff --git a/internal/connector/renewal_log_test.go b/internal/connector/renewal_log_test.go new file mode 100644 index 000000000..3b2d26546 --- /dev/null +++ b/internal/connector/renewal_log_test.go @@ -0,0 +1,157 @@ +package connector + +import ( + "bufio" + "context" + "encoding/json" + "log/slog" + "strings" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + "github.com/basecamp/basecamp-sdk/go/pkg/basecamp/eventfeed" + "github.com/basecamp/basecamp-sdk/go/pkg/basecamp/eventfeed/feedtest" +) + +// logLines decodes a JSON log, one record per line. +func logLines(t *testing.T, raw string) []map[string]any { + t.Helper() + var lines []map[string]any + scanner := bufio.NewScanner(strings.NewReader(raw)) + for scanner.Scan() { + var line map[string]any + require.NoError(t, json.Unmarshal(scanner.Bytes(), &line), "log line %q", scanner.Text()) + lines = append(lines, line) + } + require.NoError(t, scanner.Err()) + return lines +} + +// logLine returns the one record whose message is msg, or nil. +func logLine(t *testing.T, raw, msg string) map[string]any { + t.Helper() + var found map[string]any + for _, line := range logLines(t, raw) { + if line["msg"] == msg { + require.Nil(t, found, "more than one %q line", msg) + found = line + } + } + return found +} + +// writtenCommand returns the identifier of the first write on conn whose +// command is command. +func writtenCommand(conn *feedtest.Conn, command string) (string, bool) { + for _, write := range conn.Writes() { + var c struct { + Command string `json:"command"` + Identifier string `json:"identifier"` + } + if json.Unmarshal(write, &c) == nil && c.Command == command && c.Identifier != "" { + return c.Identifier, true + } + } + return "", false +} + +// A server that bounds the stream advertises its deadline in the welcome, and +// the package renews the socket in band before it. Through the real run loop: +// the advert and the renewal each reach the connector's log, with the +// deadlines they carry, and the fresh ticket the renewal sends does not. +func TestAnInBandRenewalReachesTheConnectorLog(t *testing.T) { + var logs safeBuffer + ledger := newTestLedger(t) + intake, transport, minter, polls := newFeedIntake(t, ledger, Options{ + Logger: slog.New(slog.NewJSONHandler(&logs, nil)), + }) + minter.ScriptTicket(ticket()) + const renewalTicket = "renewal-ticket-that-must-stay-out-of-the-log" + minter.ScriptTicket(eventfeed.StreamTicket{Ticket: renewalTicket, ExpiresIn: 120, + URL: "wss://cable.basecamp.com/cable?ticket=" + renewalTicket}) + polls.ScriptPage(eventfeed.PollPage{Position: "p1"}) + + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + done := runInBackground(ctx, t, intake) + + var conn *feedtest.Conn + require.Eventually(t, func() bool { + conn = transport.LastConn() + return conn != nil + }, 5*time.Second, 5*time.Millisecond, "the connector should dial") + + // Inside the package's renewal lead already, so the renewal is due as soon + // as the socket is streaming: no wait on the wall clock. + advertised := time.Now().Add(2 * time.Minute).UTC().Truncate(time.Millisecond) + conn.Serve(mustJSON(t, map[string]any{"type": "welcome", "stream_expires_at": advertised.Format(time.RFC3339Nano)})) + + var identifier string + require.Eventually(t, func() bool { + var ok bool + identifier, ok = writtenCommand(conn, "subscribe") + return ok + }, 5*time.Second, 5*time.Millisecond, "the connector should subscribe") + conn.Serve(confirmFrame(t, identifier)) + + require.Eventually(t, func() bool { + _, ok := writtenCommand(conn, "renew") + return ok + }, 5*time.Second, 5*time.Millisecond, "a socket streaming inside its renewal lead renews") + + renewed := advertised.Add(time.Hour) + conn.Serve(mustJSON(t, map[string]any{"identifier": identifier, "type": "renewed", "stream_expires_at": renewed.Format(time.RFC3339Nano)})) + + require.Eventually(t, func() bool { + return strings.Contains(logs.String(), "feed stream renewed in band") + }, 5*time.Second, 5*time.Millisecond, "the renewal reaches the log") + + cancel() + awaitReturn(t, done, "Run should return on shutdown") + + raw := logs.String() + deadline := logLine(t, raw, "feed stream deadline advertised; renewing in band before it") + require.NotNil(t, deadline, "the welcome's advert reaches the log:\n%s", raw) + assert.Equal(t, "INFO", deadline["level"]) + assert.Equal(t, advertised.Format(time.RFC3339Nano), deadline["expires_at"]) + + renewal := logLine(t, raw, "feed stream renewed in band") + require.NotNil(t, renewal) + assert.Equal(t, "INFO", renewal["level"]) + assert.Equal(t, renewed.Format(time.RFC3339Nano), renewal["expires_at"]) + + for _, line := range logLines(t, raw) { + assert.NotContains(t, line["msg"], "renewal failed", "nothing failed here") + assert.NotContains(t, line["msg"], "renewal gave up", "nothing failed here") + } + assert.NotContains(t, raw, renewalTicket, "the renewal's ticket is a bearer credential") +} + +// A failed renewal is retried once, then left to the server's lease, whose +// `remote` close the connector recovers from as from any other. The log says +// which: the first is a retry, and the second explains the close that follows +// it. The kind is the package's closed vocabulary, never the server's reason. +func TestAFailedRenewalSaysWhetherItIsRetriedOrLeftToTheLease(t *testing.T) { + var logs safeBuffer + intake, _, _ := newTestIntake(t, nil, nil) + intake.log = slog.New(slog.NewJSONHandler(&logs, nil)) + + observer := intake.observer(context.Background()) + require.NotNil(t, observer.RenewFailed) + observer.RenewFailed(eventfeed.RenewRefused, true) + observer.RenewFailed(eventfeed.RenewNoReply, false) + + lines := logLines(t, logs.String()) + require.Len(t, lines, 2) + + assert.Equal(t, "WARN", lines[0]["level"]) + assert.Equal(t, "feed stream renewal failed; retrying", lines[0]["msg"]) + assert.Equal(t, "refused", lines[0]["kind"]) + + assert.Equal(t, "WARN", lines[1]["level"]) + assert.Equal(t, "feed stream renewal gave up; the server closes the socket at its deadline, and the connector reconnects and catches up", lines[1]["msg"]) + assert.Equal(t, "no_reply", lines[1]["kind"]) +} diff --git a/internal/mcpserver/model/PROVENANCE.json b/internal/mcpserver/model/PROVENANCE.json index 3168076a2..6b6e0cefe 100644 --- a/internal/mcpserver/model/PROVENANCE.json +++ b/internal/mcpserver/model/PROVENANCE.json @@ -1,7 +1,7 @@ { "source": "github.com/basecamp/basecamp-sdk", - "commit": "96cb26cc40a847c68ad2470ef5a775dd5c452613", - "ref": "v0.28.1", + "commit": "0b66bbc3846d605d8d684a395fe6458e289ea3c7", + "ref": "v0.29.1", "files": ["behavior-model.json", "openapi.json"], "synced_by": "scripts/sync-mcp-model.sh", "patches": "binary-upload operations dropped because the toolkit refuses their non-JSON bodies (EXCLUDED_OPERATIONS) and the stream-ticket mint dropped by policy (POLICY_EXCLUDED_OPERATIONS); no tag patches applied (PATCHED_TAGS is empty — the export tags every operation) — see the sync script" diff --git a/internal/version/sdk-provenance.json b/internal/version/sdk-provenance.json index b6392da6e..f547ddbf6 100644 --- a/internal/version/sdk-provenance.json +++ b/internal/version/sdk-provenance.json @@ -1,9 +1,9 @@ { "sdk": { "module": "github.com/basecamp/basecamp-sdk/go", - "version": "v0.28.1", - "revision": "96cb26cc40a8", - "updated_at": "2026-10-25T07:19:34Z" + "version": "v0.29.1", + "revision": "0b66bbc3846d", + "updated_at": "2026-10-26T18:18:02Z" }, "api": { "repo": "basecamp/bc3", diff --git a/nix/package.nix b/nix/package.nix index f15f7ee8e..9e34ee6bb 100644 --- a/nix/package.nix +++ b/nix/package.nix @@ -8,7 +8,7 @@ buildGoModule.override { go = go_1_26; } (finalAttrs: { src = lib.cleanSource ./..; # To update: set to lib.fakeHash, run `nix build`, use the hash from the error. - vendorHash = "sha256-6Aq4KTqf7hd+wyWGUC9gI9sv5K9XyQLsRMOx+9pnhLM="; + vendorHash = "sha256-kXbdeAuZlHob+KM5z4aEbZHrkD/nreaPyaBKucFu9WI="; subPackages = [ "cmd/basecamp" ];