mirror of
https://github.com/coder/coder.git
synced 2026-09-24 15:04:27 +08:00
feat: structured disconnect attribution for agent logs (#25191)
Implements [PLAT-60](https://linear.app/codercom/issue/PLAT-60/enhance-disconnect-logs-with-structured-reason-attribution): adds structured disconnect attribution to disconnect logs throughout the agent and tailnet packages. Every disconnect log site now carries structured slog fields. All existing logs remain; existing messages are preserved with the fields added alongside. New fields on disconnect log lines: - `connect_type` — which layer disconnected: `server_to_agent`, `agent_to_client`, or `client_to_server` - `disconnect_reason` — categorical reason: `graceful`, `network_error`, `server_shutdown`, etc. - `disconnect_expected` — whether the disconnect is normal operation (`true`) or should be investigated (`false`) - `disconnect_initiator` — who started it: `client`, `agent`, `server`, or `network` (control-plane sites only) - `disconnect_detail` — free-form supplemental info (where useful) ## What's covered **Control plane (`server_to_agent`):** coordination RPC, DERP map subscriber, agent runLoop, agent Close, `BasicCoordination.Close`, `Controller.run`. **Data plane (`agent_to_client`):** SSH sessions, reconnecting PTY, JetBrains port-forwarding. <details> <summary>Control-plane sites</summary> | Site | Reason | Initiator | |---|---|---| | `agent/agent.go` `runLoop` EOF | `network_error` | `network` | | `agent/agent.go` `runCoordinator` deferred exit | `server_shutdown` / `graceful` / `network_error` | `agent` / `server` / `network` | | `agent/agent.go` `runDERPMapSubscriber` deferred exit | same (shared `classifyCoordinatorRPCExit`) | same | | `agent/agent.go` `Close` shutdown timeout | `server_shutdown` + detail | `agent` | | `agent/agent.go` `Close` clean coord disconnect | `server_shutdown` | `agent` | | `tailnet/controllers.go` `BasicCoordination.Close` | `graceful` or `network_error` | `c.initiator` | | `tailnet/controllers.go` `Controller.run` `net.ErrClosed` | `network_error` | `network` | </details> <details> <summary>Data-plane sites</summary> | Site | Reason | Notes | |---|---|---| | `agent/agentssh/agentssh.go` SSH session closed | free-form (`graceful`, `process exited with error status: N`, etc.) | Also sets `closeCause("normal exit")` for clean exits so coderd's `connection_log.DisconnectReason` is no longer empty | | `agent/reconnectingpty/server.go` PTY closed | `server_shutdown`, error string, or `graceful` | | | `agent/agentssh/jetbrainstrack.go` channel closed | `normal close` or error string | Previously passed empty reason | </details> <details> <summary>Bug fix</summary> The deferred `disconnected from coordination RPC` log no longer fires when the initial `Coordinate()` RPC call fails before any connection is established. </details> Refs PLAT-60. --- _This PR was prepared by Coder Agents on behalf of @Emyrk._ **Manually QA'd a lot of common disconnects** --------- Co-authored-by: Coder Agents <noreply@coder.com>
This commit is contained in:
co-authored by
Coder Agents
parent
c9c933a300
commit
1afc6d4fd0
+58
-7
@@ -514,7 +514,12 @@ func (a *agent) runLoop() {
|
||||
return
|
||||
}
|
||||
if errors.Is(err, io.EOF) {
|
||||
a.logger.Info(ctx, "disconnected from coderd")
|
||||
a.logger.Info(ctx, "disconnected from coderd",
|
||||
codersdk.ConnectionDirectionServerToAgent.SlogField(),
|
||||
codersdk.DisconnectReasonNetworkError.SlogField(),
|
||||
codersdk.DisconnectReasonNetworkError.SlogExpectedField(),
|
||||
codersdk.DisconnectInitiatorNetwork.SlogField(),
|
||||
)
|
||||
continue
|
||||
}
|
||||
a.logger.Warn(ctx, "run exited with error", slog.Error(err))
|
||||
@@ -1878,16 +1883,43 @@ func (a *agent) createTailnet(
|
||||
return network, nil
|
||||
}
|
||||
|
||||
// classifyCoordinatorRPCExit determines the DisconnectReason and
|
||||
// DisconnectInitiator for a coordinator-style RPC (the coordination RPC
|
||||
// and the DERP map subscriber RPC) that has just returned. A canceled
|
||||
// local context means the agent itself is shutting down. A non-nil
|
||||
// return error without context cancellation means the stream broke
|
||||
// unexpectedly.
|
||||
func classifyCoordinatorRPCExit(ctx context.Context, retErr error) (codersdk.DisconnectReason, codersdk.DisconnectInitiator) {
|
||||
localShutdown := ctx.Err() != nil
|
||||
switch {
|
||||
case localShutdown:
|
||||
return codersdk.DisconnectReasonServerShutdown, codersdk.DisconnectInitiatorAgent
|
||||
case retErr == nil:
|
||||
return codersdk.DisconnectReasonGraceful, codersdk.DisconnectInitiatorServer
|
||||
default:
|
||||
return codersdk.DisconnectReasonNetworkError, codersdk.DisconnectInitiatorNetwork
|
||||
}
|
||||
}
|
||||
|
||||
// runCoordinator runs a coordinator and returns whether a reconnect
|
||||
// should occur.
|
||||
func (a *agent) runCoordinator(ctx context.Context, tClient tailnetproto.DRPCTailnetClient24, network *tailnet.Conn) error {
|
||||
defer a.logger.Debug(ctx, "disconnected from coordination RPC")
|
||||
func (a *agent) runCoordinator(ctx context.Context, tClient tailnetproto.DRPCTailnetClient24, network *tailnet.Conn) (retErr error) {
|
||||
// we run the RPC on the hardCtx so that we have a chance to send the disconnect message if we
|
||||
// gracefully shut down.
|
||||
coordinate, err := tClient.Coordinate(a.hardCtx)
|
||||
if err != nil {
|
||||
return xerrors.Errorf("failed to connect to the coordinate endpoint: %w", err)
|
||||
}
|
||||
defer func() {
|
||||
reason, initiator := classifyCoordinatorRPCExit(ctx, retErr)
|
||||
a.logger.Debug(ctx, "disconnected from coordination RPC",
|
||||
codersdk.ConnectionDirectionServerToAgent.SlogField(),
|
||||
reason.SlogField(),
|
||||
reason.SlogExpectedField(),
|
||||
initiator.SlogField(),
|
||||
slog.Error(retErr),
|
||||
)
|
||||
}()
|
||||
defer func() {
|
||||
cErr := coordinate.Close()
|
||||
if cErr != nil {
|
||||
@@ -1935,8 +1967,7 @@ func (a *agent) setCoordDisconnected() chan struct{} {
|
||||
}
|
||||
|
||||
// runDERPMapSubscriber runs a coordinator and returns if a reconnect should occur.
|
||||
func (a *agent) runDERPMapSubscriber(ctx context.Context, tClient tailnetproto.DRPCTailnetClient24, network *tailnet.Conn) error {
|
||||
defer a.logger.Debug(ctx, "disconnected from derp map RPC")
|
||||
func (a *agent) runDERPMapSubscriber(ctx context.Context, tClient tailnetproto.DRPCTailnetClient24, network *tailnet.Conn) (retErr error) {
|
||||
ctx, cancel := context.WithCancel(ctx)
|
||||
defer cancel()
|
||||
stream, err := tClient.StreamDERPMaps(ctx, &tailnetproto.StreamDERPMapsRequest{})
|
||||
@@ -1948,6 +1979,15 @@ func (a *agent) runDERPMapSubscriber(ctx context.Context, tClient tailnetproto.D
|
||||
if cErr != nil {
|
||||
a.logger.Debug(ctx, "error closing DERPMap stream", slog.Error(err))
|
||||
}
|
||||
|
||||
reason, initiator := classifyCoordinatorRPCExit(ctx, retErr)
|
||||
a.logger.Debug(ctx, "disconnected from derp map RPC",
|
||||
codersdk.ConnectionDirectionServerToAgent.SlogField(),
|
||||
reason.SlogField(),
|
||||
reason.SlogExpectedField(),
|
||||
initiator.SlogField(),
|
||||
slog.Error(retErr),
|
||||
)
|
||||
}()
|
||||
a.logger.Info(ctx, "connected to derp map RPC")
|
||||
for {
|
||||
@@ -2260,9 +2300,20 @@ lifecycleWaitLoop:
|
||||
// Wait for graceful disconnect from the Coordinator RPC
|
||||
select {
|
||||
case <-a.hardCtx.Done():
|
||||
a.logger.Warn(context.Background(), "timed out waiting for Coordinator RPC disconnect")
|
||||
a.logger.Warn(context.Background(), "timed out waiting for Coordinator RPC disconnect",
|
||||
codersdk.ConnectionDirectionServerToAgent.SlogField(),
|
||||
codersdk.DisconnectReasonServerShutdown.SlogField(),
|
||||
codersdk.DisconnectReasonServerShutdown.SlogExpectedField(),
|
||||
codersdk.DisconnectInitiatorAgent.SlogField(),
|
||||
codersdk.SlogDisconnectDetail("timed out waiting for coordinator RPC to disconnect"),
|
||||
)
|
||||
case <-coordDisconnected:
|
||||
a.logger.Debug(context.Background(), "coordinator RPC disconnected")
|
||||
a.logger.Debug(context.Background(), "coordinator RPC disconnected",
|
||||
codersdk.ConnectionDirectionServerToAgent.SlogField(),
|
||||
codersdk.DisconnectReasonServerShutdown.SlogField(),
|
||||
codersdk.DisconnectReasonServerShutdown.SlogExpectedField(),
|
||||
codersdk.DisconnectInitiatorAgent.SlogField(),
|
||||
)
|
||||
}
|
||||
|
||||
// Wait for logs to be sent
|
||||
|
||||
@@ -1,17 +1,20 @@
|
||||
package agent
|
||||
|
||||
import (
|
||||
"context"
|
||||
"path/filepath"
|
||||
"runtime"
|
||||
"testing"
|
||||
|
||||
"github.com/google/uuid"
|
||||
"github.com/stretchr/testify/require"
|
||||
"golang.org/x/xerrors"
|
||||
|
||||
"cdr.dev/slog/v3"
|
||||
"cdr.dev/slog/v3/sloggers/slogtest"
|
||||
"github.com/coder/coder/v2/agent/agentcontextconfig"
|
||||
"github.com/coder/coder/v2/agent/proto"
|
||||
"github.com/coder/coder/v2/codersdk"
|
||||
agentsdk "github.com/coder/coder/v2/codersdk/agentsdk"
|
||||
"github.com/coder/coder/v2/testutil"
|
||||
)
|
||||
@@ -86,3 +89,56 @@ func TestContextConfigAPI_InitOnce(t *testing.T) {
|
||||
require.NotEmpty(t, mcpFiles2)
|
||||
require.Contains(t, mcpFiles2[0], dir2)
|
||||
}
|
||||
|
||||
func TestClassifyCoordinatorRPCExit(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
canceled, cancel := context.WithCancel(context.Background())
|
||||
cancel()
|
||||
|
||||
cases := []struct {
|
||||
name string
|
||||
ctx context.Context
|
||||
retErr error
|
||||
reason codersdk.DisconnectReason
|
||||
initiator codersdk.DisconnectInitiator
|
||||
}{
|
||||
{
|
||||
name: "local shutdown, no error",
|
||||
ctx: canceled,
|
||||
retErr: nil,
|
||||
reason: codersdk.DisconnectReasonServerShutdown,
|
||||
initiator: codersdk.DisconnectInitiatorAgent,
|
||||
},
|
||||
{
|
||||
name: "local shutdown, with cleanup error",
|
||||
ctx: canceled,
|
||||
retErr: xerrors.New("close timed out"),
|
||||
reason: codersdk.DisconnectReasonServerShutdown,
|
||||
initiator: codersdk.DisconnectInitiatorAgent,
|
||||
},
|
||||
{
|
||||
name: "remote graceful, no error",
|
||||
ctx: context.Background(),
|
||||
retErr: nil,
|
||||
reason: codersdk.DisconnectReasonGraceful,
|
||||
initiator: codersdk.DisconnectInitiatorServer,
|
||||
},
|
||||
{
|
||||
name: "stream broke unexpectedly",
|
||||
ctx: context.Background(),
|
||||
retErr: xerrors.New("read: connection reset"),
|
||||
reason: codersdk.DisconnectReasonNetworkError,
|
||||
initiator: codersdk.DisconnectInitiatorNetwork,
|
||||
},
|
||||
}
|
||||
|
||||
for _, tc := range cases {
|
||||
t.Run(tc.name, func(t *testing.T) {
|
||||
t.Parallel()
|
||||
reason, initiator := classifyCoordinatorRPCExit(tc.ctx, tc.retErr)
|
||||
require.Equal(t, tc.reason, reason)
|
||||
require.Equal(t, tc.initiator, initiator)
|
||||
})
|
||||
}
|
||||
}
|
||||
|
||||
@@ -462,17 +462,23 @@ func (s *Server) sessionHandler(session ssh.Session) {
|
||||
logger.Warn(ctx, "invalid magic ssh session type specified", slog.F("raw_type", magicTypeRaw))
|
||||
}
|
||||
|
||||
closeCause := func(string) {}
|
||||
closeCause := func(_ string) {}
|
||||
if reportSession {
|
||||
var reason string
|
||||
closeCause = func(r string) { reason = r }
|
||||
var reason codersdk.DisconnectReason
|
||||
closeCause = func(r string) { reason = codersdk.DisconnectReason(r) }
|
||||
|
||||
scr := &sessionCloseTracker{Session: session}
|
||||
session = scr
|
||||
|
||||
disconnected := s.config.ReportConnection(id, magicType, remoteAddrString)
|
||||
defer func() {
|
||||
disconnected(scr.exitCode(), reason)
|
||||
logger.Info(ctx, "ssh session closed",
|
||||
codersdk.ConnectionDirectionAgentToClient.SlogField(),
|
||||
reason.SlogField(),
|
||||
reason.SlogExpectedField(),
|
||||
slog.F("exit_code", scr.exitCode()),
|
||||
)
|
||||
disconnected(scr.exitCode(), string(reason))
|
||||
}()
|
||||
}
|
||||
|
||||
@@ -567,6 +573,7 @@ func (s *Server) sessionHandler(session ssh.Session) {
|
||||
_ = session.Exit(MagicSessionErrorCode)
|
||||
return
|
||||
}
|
||||
closeCause(string(codersdk.DisconnectReasonGraceful))
|
||||
logger.Info(ctx, "normal ssh session exit")
|
||||
_ = session.Exit(0)
|
||||
}
|
||||
|
||||
@@ -11,6 +11,7 @@ import (
|
||||
gossh "golang.org/x/crypto/ssh"
|
||||
|
||||
"cdr.dev/slog/v3"
|
||||
"github.com/coder/coder/v2/codersdk"
|
||||
)
|
||||
|
||||
// localForwardChannelData is copied from the ssh package.
|
||||
@@ -85,9 +86,13 @@ func (w *JetbrainsChannelWatcher) Accept() (gossh.Channel, <-chan *gossh.Request
|
||||
Channel: c,
|
||||
done: func() {
|
||||
w.jetbrainsCounter.Add(-1)
|
||||
disconnected(0, "")
|
||||
disconnected(0, "normal close")
|
||||
// nolint: gocritic // JetBrains is a proper noun and should be capitalized
|
||||
w.logger.Debug(context.Background(), "JetBrains watcher channel closed")
|
||||
w.logger.Debug(context.Background(), "JetBrains channel closed",
|
||||
codersdk.ConnectionDirectionAgentToClient.SlogField(),
|
||||
codersdk.DisconnectReasonGraceful.SlogField(),
|
||||
codersdk.DisconnectReasonGraceful.SlogExpectedField(),
|
||||
)
|
||||
},
|
||||
}, r, err
|
||||
}
|
||||
|
||||
@@ -17,6 +17,7 @@ import (
|
||||
"github.com/coder/coder/v2/agent/agentcontainers"
|
||||
"github.com/coder/coder/v2/agent/agentssh"
|
||||
"github.com/coder/coder/v2/agent/usershell"
|
||||
"github.com/coder/coder/v2/codersdk"
|
||||
"github.com/coder/coder/v2/codersdk/workspacesdk"
|
||||
)
|
||||
|
||||
@@ -95,6 +96,11 @@ func (s *Server) Serve(ctx, hardCtx context.Context, l net.Listener) (retErr err
|
||||
select {
|
||||
case <-closed:
|
||||
case <-hardCtx.Done():
|
||||
clog.Info(hardCtx, "reconnecting pty closed",
|
||||
codersdk.ConnectionDirectionAgentToClient.SlogField(),
|
||||
codersdk.DisconnectReasonServerShutdown.SlogField(),
|
||||
codersdk.DisconnectReasonServerShutdown.SlogExpectedField(),
|
||||
)
|
||||
disconnected(1, "server shut down")
|
||||
_ = conn.Close()
|
||||
}
|
||||
@@ -104,15 +110,28 @@ func (s *Server) Serve(ctx, hardCtx context.Context, l net.Listener) (retErr err
|
||||
defer close(closed)
|
||||
defer wg.Done()
|
||||
err := s.handleConn(ctx, clog, conn)
|
||||
if err != nil {
|
||||
if ctx.Err() != nil {
|
||||
disconnected(1, "server shutting down")
|
||||
} else {
|
||||
disconnected(1, err.Error())
|
||||
}
|
||||
} else {
|
||||
disconnected(0, "")
|
||||
var reason codersdk.DisconnectReason
|
||||
var code int
|
||||
var detail string
|
||||
switch {
|
||||
case err != nil && ctx.Err() != nil:
|
||||
reason = codersdk.DisconnectReasonServerShutdown
|
||||
code = 1
|
||||
case err != nil:
|
||||
reason = codersdk.DisconnectReasonNetworkError
|
||||
detail = err.Error()
|
||||
code = 1
|
||||
default:
|
||||
reason = codersdk.DisconnectReasonGraceful
|
||||
}
|
||||
clog.Info(ctx, "reconnecting pty closed",
|
||||
codersdk.ConnectionDirectionAgentToClient.SlogField(),
|
||||
reason.SlogField(),
|
||||
reason.SlogExpectedField(),
|
||||
codersdk.SlogDisconnectDetail(detail),
|
||||
slog.F("exit_code", code),
|
||||
)
|
||||
disconnected(code, string(reason))
|
||||
}()
|
||||
}
|
||||
wg.Wait()
|
||||
|
||||
Reference in New Issue
Block a user