Skip to content

Commit bea860d

Browse files
spikecurtisspikecurtis
committed
feat: capture cli logs in tests
1 parent 31c8047 commit bea860d

15 files changed

+53
-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: 22 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,11 @@ import (
99
"strings"
1010
"testing"
1111

12+
"cdr.dev/slog"
13+
"cdr.dev/slog/sloggers/slogtest"
14+
15+
"github.com/coder/coder/v2/testutil"
16+
1217
"github.com/google/uuid"
1318
"github.com/stretchr/testify/assert"
1419
"github.com/stretchr/testify/require"
@@ -20,7 +25,6 @@ import (
2025
"github.com/coder/coder/v2/coderd/database/dbfake"
2126
"github.com/coder/coder/v2/codersdk"
2227
"github.com/coder/coder/v2/provisionersdk/proto"
23-
"github.com/coder/coder/v2/pty/ptytest"
2428
)
2529

2630
func TestWorkspaceAgent(t *testing.T) {
@@ -44,17 +48,19 @@ func TestWorkspaceAgent(t *testing.T) {
4448
"--log-dir", logDir,
4549
)
4650

47-
pty := ptytest.New(t).Attach(inv)
48-
51+
// agent hits errors binding to ports for pprof, prometheus, etc., that don't affect the test
52+
inv.Logger = slogtest.Make(t, &slogtest.Options{IgnoreErrors: true}).Leveled(slog.LevelDebug)
4953
clitest.Start(t, inv)
50-
ctx := inv.Context()
51-
pty.ExpectMatchContext(ctx, "agent is starting now")
5254

5355
coderdtest.AwaitWorkspaceAgents(t, client, ws.ID)
5456

55-
info, err := os.Stat(filepath.Join(logDir, "coder-agent.log"))
56-
require.NoError(t, err)
57-
require.Greater(t, info.Size(), int64(0))
57+
require.Eventually(t, func() bool {
58+
info, err := os.Stat(filepath.Join(logDir, "coder-agent.log"))
59+
if err != nil {
60+
return false
61+
}
62+
return info.Size() > 0
63+
}, testutil.WaitLong, testutil.IntervalMedium)
5864
})
5965

6066
t.Run("Azure", func(t *testing.T) {
@@ -84,6 +90,8 @@ func TestWorkspaceAgent(t *testing.T) {
8490
//nolint:revive,staticcheck
8591
context.WithValue(inv.Context(), "azure-client", metadataClient),
8692
)
93+
// agent hits errors binding to ports for pprof, prometheus, etc., that don't affect the test
94+
inv.Logger = slogtest.Make(t, &slogtest.Options{IgnoreErrors: true}).Leveled(slog.LevelDebug)
8795
ctx := inv.Context()
8896
clitest.Start(t, inv)
8997
coderdtest.AwaitWorkspaceAgents(t, client, ws.ID)
@@ -126,6 +134,8 @@ func TestWorkspaceAgent(t *testing.T) {
126134
//nolint:revive,staticcheck
127135
context.WithValue(inv.Context(), "aws-client", metadataClient),
128136
)
137+
// agent hits errors binding to ports for pprof, prometheus, etc., that don't affect the test
138+
inv.Logger = slogtest.Make(t, &slogtest.Options{IgnoreErrors: true}).Leveled(slog.LevelDebug)
129139
clitest.Start(t, inv)
130140
ctx := inv.Context()
131141
coderdtest.AwaitWorkspaceAgents(t, client, ws.ID)
@@ -164,8 +174,9 @@ func TestWorkspaceAgent(t *testing.T) {
164174
}},
165175
})
166176
inv, cfg := clitest.New(t, "agent", "--auth", "google-instance-identity", "--agent-url", client.URL.String())
167-
ptytest.New(t).Attach(inv)
168177
clitest.SetupConfig(t, member, cfg)
178+
// agent hits errors binding to ports for pprof, prometheus, etc., that don't affect the test
179+
inv.Logger = slogtest.Make(t, &slogtest.Options{IgnoreErrors: true}).Leveled(slog.LevelDebug)
169180
clitest.Start(t,
170181
inv.WithContext(
171182
//nolint:revive,staticcheck
@@ -223,10 +234,9 @@ func TestWorkspaceAgent(t *testing.T) {
223234
// Set the subsystems for the agent.
224235
inv.Environ.Set(agent.EnvAgentSubsystem, fmt.Sprintf("%s,%s", codersdk.AgentSubsystemExectrace, codersdk.AgentSubsystemEnvbox))
225236

226-
pty := ptytest.New(t).Attach(inv)
227-
237+
// agent hits errors binding to ports for pprof, prometheus, etc., that don't affect the test
238+
inv.Logger = slogtest.Make(t, &slogtest.Options{IgnoreErrors: true}).Leveled(slog.LevelDebug)
228239
clitest.Start(t, inv)
229-
pty.ExpectMatchContext(inv.Context(), "agent is starting now")
230240

231241
resources := coderdtest.AwaitWorkspaceAgents(t, client, ws.ID)
232242
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: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -59,13 +59,14 @@ 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+
logger := slogtest.Make(t, nil).Leveled(slog.LevelDebug).Named("cli")
6363
i := &clibase.Invocation{
6464
Command: cmd,
6565
Args: append([]string{"--global-config", string(configDir)}, args...),
6666
Stdin: io.LimitReader(nil, 0),
6767
Stdout: (&logWriter{prefix: "stdout", log: logger}),
6868
Stderr: (&logWriter{prefix: "stderr", log: logger}),
69+
Logger: logger,
6970
}
7071
t.Logf("invoking command: %s %s", cmd.Name(), strings.Join(i.Args, " "))
7172

‎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: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -140,6 +140,8 @@ func TestSSH(t *testing.T) {
140140
inv.Stdin = pty.Input()
141141
inv.Stderr = pty.Output()
142142
inv.Stdout = pty.Output()
143+
// ssh exits with canceled ctx
144+
inv.Logger = slogtest.Make(t, &slogtest.Options{IgnoreErrors: true}).Leveled(slog.LevelDebug)
143145

144146
ctx, cancel := context.WithTimeout(context.Background(), testutil.WaitLong)
145147
defer cancel()
@@ -163,6 +165,8 @@ func TestSSH(t *testing.T) {
163165
inv, root := clitest.New(t, "ssh", workspace.Name)
164166
clitest.SetupConfig(t, client, root)
165167
pty := ptytest.New(t).Attach(inv)
168+
// test exits with stopped workspace which throws an error
169+
inv.Logger = slogtest.Make(t, &slogtest.Options{IgnoreErrors: true}).Leveled(slog.LevelDebug)
166170

167171
ctx, cancel := context.WithTimeout(context.Background(), testutil.WaitLong)
168172
defer cancel()
@@ -215,6 +219,8 @@ func TestSSH(t *testing.T) {
215219
inv.Stdin = clientOutput
216220
inv.Stdout = serverInput
217221
inv.Stderr = io.Discard
222+
// test ends with closed pipe, which we log an error for
223+
inv.Logger = slogtest.Make(t, &slogtest.Options{IgnoreErrors: true}).Leveled(slog.LevelDebug)
218224
cmdDone := tGo(t, func() {
219225
err := inv.WithContext(ctx).Run()
220226
assert.NoError(t, err)
@@ -282,6 +288,8 @@ func TestSSH(t *testing.T) {
282288
inv = inv.WithTestSignalNotifyContext(t, fsn.NotifyContext)
283289
inv.Stdout = io.Discard
284290
inv.Stderr = io.Discard
291+
// test ends by closing the network connection, which causes an error log to be dropped
292+
inv.Logger = slogtest.Make(t, &slogtest.Options{IgnoreErrors: true}).Leveled(slog.LevelDebug)
285293

286294
clitest.SetupConfig(t, client, root)
287295
cmdDone := tGo(t, func() {
@@ -390,6 +398,8 @@ func TestSSH(t *testing.T) {
390398
inv.Stdin = clientOutput
391399
inv.Stdout = serverInput
392400
inv.Stderr = io.Discard
401+
// test ends by closing pipes, which causes an error log to be dropped
402+
inv.Logger = slogtest.Make(t, &slogtest.Options{IgnoreErrors: true}).Leveled(slog.LevelDebug)
393403
cmdDone := tGo(t, func() {
394404
err := inv.WithContext(ctx).Run()
395405
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)