Files
coder/cli/agent_test.go
T
Andrew Aquino 6487425885 feat: buffer agent debug logs and flush on connection failure (#29671)
## What

Runs the workspace agent logger at `Info` with a slog flight recorder
(`v3.2.0`) instead of unconditionally at `Debug`. Entries below the
current log level are kept in a rolling in-memory ring and flushed to
the sinks when the agent loses its connection to coderd (and before any
`Error`+ log), so the detail leading up to a failure is available
without writing debug logs during normal operation.

Implements CLIENT-672 (connection-log RFC req 13) for the workspace
agent. Depends on the `cdr.dev/slog/v3` `v3.2.0` bump (already on
`main`).

## How

- `cli/agent.go`:
- The main agent logger is
`AppendSinks(...).Leveled(level).FlightRecorder(flightRecorderSize)`,
where `level` is `Info` by default and `Debug` under the global `-v` /
`CODER_VERBOSE`. The recorder is always attached; at `Debug` it is
inert, which keeps the setup correct if the configured level changes in
the future. The reaper logger is unchanged.
- New `--agent-flight-recorder-size` /
`CODER_AGENT_FLIGHT_RECORDER_SIZE` (default `1000`, `0` disables the
flight recorder), so the ring size is configurable per RFC req 13. The
agent flag is distinct from CLI-4's global `--flight-recorder-size`
(#29752) so the two don't collide when `coder agent` inherits the root
global.
- `workspaceAgent` is a `RootCmd` method so it reuses the root command's
global verbose flag instead of defining an agent-specific one.
- `agent/agent.go` (`runLoop`): on a lost coderd connection (the
`io.EOF` disconnect and the generic run error) the agent calls
`logger.Flush(ctx)` to emit the recorded history and then logs at
`Warn`. These are `Warn` rather than `Error` because reconnectable
disconnects are expected and `slogtest` fails tests on any `Error` log;
the manual flush is what surfaces the recorded detail. Graceful shutdown
paths (`ctx` canceled, agent closed) are not flushed.
- Tests: `agent.TestAgent_FlushFlightRecorderOnDisconnect` covers the
flush-on-disconnect path; `cli.TestWorkspaceAgent/DisabledServers` runs
with verbose since its debug messages are otherwise recorded. Golden
`--help` output regenerated.

## Default log verbosity change

This changes the default agent-log verbosity. Today `coder-agent.log`
receives `Debug` unconditionally; with this change, normal operation
logs `Info`, and recorded below-level entries are emitted only when the
agent loses its coderd connection (via a manual flush) or before any
`Error`+ log, or always under `-v` / `CODER_VERBOSE`. This is the
intended behavior of the feature: a quiet steady state with full detail
retained for diagnosing failures. Operators who want the previous
always-debug output can run with `-v` / `CODER_VERBOSE`.

## Alignment with #29752 (CLI)

This mirrors the CLI-4 (CLI log buffer) design so the two
implementations agree:

- **Level model:** Info by default, debug available on demand via the
global `-v` / `CODER_VERBOSE`.
- **Flight recorder size:** default `1000`, `0` disables. CLI-4 exposes
a global `--flight-recorder-size`; the agent uses a distinct
`--agent-flight-recorder-size` / `CODER_AGENT_FLIGHT_RECORDER_SIZE` (the
`CODER_AGENT_*` env convention) so the inherited global and the agent
flag coexist without collision.
- **Flush trigger:** the recorded history is emitted before any `Error`+
log via slog's auto-flush. The agent additionally flushes manually on a
lost coderd connection, which it logs at `Warn` (reconnectable, and
`Error` would fail `slogtest`-based tests); the CLI's failures are
fatal, so it relies on the auto-flush-on-error.

<details>
<summary>Rollout context</summary>

Cross-repo sequence: coder/slog flight recorder (released as v3.2.0) ->
go.mod bump in coder/coder (#29600, merged) -> this PR (CLIENT-672,
agent) and CLI-4 (CLI), which are independent consumers and can merge in
any order.
</details>

---
<sub>Opened by Coder Agents on behalf of @aqandrew.</sub>
2026-09-29 14:24:00 -07:00

260 lines
7.7 KiB
Go

package cli_test
import (
"fmt"
"net/http"
"os"
"path/filepath"
"runtime"
"strings"
"sync/atomic"
"testing"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
"github.com/coder/coder/v2/agent"
"github.com/coder/coder/v2/cli/clitest"
"github.com/coder/coder/v2/coderd"
"github.com/coder/coder/v2/coderd/coderdtest"
"github.com/coder/coder/v2/coderd/database"
"github.com/coder/coder/v2/coderd/database/dbfake"
"github.com/coder/coder/v2/codersdk"
"github.com/coder/coder/v2/testutil"
)
func TestWorkspaceAgent(t *testing.T) {
t.Parallel()
t.Run("LogDirectory", func(t *testing.T) {
t.Parallel()
client, db := coderdtest.NewWithDatabase(t, nil)
user := coderdtest.CreateFirstUser(t, client)
r := dbfake.WorkspaceBuild(t, db, database.WorkspaceTable{
OrganizationID: user.OrganizationID,
OwnerID: user.UserID,
}).
WithAgent().
Do()
logDir := t.TempDir()
inv, _ := clitest.New(t,
"agent",
"--auth", "token",
"--agent-token", r.AgentToken,
"--agent-url", client.URL.String(),
"--log-dir", logDir,
"--socket-path", testutil.AgentSocketPath(t),
)
clitest.Start(t, inv)
coderdtest.AwaitWorkspaceAgents(t, client, r.Workspace.ID)
require.Eventually(t, func() bool {
info, err := os.Stat(filepath.Join(logDir, "coder-agent.log"))
if err != nil {
return false
}
return info.Size() > 0
}, testutil.WaitLong, testutil.IntervalMedium)
})
t.Run("PostStartup", func(t *testing.T) {
t.Parallel()
client, db := coderdtest.NewWithDatabase(t, nil)
user := coderdtest.CreateFirstUser(t, client)
r := dbfake.WorkspaceBuild(t, db, database.WorkspaceTable{
OrganizationID: user.OrganizationID,
OwnerID: user.UserID,
}).WithAgent().Do()
logDir := t.TempDir()
inv, _ := clitest.New(t,
"agent",
"--auth", "token",
"--agent-token", r.AgentToken,
"--agent-url", client.URL.String(),
"--log-dir", logDir,
"--socket-path", testutil.AgentSocketPath(t),
)
// Set the subsystems for the agent.
inv.Environ.Set(agent.EnvAgentSubsystem, fmt.Sprintf("%s,%s", codersdk.AgentSubsystemExectrace, codersdk.AgentSubsystemEnvbox))
clitest.Start(t, inv)
resources := coderdtest.NewWorkspaceAgentWaiter(t, client, r.Workspace.ID).
MatchResources(matchAgentWithSubsystems).Wait()
require.Len(t, resources, 1)
require.Len(t, resources[0].Agents, 1)
require.Len(t, resources[0].Agents[0].Subsystems, 2)
// Sorted
require.Equal(t, codersdk.AgentSubsystemEnvbox, resources[0].Agents[0].Subsystems[0])
require.Equal(t, codersdk.AgentSubsystemExectrace, resources[0].Agents[0].Subsystems[1])
})
t.Run("Headers&DERPHeaders", func(t *testing.T) {
t.Parallel()
// Create a coderd API instance the hard way since we need to change the
// handler to inject our custom /derp handler.
dv := coderdtest.DeploymentValues(t)
dv.DERP.Config.BlockDirect = true
setHandler, cancelFunc, serverURL, newOptions := coderdtest.NewOptions(t, &coderdtest.Options{
DeploymentValues: dv,
})
// We set the handler after server creation for the access URL.
coderAPI := coderd.New(newOptions)
setHandler(coderAPI.RootHandler)
provisionerCloser := coderdtest.NewProvisionerDaemon(t, coderAPI)
t.Cleanup(func() {
_ = provisionerCloser.Close()
})
client := codersdk.New(serverURL, codersdk.WithHTTPClient(coderdtest.NewIsolatedHTTPClient(serverURL)))
t.Cleanup(func() {
cancelFunc()
_ = provisionerCloser.Close()
_ = coderAPI.Close()
client.HTTPClient.CloseIdleConnections()
})
var (
admin = coderdtest.CreateFirstUser(t, client)
member, memberUser = coderdtest.CreateAnotherUser(t, client, admin.OrganizationID)
called atomic.Int64
derpCalled atomic.Int64
)
setHandler(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
// Ignore client requests
if r.Header.Get("X-Testing") == "agent" {
assert.Equal(t, "Ethan was Here!", r.Header.Get("Cool-Header"))
assert.Equal(t, "very-wow-"+client.URL.String(), r.Header.Get("X-Process-Testing"))
assert.Equal(t, "more-wow", r.Header.Get("X-Process-Testing2"))
if strings.HasPrefix(r.URL.Path, "/derp") {
derpCalled.Add(1)
} else {
called.Add(1)
}
}
coderAPI.RootHandler.ServeHTTP(w, r)
}))
r := dbfake.WorkspaceBuild(t, coderAPI.Database, database.WorkspaceTable{
OrganizationID: memberUser.OrganizationIDs[0],
OwnerID: memberUser.ID,
}).WithAgent().Do()
coderURLEnv := "$CODER_URL"
if runtime.GOOS == "windows" {
coderURLEnv = "%CODER_URL%"
}
logDir := t.TempDir()
agentInv, _ := clitest.New(t,
"agent",
"--auth", "token",
"--agent-token", r.AgentToken,
"--agent-url", client.URL.String(),
"--log-dir", logDir,
"--agent-header", "X-Testing=agent",
"--agent-header", "Cool-Header=Ethan was Here!",
"--agent-header-command", "printf X-Process-Testing=very-wow-"+coderURLEnv+"'\\r\\n'X-Process-Testing2=more-wow",
"--socket-path", testutil.AgentSocketPath(t),
)
clitest.Start(t, agentInv)
coderdtest.NewWorkspaceAgentWaiter(t, client, r.Workspace.ID).
MatchResources(matchAgentWithVersion).Wait()
ctx := testutil.Context(t, testutil.WaitLong)
clientInv, root := clitest.New(t,
"-v",
"--no-feature-warning",
"--no-version-warning",
"ping", r.Workspace.Name,
"-n", "1",
)
clitest.SetupConfig(t, member, root)
err := clientInv.WithContext(ctx).Run()
require.NoError(t, err)
require.Greater(t, called.Load(), int64(0), "expected coderd to be reached with custom headers")
require.Greater(t, derpCalled.Load(), int64(0), "expected /derp to be called with custom headers")
})
t.Run("DisabledServers", func(t *testing.T) {
t.Parallel()
client, db := coderdtest.NewWithDatabase(t, nil)
user := coderdtest.CreateFirstUser(t, client)
r := dbfake.WorkspaceBuild(t, db, database.WorkspaceTable{
OrganizationID: user.OrganizationID,
OwnerID: user.UserID,
}).WithAgent().Do()
logDir := t.TempDir()
inv, _ := clitest.New(t,
"agent",
"--auth", "token",
"--agent-token", r.AgentToken,
"--agent-url", client.URL.String(),
"--log-dir", logDir,
// The disabled-server messages are logged at debug. Run verbose so
// they are written to the log file instead of recorded in memory.
"--verbose",
"--pprof-address", "",
"--prometheus-address", "",
"--debug-address", "",
"--socket-path", testutil.AgentSocketPath(t),
)
clitest.Start(t, inv)
// Verify the agent is connected and working.
resources := coderdtest.NewWorkspaceAgentWaiter(t, client, r.Workspace.ID).
MatchResources(matchAgentWithVersion).Wait()
require.Len(t, resources, 1)
require.Len(t, resources[0].Agents, 1)
require.NotEmpty(t, resources[0].Agents[0].Version)
// Verify the servers are not listening by checking the log for disabled
// messages.
require.Eventually(t, func() bool {
logContent, err := os.ReadFile(filepath.Join(logDir, "coder-agent.log"))
if err != nil {
return false
}
logStr := string(logContent)
return strings.Contains(logStr, "pprof address is empty, disabling pprof server") &&
strings.Contains(logStr, "prometheus address is empty, disabling prometheus server") &&
strings.Contains(logStr, "debug address is empty, disabling debug server")
}, testutil.WaitLong, testutil.IntervalMedium)
})
}
func matchAgentWithVersion(rs []codersdk.WorkspaceResource) bool {
if len(rs) < 1 {
return false
}
if len(rs[0].Agents) < 1 {
return false
}
if rs[0].Agents[0].Version == "" {
return false
}
return true
}
func matchAgentWithSubsystems(rs []codersdk.WorkspaceResource) bool {
if len(rs) < 1 {
return false
}
if len(rs[0].Agents) < 1 {
return false
}
if len(rs[0].Agents[0].Subsystems) < 1 {
return false
}
return true
}