Skip to content

Commit 71fe073

Browse files
spikecurtisericpaulsen
spikecurtis
authored and
ericpaulsen
committed
feat: capture cli logs in tests (coder#10669)
Adds a Logger to cli Invocation and standardizes CLI commands to use it. clitest creates a test logger by default so that CLI command logs are captured in the test logs. CLI commands that do their own log configuration are modified to add sinks to the existing logger, rather than create a new one. This ensures we still capture logs in CLI tests.
1 parent 6ae0975 commit 71fe073

15 files changed

+38
-48
lines changed

‎cli/agent.go

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -116,7 +116,7 @@ func (r *RootCmd) workspaceAgent() *clibase.Cmd {
116116
defer logWriter.Close()
117117

118118
sinks = append(sinks, sloghuman.Sink(logWriter))
119-
logger := slog.Make(sinks...).Leveled(slog.LevelDebug)
119+
logger := inv.Logger.AppendSinks(sinks...).Leveled(slog.LevelDebug)
120120

121121
logger.Info(ctx, "spawning reaper process")
122122
// Do not start a reaper on the child process. It's important
@@ -159,7 +159,7 @@ func (r *RootCmd) workspaceAgent() *clibase.Cmd {
159159
defer logWriter.Close()
160160

161161
sinks = append(sinks, sloghuman.Sink(logWriter))
162-
logger := slog.Make(sinks...).Leveled(slog.LevelDebug)
162+
logger := inv.Logger.AppendSinks(sinks...).Leveled(slog.LevelDebug)
163163

164164
version := buildinfo.Version()
165165
logger.Info(ctx, "agent is starting now",

‎cli/agent_test.go

Lines changed: 11 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -20,7 +20,7 @@ import (
2020
"github.com/coder/coder/v2/coderd/database/dbfake"
2121
"github.com/coder/coder/v2/codersdk"
2222
"github.com/coder/coder/v2/provisionersdk/proto"
23-
"github.com/coder/coder/v2/pty/ptytest"
23+
"github.com/coder/coder/v2/testutil"
2424
)
2525

2626
func TestWorkspaceAgent(t *testing.T) {
@@ -44,17 +44,17 @@ func TestWorkspaceAgent(t *testing.T) {
4444
"--log-dir", logDir,
4545
)
4646

47-
pty := ptytest.New(t).Attach(inv)
48-
4947
clitest.Start(t, inv)
50-
ctx := inv.Context()
51-
pty.ExpectMatchContext(ctx, "agent is starting now")
5248

5349
coderdtest.AwaitWorkspaceAgents(t, client, ws.ID)
5450

55-
info, err := os.Stat(filepath.Join(logDir, "coder-agent.log"))
56-
require.NoError(t, err)
57-
require.Greater(t, info.Size(), int64(0))
51+
require.Eventually(t, func() bool {
52+
info, err := os.Stat(filepath.Join(logDir, "coder-agent.log"))
53+
if err != nil {
54+
return false
55+
}
56+
return info.Size() > 0
57+
}, testutil.WaitLong, testutil.IntervalMedium)
5858
})
5959

6060
t.Run("Azure", func(t *testing.T) {
@@ -84,6 +84,7 @@ func TestWorkspaceAgent(t *testing.T) {
8484
//nolint:revive,staticcheck
8585
context.WithValue(inv.Context(), "azure-client", metadataClient),
8686
)
87+
8788
ctx := inv.Context()
8889
clitest.Start(t, inv)
8990
coderdtest.AwaitWorkspaceAgents(t, client, ws.ID)
@@ -126,6 +127,7 @@ func TestWorkspaceAgent(t *testing.T) {
126127
//nolint:revive,staticcheck
127128
context.WithValue(inv.Context(), "aws-client", metadataClient),
128129
)
130+
129131
clitest.Start(t, inv)
130132
ctx := inv.Context()
131133
coderdtest.AwaitWorkspaceAgents(t, client, ws.ID)
@@ -164,8 +166,8 @@ func TestWorkspaceAgent(t *testing.T) {
164166
}},
165167
})
166168
inv, cfg := clitest.New(t, "agent", "--auth", "google-instance-identity", "--agent-url", client.URL.String())
167-
ptytest.New(t).Attach(inv)
168169
clitest.SetupConfig(t, member, cfg)
170+
169171
clitest.Start(t,
170172
inv.WithContext(
171173
//nolint:revive,staticcheck
@@ -223,10 +225,7 @@ func TestWorkspaceAgent(t *testing.T) {
223225
// Set the subsystems for the agent.
224226
inv.Environ.Set(agent.EnvAgentSubsystem, fmt.Sprintf("%s,%s", codersdk.AgentSubsystemExectrace, codersdk.AgentSubsystemEnvbox))
225227

226-
pty := ptytest.New(t).Attach(inv)
227-
228228
clitest.Start(t, inv)
229-
pty.ExpectMatchContext(inv.Context(), "agent is starting now")
230229

231230
resources := coderdtest.AwaitWorkspaceAgents(t, client, ws.ID)
232231
require.Len(t, resources, 1)

‎cli/clibase/cmd.go

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -12,6 +12,8 @@ import (
1212
"testing"
1313
"unicode"
1414

15+
"cdr.dev/slog"
16+
1517
"github.com/spf13/pflag"
1618
"golang.org/x/exp/slices"
1719
"golang.org/x/xerrors"
@@ -170,6 +172,7 @@ func (c *Cmd) Invoke(args ...string) *Invocation {
170172
Stdout: io.Discard,
171173
Stderr: io.Discard,
172174
Stdin: strings.NewReader(""),
175+
Logger: slog.Make(),
173176
}
174177
}
175178

@@ -185,6 +188,7 @@ type Invocation struct {
185188
Stdout io.Writer
186189
Stderr io.Writer
187190
Stdin io.Reader
191+
Logger slog.Logger
188192

189193
// testing
190194
signalNotifyContext func(parent context.Context, signals ...os.Signal) (ctx context.Context, stop context.CancelFunc)

‎cli/clitest/clitest.go

Lines changed: 6 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -59,13 +59,18 @@ func NewWithCommand(
5959
t testing.TB, cmd *clibase.Cmd, args ...string,
6060
) (*clibase.Invocation, config.Root) {
6161
configDir := config.Root(t.TempDir())
62-
logger := slogtest.Make(t, nil)
62+
// I really would like to fail test on error logs, but realistically, turning on by default
63+
// in all our CLI tests is going to create a lot of flaky noise.
64+
logger := slogtest.Make(t, &slogtest.Options{IgnoreErrors: true}).
65+
Leveled(slog.LevelDebug).
66+
Named("cli")
6367
i := &clibase.Invocation{
6468
Command: cmd,
6569
Args: append([]string{"--global-config", string(configDir)}, args...),
6670
Stdin: io.LimitReader(nil, 0),
6771
Stdout: (&logWriter{prefix: "stdout", log: logger}),
6872
Stderr: (&logWriter{prefix: "stderr", log: logger}),
73+
Logger: logger,
6974
}
7075
t.Logf("invoking command: %s %s", cmd.Name(), strings.Join(i.Args, " "))
7176

‎cli/exp_scaletest.go

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -882,7 +882,7 @@ func (r *RootCmd) scaletestWorkspaceTraffic() *clibase.Cmd {
882882
reg := prometheus.NewRegistry()
883883
metrics := workspacetraffic.NewMetrics(reg, "username", "workspace_name", "agent_name")
884884

885-
logger := slog.Make(sloghuman.Sink(io.Discard))
885+
logger := inv.Logger
886886
prometheusSrvClose := ServeHandler(ctx, logger, promhttp.HandlerFor(reg, promhttp.HandlerOpts{}), prometheusFlags.Address, "prometheus")
887887
defer prometheusSrvClose()
888888

@@ -1075,7 +1075,7 @@ func (r *RootCmd) scaletestDashboard() *clibase.Cmd {
10751075
return xerrors.Errorf("--jitter must be less than --interval")
10761076
}
10771077
ctx := inv.Context()
1078-
logger := slog.Make(sloghuman.Sink(inv.Stdout)).Leveled(slog.LevelInfo)
1078+
logger := inv.Logger.AppendSinks(sloghuman.Sink(inv.Stdout))
10791079
if r.verbose {
10801080
logger = logger.Leveled(slog.LevelDebug)
10811081
}

‎cli/ping.go

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -46,9 +46,9 @@ func (r *RootCmd) ping() *clibase.Cmd {
4646
return err
4747
}
4848

49-
var logger slog.Logger
49+
logger := inv.Logger
5050
if r.verbose {
51-
logger = slog.Make(sloghuman.Sink(inv.Stdout)).Leveled(slog.LevelDebug)
51+
logger = logger.AppendSinks(sloghuman.Sink(inv.Stdout)).Leveled(slog.LevelDebug)
5252
}
5353

5454
if r.disableDirect {

‎cli/portforward.go

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -98,9 +98,9 @@ func (r *RootCmd) portForward() *clibase.Cmd {
9898
return xerrors.Errorf("await agent: %w", err)
9999
}
100100

101-
logger := slog.Make()
101+
logger := inv.Logger
102102
if r.verbose {
103-
logger = slog.Make(sloghuman.Sink(inv.Stdout)).Leveled(slog.LevelDebug)
103+
logger = logger.AppendSinks(sloghuman.Sink(inv.Stdout)).Leveled(slog.LevelDebug)
104104
}
105105

106106
if r.disableDirect {

‎cli/root.go

Lines changed: 0 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -30,7 +30,6 @@ import (
3030

3131
"github.com/coder/pretty"
3232

33-
"cdr.dev/slog"
3433
"github.com/coder/coder/v2/buildinfo"
3534
"github.com/coder/coder/v2/cli/clibase"
3635
"github.com/coder/coder/v2/cli/cliui"
@@ -442,21 +441,6 @@ func (r *RootCmd) Command(subcommands []*clibase.Cmd) (*clibase.Cmd, error) {
442441
return cmd, nil
443442
}
444443

445-
type contextKey int
446-
447-
const (
448-
contextKeyLogger contextKey = iota
449-
)
450-
451-
func ContextWithLogger(ctx context.Context, l slog.Logger) context.Context {
452-
return context.WithValue(ctx, contextKeyLogger, l)
453-
}
454-
455-
func LoggerFromContext(ctx context.Context) (slog.Logger, bool) {
456-
l, ok := ctx.Value(contextKeyLogger).(slog.Logger)
457-
return l, ok
458-
}
459-
460444
// RootCmd contains parameters and helpers useful to all commands.
461445
type RootCmd struct {
462446
clientURL *url.URL

‎cli/server.go

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1092,7 +1092,7 @@ func (r *RootCmd) Server(newAPI func(context.Context, *coderd.Options) (*coderd.
10921092
ctx := inv.Context()
10931093

10941094
cfg := r.createConfig()
1095-
logger := slog.Make(sloghuman.Sink(inv.Stderr))
1095+
logger := inv.Logger.AppendSinks(sloghuman.Sink(inv.Stderr))
10961096
if ok, _ := inv.ParsedFlags().GetBool(varVerbose); ok {
10971097
logger = logger.Leveled(slog.LevelDebug)
10981098
}
@@ -2063,7 +2063,7 @@ func BuildLogger(inv *clibase.Invocation, cfg *codersdk.DeploymentValues) (slog.
20632063
level = slog.LevelDebug
20642064
}
20652065

2066-
return slog.Make(filter).Leveled(level), func() {
2066+
return inv.Logger.AppendSinks(filter).Leveled(level), func() {
20672067
for _, closer := range closers {
20682068
_ = closer()
20692069
}

‎cli/server_createadminuser.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -42,7 +42,7 @@ func (r *RootCmd) newCreateAdminUserCommand() *clibase.Cmd {
4242
}
4343

4444
cfg := r.createConfig()
45-
logger := slog.Make(sloghuman.Sink(inv.Stderr))
45+
logger := inv.Logger.AppendSinks(sloghuman.Sink(inv.Stderr))
4646
if r.verbose {
4747
logger = logger.Leveled(slog.LevelDebug)
4848
}

‎cli/speedtest.go

Lines changed: 1 addition & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -48,10 +48,7 @@ func (r *RootCmd) speedtest() *clibase.Cmd {
4848
return xerrors.Errorf("await agent: %w", err)
4949
}
5050

51-
logger, ok := LoggerFromContext(ctx)
52-
if !ok {
53-
logger = slog.Make(sloghuman.Sink(inv.Stderr))
54-
}
51+
logger := inv.Logger.AppendSinks(sloghuman.Sink(inv.Stderr))
5552
if r.verbose {
5653
logger = logger.Leveled(slog.LevelDebug)
5754
}

‎cli/speedtest_test.go

Lines changed: 1 addition & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -10,7 +10,6 @@ import (
1010
"cdr.dev/slog"
1111
"cdr.dev/slog/sloggers/slogtest"
1212
"github.com/coder/coder/v2/agent/agenttest"
13-
"github.com/coder/coder/v2/cli"
1413
"github.com/coder/coder/v2/cli/clitest"
1514
"github.com/coder/coder/v2/coderd/coderdtest"
1615
"github.com/coder/coder/v2/codersdk"
@@ -50,7 +49,7 @@ func TestSpeedtest(t *testing.T) {
5049
ctx, cancel = context.WithTimeout(context.Background(), testutil.WaitLong)
5150
defer cancel()
5251

53-
ctx = cli.ContextWithLogger(ctx, slogtest.Make(t, nil).Named("speedtest").Leveled(slog.LevelDebug))
52+
inv.Logger = slogtest.Make(t, nil).Named("speedtest").Leveled(slog.LevelDebug)
5453
cmdDone := tGo(t, func() {
5554
err := inv.WithContext(ctx).Run()
5655
assert.NoError(t, err)

‎cli/ssh.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -74,7 +74,7 @@ func (r *RootCmd) ssh() *clibase.Cmd {
7474
ctx, cancel := context.WithCancel(ctx)
7575
defer cancel()
7676

77-
logger := slog.Make() // empty logger
77+
logger := inv.Logger
7878
defer func() {
7979
if retErr != nil {
8080
// catch and log all returned errors so we see them in the

‎cli/ssh_test.go

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -215,6 +215,7 @@ func TestSSH(t *testing.T) {
215215
inv.Stdin = clientOutput
216216
inv.Stdout = serverInput
217217
inv.Stderr = io.Discard
218+
218219
cmdDone := tGo(t, func() {
219220
err := inv.WithContext(ctx).Run()
220221
assert.NoError(t, err)
@@ -390,6 +391,7 @@ func TestSSH(t *testing.T) {
390391
inv.Stdin = clientOutput
391392
inv.Stdout = serverInput
392393
inv.Stderr = io.Discard
394+
393395
cmdDone := tGo(t, func() {
394396
err := inv.WithContext(ctx).Run()
395397
assert.NoError(t, err)

‎cli/vscodessh.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -138,7 +138,7 @@ func (r *RootCmd) vscodeSSH() *clibase.Cmd {
138138
// command via the ProxyCommand SSH option.
139139
pid := os.Getppid()
140140

141-
logger := slog.Make()
141+
logger := inv.Logger
142142
if logDir != "" {
143143
logFilePath := filepath.Join(logDir, fmt.Sprintf("%d.log", pid))
144144
logFile, err := fs.OpenFile(logFilePath, os.O_CREATE|os.O_WRONLY, 0o600)

0 commit comments

Comments
 (0)