From 4894eda711a67f1e178d709b024f2ce8524ad551 Mon Sep 17 00:00:00 2001 From: Spike Curtis Date: Tue, 14 Nov 2023 22:56:27 +0400 Subject: [PATCH] feat: capture cli logs in tests (#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. --- cli/agent.go | 4 ++-- cli/agent_test.go | 23 +++++++++++------------ cli/clibase/cmd.go | 4 ++++ cli/clitest/clitest.go | 7 ++++++- cli/exp_scaletest.go | 4 ++-- cli/ping.go | 4 ++-- cli/portforward.go | 4 ++-- cli/root.go | 16 ---------------- cli/server.go | 4 ++-- cli/server_createadminuser.go | 2 +- cli/speedtest.go | 5 +---- cli/speedtest_test.go | 3 +-- cli/ssh.go | 2 +- cli/ssh_test.go | 2 ++ cli/vscodessh.go | 2 +- 15 files changed, 38 insertions(+), 48 deletions(-) diff --git a/cli/agent.go b/cli/agent.go index fa62761cc1..0cdfc66c80 100644 --- a/cli/agent.go +++ b/cli/agent.go @@ -116,7 +116,7 @@ func (r *RootCmd) workspaceAgent() *clibase.Cmd { defer logWriter.Close() sinks = append(sinks, sloghuman.Sink(logWriter)) - logger := slog.Make(sinks...).Leveled(slog.LevelDebug) + logger := inv.Logger.AppendSinks(sinks...).Leveled(slog.LevelDebug) logger.Info(ctx, "spawning reaper process") // Do not start a reaper on the child process. It's important @@ -159,7 +159,7 @@ func (r *RootCmd) workspaceAgent() *clibase.Cmd { defer logWriter.Close() sinks = append(sinks, sloghuman.Sink(logWriter)) - logger := slog.Make(sinks...).Leveled(slog.LevelDebug) + logger := inv.Logger.AppendSinks(sinks...).Leveled(slog.LevelDebug) version := buildinfo.Version() logger.Info(ctx, "agent is starting now", diff --git a/cli/agent_test.go b/cli/agent_test.go index a1f519cf4d..1f366da8b4 100644 --- a/cli/agent_test.go +++ b/cli/agent_test.go @@ -20,7 +20,7 @@ import ( "github.com/coder/coder/v2/coderd/database/dbfake" "github.com/coder/coder/v2/codersdk" "github.com/coder/coder/v2/provisionersdk/proto" - "github.com/coder/coder/v2/pty/ptytest" + "github.com/coder/coder/v2/testutil" ) func TestWorkspaceAgent(t *testing.T) { @@ -44,17 +44,17 @@ func TestWorkspaceAgent(t *testing.T) { "--log-dir", logDir, ) - pty := ptytest.New(t).Attach(inv) - clitest.Start(t, inv) - ctx := inv.Context() - pty.ExpectMatchContext(ctx, "agent is starting now") coderdtest.AwaitWorkspaceAgents(t, client, ws.ID) - info, err := os.Stat(filepath.Join(logDir, "coder-agent.log")) - require.NoError(t, err) - require.Greater(t, info.Size(), int64(0)) + 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("Azure", func(t *testing.T) { @@ -84,6 +84,7 @@ func TestWorkspaceAgent(t *testing.T) { //nolint:revive,staticcheck context.WithValue(inv.Context(), "azure-client", metadataClient), ) + ctx := inv.Context() clitest.Start(t, inv) coderdtest.AwaitWorkspaceAgents(t, client, ws.ID) @@ -126,6 +127,7 @@ func TestWorkspaceAgent(t *testing.T) { //nolint:revive,staticcheck context.WithValue(inv.Context(), "aws-client", metadataClient), ) + clitest.Start(t, inv) ctx := inv.Context() coderdtest.AwaitWorkspaceAgents(t, client, ws.ID) @@ -164,8 +166,8 @@ func TestWorkspaceAgent(t *testing.T) { }}, }) inv, cfg := clitest.New(t, "agent", "--auth", "google-instance-identity", "--agent-url", client.URL.String()) - ptytest.New(t).Attach(inv) clitest.SetupConfig(t, member, cfg) + clitest.Start(t, inv.WithContext( //nolint:revive,staticcheck @@ -223,10 +225,7 @@ func TestWorkspaceAgent(t *testing.T) { // Set the subsystems for the agent. inv.Environ.Set(agent.EnvAgentSubsystem, fmt.Sprintf("%s,%s", codersdk.AgentSubsystemExectrace, codersdk.AgentSubsystemEnvbox)) - pty := ptytest.New(t).Attach(inv) - clitest.Start(t, inv) - pty.ExpectMatchContext(inv.Context(), "agent is starting now") resources := coderdtest.AwaitWorkspaceAgents(t, client, ws.ID) require.Len(t, resources, 1) diff --git a/cli/clibase/cmd.go b/cli/clibase/cmd.go index a2ca36b2c9..d678910887 100644 --- a/cli/clibase/cmd.go +++ b/cli/clibase/cmd.go @@ -12,6 +12,8 @@ import ( "testing" "unicode" + "cdr.dev/slog" + "github.com/spf13/pflag" "golang.org/x/exp/slices" "golang.org/x/xerrors" @@ -170,6 +172,7 @@ func (c *Cmd) Invoke(args ...string) *Invocation { Stdout: io.Discard, Stderr: io.Discard, Stdin: strings.NewReader(""), + Logger: slog.Make(), } } @@ -185,6 +188,7 @@ type Invocation struct { Stdout io.Writer Stderr io.Writer Stdin io.Reader + Logger slog.Logger // testing signalNotifyContext func(parent context.Context, signals ...os.Signal) (ctx context.Context, stop context.CancelFunc) diff --git a/cli/clitest/clitest.go b/cli/clitest/clitest.go index 23acc7c01b..451757debf 100644 --- a/cli/clitest/clitest.go +++ b/cli/clitest/clitest.go @@ -59,13 +59,18 @@ func NewWithCommand( t testing.TB, cmd *clibase.Cmd, args ...string, ) (*clibase.Invocation, config.Root) { configDir := config.Root(t.TempDir()) - logger := slogtest.Make(t, nil) + // I really would like to fail test on error logs, but realistically, turning on by default + // in all our CLI tests is going to create a lot of flaky noise. + logger := slogtest.Make(t, &slogtest.Options{IgnoreErrors: true}). + Leveled(slog.LevelDebug). + Named("cli") i := &clibase.Invocation{ Command: cmd, Args: append([]string{"--global-config", string(configDir)}, args...), Stdin: io.LimitReader(nil, 0), Stdout: (&logWriter{prefix: "stdout", log: logger}), Stderr: (&logWriter{prefix: "stderr", log: logger}), + Logger: logger, } t.Logf("invoking command: %s %s", cmd.Name(), strings.Join(i.Args, " ")) diff --git a/cli/exp_scaletest.go b/cli/exp_scaletest.go index 32f3bdd47e..748fcdb6dc 100644 --- a/cli/exp_scaletest.go +++ b/cli/exp_scaletest.go @@ -882,7 +882,7 @@ func (r *RootCmd) scaletestWorkspaceTraffic() *clibase.Cmd { reg := prometheus.NewRegistry() metrics := workspacetraffic.NewMetrics(reg, "username", "workspace_name", "agent_name") - logger := slog.Make(sloghuman.Sink(io.Discard)) + logger := inv.Logger prometheusSrvClose := ServeHandler(ctx, logger, promhttp.HandlerFor(reg, promhttp.HandlerOpts{}), prometheusFlags.Address, "prometheus") defer prometheusSrvClose() @@ -1075,7 +1075,7 @@ func (r *RootCmd) scaletestDashboard() *clibase.Cmd { return xerrors.Errorf("--jitter must be less than --interval") } ctx := inv.Context() - logger := slog.Make(sloghuman.Sink(inv.Stdout)).Leveled(slog.LevelInfo) + logger := inv.Logger.AppendSinks(sloghuman.Sink(inv.Stdout)) if r.verbose { logger = logger.Leveled(slog.LevelDebug) } diff --git a/cli/ping.go b/cli/ping.go index 2df0d57446..94ca23e3aa 100644 --- a/cli/ping.go +++ b/cli/ping.go @@ -46,9 +46,9 @@ func (r *RootCmd) ping() *clibase.Cmd { return err } - var logger slog.Logger + logger := inv.Logger if r.verbose { - logger = slog.Make(sloghuman.Sink(inv.Stdout)).Leveled(slog.LevelDebug) + logger = logger.AppendSinks(sloghuman.Sink(inv.Stdout)).Leveled(slog.LevelDebug) } if r.disableDirect { diff --git a/cli/portforward.go b/cli/portforward.go index d47a6acb22..73a279200c 100644 --- a/cli/portforward.go +++ b/cli/portforward.go @@ -98,9 +98,9 @@ func (r *RootCmd) portForward() *clibase.Cmd { return xerrors.Errorf("await agent: %w", err) } - logger := slog.Make() + logger := inv.Logger if r.verbose { - logger = slog.Make(sloghuman.Sink(inv.Stdout)).Leveled(slog.LevelDebug) + logger = logger.AppendSinks(sloghuman.Sink(inv.Stdout)).Leveled(slog.LevelDebug) } if r.disableDirect { diff --git a/cli/root.go b/cli/root.go index ecb5e1309a..8d645ea5f1 100644 --- a/cli/root.go +++ b/cli/root.go @@ -30,7 +30,6 @@ import ( "github.com/coder/pretty" - "cdr.dev/slog" "github.com/coder/coder/v2/buildinfo" "github.com/coder/coder/v2/cli/clibase" "github.com/coder/coder/v2/cli/cliui" @@ -442,21 +441,6 @@ func (r *RootCmd) Command(subcommands []*clibase.Cmd) (*clibase.Cmd, error) { return cmd, nil } -type contextKey int - -const ( - contextKeyLogger contextKey = iota -) - -func ContextWithLogger(ctx context.Context, l slog.Logger) context.Context { - return context.WithValue(ctx, contextKeyLogger, l) -} - -func LoggerFromContext(ctx context.Context) (slog.Logger, bool) { - l, ok := ctx.Value(contextKeyLogger).(slog.Logger) - return l, ok -} - // RootCmd contains parameters and helpers useful to all commands. type RootCmd struct { clientURL *url.URL diff --git a/cli/server.go b/cli/server.go index b09f814068..ab2f7bb01e 100644 --- a/cli/server.go +++ b/cli/server.go @@ -1092,7 +1092,7 @@ func (r *RootCmd) Server(newAPI func(context.Context, *coderd.Options) (*coderd. ctx := inv.Context() cfg := r.createConfig() - logger := slog.Make(sloghuman.Sink(inv.Stderr)) + logger := inv.Logger.AppendSinks(sloghuman.Sink(inv.Stderr)) if ok, _ := inv.ParsedFlags().GetBool(varVerbose); ok { logger = logger.Leveled(slog.LevelDebug) } @@ -2063,7 +2063,7 @@ func BuildLogger(inv *clibase.Invocation, cfg *codersdk.DeploymentValues) (slog. level = slog.LevelDebug } - return slog.Make(filter).Leveled(level), func() { + return inv.Logger.AppendSinks(filter).Leveled(level), func() { for _, closer := range closers { _ = closer() } diff --git a/cli/server_createadminuser.go b/cli/server_createadminuser.go index 3200177b6d..7491afac3c 100644 --- a/cli/server_createadminuser.go +++ b/cli/server_createadminuser.go @@ -42,7 +42,7 @@ func (r *RootCmd) newCreateAdminUserCommand() *clibase.Cmd { } cfg := r.createConfig() - logger := slog.Make(sloghuman.Sink(inv.Stderr)) + logger := inv.Logger.AppendSinks(sloghuman.Sink(inv.Stderr)) if r.verbose { logger = logger.Leveled(slog.LevelDebug) } diff --git a/cli/speedtest.go b/cli/speedtest.go index ca6c5e50a6..bfc259dc67 100644 --- a/cli/speedtest.go +++ b/cli/speedtest.go @@ -48,10 +48,7 @@ func (r *RootCmd) speedtest() *clibase.Cmd { return xerrors.Errorf("await agent: %w", err) } - logger, ok := LoggerFromContext(ctx) - if !ok { - logger = slog.Make(sloghuman.Sink(inv.Stderr)) - } + logger := inv.Logger.AppendSinks(sloghuman.Sink(inv.Stderr)) if r.verbose { logger = logger.Leveled(slog.LevelDebug) } diff --git a/cli/speedtest_test.go b/cli/speedtest_test.go index f16b769cc8..66dcab5abb 100644 --- a/cli/speedtest_test.go +++ b/cli/speedtest_test.go @@ -10,7 +10,6 @@ import ( "cdr.dev/slog" "cdr.dev/slog/sloggers/slogtest" "github.com/coder/coder/v2/agent/agenttest" - "github.com/coder/coder/v2/cli" "github.com/coder/coder/v2/cli/clitest" "github.com/coder/coder/v2/coderd/coderdtest" "github.com/coder/coder/v2/codersdk" @@ -50,7 +49,7 @@ func TestSpeedtest(t *testing.T) { ctx, cancel = context.WithTimeout(context.Background(), testutil.WaitLong) defer cancel() - ctx = cli.ContextWithLogger(ctx, slogtest.Make(t, nil).Named("speedtest").Leveled(slog.LevelDebug)) + inv.Logger = slogtest.Make(t, nil).Named("speedtest").Leveled(slog.LevelDebug) cmdDone := tGo(t, func() { err := inv.WithContext(ctx).Run() assert.NoError(t, err) diff --git a/cli/ssh.go b/cli/ssh.go index 9287ee1ef1..0b0a81f2ad 100644 --- a/cli/ssh.go +++ b/cli/ssh.go @@ -74,7 +74,7 @@ func (r *RootCmd) ssh() *clibase.Cmd { ctx, cancel := context.WithCancel(ctx) defer cancel() - logger := slog.Make() // empty logger + logger := inv.Logger defer func() { if retErr != nil { // catch and log all returned errors so we see them in the diff --git a/cli/ssh_test.go b/cli/ssh_test.go index 77eae7d3b0..0f94fcce90 100644 --- a/cli/ssh_test.go +++ b/cli/ssh_test.go @@ -215,6 +215,7 @@ func TestSSH(t *testing.T) { inv.Stdin = clientOutput inv.Stdout = serverInput inv.Stderr = io.Discard + cmdDone := tGo(t, func() { err := inv.WithContext(ctx).Run() assert.NoError(t, err) @@ -390,6 +391,7 @@ func TestSSH(t *testing.T) { inv.Stdin = clientOutput inv.Stdout = serverInput inv.Stderr = io.Discard + cmdDone := tGo(t, func() { err := inv.WithContext(ctx).Run() assert.NoError(t, err) diff --git a/cli/vscodessh.go b/cli/vscodessh.go index 87458d8583..5a61946cda 100644 --- a/cli/vscodessh.go +++ b/cli/vscodessh.go @@ -138,7 +138,7 @@ func (r *RootCmd) vscodeSSH() *clibase.Cmd { // command via the ProxyCommand SSH option. pid := os.Getppid() - logger := slog.Make() + logger := inv.Logger if logDir != "" { logFilePath := filepath.Join(logDir, fmt.Sprintf("%d.log", pid)) logFile, err := fs.OpenFile(logFilePath, os.O_CREATE|os.O_WRONLY, 0o600)