Files
coder/cli/flightrecorder_internal_test.go
T
Andrew Aquino 4a67ac3306 feat: buffer CLI session logs and flush on connection failure (#29752)
## What

Adds in-memory log buffering for CLI diagnostics so the debug detail
leading up to a failure is available without logging debug during normal
operation. Below-level entries are kept in a slog flight recorder
(`v3.2.0`) and emitted only when a command returns an error. This
implements CLI-4 (connection-log RFC req 13). Depends on the
`cdr.dev/slog/v3` `v3.2.0` bump (already on `main`).

## How

- **Root command** (`cli/root.go`):
- New global `--log-buffer-size` / `CODER_LOG_BUFFER_SIZE` (default
`10`, `0` disables, clamped to `10000`), shared by all commands instead
of duplicated per command.
- `bufferedLoggerMiddleware` runs the invocation logger at `Info` (or
`Debug` with `-v`) with a flight recorder, and on a returned error calls
`Flush` to replay the buffered history to stderr. `Flush` does not add a
duplicate error line; the returned error is still rendered by the normal
formatter.
- Opt-in via an `annotationBufferedLogger` annotation so it does not
clobber the ~17 commands that build their own logger on `inv.Logger`
(which would otherwise double-log). Future commands opt in with one
line.
- `start` / `stop` / `update`: opt into the middleware and just
`client.SetLogger(inv.Logger)` so codersdk request/response debug is
captured and flushed to stderr on failure. They **no longer write
session log files** and dropped their per-command `--log-dir` /
`--log-buffer-size`.
- `ssh`: keeps its own file logger (writing to stderr would corrupt its
stdio stream), now using the global buffer size and the shared
`bufferedLogger` helper. It retains `--log-dir` / `CODER_SSH_LOG_DIR`,
stdio/PID filename handling, and file pruning (50 most recent).
- `restart` is excluded, matching the `client_session_id` opt-in set
(DEVEX-664).

## Default behavior change

`start` / `stop` / `update` now emit buffered diagnostics (recent
below-level entries, e.g. sdk request/response) to **stderr** when they
fail; on success they stay quiet. `coder ssh` continues to write a
per-connection diagnostic file by default under the XDG state dir
(`~/.local/state/coder/logs`), pruned to the 50 most recent. Opt out of
buffering with `--log-buffer-size 0`.

## Review changes (Asher)

- Shared logger construction: the level is computed once and the flight
recorder is always attached, in a single `bufferedLogger` helper used by
ssh and the workspace commands.
- Workspace commands print to normal output instead of a log file, and
the default buffer is `10` to avoid flooding the terminal on failure.
- The buffer lives on the root command / logger (global option +
middleware) rather than being wired into each command.

## Alignment with #29671 (agent)

Same core model: `Info` default with a flight recorder, `-v` for full
debug, and the shared `--log-buffer-size` semantics (`0` disables).
Differences: the agent writes to a file and defaults the buffer to
`1000`, while the CLI prints to stderr and defaults to `10`; both now
rely on slog's auto-flush-on-error (the CLI additionally flushes via the
middleware on a returned error).

> [!NOTE]
> The agent PR (#29671) adds an agent-scoped `--log-buffer-size` /
`CODER_AGENT_LOG_BUFFER_SIZE` on the hidden `coder agent` command. Once
both land, the global `--log-buffer-size` here and the agent's own flag
will need reconciling on `coder agent`. Flagging for whichever merges
second.

## Testing

`cli.TestClampLogBufferSize`, `TestPruneSessionLogs`,
`TestDefaultSessionLogDir`, and `TestBufferedLogger_*` cover clamping,
ssh log retention, the default state dir, buffer-until-error, the
middleware's flush path, and the verbose escape hatch.
`start`/`stop`/`update`/`ssh` command tests pass. Golden `--help` output
and `docs/reference/cli` regenerated. (`TestSSH/Env` is a pre-existing
interactive-PTY test that does not run in all sandboxes; it fails
identically on `main` here.)

<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) -> CLIENT-672 (agent,
#29671) and this PR (CLI-4), which are independent consumers and can
merge in any order.
</details>

---
<sub>Opened by Coder Agents on behalf of @aqandrew.</sub>
2026-09-29 22:27:30 +00:00

158 lines
4.4 KiB
Go

package cli
import (
"bytes"
"context"
"fmt"
"os"
"path/filepath"
"runtime"
"strings"
"testing"
"time"
"github.com/stretchr/testify/require"
"cdr.dev/slog/v3"
"cdr.dev/slog/v3/sloggers/sloghuman"
)
func TestClampFlightRecorderSize(t *testing.T) {
t.Parallel()
cases := []struct {
in int64
want int64
}{
{in: -1, want: 0},
{in: 0, want: 0},
{in: 1000, want: 1000},
{in: maxCLIFlightRecorderSize, want: maxCLIFlightRecorderSize},
{in: maxCLIFlightRecorderSize + 1, want: maxCLIFlightRecorderSize},
}
for _, c := range cases {
require.Equal(t, c.want, clampFlightRecorderSize(c.in))
}
}
func TestPruneSessionLogs(t *testing.T) {
t.Parallel()
dir := t.TempDir()
base := time.Now()
const total = 55
for i := 0; i < total; i++ {
path := filepath.Join(dir, fmt.Sprintf("coder-ssh-%03d.log", i))
require.NoError(t, os.WriteFile(path, []byte("x"), 0o600))
// Older index => older modtime, so the highest indexes are newest.
modTime := base.Add(time.Duration(i) * time.Minute)
require.NoError(t, os.Chtimes(path, modTime, modTime))
}
// A non-matching file should never be pruned.
other := filepath.Join(dir, "unrelated.txt")
require.NoError(t, os.WriteFile(other, []byte("x"), 0o600))
pruneErr := pruneSessionLogs(dir, keepSessionLogFiles)
require.NoError(t, pruneErr)
remaining, err := filepath.Glob(filepath.Join(dir, "coder-*.log"))
require.NoError(t, err)
require.Len(t, remaining, keepSessionLogFiles)
// The oldest (lowest index) files were removed; the newest were kept.
require.NoFileExists(t, filepath.Join(dir, "coder-ssh-000.log"))
require.FileExists(t, filepath.Join(dir, fmt.Sprintf("coder-ssh-%03d.log", total-1)))
require.FileExists(t, other)
}
func TestPruneSessionLogs_ReturnsRemoveErrors(t *testing.T) {
t.Parallel()
if runtime.GOOS == "windows" {
t.Skip("a read-only directory does not prevent file removal on Windows, so os.Remove would not fail")
}
if os.Geteuid() == 0 {
t.Skip("root ignores directory permissions, so os.Remove would not fail")
}
dir := t.TempDir()
base := time.Now()
const total = 3
for i := 0; i < total; i++ {
path := filepath.Join(dir, fmt.Sprintf("coder-ssh-%03d.log", i))
require.NoError(t, os.WriteFile(path, []byte("x"), 0o600))
modTime := base.Add(time.Duration(i) * time.Minute)
require.NoError(t, os.Chtimes(path, modTime, modTime))
}
// Removing a file requires write permission on the containing directory, so a
// read-only dir forces os.Remove to fail. Restore perms before t.TempDir's
// cleanup (which runs after this LIFO-ordered cleanup) tries to remove it.
require.NoError(t, os.Chmod(dir, 0o500))
t.Cleanup(func() { _ = os.Chmod(dir, 0o700) })
err := pruneSessionLogs(dir, 1)
require.Error(t, err, "prune should return the remove failures")
}
func TestDefaultSessionLogDir(t *testing.T) {
t.Parallel()
require.True(t, strings.HasSuffix(
filepath.ToSlash(defaultSessionLogDir()), "coder/logs"),
"got %q", defaultSessionLogDir())
}
func TestFlightRecorder_RecordsUntilError(t *testing.T) {
t.Parallel()
var buf bytes.Buffer
r := &RootCmd{}
logger := r.flightRecorder(slog.Make(), sloghuman.Sink(&buf), 10)
ctx := context.Background()
logger.Debug(ctx, "recorded-debug")
logger.Sync()
require.NotContains(t, buf.String(), "recorded-debug",
"debug entry should be recorded, not written")
// Logging an error flushes the recorded history before the error entry.
logger.Error(ctx, "command failed for test")
logger.Sync()
got := buf.String()
require.Contains(t, got, "recorded-debug")
require.Contains(t, got, "command failed for test")
}
func TestFlightRecorder_FlushEmitsHistory(t *testing.T) {
t.Parallel()
// Flush is the path flightRecorderMiddleware uses to emit the recorded
// history on a returned error without logging a duplicate error line.
var buf bytes.Buffer
r := &RootCmd{}
logger := r.flightRecorder(slog.Make(), sloghuman.Sink(&buf), 10)
ctx := context.Background()
logger.Debug(ctx, "recorded-debug")
logger.Sync()
require.NotContains(t, buf.String(), "recorded-debug")
logger.Flush(ctx)
logger.Sync()
require.Contains(t, buf.String(), "recorded-debug")
}
func TestFlightRecorder_VerboseWritesDebug(t *testing.T) {
t.Parallel()
var buf bytes.Buffer
r := &RootCmd{verbose: true}
logger := r.flightRecorder(slog.Make(), sloghuman.Sink(&buf), 10)
logger.Debug(context.Background(), "verbose-debug")
logger.Sync()
require.Contains(t, buf.String(), "verbose-debug",
"verbose should write debug entries directly")
}