From 1a6b428ba91be345d82617ebba296812c3c50eb6 Mon Sep 17 00:00:00 2001 From: Mathias Fredriksson Date: Fri, 27 Oct 2023 11:55:49 +0000 Subject: [PATCH 1/3] fix(agent/agentscripts): show informative error for ErrWaitDelay --- agent/agent.go | 3 ++- agent/agentscripts/agentscripts.go | 18 +++++++++++++++++- 2 files changed, 19 insertions(+), 2 deletions(-) diff --git a/agent/agent.go b/agent/agent.go index 7f7e8cd64dff8..0d2326d2ab9d3 100644 --- a/agent/agent.go +++ b/agent/agent.go @@ -743,7 +743,7 @@ func (a *agent) run(ctx context.Context) error { return script.RunOnStart }) if err != nil { - a.logger.Warn(ctx, "startup script failed", slog.Error(err)) + a.logger.Warn(ctx, "startup script(s) failed", slog.Error(err)) if errors.Is(err, agentscripts.ErrTimeout) { a.setLifecycle(ctx, codersdk.WorkspaceAgentLifecycleStartTimeout) } else { @@ -1465,6 +1465,7 @@ func (a *agent) Close() error { return script.RunOnStop }) if err != nil { + a.logger.Warn(ctx, "shutdown script(s) failed", slog.Error(err)) if errors.Is(err, agentscripts.ErrTimeout) { lifecycleState = codersdk.WorkspaceAgentLifecycleShutdownTimeout } else { diff --git a/agent/agentscripts/agentscripts.go b/agent/agentscripts/agentscripts.go index c3bd525109ced..9fbdf17b564e1 100644 --- a/agent/agentscripts/agentscripts.go +++ b/agent/agentscripts/agentscripts.go @@ -27,6 +27,8 @@ import ( var ( // ErrTimeout is returned when a script times out. ErrTimeout = xerrors.New("script timed out") + // ErrTimeout is returned when a script times out. + ErrOutputPipesOpen = xerrors.New("script exited without closing output pipes") parser = cron.NewParser(cron.Second | cron.Minute | cron.Hour | cron.Dom | cron.Month | cron.DowOptional) ) @@ -248,7 +250,21 @@ func (r *Runner) run(ctx context.Context, script codersdk.WorkspaceAgentScript) err = cmdCtx.Err() case err = <-cmdDone: } - if errors.Is(err, context.DeadlineExceeded) { + switch { + case errors.Is(err, exec.ErrWaitDelay): + err = ErrOutputPipesOpen + message := fmt.Sprintf("script exited successfully, but output pipes were not closed after %s", cmd.WaitDelay) + details := fmt.Sprint( + "This usually means a child process was started with references to stdout or stderr. As a result, this " + + "process may now have been terminated. Consider using a separate \"coder_script\" for the service, " + + "see https://coder.com/docs/v2/latest/templates/troubleshooting#startup-script-issues for more information.", + ) + // Inform the user by propagating the message via log writers. + _, _ = fmt.Fprintf(cmd.Stderr, "WARNING: %s. %s\n", message, details) + // Also log to agent logs for ease of debugging. + r.Logger.Warn(ctx, message, slog.F("details", details), slog.Error(err)) + + case errors.Is(err, context.DeadlineExceeded): err = ErrTimeout } return err From c6a459378874e3e73645c2a9d27a8d97809d1b66 Mon Sep 17 00:00:00 2001 From: Mathias Fredriksson Date: Fri, 27 Oct 2023 12:10:30 +0000 Subject: [PATCH 2/3] fix comment --- agent/agentscripts/agentscripts.go | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/agent/agentscripts/agentscripts.go b/agent/agentscripts/agentscripts.go index 9fbdf17b564e1..189c2d4d50d89 100644 --- a/agent/agentscripts/agentscripts.go +++ b/agent/agentscripts/agentscripts.go @@ -27,7 +27,13 @@ import ( var ( // ErrTimeout is returned when a script times out. ErrTimeout = xerrors.New("script timed out") - // ErrTimeout is returned when a script times out. + // ErrOutputPipesOpen is returned when a script exits leaving the output + // pipe(s) (stdout, stderr) open. This happens because we set WaitDelay on + // the command, which gives us two things: + // + // 1. The ability to ensure that a script exits (this is important for e.g. + // blocking login, and avoiding doing so indefinitely) + // 2. Improved command cancellation on timeout ErrOutputPipesOpen = xerrors.New("script exited without closing output pipes") parser = cron.NewParser(cron.Second | cron.Minute | cron.Hour | cron.Dom | cron.Month | cron.DowOptional) From 3b4be865bd77b23a3cdf990196ae05169cf7fb60 Mon Sep 17 00:00:00 2001 From: Mathias Fredriksson Date: Fri, 27 Oct 2023 12:39:10 +0000 Subject: [PATCH 3/3] improve message --- agent/agentscripts/agentscripts.go | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/agent/agentscripts/agentscripts.go b/agent/agentscripts/agentscripts.go index 189c2d4d50d89..3acc48b0a140c 100644 --- a/agent/agentscripts/agentscripts.go +++ b/agent/agentscripts/agentscripts.go @@ -262,8 +262,9 @@ func (r *Runner) run(ctx context.Context, script codersdk.WorkspaceAgentScript) message := fmt.Sprintf("script exited successfully, but output pipes were not closed after %s", cmd.WaitDelay) details := fmt.Sprint( "This usually means a child process was started with references to stdout or stderr. As a result, this " + - "process may now have been terminated. Consider using a separate \"coder_script\" for the service, " + - "see https://coder.com/docs/v2/latest/templates/troubleshooting#startup-script-issues for more information.", + "process may now have been terminated. Consider redirecting the output or using a separate " + + "\"coder_script\" for the process, see " + + "https://coder.com/docs/v2/latest/templates/troubleshooting#startup-script-issues for more information.", ) // Inform the user by propagating the message via log writers. _, _ = fmt.Fprintf(cmd.Stderr, "WARNING: %s. %s\n", message, details)