From 08d88f2c6bc301c92c25139eedf11d7ec54deac5 Mon Sep 17 00:00:00 2001 From: scttbnsn <80784472+scttbnsn@users.noreply.github.com> Date: Thu, 8 Oct 2026 11:55:14 -0400 Subject: [PATCH 1/3] fix(edge): skip exec_end when a failing exec start was already ended The controller's exec_end landing while a create or start round trip is in flight closes the session and fails the round trip. failStart then sent an exec_end back, while the same cancel landing between the round trips went through abortStart and sent none. A tunnel drop mid round trip did the same toward a connection that was already gone. failStart now takes the abortStart path when the bring-up's context has ended or the session is already closed: whoever ended it owns the exec_end. It checks the context as well as the closed flag because Close cancels the context before it sets the flag. The error record is written either way. --- CHANGELOG.md | 6 ++++ internal/edge/exec_start_error_test.go | 31 ++++++++++++++++++++ internal/edge/tunnel.go | 15 ++++++++-- internal/edge/tunnel_resource_limits_test.go | 2 +- 4 files changed, 50 insertions(+), 4 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index f3d014a6..d80cd3bb 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,12 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +### Fixed + +- A typed exec start that fails after the controller's own `exec_end` already + ended it no longer sends an `exec_end` back. A start cancelled between the + two daemon calls already sent none. + ## [v0.9.23] - 2026-10-07 ### Added diff --git a/internal/edge/exec_start_error_test.go b/internal/edge/exec_start_error_test.go index 23fc27b9..0b5eea8e 100644 --- a/internal/edge/exec_start_error_test.go +++ b/internal/edge/exec_start_error_test.go @@ -140,6 +140,37 @@ func TestBringUpExecExitsWriteOneErrorRecord(t *testing.T) { requireOneStartError(t, logger) }) + // The controller's exec_end landing mid round trip closes the session and + // fails the round trip. It owns the exec_end, so the bring-up sends none. + t.Run("create fails after the session was closed", func(t *testing.T) { + t.Parallel() + c, logger, next := newAuditedTestClient(t) + var session *ExecSession + c.dockerClient = &fakeDocker{createExecErr: errors.New("boom"), createHook: func() { session.Close() }} + sessionCtx, registered := registeredSession(t, c, context.Background(), msg) + session = registered + + c.bringUpExec(sessionCtx, msg, session) + + requireOneStartError(t, logger) + requireTornDownSilently(t, c, session, next) + }) + + // A tunnel drop ends the bring-up's context before anything closes the + // session, and fails the round trip the same way. Nobody is left to tell. + t.Run("create fails after the context ended", func(t *testing.T) { + t.Parallel() + c, logger, next := newAuditedTestClient(t) + ctx, cancel := context.WithCancel(context.Background()) + c.dockerClient = &fakeDocker{createExecErr: errors.New("boom"), createHook: cancel} + sessionCtx, session := registeredSession(t, c, ctx, msg) + + c.bringUpExec(sessionCtx, msg, session) + + requireOneStartError(t, logger) + requireTornDownSilently(t, c, session, next) + }) + t.Run("start fails", func(t *testing.T) { t.Parallel() c, logger, next := newAuditedTestClient(t) diff --git a/internal/edge/tunnel.go b/internal/edge/tunnel.go index 1d130eea..06078e94 100644 --- a/internal/edge/tunnel.go +++ b/internal/edge/tunnel.go @@ -205,7 +205,7 @@ func (c *Client) bringUpExec(ctx context.Context, msg protocol.ExecStartMessage, execID, err := c.dockerClient.CreateExec(ctx, msg.ContainerID, msg.Cmd, msg.User, tty) if err != nil { slog.Error("failed to create exec", "container", applog.Sanitize(msg.ContainerID), "error", applog.Sanitize(err.Error())) - session.failStart(fmt.Sprintf("create exec failed: %v", err)) + session.failStart(ctx, fmt.Sprintf("create exec failed: %v", err)) return } if ctx.Err() != nil || session.isClosed() { @@ -223,7 +223,7 @@ func (c *Client) bringUpExec(ctx context.Context, msg protocol.ExecStartMessage, conn, err := c.dockerClient.StartExec(ctx, execID, tty) if err != nil { slog.Error("failed to start exec", "execID", applog.Sanitize(execID), "error", applog.Sanitize(err.Error())) - session.failStart(fmt.Sprintf("start exec failed: %v", err)) + session.failStart(ctx, fmt.Sprintf("start exec failed: %v", err)) return } @@ -483,7 +483,16 @@ func (s *ExecSession) abortStart() { // failStart tears the session down and reports a terminal exec_end. It closes // first so the session is deregistered before the controller sees the failure. -func (s *ExecSession) failStart(reason string) { +// A bring-up whose context has ended or whose session is already closed gets +// the record and no exec_end, as in abortStart: the controller's exec_end or a +// tunnel drop landing mid round trip fails the round trip too, and whoever +// ended the session owns the exec_end. The context is checked as well as the +// closed flag because Close cancels it before it sets the flag. +func (s *ExecSession) failStart(ctx context.Context, reason string) { + if ctx.Err() != nil || s.isClosed() { + s.abortStart() + return + } s.auditStartError() s.Close() // Best-effort error reply; connection loss will surface on the read pump. diff --git a/internal/edge/tunnel_resource_limits_test.go b/internal/edge/tunnel_resource_limits_test.go index ffc28a10..56ce349f 100644 --- a/internal/edge/tunnel_resource_limits_test.go +++ b/internal/edge/tunnel_resource_limits_test.go @@ -284,7 +284,7 @@ func TestDelayedExecFailureCannotReachReplacementConnection(t *testing.T) { c.connMu.Unlock() oldState.closeAndDiscard(oldCh) - session.failStart("late old-generation failure") + session.failStart(context.Background(), "late old-generation failure") if got := len(newCh); got != 0 { t.Fatalf("replacement connection received %d delayed old-generation exec failures, want 0", got) From e4a33cc2ff3978d8de5952c35698a2eea5eb29aa Mon Sep 17 00:00:00 2001 From: scttbnsn <80784472+scttbnsn@users.noreply.github.com> Date: Thu, 8 Oct 2026 11:55:31 -0400 Subject: [PATCH 2/3] fix(edge): audit and close a typed exec bring-up that panics A panic inside bringUpExec was recovered and logged, and that was all: no audit record, the session stayed registered and kept its exec slot, and the controller never got an exec_end. It was the one bring-up exit #367 left without a record. The bring-up now recovers on its own and takes the failed-start exit: one api_request error record under exec_start, the session closed, and an exec_end with a fixed reason unless the session was already ended. A conn the daemon handed over that activate hadn't taken yet is closed too. The record sits behind a sync.Once so a panic after an exit already wrote it doesn't write a second, and recoverSession stays as the outer defer so a panic in the teardown itself still can't reach the agent. --- CHANGELOG.md | 6 + internal/edge/exec_start_panic_test.go | 204 +++++++++++++++++++++++++ internal/edge/tunnel.go | 47 +++++- 3 files changed, 253 insertions(+), 4 deletions(-) create mode 100644 internal/edge/exec_start_panic_test.go diff --git a/CHANGELOG.md b/CHANGELOG.md index d80cd3bb..e9c68a37 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,6 +9,12 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Fixed +- A typed exec start on the edge whose bring-up panics is now handled as a + failed start. It writes the same `api_request` record (outcome `error`, + method `exec_start`), closes the session along with any daemon connection it + had opened, and sends the controller an `exec_end`. The panic used to be + logged and nothing else, so there was no record and the session held its + exec slot until the controller ended it or the tunnel dropped. - A typed exec start that fails after the controller's own `exec_end` already ended it no longer sends an `exec_end` back. A start cancelled between the two daemon calls already sent none. diff --git a/internal/edge/exec_start_panic_test.go b/internal/edge/exec_start_panic_test.go new file mode 100644 index 00000000..b543c3a8 --- /dev/null +++ b/internal/edge/exec_start_panic_test.go @@ -0,0 +1,204 @@ +package edge + +import ( + "context" + "errors" + "log/slog" + "net" + "strings" + "sync/atomic" + "testing" + + "github.com/codeswhat/portwing/internal/protocol" +) + +// panickingDocker panics from one daemon call, standing in for a bug under the +// bring-up that only a recover stops. +type panickingDocker struct { + *fakeDocker + at string // "create", "start" or "resize" +} + +func (p *panickingDocker) CreateExec(ctx context.Context, containerID string, cmd []string, user string, tty bool) (string, error) { + if p.at == "create" { + panic("boom in create") + } + return p.fakeDocker.CreateExec(ctx, containerID, cmd, user, tty) +} + +func (p *panickingDocker) StartExec(ctx context.Context, execID string, tty bool) (net.Conn, error) { + if p.at == "start" { + panic("boom in start") + } + return p.fakeDocker.StartExec(ctx, execID, tty) +} + +func (p *panickingDocker) ResizeExec(ctx context.Context, execID string, cols, rows int) error { + if p.at == "resize" { + panic("boom in resize") + } + return p.fakeDocker.ResizeExec(ctx, execID, cols, rows) +} + +// countingConn counts Close calls, which tells a conn closed once from one +// that leaked or was closed twice. +type countingConn struct { + *fakeConn + closes atomic.Int32 +} + +func (c *countingConn) Close() error { + c.closes.Add(1) + return c.fakeConn.Close() +} + +func requireClosedAndDeregistered(t *testing.T, c *Client, session *ExecSession) { + t.Helper() + if !session.isClosed() { + t.Fatal("session not closed") + } + if _, ok := c.execSessions.Load(session.execID); ok { + t.Fatal("session still registered, so it still holds its exec slot") + } +} + +// A bring-up that panics is a failed start like any other: exactly one +// api_request error record under exec_start, the session closed and +// deregistered, and an exec_end so the controller isn't left waiting for an +// exec_ready. The hijacked conn is closed when the panic lands after the daemon +// handed it over and before the session took it. +func TestBringUpExecPanicFailsTheStart(t *testing.T) { + t.Parallel() + + msg := protocol.ExecStartMessage{ExecID: "e1", ContainerID: "c1", Cols: 80, Rows: 24} + for _, tc := range []struct { + at string + wantCloses int32 + }{ + {"create", 0}, + {"start", 0}, + {"resize", 1}, + } { + t.Run(tc.at, func(t *testing.T) { + t.Parallel() + c, logger, next := newAuditedTestClient(t) + conn := &countingConn{fakeConn: &fakeConn{}} + c.dockerClient = &panickingDocker{ + fakeDocker: &fakeDocker{createExecID: "d1", startConn: conn}, + at: tc.at, + } + sessionCtx, session := registeredSession(t, c, context.Background(), msg) + + // Returning at all is the agent surviving the panic. + c.bringUpExec(sessionCtx, msg, session) + + requireOneStartError(t, logger) + requireClosedAndDeregistered(t, c, session) + if got := conn.closes.Load(); got != tc.wantCloses { + t.Fatalf("hijacked conn closed %d times, want %d", got, tc.wantCloses) + } + env := next() + if env.Type != protocol.TypeExecEnd { + t.Fatalf("frame = %q, want exec_end", env.Type) + } + var end protocol.ExecEndMessage + decodeData(t, env.Data, &end) + if end.ExecID != "e1" || end.Reason != "exec start failed: internal error" { + t.Fatalf("exec_end = %+v, want e1 with the fixed internal-error reason", end) + } + }) + } +} + +// A panic after the controller's exec_end or a tunnel drop already closed the +// session still writes the record, and sends no exec_end of its own: whoever +// closed the session owns that. +func TestBringUpExecPanicAfterCloseSendsNoExecEnd(t *testing.T) { + t.Parallel() + + msg := protocol.ExecStartMessage{ExecID: "e1", ContainerID: "c1"} + c, logger, next := newAuditedTestClient(t) + var session *ExecSession + c.dockerClient = &fakeDocker{createHook: func() { + session.Close() + panic("boom after close") + }} + sessionCtx, registered := registeredSession(t, c, context.Background(), msg) + session = registered + + c.bringUpExec(sessionCtx, msg, session) + + requireOneStartError(t, logger) + requireTornDownSilently(t, c, session, next) +} + +// brokenTarget is an outbound target whose every send panics (a queue with no +// state behind it), standing in for a bug in the send path. +func brokenTarget() outboundTarget { + return outboundTarget{ch: make(chan protocol.Envelope, 1)} +} + +// A panic after the exit already wrote its record adds no second one. Here the +// create fails, failStart writes the record and closes, and its exec_end is +// what panics. +func TestBringUpExecPanicAfterRecordWritesNoSecond(t *testing.T) { + t.Parallel() + + msg := protocol.ExecStartMessage{ExecID: "e1", ContainerID: "c1"} + c, logger, _ := newAuditedTestClient(t) + c.dockerClient = &fakeDocker{createExecErr: errors.New("boom")} + sessionCtx, session := registeredSession(t, c, context.Background(), msg) + session.target = brokenTarget() + + c.bringUpExec(sessionCtx, msg, session) + + requireOneStartError(t, logger) + requireClosedAndDeregistered(t, c, session) +} + +// A panic after activate handed the conn to the session closes it once, +// through the session, and the teardown's own exec_end panicking on the same +// broken send path still doesn't escape the bring-up. +func TestBringUpExecPanicAfterActivateClosesConnOnce(t *testing.T) { + t.Parallel() + + msg := protocol.ExecStartMessage{ExecID: "e1", ContainerID: "c1"} + c, logger, _ := newAuditedTestClient(t) + conn := &countingConn{fakeConn: &fakeConn{}} + c.dockerClient = &fakeDocker{createExecID: "d1", startConn: conn} + sessionCtx, session := registeredSession(t, c, context.Background(), msg) + session.target = brokenTarget() + + c.bringUpExec(sessionCtx, msg, session) + + requireOneStartError(t, logger) + requireClosedAndDeregistered(t, c, session) + if got := conn.closes.Load(); got != 1 { + t.Fatalf("hijacked conn closed %d times, want 1", got) + } +} + +// The panic value goes to the agent's log, which is the only place it lands: +// the controller gets the fixed reason. +func TestBringUpExecPanicIsLogged(t *testing.T) { + // Not parallel: it swaps the process-global slog default. + // syncBuffer because the client's send pump is live and may log too. + logBuf := &syncBuffer{} + oldLogger := slog.Default() + slog.SetDefault(slog.New(slog.NewTextHandler(logBuf, nil))) + defer slog.SetDefault(oldLogger) + + msg := protocol.ExecStartMessage{ExecID: "e1", ContainerID: "c1"} + c, _, _ := newAuditedTestClient(t) + c.dockerClient = &panickingDocker{fakeDocker: &fakeDocker{}, at: "create"} + sessionCtx, session := registeredSession(t, c, context.Background(), msg) + + c.bringUpExec(sessionCtx, msg, session) + + out := logBuf.String() + for _, want := range []string{"recovered from panic", "where=bringUpExec", "execID=e1", "boom in create"} { + if !strings.Contains(out, want) { + t.Errorf("log = %q, want it to contain %q", out, want) + } + } +} diff --git a/internal/edge/tunnel.go b/internal/edge/tunnel.go index 06078e94..75f297aa 100644 --- a/internal/edge/tunnel.go +++ b/internal/edge/tunnel.go @@ -89,6 +89,9 @@ type ExecSession struct { once sync.Once cancel context.CancelFunc + // startErrOnce keeps a failed bring-up to one error record. + startErrOnce sync.Once + mu sync.Mutex closed bool queuedInputBytes int @@ -193,7 +196,19 @@ func (c *Client) auditTypedExecStart(msg protocol.ExecStartMessage, admitted boo // bringUpExec performs the Docker round-trips for an already-registered session // and, on success, wires the live connection and starts streaming. func (c *Client) bringUpExec(ctx context.Context, msg protocol.ExecStartMessage, session *ExecSession) { + // Deferred first so it runs last: a panic in the teardown below still + // stops here instead of taking the agent down. defer recoverSession("bringUpExec", msg.ExecID) + // unwired is the hijacked conn while only this goroutine holds it, from + // StartExec returning it until activate hands it to the session. A panic + // in that window has to close it here because Close can't reach it yet. + var unwired net.Conn + defer func() { + if r := recover(); r != nil { + logSessionPanic("bringUpExec", msg.ExecID, r) + session.panicStart(ctx, unwired) + } + }() if ctx.Err() != nil || session.isClosed() { session.abortStart() return @@ -226,6 +241,7 @@ func (c *Client) bringUpExec(ctx context.Context, msg protocol.ExecStartMessage, session.failStart(ctx, fmt.Sprintf("start exec failed: %v", err)) return } + unwired = conn // Resize terminal to requested dimensions. if msg.Cols > 0 && msg.Rows > 0 { @@ -240,6 +256,7 @@ func (c *Client) bringUpExec(ctx context.Context, msg protocol.ExecStartMessage, session.auditStartError() return } + unwired = nil // Announce readiness; best-effort — connection loss surfaces on the read pump. _ = c.sendTypedMessageTo(session.target, protocol.TypeExecReady, protocol.ExecReadyMessage{ @@ -468,9 +485,12 @@ func (s *ExecSession) isClosed() bool { // auditStartError records that an admitted typed exec did not come up, as the // api_request error record under the exec_start message type. Each bringUpExec -// exit that gives up calls it once. +// exit that gives up calls it once. The Once is for the panic exit, which can +// follow an exit that already wrote the record and then panicked. func (s *ExecSession) auditStartError() { - s.client.auditor.APIRequest(s.client.cfg.DrydockURL, protocol.TypeExecStart, s.containerID, audit.OutcomeError, 0, 0) + s.startErrOnce.Do(func() { + s.client.auditor.APIRequest(s.client.cfg.DrydockURL, protocol.TypeExecStart, s.containerID, audit.OutcomeError, 0, 0) + }) } // abortStart records the failed start and tears the session down for a @@ -502,6 +522,17 @@ func (s *ExecSession) failStart(ctx context.Context, reason string) { }) } +// panicStart is the bring-up's exit when it panicked: a failed start like the +// others, plus the hijacked conn when the panic landed while only the bring-up +// held it. The reason is fixed so the panic value stays in the agent's log. +func (s *ExecSession) panicStart(ctx context.Context, unwired net.Conn) { + if unwired != nil { + // Best effort: the conn is abandoned either way. + _ = unwired.Close() + } + s.failStart(ctx, "exec start failed: internal error") +} + // execFrameHeaderLen is the size of Docker's stream-multiplexing frame header // on a non-TTY exec: a stream-type byte, three zero bytes, then the payload // length as a 4-byte big-endian integer. @@ -697,11 +728,19 @@ func (s *ExecSession) Close() { // entry of each per-session goroutine (bringUpExec, inputWriter, readLoop). func recoverSession(where, execID string) { if r := recover(); r != nil { - slog.Error("recovered from panic in exec session goroutine", - "where", where, "execID", applog.Sanitize(execID), "panic", applog.Sanitize(fmt.Sprint(r))) + logSessionPanic(where, execID, r) } } +// logSessionPanic logs a panic recovered in a per-session goroutine. It is +// separate from recoverSession because recover only works when the deferred +// function itself calls it, so a caller that does more than log recovers on +// its own and logs through here. +func logSessionPanic(where, execID string, r any) { + slog.Error("recovered from panic in exec session goroutine", + "where", where, "execID", applog.Sanitize(execID), "panic", applog.Sanitize(fmt.Sprint(r))) +} + // execSlotsFullLocked reports whether typed exec sessions plus raw exec starts // have used every maxExecSessions slot. The caller holds execAdmissionMu. func (c *Client) execSlotsFullLocked() bool { From aa9f55518944938db60131b55303b0c377e1f852 Mon Sep 17 00:00:00 2001 From: scttbnsn <80784472+scttbnsn@users.noreply.github.com> Date: Thu, 8 Oct 2026 12:00:29 -0400 Subject: [PATCH 3/3] docs(drydock-integration): say when a failed exec start sends no exec_end --- docs/content/docs/drydock-integration.mdx | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/docs/content/docs/drydock-integration.mdx b/docs/content/docs/drydock-integration.mdx index b14a152a..1c02bee1 100644 --- a/docs/content/docs/drydock-integration.mdx +++ b/docs/content/docs/drydock-integration.mdx @@ -379,7 +379,9 @@ the desynchronization, rather than forwarding bytes it can no longer frame. If a session fails to start (for example, a sockguard exec-policy denial), the agent's failStart path sends `exec_end` immediately instead of -`exec_ready`. Its `reason` field now carries the underlying Docker/sockguard +`exec_ready`, unless the controller's own `exec_end` or a tunnel drop already +ended the session, in which case it sends nothing back. The `reason` field +of that `exec_end` carries the underlying Docker/sockguard error body — e.g. `not allowed by portwing preset` or `exec denied: privileged exec is not allowed` — rather than a bare status code. Drydock's edge agent adapter does not yet surface that reason to the user; today it