From 4b3b2bdb02a6ed713ba7462f4370f3b4f7cdafef Mon Sep 17 00:00:00 2001 From: Ammar Bandukwala Date: Mon, 5 Jun 2023 23:51:34 +0000 Subject: [PATCH 01/13] feat(cli/ssh): simplify log file flags --- cli/ssh.go | 36 +++++++--------------------- cli/ssh_test.go | 15 ++++-------- cli/testdata/coder_ssh_--help.golden | 7 ++---- 3 files changed, 15 insertions(+), 43 deletions(-) diff --git a/cli/ssh.go b/cli/ssh.go index fa3611a055a00..33e6bf2146e31 100644 --- a/cli/ssh.go +++ b/cli/ssh.go @@ -10,7 +10,6 @@ import ( "net/url" "os" "os/exec" - "path" "path/filepath" "strings" "time" @@ -50,8 +49,7 @@ func (r *RootCmd) ssh() *clibase.Cmd { identityAgent string wsPollInterval time.Duration noWait bool - logDir string - logToFile bool + logFilePath string ) client := new(codersdk.Client) cmd := &clibase.Cmd{ @@ -74,21 +72,10 @@ func (r *RootCmd) ssh() *clibase.Cmd { logger.Error(ctx, "command exit", slog.Error(retErr)) } }() - if logToFile { - // we need a way to ensure different ssh invocations don't clobber - // each other's logs. Date-time strings will likely have collisions - // in unit tests and/or scripts unless we extend precision out to - // sub-millisecond, which seems unwieldy. A simple 5-character random - // string will do it, since the operating system already tracks - // dates and times for file IO. - qual, err := cryptorand.String(5) + if logFilePath != "" { + logFile, err := os.OpenFile(logFilePath, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0o600) if err != nil { - return xerrors.Errorf("generate random qualifier: %w", err) - } - logPth := path.Join(logDir, fmt.Sprintf("coder-ssh-%s.log", qual)) - logFile, err := os.Create(logPth) - if err != nil { - return xerrors.Errorf("error opening %s for logging: %w", logPth, err) + return xerrors.Errorf("error opening %s for logging: %w", logFilePath, err) } logger = slog.Make(sloghuman.Sink(logFile)) defer logFile.Close() @@ -354,18 +341,11 @@ func (r *RootCmd) ssh() *clibase.Cmd { Value: clibase.BoolOf(&noWait), }, { - Flag: "log-dir", - Default: os.TempDir(), - Description: "Specify the location for the log files.", - Env: "CODER_SSH_LOG_DIR", - Value: clibase.StringOf(&logDir), - }, - { - Flag: "log-to-file", + Flag: "log-file", + Description: "Specify the location of an SSH diagnostic log file.", + Env: "CODER_SSH_LOG_FILE", FlagShorthand: "l", - Env: "CODER_SSH_LOG_TO_FILE", - Description: "Enable diagnostic logging to file.", - Value: clibase.BoolOf(&logToFile), + Value: clibase.StringOf(&logFilePath), }, } return cmd diff --git a/cli/ssh_test.go b/cli/ssh_test.go index 88e64d6fe48d7..21f5654916f60 100644 --- a/cli/ssh_test.go +++ b/cli/ssh_test.go @@ -411,10 +411,10 @@ func TestSSH(t *testing.T) { t.Run("FileLogging", func(t *testing.T) { t.Parallel() - dir := t.TempDir() + logFile := filepath.Join(t.TempDir(), "coder-ssh.log") client, workspace, agentToken := setupWorkspaceForAgent(t, nil) - inv, root := clitest.New(t, "ssh", workspace.Name, "-l", "--log-dir", dir) + inv, root := clitest.New(t, "ssh", workspace.Name, "-l", logFile) clitest.SetupConfig(t, client, root) pty := ptytest.New(t).Attach(inv) @@ -441,15 +441,10 @@ func TestSSH(t *testing.T) { pty.WriteLine("exit") <-cmdDone - entries, err := os.ReadDir(dir) - require.NoError(t, err) - for _, e := range entries { - t.Logf("logdir entry: %s", e.Name()) - if strings.HasPrefix(e.Name(), "coder-ssh") { - return - } + _, err := os.Stat(logFile) + if err != nil { + t.Fatalf("failed to find ssh logfile: %v", err) } - t.Fatal("failed to find ssh logfile") }) } diff --git a/cli/testdata/coder_ssh_--help.golden b/cli/testdata/coder_ssh_--help.golden index 632003ffdbdb8..4e7d43f362ceb 100644 --- a/cli/testdata/coder_ssh_--help.golden +++ b/cli/testdata/coder_ssh_--help.golden @@ -18,11 +18,8 @@ Start a shell into a workspace Specifies which identity agent to use (overrides $SSH_AUTH_SOCK), forward agent must also be enabled. - --log-dir string, $CODER_SSH_LOG_DIR (default: /tmp) - Specify the location for the log files. - - -l, --log-to-file bool, $CODER_SSH_LOG_TO_FILE - Enable diagnostic logging to file. + -l, --log-file string, $CODER_SSH_LOG_FILE + Specify the location of an SSH diagnostic log file. --no-wait bool, $CODER_SSH_NO_WAIT Specifies whether to wait for a workspace to become ready before From 82ce7a21410c038d8c83e3bd1e16311df125e876 Mon Sep 17 00:00:00 2001 From: Ammar Bandukwala Date: Tue, 6 Jun 2023 00:59:51 +0000 Subject: [PATCH 02/13] Fix race --- cli/ssh.go | 14 ++++++++++++-- cli/ssh_test.go | 4 +++- docs/cli/ssh.md | 22 ++++++---------------- 3 files changed, 21 insertions(+), 19 deletions(-) diff --git a/cli/ssh.go b/cli/ssh.go index 33e6bf2146e31..debc84c0475ef 100644 --- a/cli/ssh.go +++ b/cli/ssh.go @@ -77,8 +77,18 @@ func (r *RootCmd) ssh() *clibase.Cmd { if err != nil { return xerrors.Errorf("error opening %s for logging: %w", logFilePath, err) } - logger = slog.Make(sloghuman.Sink(logFile)) - defer logFile.Close() + // HACK: Something was keeping a reference to this file + // after the goroutine ends, leading to the race observed + // here: https://github.com/coder/coder/actions/runs/5178818818/jobs/9331016395. + rd, wr := io.Pipe() + go func() { + _, _ = io.Copy(logFile, rd) + }() + defer func() { + _ = wr.Close() + _ = logFile.Close() + }() + logger = slog.Make(sloghuman.Sink(wr)) if r.verbose { logger = logger.Leveled(slog.LevelDebug) } diff --git a/cli/ssh_test.go b/cli/ssh_test.go index 21f5654916f60..7988299e31803 100644 --- a/cli/ssh_test.go +++ b/cli/ssh_test.go @@ -441,10 +441,12 @@ func TestSSH(t *testing.T) { pty.WriteLine("exit") <-cmdDone - _, err := os.Stat(logFile) + info, err := os.Stat(logFile) if err != nil { t.Fatalf("failed to find ssh logfile: %v", err) } + + require.Greater(t, info.Size(), int64(0), "ssh logfile is empty") }) } diff --git a/docs/cli/ssh.md b/docs/cli/ssh.md index 2ec3ff5beb4dd..0ad4af1a22328 100644 --- a/docs/cli/ssh.md +++ b/docs/cli/ssh.md @@ -39,24 +39,14 @@ Specifies whether to forward the GPG agent. Unsupported on Windows workspaces, b Specifies which identity agent to use (overrides $SSH_AUTH_SOCK), forward agent must also be enabled. -### --log-dir +### -l, --log-file -| | | -| ----------- | ------------------------------- | -| Type | string | -| Environment | $CODER_SSH_LOG_DIR | -| Default | /tmp | - -Specify the location for the log files. - -### -l, --log-to-file - -| | | -| ----------- | ----------------------------------- | -| Type | bool | -| Environment | $CODER_SSH_LOG_TO_FILE | +| | | +| ----------- | -------------------------------- | +| Type | string | +| Environment | $CODER_SSH_LOG_FILE | -Enable diagnostic logging to file. +Specify the location of an SSH diagnostic log file. ### --no-wait From ad2c946290107faf01c15d1aa133d0cca903b194 Mon Sep 17 00:00:00 2001 From: Ammar Bandukwala Date: Tue, 6 Jun 2023 13:37:18 +0000 Subject: [PATCH 03/13] Fix race the right way --- cli/ssh.go | 60 +++++++++++++++++++++++++++++++----------------------- 1 file changed, 34 insertions(+), 26 deletions(-) diff --git a/cli/ssh.go b/cli/ssh.go index debc84c0475ef..3b62e349360fc 100644 --- a/cli/ssh.go +++ b/cli/ssh.go @@ -12,6 +12,7 @@ import ( "os/exec" "path/filepath" "strings" + "sync" "time" "github.com/gen2brain/beeep" @@ -77,18 +78,7 @@ func (r *RootCmd) ssh() *clibase.Cmd { if err != nil { return xerrors.Errorf("error opening %s for logging: %w", logFilePath, err) } - // HACK: Something was keeping a reference to this file - // after the goroutine ends, leading to the race observed - // here: https://github.com/coder/coder/actions/runs/5178818818/jobs/9331016395. - rd, wr := io.Pipe() - go func() { - _, _ = io.Copy(logFile, rd) - }() - defer func() { - _ = wr.Close() - _ = logFile.Close() - }() - logger = slog.Make(sloghuman.Sink(wr)) + logger = slog.Make(sloghuman.Sink(logFile)) if r.verbose { logger = logger.Leveled(slog.LevelDebug) } @@ -157,15 +147,28 @@ func (r *RootCmd) ssh() *clibase.Cmd { stopPolling := tryPollWorkspaceAutostop(ctx, client, workspace) defer stopPolling() + // This WaitGroup solves for a race condition where we were logging + // while closing the log file in in a defer. It probably solves + // others too. + var wg sync.WaitGroup + defer wg.Wait() + if stdio { rawSSH, err := conn.SSH(ctx) if err != nil { return xerrors.Errorf("connect SSH: %w", err) } defer rawSSH.Close() - go watchAndClose(ctx, rawSSH.Close, logger, client, workspace) + wg.Add(1) + go func() { + defer wg.Done() + watchAndClose(ctx, rawSSH.Close, logger, client, workspace) + }() + + wg.Add(1) go func() { + defer wg.Done() // Ensure stdout copy closes incase stdin is closed // unexpectedly. Typically we wouldn't worry about // this since OpenSSH should kill the proxy command. @@ -198,19 +201,24 @@ func (r *RootCmd) ssh() *clibase.Cmd { return xerrors.Errorf("ssh session: %w", err) } defer sshSession.Close() - go watchAndClose( - ctx, - func() error { - err := sshSession.Close() - logger.Debug(ctx, "session close", slog.Error(err)) - err = sshClient.Close() - logger.Debug(ctx, "client close", slog.Error(err)) - return nil - }, - logger, - client, - workspace, - ) + + wg.Add(1) + go func() { + defer wg.Done() + watchAndClose( + ctx, + func() error { + err := sshSession.Close() + logger.Debug(ctx, "session close", slog.Error(err)) + err = sshClient.Close() + logger.Debug(ctx, "client close", slog.Error(err)) + return nil + }, + logger, + client, + workspace, + ) + }() if identityAgent == "" { identityAgent = os.Getenv("SSH_AUTH_SOCK") From 1ca5930c4a19c8bdbacb3af349bc92ae3f69ed35 Mon Sep 17 00:00:00 2001 From: Ammar Bandukwala Date: Tue, 6 Jun 2023 22:12:45 +0000 Subject: [PATCH 04/13] Restore directory flag --- cli/ssh.go | 38 ++++++++++++++++++++++++++++++-------- cli/ssh_test.go | 12 +++++------- 2 files changed, 35 insertions(+), 15 deletions(-) diff --git a/cli/ssh.go b/cli/ssh.go index 3b62e349360fc..202b9453882f2 100644 --- a/cli/ssh.go +++ b/cli/ssh.go @@ -50,7 +50,7 @@ func (r *RootCmd) ssh() *clibase.Cmd { identityAgent string wsPollInterval time.Duration noWait bool - logFilePath string + logDirPath string ) client := new(codersdk.Client) cmd := &clibase.Cmd{ @@ -73,11 +73,33 @@ func (r *RootCmd) ssh() *clibase.Cmd { logger.Error(ctx, "command exit", slog.Error(retErr)) } }() - if logFilePath != "" { - logFile, err := os.OpenFile(logFilePath, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0o600) + if logDirPath != "" { + nonce, err := cryptorand.StringCharset(cryptorand.Lower, 5) if err != nil { - return xerrors.Errorf("error opening %s for logging: %w", logFilePath, err) + panic(err) } + logFilePath := filepath.Join( + logDirPath, + fmt.Sprintf( + "coder-ssh-%s-%s.log", + // The time portion makes it easier to find the right + // log file. + time.Now().Format("20060102-150405"), + // The nonce prevents collisions, as SSH invocations + // frequently happen in parallel. + nonce, + ), + ) + logFile, err := os.OpenFile( + logFilePath, + os.O_CREATE|os.O_APPEND|os.O_WRONLY|os.O_EXCL, + 0o600, + ) + if err != nil { + return xerrors.Errorf("error opening %s for logging: %w", logDirPath, err) + } + defer logFile.Close() + logger = slog.Make(sloghuman.Sink(logFile)) if r.verbose { logger = logger.Leveled(slog.LevelDebug) @@ -359,11 +381,11 @@ func (r *RootCmd) ssh() *clibase.Cmd { Value: clibase.BoolOf(&noWait), }, { - Flag: "log-file", - Description: "Specify the location of an SSH diagnostic log file.", - Env: "CODER_SSH_LOG_FILE", + Flag: "log-dir", + Description: "Specify the directory containing SSH diagnostic log files.", + Env: "CODER_SSH_LOG_DIR", FlagShorthand: "l", - Value: clibase.StringOf(&logFilePath), + Value: clibase.StringOf(&logDirPath), }, } return cmd diff --git a/cli/ssh_test.go b/cli/ssh_test.go index 7988299e31803..9c98ed1ee6bd2 100644 --- a/cli/ssh_test.go +++ b/cli/ssh_test.go @@ -411,10 +411,10 @@ func TestSSH(t *testing.T) { t.Run("FileLogging", func(t *testing.T) { t.Parallel() - logFile := filepath.Join(t.TempDir(), "coder-ssh.log") + logDir := t.TempDir() client, workspace, agentToken := setupWorkspaceForAgent(t, nil) - inv, root := clitest.New(t, "ssh", workspace.Name, "-l", logFile) + inv, root := clitest.New(t, "ssh", workspace.Name, "-l", logDir) clitest.SetupConfig(t, client, root) pty := ptytest.New(t).Attach(inv) @@ -441,12 +441,10 @@ func TestSSH(t *testing.T) { pty.WriteLine("exit") <-cmdDone - info, err := os.Stat(logFile) - if err != nil { - t.Fatalf("failed to find ssh logfile: %v", err) - } + ents, err := os.ReadDir(t.TempDir()) + require.NoError(t, err) - require.Greater(t, info.Size(), int64(0), "ssh logfile is empty") + require.Len(t, ents, 1, "expected one file in logdir") }) } From d7b26ad61eb78d24551c25e933988665516986f6 Mon Sep 17 00:00:00 2001 From: Ammar Bandukwala Date: Tue, 6 Jun 2023 22:31:27 +0000 Subject: [PATCH 05/13] Update tests --- cli/ssh_test.go | 17 +++++------------ 1 file changed, 5 insertions(+), 12 deletions(-) diff --git a/cli/ssh_test.go b/cli/ssh_test.go index 9c98ed1ee6bd2..98c6872815309 100644 --- a/cli/ssh_test.go +++ b/cli/ssh_test.go @@ -414,17 +414,11 @@ func TestSSH(t *testing.T) { logDir := t.TempDir() client, workspace, agentToken := setupWorkspaceForAgent(t, nil) - inv, root := clitest.New(t, "ssh", workspace.Name, "-l", logDir) + inv, root := clitest.New(t, "ssh", "-l", logDir, workspace.Name) clitest.SetupConfig(t, client, root) pty := ptytest.New(t).Attach(inv) + w := clitest.StartWithWaiter(t, inv) - ctx, cancel := context.WithTimeout(context.Background(), testutil.WaitLong) - defer cancel() - - cmdDone := tGo(t, func() { - err := inv.WithContext(ctx).Run() - assert.NoError(t, err) - }) pty.ExpectMatch("Waiting") agentClient := agentsdk.New(client.URL) @@ -439,12 +433,11 @@ func TestSSH(t *testing.T) { // Shells on Mac, Windows, and Linux all exit shells with the "exit" command. pty.WriteLine("exit") - <-cmdDone + w.RequireSuccess() - ents, err := os.ReadDir(t.TempDir()) + ents, err := os.ReadDir(logDir) require.NoError(t, err) - - require.Len(t, ents, 1, "expected one file in logdir") + require.Len(t, ents, 1, "expected one file in logdir %s", logDir) }) } From 48cb9b29392aee10360067f51b0b12906f227226 Mon Sep 17 00:00:00 2001 From: Ammar Bandukwala Date: Tue, 6 Jun 2023 22:33:33 +0000 Subject: [PATCH 06/13] make --- cli/testdata/coder_ssh_--help.golden | 4 ++-- docs/cli/ssh.md | 12 ++++++------ 2 files changed, 8 insertions(+), 8 deletions(-) diff --git a/cli/testdata/coder_ssh_--help.golden b/cli/testdata/coder_ssh_--help.golden index 4e7d43f362ceb..d85088b4f5de7 100644 --- a/cli/testdata/coder_ssh_--help.golden +++ b/cli/testdata/coder_ssh_--help.golden @@ -18,8 +18,8 @@ Start a shell into a workspace Specifies which identity agent to use (overrides $SSH_AUTH_SOCK), forward agent must also be enabled. - -l, --log-file string, $CODER_SSH_LOG_FILE - Specify the location of an SSH diagnostic log file. + -l, --log-dir string, $CODER_SSH_LOG_DIR + Specify the directory containing SSH diagnostic log files. --no-wait bool, $CODER_SSH_NO_WAIT Specifies whether to wait for a workspace to become ready before diff --git a/docs/cli/ssh.md b/docs/cli/ssh.md index 0ad4af1a22328..58c9023599437 100644 --- a/docs/cli/ssh.md +++ b/docs/cli/ssh.md @@ -39,14 +39,14 @@ Specifies whether to forward the GPG agent. Unsupported on Windows workspaces, b Specifies which identity agent to use (overrides $SSH_AUTH_SOCK), forward agent must also be enabled. -### -l, --log-file +### -l, --log-dir -| | | -| ----------- | -------------------------------- | -| Type | string | -| Environment | $CODER_SSH_LOG_FILE | +| | | +| ----------- | ------------------------------- | +| Type | string | +| Environment | $CODER_SSH_LOG_DIR | -Specify the location of an SSH diagnostic log file. +Specify the directory containing SSH diagnostic log files. ### --no-wait From a1b68e55996b986d8b24124a2511c6754865dcdc Mon Sep 17 00:00:00 2001 From: Ammar Bandukwala Date: Thu, 8 Jun 2023 04:29:54 +0000 Subject: [PATCH 07/13] mess around --- cli/ssh.go | 21 ++++++++++++++------- cli/ssh_test.go | 2 +- 2 files changed, 15 insertions(+), 8 deletions(-) diff --git a/cli/ssh.go b/cli/ssh.go index 70ac62a2634ec..773d4185a16c2 100644 --- a/cli/ssh.go +++ b/cli/ssh.go @@ -76,7 +76,7 @@ func (r *RootCmd) ssh() *clibase.Cmd { if logDirPath != "" { nonce, err := cryptorand.StringCharset(cryptorand.Lower, 5) if err != nil { - panic(err) + return xerrors.Errorf("generate nonce: %w", err) } logFilePath := filepath.Join( logDirPath, @@ -109,6 +109,19 @@ func (r *RootCmd) ssh() *clibase.Cmd { client.Logger = logger } + // This WaitGroup solves for a race condition where we were logging + // while closing the log file in in a defer. It probably solves + // others too. + // + // Its position in this function is important. It must be after + // the logger is created but before any goroutines or wind-down + // defers (e.g. context cancels) are declared. + var wg sync.WaitGroup + defer func() { + cancel() + wg.Wait() + }() + workspace, workspaceAgent, err := getWorkspaceAndAgent(ctx, inv, client, codersdk.Me, inv.Args[0]) if err != nil { return err @@ -169,12 +182,6 @@ func (r *RootCmd) ssh() *clibase.Cmd { stopPolling := tryPollWorkspaceAutostop(ctx, client, workspace) defer stopPolling() - // This WaitGroup solves for a race condition where we were logging - // while closing the log file in in a defer. It probably solves - // others too. - var wg sync.WaitGroup - defer wg.Wait() - if stdio { rawSSH, err := conn.SSH(ctx) if err != nil { diff --git a/cli/ssh_test.go b/cli/ssh_test.go index 98c6872815309..fc2cf45b6ee82 100644 --- a/cli/ssh_test.go +++ b/cli/ssh_test.go @@ -714,7 +714,7 @@ type stdioConn struct { io.Writer } -func (*stdioConn) Close() (err error) { +func (c *stdioConn) Close() (err error) { return nil } From 23a6833c775c5f5e57d45c071132fd30f9c6f4c4 Mon Sep 17 00:00:00 2001 From: Ammar Bandukwala Date: Thu, 8 Jun 2023 04:39:39 +0000 Subject: [PATCH 08/13] Fix another race --- cli/ssh.go | 15 ++++++++++----- 1 file changed, 10 insertions(+), 5 deletions(-) diff --git a/cli/ssh.go b/cli/ssh.go index 773d4185a16c2..18ed7c9cabde8 100644 --- a/cli/ssh.go +++ b/cli/ssh.go @@ -117,10 +117,7 @@ func (r *RootCmd) ssh() *clibase.Cmd { // the logger is created but before any goroutines or wind-down // defers (e.g. context cancels) are declared. var wg sync.WaitGroup - defer func() { - cancel() - wg.Wait() - }() + defer wg.Wait() workspace, workspaceAgent, err := getWorkspaceAndAgent(ctx, inv, client, codersdk.Me, inv.Args[0]) if err != nil { @@ -192,7 +189,15 @@ func (r *RootCmd) ssh() *clibase.Cmd { wg.Add(1) go func() { defer wg.Done() - watchAndClose(ctx, rawSSH.Close, logger, client, workspace) + watchAndClose(ctx, func() error { + rawSSH.Close() + // If we don't close Stdin, the io.Copy below may + // block indefinitely on Stdin Read. + if rc, ok := inv.Stdin.(io.Closer); ok { + rc.Close() + } + return nil + }, logger, client, workspace) }() wg.Add(1) From f17e7ceabe09ab7dcb18c8e075b7a16dbd4b92dc Mon Sep 17 00:00:00 2001 From: Ammar Bandukwala Date: Thu, 8 Jun 2023 04:40:24 +0000 Subject: [PATCH 09/13] fixup! Fix another race --- cli/ssh_test.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/cli/ssh_test.go b/cli/ssh_test.go index fc2cf45b6ee82..b38c02bd371b0 100644 --- a/cli/ssh_test.go +++ b/cli/ssh_test.go @@ -261,7 +261,7 @@ func TestSSH(t *testing.T) { client, workspace, agentToken := setupWorkspaceForAgent(t, nil) _, _ = tGoContext(t, func(ctx context.Context) { // Run this async so the SSH command has to wait for - // the build and agent to connect! + // the build and agent to connect. agentClient := agentsdk.New(client.URL) agentClient.SetSessionToken(agentToken) agentCloser := agent.New(agent.Options{ @@ -714,7 +714,7 @@ type stdioConn struct { io.Writer } -func (c *stdioConn) Close() (err error) { +func (*stdioConn) Close() (err error) { return nil } From 5a311b36f6ecc375a15c616aabf2342ffdff9f86 Mon Sep 17 00:00:00 2001 From: Ammar Bandukwala Date: Thu, 8 Jun 2023 10:17:01 -0500 Subject: [PATCH 10/13] Update cli/ssh.go Co-authored-by: Spike Curtis --- cli/ssh.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/cli/ssh.go b/cli/ssh.go index 18ed7c9cabde8..21493baf40476 100644 --- a/cli/ssh.go +++ b/cli/ssh.go @@ -110,7 +110,7 @@ func (r *RootCmd) ssh() *clibase.Cmd { } // This WaitGroup solves for a race condition where we were logging - // while closing the log file in in a defer. It probably solves + // while closing the log file in a defer. It probably solves // others too. // // Its position in this function is important. It must be after From 65cdbcc6da7ec699046083d950ed7b6c45b7cadb Mon Sep 17 00:00:00 2001 From: Ammar Bandukwala Date: Fri, 9 Jun 2023 19:51:33 +0000 Subject: [PATCH 11/13] Move CloseStdin into clibase --- cli/clibase/cmd.go | 10 ++++++++++ cli/ssh.go | 4 +--- 2 files changed, 11 insertions(+), 3 deletions(-) diff --git a/cli/clibase/cmd.go b/cli/clibase/cmd.go index dff1e10a63b9b..1cc511df1b759 100644 --- a/cli/clibase/cmd.go +++ b/cli/clibase/cmd.go @@ -381,6 +381,16 @@ func (inv *Invocation) run(state *runState) error { return nil } +// CloseStdin closes the invocation's Stdin if it is an io.Closer. +func (inv *Invocation) CloseStdin() error { + // If we don't close Stdin, the io.Copy below may + // block indefinitely on Stdin Read. + if rc, ok := inv.Stdin.(io.Closer); ok { + return rc.Close() + } + return nil +} + type RunCommandError struct { Cmd *Cmd Err error diff --git a/cli/ssh.go b/cli/ssh.go index 21493baf40476..e9bfcd1bc5967 100644 --- a/cli/ssh.go +++ b/cli/ssh.go @@ -193,9 +193,7 @@ func (r *RootCmd) ssh() *clibase.Cmd { rawSSH.Close() // If we don't close Stdin, the io.Copy below may // block indefinitely on Stdin Read. - if rc, ok := inv.Stdin.(io.Closer); ok { - rc.Close() - } + _ = inv.CloseStdin() return nil }, logger, client, workspace) }() From 8471555cbee56d1e3a6be2e0455b4189b4fc6870 Mon Sep 17 00:00:00 2001 From: Ammar Bandukwala Date: Sat, 10 Jun 2023 16:55:37 +0000 Subject: [PATCH 12/13] Revert "Move CloseStdin into clibase" This reverts commit 65cdbcc6da7ec699046083d950ed7b6c45b7cadb. --- cli/clibase/cmd.go | 10 ---------- cli/ssh.go | 4 +++- 2 files changed, 3 insertions(+), 11 deletions(-) diff --git a/cli/clibase/cmd.go b/cli/clibase/cmd.go index 1cc511df1b759..dff1e10a63b9b 100644 --- a/cli/clibase/cmd.go +++ b/cli/clibase/cmd.go @@ -381,16 +381,6 @@ func (inv *Invocation) run(state *runState) error { return nil } -// CloseStdin closes the invocation's Stdin if it is an io.Closer. -func (inv *Invocation) CloseStdin() error { - // If we don't close Stdin, the io.Copy below may - // block indefinitely on Stdin Read. - if rc, ok := inv.Stdin.(io.Closer); ok { - return rc.Close() - } - return nil -} - type RunCommandError struct { Cmd *Cmd Err error diff --git a/cli/ssh.go b/cli/ssh.go index be791a2c75341..444d91757cd58 100644 --- a/cli/ssh.go +++ b/cli/ssh.go @@ -219,7 +219,9 @@ func (r *RootCmd) ssh() *clibase.Cmd { rawSSH.Close() // If we don't close Stdin, the io.Copy below may // block indefinitely on Stdin Read. - _ = inv.CloseStdin() + if rc, ok := inv.Stdin.(io.Closer); ok { + rc.Close() + } return nil }, logger, client, workspace) }() From c5a1968f2b3f75cb121865797f465ca297cbc079 Mon Sep 17 00:00:00 2001 From: Ammar Bandukwala Date: Sat, 10 Jun 2023 17:08:20 +0000 Subject: [PATCH 13/13] Spike-ify --- cli/clibase/cmd.go | 13 +++++++++++++ cli/ssh.go | 31 +++++++++++++------------------ 2 files changed, 26 insertions(+), 18 deletions(-) diff --git a/cli/clibase/cmd.go b/cli/clibase/cmd.go index dff1e10a63b9b..0d4258d46023f 100644 --- a/cli/clibase/cmd.go +++ b/cli/clibase/cmd.go @@ -448,6 +448,19 @@ func (inv *Invocation) Run() (err error) { panic(err) } }() + // We close Stdin to prevent deadlocks, e.g. when the command + // has ended but an io.Copy is still reading from Stdin. + defer func() { + if inv.Stdin == nil { + return + } + rc, ok := inv.Stdin.(io.ReadCloser) + if !ok { + return + } + e := rc.Close() + err = errors.Join(err, e) + }() err = inv.run(&runState{ allArgs: inv.Args, }) diff --git a/cli/ssh.go b/cli/ssh.go index 444d91757cd58..51226cde6b93d 100644 --- a/cli/ssh.go +++ b/cli/ssh.go @@ -75,6 +75,14 @@ func (r *RootCmd) ssh() *clibase.Cmd { logger.Error(ctx, "command exit", slog.Error(retErr)) } }() + + // This WaitGroup solves for a race condition where we were logging + // while closing the log file in a defer. It probably solves + // others too. + var wg sync.WaitGroup + wg.Add(1) + defer wg.Done() + if logDirPath != "" { nonce, err := cryptorand.StringCharset(cryptorand.Lower, 5) if err != nil { @@ -100,7 +108,10 @@ func (r *RootCmd) ssh() *clibase.Cmd { if err != nil { return xerrors.Errorf("error opening %s for logging: %w", logDirPath, err) } - defer logFile.Close() + go func() { + wg.Wait() + logFile.Close() + }() logger = slog.Make(sloghuman.Sink(logFile)) if r.verbose { @@ -111,16 +122,6 @@ func (r *RootCmd) ssh() *clibase.Cmd { client.Logger = logger } - // This WaitGroup solves for a race condition where we were logging - // while closing the log file in a defer. It probably solves - // others too. - // - // Its position in this function is important. It must be after - // the logger is created but before any goroutines or wind-down - // defers (e.g. context cancels) are declared. - var wg sync.WaitGroup - defer wg.Wait() - workspace, workspaceAgent, err := getWorkspaceAndAgent(ctx, inv, client, codersdk.Me, inv.Args[0]) if err != nil { return err @@ -216,13 +217,7 @@ func (r *RootCmd) ssh() *clibase.Cmd { go func() { defer wg.Done() watchAndClose(ctx, func() error { - rawSSH.Close() - // If we don't close Stdin, the io.Copy below may - // block indefinitely on Stdin Read. - if rc, ok := inv.Stdin.(io.Closer); ok { - rc.Close() - } - return nil + return rawSSH.Close() }, logger, client, workspace) }()