- Notifications
You must be signed in to change notification settings - Fork928
feat: add agent timings#14713
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to ourterms of service andprivacy statement. We’ll occasionally send you account related emails.
Already on GitHub?Sign in to your account
Merged
Uh oh!
There was an error while loading.Please reload this page.
Merged
feat: add agent timings#14713
Changes fromall commits
Commits
Show all changes
57 commits Select commitHold shift + click to select a range
bcfacf7 feat: begin impl of agent script timings
DanielleMaywoodd55b2e6 feat: add job_id and display_name to script timings
DanielleMaywood05d8a8b fix: increment migration number
DanielleMaywoodd54f6c3 fix: rename migrations from 251 to 254
DanielleMaywoodd573c67 test: get tests compiling
DanielleMaywood09a1a42 fix: appease the linter
DanielleMaywood6d829f3 fix: get tests passing again
DanielleMaywood4df7831 fix: drop column from correct table
DanielleMaywood2565f0a test: add fixture for agent script timings
DanielleMaywood669b837 fix: typo
DanielleMaywooddf51673 fix: use job id used in provisioner job timings
DanielleMaywoodc6d71d1 fix: increment migration number
DanielleMaywooda306e48 test: behaviour of script runner
DanielleMaywood4b0056c test: rewrite test
DanielleMaywood14b68a1 test: does exit 1 script break things?
DanielleMaywoodb22cb57 test: rewrite test again
DanielleMaywoodef5e2fe fix: revert change
DanielleMaywooda5b412b fix: let code breathe
DanielleMaywood57ebf30 fix: wrap errors
DanielleMaywood2a49f67 fix: justify nolint
DanielleMaywood0698584 fix: swap require.Equal argument order
DanielleMaywood3580069 fix: add mutex operations
DanielleMaywood9cb1252 feat: add 'ran_on_start' and 'blocked_login' fields
DanielleMaywood0b0d1ef fix: update testdata fixture
DanielleMaywoodeb857c1 fix: refer to agent_id instead of job_id in timings
DanielleMaywood586d88f fix: JobID -> AgentID in dbauthz_test
DanielleMaywoodb6289bb fix: add 'id' to scripts, make timing refer to script id
DanielleMaywood863c3dc fix: fix broken tests and convert bug
DanielleMaywoodb8d5d1d fix: update testdata fixtures
DanielleMaywood61c26ea fix: update testdata fixtures again
DanielleMaywood7f8b6f9 feat: capture stage and if script timed out
DanielleMaywoodc20ac32 fix: update migration number
DanielleMaywoodc652133 test: add test for script api
DanielleMaywood1199b64 fix: fake db query
DanielleMaywoodafa61eb fix: use UTC time
DanielleMaywood8d325e2 fix: ensure r.scriptComplete is not nil
DanielleMaywoodaeee582 fix: move err check to right after call
DanielleMaywood424069c fix: uppercase sql
DanielleMaywood9b43a94 fix: use dbtime.Now()
DanielleMaywooded31199 fix: debug log on r.scriptCompleted being nil
DanielleMaywood8814711 fix: ensure correct rbac permissions
DanielleMaywood0414623 chore: remove DisplayName
DanielleMaywooda8192a5 Merge branch 'main' into dm-add-agent-timings
DanielleMaywood08a466a fix: get tests passing
DanielleMaywood8e7c757 fix: remove space in sql up
DanielleMaywood621071e docs: document ExecuteOption
DanielleMaywood3b4df92 fix: drop 'RETURNING' from sql
DanielleMaywood44127b8 chore: remove 'display_name' from timing table
DanielleMaywood5846216 fix: testdata fixture
DanielleMaywoodc43a143 fix: put r.scriptCompleted call in goroutine
DanielleMaywood13889bf fix: track goroutine for test + use separate context for reporting
DanielleMaywoodbf32b89 fix: appease linter, handle trackCommandGoroutine error
DanielleMaywood7fe6d8c fix: resolve race condition
DanielleMaywoodd7e86c6 feat: replace timed_out column with status column
DanielleMaywood6e338f2 test: update testdata fixture
DanielleMaywood79a620b fix: apply suggestions from review
DanielleMaywood180307f revert: linter changes
DanielleMaywoodFile filter
Filter by extension
Conversations
Failed to load comments.
Loading
Uh oh!
There was an error while loading.Please reload this page.
Jump to
Jump to file
Failed to load files.
Loading
Uh oh!
There was an error while loading.Please reload this page.
Diff view
Diff view
There are no files selected for viewing
10 changes: 3 additions & 7 deletionsagent/agent.go
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.Learn more about bidirectional Unicode characters
2 changes: 2 additions & 0 deletionsagent/agent_test.go
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.Learn more about bidirectional Unicode characters
122 changes: 97 additions & 25 deletionsagent/agentscripts/agentscripts.go
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -19,10 +19,13 @@ import ( | ||
| "github.com/spf13/afero" | ||
| "golang.org/x/sync/errgroup" | ||
| "golang.org/x/xerrors" | ||
| "google.golang.org/protobuf/types/known/timestamppb" | ||
| "cdr.dev/slog" | ||
| "github.com/coder/coder/v2/agent/agentssh" | ||
| "github.com/coder/coder/v2/agent/proto" | ||
| "github.com/coder/coder/v2/coderd/database/dbtime" | ||
| "github.com/coder/coder/v2/codersdk" | ||
| "github.com/coder/coder/v2/codersdk/agentsdk" | ||
| ) | ||
| @@ -75,18 +78,21 @@ func New(opts Options) *Runner { | ||
| } | ||
| } | ||
| type ScriptCompletedFunc func(context.Context, *proto.WorkspaceAgentScriptCompletedRequest) (*proto.WorkspaceAgentScriptCompletedResponse, error) | ||
| type Runner struct { | ||
| Options | ||
| cronCtx context.Context | ||
| cronCtxCancel context.CancelFunc | ||
| cmdCloseWait sync.WaitGroup | ||
| closed chan struct{} | ||
| closeMutex sync.Mutex | ||
| cron *cron.Cron | ||
| initialized atomic.Bool | ||
| scripts []codersdk.WorkspaceAgentScript | ||
| dataDir string | ||
| scriptCompleted ScriptCompletedFunc | ||
| // scriptsExecuted includes all scripts executed by the workspace agent. Agents | ||
| // execute startup scripts, and scripts on a cron schedule. Both will increment | ||
| @@ -116,12 +122,13 @@ func (r *Runner) RegisterMetrics(reg prometheus.Registerer) { | ||
| // Init initializes the runner with the provided scripts. | ||
| // It also schedules any scripts that have a schedule. | ||
| // This function must be called before Execute. | ||
| func (r *Runner) Init(scripts []codersdk.WorkspaceAgentScript, scriptCompleted ScriptCompletedFunc) error { | ||
| if r.initialized.Load() { | ||
| return xerrors.New("init: already initialized") | ||
| } | ||
| r.initialized.Store(true) | ||
| r.scripts = scripts | ||
| r.scriptCompleted = scriptCompleted | ||
| r.Logger.Info(r.cronCtx, "initializing agent scripts", slog.F("script_count", len(scripts)), slog.F("log_dir", r.LogDir)) | ||
| err := r.Filesystem.MkdirAll(r.ScriptBinDir(), 0o700) | ||
| @@ -135,7 +142,7 @@ func (r *Runner) Init(scripts []codersdk.WorkspaceAgentScript) error { | ||
| } | ||
| script := script | ||
| _, err := r.cron.AddFunc(script.Cron, func() { | ||
| err := r.trackRun(r.cronCtx, script, ExecuteCronScripts) | ||
| if err != nil { | ||
| r.Logger.Warn(context.Background(), "run agent script on schedule", slog.Error(err)) | ||
| } | ||
| @@ -172,22 +179,33 @@ func (r *Runner) StartCron() { | ||
| } | ||
| } | ||
| // ExecuteOption describes what scripts we want to execute. | ||
| type ExecuteOption int | ||
DanielleMaywood marked this conversation as resolved. Show resolvedHide resolvedUh oh!There was an error while loading.Please reload this page. | ||
| // ExecuteOption enums. | ||
| const ( | ||
DanielleMaywood marked this conversation as resolved. Show resolvedHide resolvedUh oh!There was an error while loading.Please reload this page. | ||
| ExecuteAllScripts ExecuteOption = iota | ||
| ExecuteStartScripts | ||
| ExecuteStopScripts | ||
| ExecuteCronScripts | ||
| ) | ||
| // Execute runs a set of scripts according to a filter. | ||
| func (r *Runner) Execute(ctx context.Context, option ExecuteOption) error { | ||
| var eg errgroup.Group | ||
| for _, script := range r.scripts { | ||
| runScript := (option == ExecuteStartScripts && script.RunOnStart) || | ||
| (option == ExecuteStopScripts && script.RunOnStop) || | ||
| (option == ExecuteCronScripts && script.Cron != "") || | ||
| option == ExecuteAllScripts | ||
johnstcn marked this conversation as resolved. Show resolvedHide resolvedUh oh!There was an error while loading.Please reload this page. | ||
| if !runScript { | ||
| continue | ||
| } | ||
| script := script | ||
| eg.Go(func() error { | ||
| err := r.trackRun(ctx, script, option) | ||
| if err != nil { | ||
| return xerrors.Errorf("run agent script %q: %w", script.LogSourceID, err) | ||
| } | ||
| @@ -198,8 +216,8 @@ func (r *Runner) Execute(ctx context.Context, filter func(script codersdk.Worksp | ||
| } | ||
| // trackRun wraps "run" with metrics. | ||
| func (r *Runner) trackRun(ctx context.Context, script codersdk.WorkspaceAgentScript, option ExecuteOption) error { | ||
| err := r.run(ctx, script, option) | ||
| if err != nil { | ||
| r.scriptsExecuted.WithLabelValues("false").Add(1) | ||
| } else { | ||
| @@ -212,7 +230,7 @@ func (r *Runner) trackRun(ctx context.Context, script codersdk.WorkspaceAgentScr | ||
| // If the timeout is exceeded, the process is sent an interrupt signal. | ||
| // If the process does not exit after a few seconds, it is forcefully killed. | ||
| // This function immediately returns after a timeout, and does not wait for the process to exit. | ||
| func (r *Runner) run(ctx context.Context, script codersdk.WorkspaceAgentScript, option ExecuteOption) error { | ||
| logPath := script.LogPath | ||
| if logPath == "" { | ||
| logPath = fmt.Sprintf("coder-script-%s.log", script.LogSourceID) | ||
| @@ -299,9 +317,9 @@ func (r *Runner) run(ctx context.Context, script codersdk.WorkspaceAgentScript) | ||
| cmd.Stdout = io.MultiWriter(fileWriter, infoW) | ||
| cmd.Stderr = io.MultiWriter(fileWriter, errW) | ||
| start :=dbtime.Now() | ||
| defer func() { | ||
| end :=dbtime.Now() | ||
| execTime := end.Sub(start) | ||
| exitCode := 0 | ||
| if err != nil { | ||
| @@ -314,6 +332,60 @@ func (r *Runner) run(ctx context.Context, script codersdk.WorkspaceAgentScript) | ||
| } else { | ||
| logger.Info(ctx, fmt.Sprintf("%s script completed", logPath), slog.F("execution_time", execTime), slog.F("exit_code", exitCode)) | ||
| } | ||
| if r.scriptCompleted == nil { | ||
| logger.Debug(ctx, "r.scriptCompleted unexpectedly nil") | ||
| return | ||
| } | ||
| // We want to check this outside of the goroutine to avoid a race condition | ||
| timedOut := errors.Is(err, ErrTimeout) | ||
| pipesLeftOpen := errors.Is(err, ErrOutputPipesOpen) | ||
| err = r.trackCommandGoroutine(func() { | ||
| var stage proto.Timing_Stage | ||
| switch option { | ||
| case ExecuteStartScripts: | ||
| stage = proto.Timing_START | ||
| case ExecuteStopScripts: | ||
| stage = proto.Timing_STOP | ||
| case ExecuteCronScripts: | ||
| stage = proto.Timing_CRON | ||
| } | ||
| var status proto.Timing_Status | ||
| switch { | ||
| case timedOut: | ||
| status = proto.Timing_TIMED_OUT | ||
| case pipesLeftOpen: | ||
| status = proto.Timing_PIPES_LEFT_OPEN | ||
| case exitCode != 0: | ||
| status = proto.Timing_EXIT_FAILURE | ||
| default: | ||
| status = proto.Timing_OK | ||
| } | ||
| reportTimeout := 30 * time.Second | ||
| reportCtx, cancel := context.WithTimeout(context.Background(), reportTimeout) | ||
| defer cancel() | ||
| _, err := r.scriptCompleted(reportCtx, &proto.WorkspaceAgentScriptCompletedRequest{ | ||
| Timing: &proto.Timing{ | ||
| ScriptId: script.ID[:], | ||
| Start: timestamppb.New(start), | ||
| End: timestamppb.New(end), | ||
| ExitCode: int32(exitCode), | ||
| Stage: stage, | ||
| Status: status, | ||
| }, | ||
| }) | ||
| if err != nil { | ||
| logger.Error(ctx, fmt.Sprintf("reporting script completed: %s", err.Error())) | ||
| } | ||
| }) | ||
| if err != nil { | ||
| logger.Error(ctx, fmt.Sprintf("reporting script completed: track command goroutine: %s", err.Error())) | ||
| } | ||
| }() | ||
| err = cmd.Start() | ||
50 changes: 40 additions & 10 deletionsagent/agentscripts/agentscripts_test.go
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -17,6 +17,7 @@ import ( | ||
| "cdr.dev/slog/sloggers/slogtest" | ||
| "github.com/coder/coder/v2/agent/agentscripts" | ||
| "github.com/coder/coder/v2/agent/agentssh" | ||
| "github.com/coder/coder/v2/agent/agenttest" | ||
| "github.com/coder/coder/v2/codersdk" | ||
| "github.com/coder/coder/v2/codersdk/agentsdk" | ||
| "github.com/coder/coder/v2/testutil" | ||
| @@ -34,14 +35,13 @@ func TestExecuteBasic(t *testing.T) { | ||
| return fLogger | ||
| }) | ||
| defer runner.Close() | ||
| aAPI := agenttest.NewFakeAgentAPI(t, slogtest.Make(t, nil), nil, nil) | ||
| err := runner.Init([]codersdk.WorkspaceAgentScript{{ | ||
| LogSourceID: uuid.New(), | ||
| Script: "echo hello", | ||
| }}, aAPI.ScriptCompleted) | ||
| require.NoError(t, err) | ||
| require.NoError(t, runner.Execute(context.Background(), agentscripts.ExecuteAllScripts)) | ||
| log := testutil.RequireRecvCtx(ctx, t, fLogger.logs) | ||
| require.Equal(t, "hello", log.Output) | ||
| } | ||
| @@ -61,18 +61,17 @@ func TestEnv(t *testing.T) { | ||
| cmd.exe /c echo %CODER_SCRIPT_BIN_DIR% | ||
| ` | ||
| } | ||
| aAPI := agenttest.NewFakeAgentAPI(t, slogtest.Make(t, nil), nil, nil) | ||
| err := runner.Init([]codersdk.WorkspaceAgentScript{{ | ||
| LogSourceID: id, | ||
| Script: script, | ||
| }}, aAPI.ScriptCompleted) | ||
| require.NoError(t, err) | ||
| ctx := testutil.Context(t, testutil.WaitLong) | ||
| done := testutil.Go(t, func() { | ||
| err := runner.Execute(ctx, agentscripts.ExecuteAllScripts) | ||
| assert.NoError(t, err) | ||
| }) | ||
| defer func() { | ||
| @@ -103,13 +102,44 @@ func TestTimeout(t *testing.T) { | ||
| t.Parallel() | ||
| runner := setup(t, nil) | ||
| defer runner.Close() | ||
| aAPI := agenttest.NewFakeAgentAPI(t, slogtest.Make(t, nil), nil, nil) | ||
| err := runner.Init([]codersdk.WorkspaceAgentScript{{ | ||
| LogSourceID: uuid.New(), | ||
| Script: "sleep infinity", | ||
| Timeout: time.Millisecond, | ||
| }}, aAPI.ScriptCompleted) | ||
| require.NoError(t, err) | ||
| require.ErrorIs(t, runner.Execute(context.Background(), agentscripts.ExecuteAllScripts), agentscripts.ErrTimeout) | ||
| } | ||
| func TestScriptReportsTiming(t *testing.T) { | ||
dannykopping marked this conversation as resolved. Show resolvedHide resolvedUh oh!There was an error while loading.Please reload this page. There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others.Learn more. I think we need to expand this a bit to cover the timeout and non-zero exit status use-cases. There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others.Learn more. Yeah, definitely a good idea. I had tried a non-zero exit code but it appeared to cause the test to fail so I'll investigate that again to make sure it wasn't me doing something wrong. There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others.Learn more. Potentially a follow-up PR? | ||
| t.Parallel() | ||
| ctx := testutil.Context(t, testutil.WaitShort) | ||
| fLogger := newFakeScriptLogger() | ||
| runner := setup(t, func(uuid2 uuid.UUID) agentscripts.ScriptLogger { | ||
| return fLogger | ||
| }) | ||
| aAPI := agenttest.NewFakeAgentAPI(t, slogtest.Make(t, nil), nil, nil) | ||
| err := runner.Init([]codersdk.WorkspaceAgentScript{{ | ||
| DisplayName: "say-hello", | ||
| LogSourceID: uuid.New(), | ||
| Script: "echo hello", | ||
| }}, aAPI.ScriptCompleted) | ||
| require.NoError(t, err) | ||
| require.NoError(t, runner.Execute(ctx, agentscripts.ExecuteAllScripts)) | ||
| runner.Close() | ||
| log := testutil.RequireRecvCtx(ctx, t, fLogger.logs) | ||
| require.Equal(t, "hello", log.Output) | ||
| timings := aAPI.GetTimings() | ||
| require.Equal(t, 1, len(timings)) | ||
| timing := timings[0] | ||
| require.Equal(t, int32(0), timing.ExitCode) | ||
| require.GreaterOrEqual(t, timing.End.AsTime(), timing.Start.AsTime()) | ||
| } | ||
| // TestCronClose exists because cron.Run() can happen after cron.Close(). | ||
15 changes: 15 additions & 0 deletionsagent/agenttest/client.go
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.Learn more about bidirectional Unicode characters
Oops, something went wrong.
Uh oh!
There was an error while loading.Please reload this page.
Oops, something went wrong.
Uh oh!
There was an error while loading.Please reload this page.
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.