From 624e367827c6ab018f479d92d533e6c2ae01eae8 Mon Sep 17 00:00:00 2001 From: Mathias Fredriksson Date: Wed, 14 Jun 2023 15:29:30 +0000 Subject: [PATCH 1/9] fix: Send startup log EOF and prevent lost messages --- agent/agent.go | 13 ++ agent/agent_test.go | 4 +- coderd/apidoc/docs.go | 3 + coderd/apidoc/swagger.json | 3 + coderd/database/dbfake/dbfake.go | 3 +- coderd/database/dump.sql | 5 +- .../000126_add_startup_logs_eof.down.sql | 1 + .../000126_add_startup_logs_eof.up.sql | 3 + coderd/database/models.go | 2 + coderd/database/querier_test.go | 2 + coderd/database/queries.sql.go | 15 +- coderd/database/queries/workspaceagents.sql | 5 +- coderd/database/sqlc.yaml | 1 + coderd/workspaceagents.go | 184 +++++++++++------- coderd/workspaceagents_test.go | 113 +++++++++++ coderd/workspaces.go | 12 ++ codersdk/agentsdk/agentsdk.go | 1 + codersdk/workspaceagents.go | 10 + docs/api/schemas.md | 3 + 19 files changed, 300 insertions(+), 83 deletions(-) create mode 100644 coderd/database/migrations/000126_add_startup_logs_eof.down.sql create mode 100644 coderd/database/migrations/000126_add_startup_logs_eof.up.sql diff --git a/agent/agent.go b/agent/agent.go index 506de80f6ad54..a60471c32a7aa 100644 --- a/agent/agent.go +++ b/agent/agent.go @@ -929,6 +929,11 @@ func (a *agent) trackScriptLogs(ctx context.Context, reader io.Reader) (chan str if errors.As(err, &sdkErr) { if sdkErr.StatusCode() == http.StatusRequestEntityTooLarge { a.logger.Warn(ctx, "startup logs too large, dropping logs") + // Always send the EOF even if logs overflow. + if len(logsToSend) > 1 && logsToSend[len(logsToSend)-1].EOF { + logsToSend = logsToSend[len(logsToSend)-1:] + continue + } break } } @@ -978,6 +983,14 @@ func (a *agent) trackScriptLogs(ctx context.Context, reader io.Reader) (chan str Output: scanner.Text(), }) } + if err := scanner.Err(); err != nil { + a.logger.Error(ctx, "scan startup logs", slog.Error(err)) + } + queueLog(agentsdk.StartupLog{ + CreatedAt: database.Now(), + Output: "", + EOF: true, + }) defer close(logsFinished) logsFlushed.L.Lock() for { diff --git a/agent/agent_test.go b/agent/agent_test.go index 832919e7bf5df..0c15269343a40 100644 --- a/agent/agent_test.go +++ b/agent/agent_test.go @@ -905,8 +905,10 @@ func TestAgent_StartupScript(t *testing.T) { return len(got) > 0 && got[len(got)-1] == codersdk.WorkspaceAgentLifecycleReady }, testutil.WaitShort, testutil.IntervalMedium) - require.Len(t, client.getStartupLogs(), 1) + require.Len(t, client.getStartupLogs(), 2) require.Equal(t, output, client.getStartupLogs()[0].Output) + require.False(t, client.getStartupLogs()[0].EOF) + require.True(t, client.getStartupLogs()[1].EOF) }) // This ensures that even when coderd sends back that the startup // script has written too many lines it will still succeed! diff --git a/coderd/apidoc/docs.go b/coderd/apidoc/docs.go index c29243d6c6e1a..caad2e2966a82 100644 --- a/coderd/apidoc/docs.go +++ b/coderd/apidoc/docs.go @@ -5856,6 +5856,9 @@ const docTemplate = `{ "created_at": { "type": "string" }, + "eof": { + "type": "boolean" + }, "level": { "$ref": "#/definitions/codersdk.LogLevel" }, diff --git a/coderd/apidoc/swagger.json b/coderd/apidoc/swagger.json index 38f72a070b17b..b4d5ccb215de0 100644 --- a/coderd/apidoc/swagger.json +++ b/coderd/apidoc/swagger.json @@ -5171,6 +5171,9 @@ "created_at": { "type": "string" }, + "eof": { + "type": "boolean" + }, "level": { "$ref": "#/definitions/codersdk.LogLevel" }, diff --git a/coderd/database/dbfake/dbfake.go b/coderd/database/dbfake/dbfake.go index dad08f081a4a9..8e1b31298dccb 100644 --- a/coderd/database/dbfake/dbfake.go +++ b/coderd/database/dbfake/dbfake.go @@ -2722,7 +2722,7 @@ func (q *fakeQuerier) GetWorkspaceAgentStartupLogsAfter(_ context.Context, arg d if log.AgentID != arg.AgentID { continue } - if arg.CreatedAfter != 0 && log.ID < arg.CreatedAfter { + if arg.CreatedAfter != 0 && log.ID <= arg.CreatedAfter { continue } logs = append(logs, log) @@ -4026,6 +4026,7 @@ func (q *fakeQuerier) InsertWorkspaceAgentStartupLogs(_ context.Context, arg dat CreatedAt: arg.CreatedAt[index], Level: arg.Level[index], Output: output, + EOF: arg.EOF[index], }) outputLength += int32(len(output)) } diff --git a/coderd/database/dump.sql b/coderd/database/dump.sql index 174e6d42aa0d9..33e1e9f24b523 100644 --- a/coderd/database/dump.sql +++ b/coderd/database/dump.sql @@ -545,9 +545,12 @@ CREATE TABLE workspace_agent_startup_logs ( created_at timestamp with time zone NOT NULL, output character varying(1024) NOT NULL, id bigint NOT NULL, - level log_level DEFAULT 'info'::log_level NOT NULL + level log_level DEFAULT 'info'::log_level NOT NULL, + eof boolean DEFAULT false NOT NULL ); +COMMENT ON COLUMN workspace_agent_startup_logs.eof IS 'End of file reached'; + CREATE SEQUENCE workspace_agent_startup_logs_id_seq START WITH 1 INCREMENT BY 1 diff --git a/coderd/database/migrations/000126_add_startup_logs_eof.down.sql b/coderd/database/migrations/000126_add_startup_logs_eof.down.sql new file mode 100644 index 0000000000000..f5b684da8236b --- /dev/null +++ b/coderd/database/migrations/000126_add_startup_logs_eof.down.sql @@ -0,0 +1 @@ +ALTER TABLE workspace_agent_startup_logs DROP COLUMN eof; diff --git a/coderd/database/migrations/000126_add_startup_logs_eof.up.sql b/coderd/database/migrations/000126_add_startup_logs_eof.up.sql new file mode 100644 index 0000000000000..b7c1aa5848486 --- /dev/null +++ b/coderd/database/migrations/000126_add_startup_logs_eof.up.sql @@ -0,0 +1,3 @@ +ALTER TABLE workspace_agent_startup_logs ADD COLUMN eof boolean NOT NULL DEFAULT false; + +COMMENT ON COLUMN workspace_agent_startup_logs.eof IS 'End of file reached'; diff --git a/coderd/database/models.go b/coderd/database/models.go index cd571d6bba803..19b991b10de9d 100644 --- a/coderd/database/models.go +++ b/coderd/database/models.go @@ -1727,6 +1727,8 @@ type WorkspaceAgentStartupLog struct { Output string `db:"output" json:"output"` ID int64 `db:"id" json:"id"` Level LogLevel `db:"level" json:"level"` + // End of file reached + EOF bool `db:"eof" json:"eof"` } type WorkspaceAgentStat struct { diff --git a/coderd/database/querier_test.go b/coderd/database/querier_test.go index 73bc960488a15..4a11847d5b4aa 100644 --- a/coderd/database/querier_test.go +++ b/coderd/database/querier_test.go @@ -114,6 +114,7 @@ func TestInsertWorkspaceAgentStartupLogs(t *testing.T) { CreatedAt: []time.Time{database.Now()}, Output: []string{"first"}, Level: []database.LogLevel{database.LogLevelInfo}, + EOF: []bool{false}, // 1 MB is the max OutputLength: 1 << 20, }) @@ -125,6 +126,7 @@ func TestInsertWorkspaceAgentStartupLogs(t *testing.T) { CreatedAt: []time.Time{database.Now()}, Output: []string{"second"}, Level: []database.LogLevel{database.LogLevelInfo}, + EOF: []bool{false}, OutputLength: 1, }) require.True(t, database.IsStartupLogsLimitError(err)) diff --git a/coderd/database/queries.sql.go b/coderd/database/queries.sql.go index 2c71a96ccc4e0..cfc51c2ab393e 100644 --- a/coderd/database/queries.sql.go +++ b/coderd/database/queries.sql.go @@ -5438,7 +5438,7 @@ func (q *sqlQuerier) GetWorkspaceAgentMetadata(ctx context.Context, workspaceAge const getWorkspaceAgentStartupLogsAfter = `-- name: GetWorkspaceAgentStartupLogsAfter :many SELECT - agent_id, created_at, output, id, level + agent_id, created_at, output, id, level, eof FROM workspace_agent_startup_logs WHERE @@ -5468,6 +5468,7 @@ func (q *sqlQuerier) GetWorkspaceAgentStartupLogsAfter(ctx context.Context, arg &i.Output, &i.ID, &i.Level, + &i.EOF, ); err != nil { return nil, err } @@ -5833,16 +5834,17 @@ func (q *sqlQuerier) InsertWorkspaceAgentMetadata(ctx context.Context, arg Inser const insertWorkspaceAgentStartupLogs = `-- name: InsertWorkspaceAgentStartupLogs :many WITH new_length AS ( UPDATE workspace_agents SET - startup_logs_length = startup_logs_length + $5 WHERE workspace_agents.id = $1 + startup_logs_length = startup_logs_length + $6 WHERE workspace_agents.id = $1 ) INSERT INTO - workspace_agent_startup_logs (agent_id, created_at, output, level) + workspace_agent_startup_logs (agent_id, created_at, output, level, eof) SELECT $1 :: uuid AS agent_id, unnest($2 :: timestamptz [ ]) AS created_at, unnest($3 :: VARCHAR(1024) [ ]) AS output, - unnest($4 :: log_level [ ]) AS level - RETURNING workspace_agent_startup_logs.agent_id, workspace_agent_startup_logs.created_at, workspace_agent_startup_logs.output, workspace_agent_startup_logs.id, workspace_agent_startup_logs.level + unnest($4 :: log_level [ ]) AS level, + unnest($5 :: boolean [ ]) AS eof + RETURNING workspace_agent_startup_logs.agent_id, workspace_agent_startup_logs.created_at, workspace_agent_startup_logs.output, workspace_agent_startup_logs.id, workspace_agent_startup_logs.level, workspace_agent_startup_logs.eof ` type InsertWorkspaceAgentStartupLogsParams struct { @@ -5850,6 +5852,7 @@ type InsertWorkspaceAgentStartupLogsParams struct { CreatedAt []time.Time `db:"created_at" json:"created_at"` Output []string `db:"output" json:"output"` Level []LogLevel `db:"level" json:"level"` + EOF []bool `db:"eof" json:"eof"` OutputLength int32 `db:"output_length" json:"output_length"` } @@ -5859,6 +5862,7 @@ func (q *sqlQuerier) InsertWorkspaceAgentStartupLogs(ctx context.Context, arg In pq.Array(arg.CreatedAt), pq.Array(arg.Output), pq.Array(arg.Level), + pq.Array(arg.EOF), arg.OutputLength, ) if err != nil { @@ -5874,6 +5878,7 @@ func (q *sqlQuerier) InsertWorkspaceAgentStartupLogs(ctx context.Context, arg In &i.Output, &i.ID, &i.Level, + &i.EOF, ); err != nil { return nil, err } diff --git a/coderd/database/queries/workspaceagents.sql b/coderd/database/queries/workspaceagents.sql index b587e314fe5a6..a57843d709be8 100644 --- a/coderd/database/queries/workspaceagents.sql +++ b/coderd/database/queries/workspaceagents.sql @@ -152,12 +152,13 @@ WITH new_length AS ( startup_logs_length = startup_logs_length + @output_length WHERE workspace_agents.id = @agent_id ) INSERT INTO - workspace_agent_startup_logs (agent_id, created_at, output, level) + workspace_agent_startup_logs (agent_id, created_at, output, level, eof) SELECT @agent_id :: uuid AS agent_id, unnest(@created_at :: timestamptz [ ]) AS created_at, unnest(@output :: VARCHAR(1024) [ ]) AS output, - unnest(@level :: log_level [ ]) AS level + unnest(@level :: log_level [ ]) AS level, + unnest(@eof :: boolean [ ]) AS eof RETURNING workspace_agent_startup_logs.*; -- If an agent hasn't connected in the last 7 days, we purge it's logs. diff --git a/coderd/database/sqlc.yaml b/coderd/database/sqlc.yaml index 0330a3503e1ef..1eee41678458d 100644 --- a/coderd/database/sqlc.yaml +++ b/coderd/database/sqlc.yaml @@ -55,6 +55,7 @@ overrides: uuid: UUID failure_ttl: FailureTTL inactivity_ttl: InactivityTTL + eof: EOF sql: - schema: "./dump.sql" diff --git a/coderd/workspaceagents.go b/coderd/workspaceagents.go index f2d3acfb742dd..82b129172be6e 100644 --- a/coderd/workspaceagents.go +++ b/coderd/workspaceagents.go @@ -259,6 +259,8 @@ func (api *API) patchWorkspaceAgentStartupLogs(rw http.ResponseWriter, r *http.R createdAt := make([]time.Time, 0) output := make([]string, 0) level := make([]database.LogLevel, 0) + eof := make([]bool, 0) + var endLog agentsdk.StartupLog outputLength := 0 for _, logEntry := range req.Logs { createdAt = append(createdAt, logEntry.CreatedAt) @@ -277,12 +279,17 @@ func (api *API) patchWorkspaceAgentStartupLogs(rw http.ResponseWriter, r *http.R return } level = append(level, parsedLevel) + eof = append(eof, logEntry.EOF) + if logEntry.EOF { + endLog = logEntry + } } logs, err := api.Database.InsertWorkspaceAgentStartupLogs(ctx, database.InsertWorkspaceAgentStartupLogsParams{ AgentID: workspaceAgent.ID, CreatedAt: createdAt, Output: output, Level: level, + EOF: eof, OutputLength: int32(outputLength), }) if err != nil { @@ -332,6 +339,13 @@ func (api *API) patchWorkspaceAgentStartupLogs(rw http.ResponseWriter, r *http.R }) return } + + lowestID := logs[0].ID + + // Publish by the lowest log ID inserted so the + // log stream will fetch everything from that point. + api.publishWorkspaceAgentStartupLogsUpdate(ctx, workspaceAgent.ID, agentsdk.StartupLogsNotifyMessage{CreatedAfter: lowestID - 1, EndOfLogs: endLog.EOF}) + if workspaceAgent.StartupLogsLength == 0 { // If these are the first logs being appended, we publish a UI update // to notify the UI that logs are now available. @@ -356,26 +370,6 @@ func (api *API) patchWorkspaceAgentStartupLogs(rw http.ResponseWriter, r *http.R api.publishWorkspaceUpdate(ctx, build.WorkspaceID) } - lowestID := logs[0].ID - // Publish by the lowest log ID inserted so the - // log stream will fetch everything from that point. - data, err := json.Marshal(agentsdk.StartupLogsNotifyMessage{ - CreatedAfter: lowestID - 1, - }) - if err != nil { - httpapi.Write(ctx, rw, http.StatusInternalServerError, codersdk.Response{ - Message: "Failed to marshal startup logs notify message", - Detail: err.Error(), - }) - return - } - err = api.Pubsub.Publish(agentsdk.StartupLogsNotifyChannel(workspaceAgent.ID), data) - if err != nil { - // We don't want to return an error to the agent here, - // otherwise it might try to reinsert the logs. - api.Logger.Warn(ctx, "failed to publish startup logs notify message", slog.Error(err)) - } - httpapi.Write(ctx, rw, http.StatusOK, nil) } @@ -397,7 +391,6 @@ func (api *API) workspaceAgentStartupLogs(rw http.ResponseWriter, r *http.Reques // This mostly copies how provisioner job logs are streamed! var ( ctx = r.Context() - actor, _ = dbauthz.ActorFromContext(ctx) workspaceAgent = httpmw.WorkspaceAgentParam(r) logger = api.Logger.With(slog.F("workspace_agent_id", workspaceAgent.ID)) follow = r.URL.Query().Has("follow") @@ -438,6 +431,21 @@ func (api *API) workspaceAgentStartupLogs(rw http.ResponseWriter, r *http.Reques logs = []database.WorkspaceAgentStartupLog{} } + var ( + eof = false + lastSentLogID = after // Used further down to avoid fetching the same logs twice. + ) + if len(logs) > 0 { + last := logs[len(logs)-1] + eof = last.EOF + lastSentLogID = last.ID + } + + if eof { + // We don't send the EOF log, it simply indicates we are done. + logs = logs[:len(logs)-1] + } + if !follow { logger.Debug(ctx, "Finished non-follow job logs") httpapi.Write(ctx, rw, http.StatusOK, convertWorkspaceAgentStartupLogs(logs)) @@ -467,84 +475,114 @@ func (api *API) workspaceAgentStartupLogs(rw http.ResponseWriter, r *http.Reques if err != nil { return } - if workspaceAgent.LifecycleState == database.WorkspaceAgentLifecycleStateReady { + if eof { // The startup script has finished running, so we can close the connection. return } + if !codersdk.WorkspaceAgentLifecycle(workspaceAgent.LifecycleState).Starting() { + // Avoid waiting forever in case EOF was lost or the agent is old. + // Note that it's still possible for this websocket to remain + // open indefinitely if either of the above conditions are true + // and this follow request is made while the agent is starting. + return + } - var ( - bufferedLogs = make(chan []database.WorkspaceAgentStartupLog, 128) - endOfLogs atomic.Bool - lastSentLogID atomic.Int64 - ) + notifyCh := make(chan struct{}, 1) + // Allow us to immediately check if we missed any logs + // between initial fetch and subscribe. + notifyCh <- struct{}{} - sendLogs := func(logs []database.WorkspaceAgentStartupLog) { + // Subscribe early to prevent missing log events. + closeSubscribe, err := api.Pubsub.Subscribe(agentsdk.StartupLogsNotifyChannel(workspaceAgent.ID), func(ctx context.Context, message []byte) { + logger.Debug(ctx, "received startup log message") + // The message is not important, we're tracking lastSentLogID manually. select { - case bufferedLogs <- logs: - lastSentLogID.Store(logs[len(logs)-1].ID) + case notifyCh <- struct{}{}: default: - logger.Warn(ctx, "workspace agent startup log overflowing channel") } + }) + if err != nil { + httpapi.Write(ctx, rw, http.StatusInternalServerError, codersdk.Response{ + Message: "Failed to subscribe to startup logs.", + Detail: err.Error(), + }) + return } + defer closeSubscribe() - closeSubscribe, err := api.Pubsub.Subscribe( - agentsdk.StartupLogsNotifyChannel(workspaceAgent.ID), - func(ctx context.Context, message []byte) { - if endOfLogs.Load() { - return - } - jlMsg := agentsdk.StartupLogsNotifyMessage{} - err := json.Unmarshal(message, &jlMsg) - if err != nil { - logger.Warn(ctx, "invalid startup logs notify message", slog.Error(err)) + // Buffer size controls the log prefetch capacity. + bufferedLogs := make(chan []database.WorkspaceAgentStartupLog, 8) + // Check at least once per minute in case we didn't receive a pubsub message. + recheckInterval := time.Minute + t := time.NewTicker(recheckInterval) + defer t.Stop() + + go func() { + defer close(bufferedLogs) + for { + select { + case <-ctx.Done(): return + case <-t.C: + case <-notifyCh: + t.Reset(recheckInterval) } - if jlMsg.CreatedAfter != 0 { - logs, err := api.Database.GetWorkspaceAgentStartupLogsAfter(dbauthz.As(ctx, actor), database.GetWorkspaceAgentStartupLogsAfterParams{ - AgentID: workspaceAgent.ID, - CreatedAfter: jlMsg.CreatedAfter, - }) - if err != nil { - logger.Warn(ctx, "failed to get workspace agent startup logs after", slog.Error(err)) + logs, err := api.Database.GetWorkspaceAgentStartupLogsAfter(ctx, database.GetWorkspaceAgentStartupLogsAfterParams{ + AgentID: workspaceAgent.ID, + CreatedAfter: lastSentLogID, + }) + if err != nil { + if xerrors.Is(err, context.Canceled) { return } - sendLogs(logs) + logger.Warn(ctx, "failed to get workspace agent startup logs after", slog.Error(err)) + continue + } + if len(logs) == 0 { + continue } - if jlMsg.EndOfLogs { - endOfLogs.Store(true) - logs, err := api.Database.GetWorkspaceAgentStartupLogsAfter(dbauthz.As(ctx, actor), database.GetWorkspaceAgentStartupLogsAfterParams{ - AgentID: workspaceAgent.ID, - CreatedAfter: lastSentLogID.Load(), - }) - if err != nil { - logger.Warn(ctx, "get workspace agent startup logs after", slog.Error(err)) + eof := logs[len(logs)-1].EOF + if eof { + // Discard the EOF message, it's an empty log entry. + logs = logs[:len(logs)-1] + if len(logs) == 0 { return } - sendLogs(logs) - bufferedLogs <- nil } - }, - ) - if err != nil { - httpapi.Write(ctx, rw, http.StatusInternalServerError, codersdk.Response{ - Message: "Failed to subscribe to startup logs.", - Detail: err.Error(), - }) - return - } - defer closeSubscribe() + + select { + case <-ctx.Done(): + return + case bufferedLogs <- logs: + lastSentLogID = logs[len(logs)-1].ID + } + if eof { + return + } + } + }() + defer func() { + // Ensure that we don't return until the goroutine has exited. + //nolint:revive // Consume channel to wait until it's closed. + for range bufferedLogs { + } + }() for { select { case <-ctx.Done(): - logger.Debug(context.Background(), "job logs context canceled") + logger.Debug(ctx, "job logs context canceled") return case logs, ok := <-bufferedLogs: - // A nil log is sent when complete! - if !ok || logs == nil { - logger.Debug(context.Background(), "reached the end of published logs") + if !ok { + select { + case <-ctx.Done(): + logger.Debug(ctx, "job logs context canceled") + default: + logger.Debug(ctx, "reached the end of published logs") + } return } err = encoder.Encode(convertWorkspaceAgentStartupLogs(logs)) diff --git a/coderd/workspaceagents_test.go b/coderd/workspaceagents_test.go index 2a514385d94df..a3608bfeb3964 100644 --- a/coderd/workspaceagents_test.go +++ b/coderd/workspaceagents_test.go @@ -294,6 +294,119 @@ func TestWorkspaceAgentStartupLogs(t *testing.T) { } } }) + t.Run("AllowEOFAfterOverflowAndCloseFollow", func(t *testing.T) { + t.Parallel() + ctx := testutil.Context(t, testutil.WaitMedium) + client := coderdtest.New(t, &coderdtest.Options{ + IncludeProvisionerDaemon: true, + }) + user := coderdtest.CreateFirstUser(t, client) + authToken := uuid.NewString() + version := coderdtest.CreateTemplateVersion(t, client, user.OrganizationID, &echo.Responses{ + Parse: echo.ParseComplete, + ProvisionPlan: echo.ProvisionComplete, + ProvisionApply: []*proto.Provision_Response{{ + Type: &proto.Provision_Response_Complete{ + Complete: &proto.Provision_Complete{ + Resources: []*proto.Resource{{ + Name: "example", + Type: "aws_instance", + Agents: []*proto.Agent{{ + Id: uuid.NewString(), + Auth: &proto.Agent_Token{ + Token: authToken, + }, + }}, + }}, + }, + }, + }}, + }) + template := coderdtest.CreateTemplate(t, client, user.OrganizationID, version.ID) + coderdtest.AwaitTemplateVersionJob(t, client, version.ID) + workspace := coderdtest.CreateWorkspace(t, client, user.OrganizationID, template.ID) + build := coderdtest.AwaitWorkspaceBuildJob(t, client, workspace.LatestBuild.ID) + + updates, err := client.WatchWorkspace(ctx, workspace.ID) + require.NoError(t, err) + + logs, closeLogs, err := client.WorkspaceAgentStartupLogsAfter(ctx, build.Resources[0].Agents[0].ID, 0) + require.NoError(t, err) + defer closeLogs.Close() + + wantLogs := []codersdk.WorkspaceAgentStartupLog{ + { + CreatedAt: database.Now(), + Output: "testing", + Level: "info", + }, + } + + agentClient := agentsdk.New(client.URL) + agentClient.SetSessionToken(authToken) + + var startupLogs []agentsdk.StartupLog + for _, log := range wantLogs { + startupLogs = append(startupLogs, agentsdk.StartupLog{ + CreatedAt: log.CreatedAt, + Output: log.Output, + Level: log.Level, + }) + } + err = agentClient.PatchStartupLogs(ctx, agentsdk.PatchStartupLogs{Logs: startupLogs}) + require.NoError(t, err) + + overflowLogs := []agentsdk.StartupLog{ + { + CreatedAt: database.Now(), + Output: strings.Repeat("a", (1<<20)+1), + }, + { + CreatedAt: database.Now(), + EOF: true, + }, + } + err = agentClient.PatchStartupLogs(ctx, agentsdk.PatchStartupLogs{Logs: overflowLogs}) + var apiError *codersdk.Error + require.ErrorAs(t, err, &apiError) + require.Equal(t, http.StatusRequestEntityTooLarge, apiError.StatusCode()) + + // It's possible we have multiple updates queued, but that's alright, we just + // wait for the one where it overflows. + for { + var update codersdk.Workspace + select { + case <-ctx.Done(): + require.Fail(t, "timed out waiting for overflow") + case update = <-updates: + } + if update.LatestBuild.Resources[0].Agents[0].StartupLogsOverflowed { + break + } + } + + // Now we should still be able to send the EOF. + err = agentClient.PatchStartupLogs(ctx, agentsdk.PatchStartupLogs{Logs: overflowLogs[len(overflowLogs)-1:]}) + require.NoError(t, err) + + var gotLogs []codersdk.WorkspaceAgentStartupLog + logsLoop: + for { + select { + case <-ctx.Done(): + require.Fail(t, "timed out waiting for logs") + case l, ok := <-logs: + if !ok { + break logsLoop + } + gotLogs = append(gotLogs, l...) + } + } + for i := range gotLogs { + gotLogs[i].ID = 0 // Ignore ID for comparison. + } + require.Equal(t, wantLogs, gotLogs) + }) } func TestWorkspaceAgentListen(t *testing.T) { diff --git a/coderd/workspaces.go b/coderd/workspaces.go index a1bed7c9d1f45..981d161bf3e2b 100644 --- a/coderd/workspaces.go +++ b/coderd/workspaces.go @@ -27,6 +27,7 @@ import ( "github.com/coder/coder/coderd/util/ptr" "github.com/coder/coder/coderd/wsbuilder" "github.com/coder/coder/codersdk" + "github.com/coder/coder/codersdk/agentsdk" ) var ( @@ -1178,3 +1179,14 @@ func (api *API) publishWorkspaceUpdate(ctx context.Context, workspaceID uuid.UUI slog.F("workspace_id", workspaceID), slog.Error(err)) } } + +func (api *API) publishWorkspaceAgentStartupLogsUpdate(ctx context.Context, workspaceAgentID uuid.UUID, m agentsdk.StartupLogsNotifyMessage) { + b, err := json.Marshal(m) + if err != nil { + api.Logger.Warn(ctx, "failed to marshal startup logs notify message", slog.F("workspace_agent_id", workspaceAgentID), slog.Error(err)) + } + err = api.Pubsub.Publish(agentsdk.StartupLogsNotifyChannel(workspaceAgentID), b) + if err != nil { + api.Logger.Warn(ctx, "failed to publish workspace agent startup logs update", slog.F("workspace_agent_id", workspaceAgentID), slog.Error(err)) + } +} diff --git a/codersdk/agentsdk/agentsdk.go b/codersdk/agentsdk/agentsdk.go index a14dbb54ccccc..90d2834a37337 100644 --- a/codersdk/agentsdk/agentsdk.go +++ b/codersdk/agentsdk/agentsdk.go @@ -571,6 +571,7 @@ type StartupLog struct { CreatedAt time.Time `json:"created_at"` Output string `json:"output"` Level codersdk.LogLevel `json:"level"` + EOF bool `json:"eof"` } type PatchStartupLogs struct { diff --git a/codersdk/workspaceagents.go b/codersdk/workspaceagents.go index 34397e89c43f7..26b4fa7284720 100644 --- a/codersdk/workspaceagents.go +++ b/codersdk/workspaceagents.go @@ -58,6 +58,16 @@ const ( WorkspaceAgentLifecycleOff WorkspaceAgentLifecycle = "off" ) +// Starting returns true if the agent is in the process of starting. +func (l WorkspaceAgentLifecycle) Starting() bool { + switch l { + case WorkspaceAgentLifecycleCreated, WorkspaceAgentLifecycleStarting, WorkspaceAgentLifecycleStartTimeout: + return true + default: + return false + } +} + // WorkspaceAgentLifecycleOrder is the order in which workspace agent // lifecycle states are expected to be reported during the lifetime of // the agent process. For instance, the agent can go from starting to diff --git a/docs/api/schemas.md b/docs/api/schemas.md index e4fd03c5cd0b7..0d793f02acdfb 100644 --- a/docs/api/schemas.md +++ b/docs/api/schemas.md @@ -280,6 +280,7 @@ "logs": [ { "created_at": "string", + "eof": true, "level": "trace", "output": "string" } @@ -368,6 +369,7 @@ ```json { "created_at": "string", + "eof": true, "level": "trace", "output": "string" } @@ -378,6 +380,7 @@ | Name | Type | Required | Restrictions | Description | | ------------ | -------------------------------------- | -------- | ------------ | ----------- | | `created_at` | string | false | | | +| `eof` | boolean | false | | | | `level` | [codersdk.LogLevel](#codersdkloglevel) | false | | | | `output` | string | false | | | From 6fe8045f48fee55f1a406b96e69e69197a95b5db Mon Sep 17 00:00:00 2001 From: Mathias Fredriksson Date: Fri, 16 Jun 2023 12:44:28 +0000 Subject: [PATCH 2/9] Ensure startup logs are closed on lifecycle state change --- coderd/apidoc/docs.go | 4 + coderd/apidoc/swagger.json | 4 + coderd/database/dbauthz/dbauthz.go | 8 + coderd/database/dbfake/dbfake.go | 18 +- coderd/database/dbmetrics/dbmetrics.go | 7 + coderd/database/dbmock/dbmock.go | 15 ++ ...l => 000127_add_startup_logs_eof.down.sql} | 0 ...sql => 000127_add_startup_logs_eof.up.sql} | 0 coderd/database/querier.go | 1 + coderd/database/queries.sql.go | 20 +++ coderd/database/queries/workspaceagents.sql | 12 ++ coderd/workspaceagents.go | 164 +++++++++++------ coderd/workspaceagents_test.go | 169 ++++++++++++++++-- codersdk/workspaceagents.go | 1 + docs/api/agents.md | 16 +- docs/api/schemas.md | 14 +- site/src/api/typesGenerated.ts | 1 + site/src/testHelpers/entities.ts | 11 ++ 18 files changed, 382 insertions(+), 83 deletions(-) rename coderd/database/migrations/{000126_add_startup_logs_eof.down.sql => 000127_add_startup_logs_eof.down.sql} (100%) rename coderd/database/migrations/{000126_add_startup_logs_eof.up.sql => 000127_add_startup_logs_eof.up.sql} (100%) diff --git a/coderd/apidoc/docs.go b/coderd/apidoc/docs.go index 133317f200184..4ea7036e01129 100644 --- a/coderd/apidoc/docs.go +++ b/coderd/apidoc/docs.go @@ -9381,6 +9381,10 @@ const docTemplate = `{ "type": "string", "format": "date-time" }, + "eof": { + "description": "EOF indicates that this is the last log entry and the file is closed.", + "type": "boolean" + }, "id": { "type": "integer" }, diff --git a/coderd/apidoc/swagger.json b/coderd/apidoc/swagger.json index b31f9244b9878..eea32d65ade16 100644 --- a/coderd/apidoc/swagger.json +++ b/coderd/apidoc/swagger.json @@ -8477,6 +8477,10 @@ "type": "string", "format": "date-time" }, + "eof": { + "description": "EOF indicates that this is the last log entry and the file is closed.", + "type": "boolean" + }, "id": { "type": "integer" }, diff --git a/coderd/database/dbauthz/dbauthz.go b/coderd/database/dbauthz/dbauthz.go index 30b8c5d33569c..dc8b10e5a1f27 100644 --- a/coderd/database/dbauthz/dbauthz.go +++ b/coderd/database/dbauthz/dbauthz.go @@ -1407,6 +1407,14 @@ func (q *querier) GetWorkspaceAgentStartupLogsAfter(ctx context.Context, arg dat return q.db.GetWorkspaceAgentStartupLogsAfter(ctx, arg) } +func (q *querier) GetWorkspaceAgentStartupLogsEOF(ctx context.Context, agentID uuid.UUID) (bool, error) { + _, err := q.GetWorkspaceAgentByID(ctx, agentID) + if err != nil { + return false, err + } + return q.db.GetWorkspaceAgentStartupLogsEOF(ctx, agentID) +} + func (q *querier) GetWorkspaceAgentStats(ctx context.Context, createdAfter time.Time) ([]database.GetWorkspaceAgentStatsRow, error) { return q.db.GetWorkspaceAgentStats(ctx, createdAfter) } diff --git a/coderd/database/dbfake/dbfake.go b/coderd/database/dbfake/dbfake.go index 8e1b31298dccb..ad7aa81c3bf35 100644 --- a/coderd/database/dbfake/dbfake.go +++ b/coderd/database/dbfake/dbfake.go @@ -2730,6 +2730,22 @@ func (q *fakeQuerier) GetWorkspaceAgentStartupLogsAfter(_ context.Context, arg d return logs, nil } +func (q *fakeQuerier) GetWorkspaceAgentStartupLogsEOF(ctx context.Context, agentID uuid.UUID) (bool, error) { + q.mutex.RLock() + defer q.mutex.RUnlock() + + var lastLog database.WorkspaceAgentStartupLog + for _, log := range q.workspaceAgentLogs { + if log.AgentID != agentID { + continue + } + if log.ID > lastLog.ID { + lastLog = log + } + } + return lastLog.EOF, nil +} + func (q *fakeQuerier) GetWorkspaceAgentStats(_ context.Context, createdAfter time.Time) ([]database.GetWorkspaceAgentStatsRow, error) { q.mutex.RLock() defer q.mutex.RUnlock() @@ -4013,7 +4029,7 @@ func (q *fakeQuerier) InsertWorkspaceAgentStartupLogs(_ context.Context, arg dat defer q.mutex.Unlock() logs := []database.WorkspaceAgentStartupLog{} - id := int64(1) + id := int64(0) if len(q.workspaceAgentLogs) > 0 { id = q.workspaceAgentLogs[len(q.workspaceAgentLogs)-1].ID } diff --git a/coderd/database/dbmetrics/dbmetrics.go b/coderd/database/dbmetrics/dbmetrics.go index 49cf5fc402c5e..416ad3a9a368d 100644 --- a/coderd/database/dbmetrics/dbmetrics.go +++ b/coderd/database/dbmetrics/dbmetrics.go @@ -738,6 +738,13 @@ func (m metricsStore) GetWorkspaceAgentStartupLogsAfter(ctx context.Context, arg return logs, err } +func (m metricsStore) GetWorkspaceAgentStartupLogsEOF(ctx context.Context, agentID uuid.UUID) (bool, error) { + start := time.Now() + r0, r1 := m.s.GetWorkspaceAgentStartupLogsEOF(ctx, agentID) + m.queryLatencies.WithLabelValues("GetWorkspaceAgentStartupLogsEOF").Observe(time.Since(start).Seconds()) + return r0, r1 +} + func (m metricsStore) GetWorkspaceAgentStats(ctx context.Context, createdAt time.Time) ([]database.GetWorkspaceAgentStatsRow, error) { start := time.Now() stats, err := m.s.GetWorkspaceAgentStats(ctx, createdAt) diff --git a/coderd/database/dbmock/dbmock.go b/coderd/database/dbmock/dbmock.go index a1c75353b7a96..48ba84c92630f 100644 --- a/coderd/database/dbmock/dbmock.go +++ b/coderd/database/dbmock/dbmock.go @@ -1453,6 +1453,21 @@ func (mr *MockStoreMockRecorder) GetWorkspaceAgentStartupLogsAfter(arg0, arg1 in return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "GetWorkspaceAgentStartupLogsAfter", reflect.TypeOf((*MockStore)(nil).GetWorkspaceAgentStartupLogsAfter), arg0, arg1) } +// GetWorkspaceAgentStartupLogsEOF mocks base method. +func (m *MockStore) GetWorkspaceAgentStartupLogsEOF(arg0 context.Context, arg1 uuid.UUID) (bool, error) { + m.ctrl.T.Helper() + ret := m.ctrl.Call(m, "GetWorkspaceAgentStartupLogsEOF", arg0, arg1) + ret0, _ := ret[0].(bool) + ret1, _ := ret[1].(error) + return ret0, ret1 +} + +// GetWorkspaceAgentStartupLogsEOF indicates an expected call of GetWorkspaceAgentStartupLogsEOF. +func (mr *MockStoreMockRecorder) GetWorkspaceAgentStartupLogsEOF(arg0, arg1 interface{}) *gomock.Call { + mr.mock.ctrl.T.Helper() + return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "GetWorkspaceAgentStartupLogsEOF", reflect.TypeOf((*MockStore)(nil).GetWorkspaceAgentStartupLogsEOF), arg0, arg1) +} + // GetWorkspaceAgentStats mocks base method. func (m *MockStore) GetWorkspaceAgentStats(arg0 context.Context, arg1 time.Time) ([]database.GetWorkspaceAgentStatsRow, error) { m.ctrl.T.Helper() diff --git a/coderd/database/migrations/000126_add_startup_logs_eof.down.sql b/coderd/database/migrations/000127_add_startup_logs_eof.down.sql similarity index 100% rename from coderd/database/migrations/000126_add_startup_logs_eof.down.sql rename to coderd/database/migrations/000127_add_startup_logs_eof.down.sql diff --git a/coderd/database/migrations/000126_add_startup_logs_eof.up.sql b/coderd/database/migrations/000127_add_startup_logs_eof.up.sql similarity index 100% rename from coderd/database/migrations/000126_add_startup_logs_eof.up.sql rename to coderd/database/migrations/000127_add_startup_logs_eof.up.sql diff --git a/coderd/database/querier.go b/coderd/database/querier.go index c427ac768c79f..f07b5e5b8d59a 100644 --- a/coderd/database/querier.go +++ b/coderd/database/querier.go @@ -127,6 +127,7 @@ type sqlcQuerier interface { GetWorkspaceAgentByInstanceID(ctx context.Context, authInstanceID string) (WorkspaceAgent, error) GetWorkspaceAgentMetadata(ctx context.Context, workspaceAgentID uuid.UUID) ([]WorkspaceAgentMetadatum, error) GetWorkspaceAgentStartupLogsAfter(ctx context.Context, arg GetWorkspaceAgentStartupLogsAfterParams) ([]WorkspaceAgentStartupLog, error) + GetWorkspaceAgentStartupLogsEOF(ctx context.Context, agentID uuid.UUID) (bool, error) GetWorkspaceAgentStats(ctx context.Context, createdAt time.Time) ([]GetWorkspaceAgentStatsRow, error) GetWorkspaceAgentStatsAndLabels(ctx context.Context, createdAt time.Time) ([]GetWorkspaceAgentStatsAndLabelsRow, error) GetWorkspaceAgentsByResourceIDs(ctx context.Context, ids []uuid.UUID) ([]WorkspaceAgent, error) diff --git a/coderd/database/queries.sql.go b/coderd/database/queries.sql.go index cfc51c2ab393e..bab3b845b24d9 100644 --- a/coderd/database/queries.sql.go +++ b/coderd/database/queries.sql.go @@ -5483,6 +5483,26 @@ func (q *sqlQuerier) GetWorkspaceAgentStartupLogsAfter(ctx context.Context, arg return items, nil } +const getWorkspaceAgentStartupLogsEOF = `-- name: GetWorkspaceAgentStartupLogsEOF :one +SELECT CASE WHEN EXISTS ( + SELECT + agent_id, created_at, output, id, level, eof + FROM + workspace_agent_startup_logs + WHERE + agent_id = $1 + AND eof = true + LIMIT 1 +) THEN TRUE ELSE FALSE END +` + +func (q *sqlQuerier) GetWorkspaceAgentStartupLogsEOF(ctx context.Context, agentID uuid.UUID) (bool, error) { + row := q.db.QueryRowContext(ctx, getWorkspaceAgentStartupLogsEOF, agentID) + var column_1 bool + err := row.Scan(&column_1) + return column_1, err +} + const getWorkspaceAgentsByResourceIDs = `-- name: GetWorkspaceAgentsByResourceIDs :many SELECT id, created_at, updated_at, name, first_connected_at, last_connected_at, disconnected_at, resource_id, auth_token, auth_instance_id, architecture, environment_variables, operating_system, startup_script, instance_metadata, resource_metadata, directory, version, last_connected_replica_id, connection_timeout_seconds, troubleshooting_url, motd_file, lifecycle_state, startup_script_timeout_seconds, expanded_directory, shutdown_script, shutdown_script_timeout_seconds, startup_logs_length, startup_logs_overflowed, subsystem, startup_script_behavior diff --git a/coderd/database/queries/workspaceagents.sql b/coderd/database/queries/workspaceagents.sql index a57843d709be8..84d81eec9fdf3 100644 --- a/coderd/database/queries/workspaceagents.sql +++ b/coderd/database/queries/workspaceagents.sql @@ -146,6 +146,18 @@ WHERE id > @created_after ) ORDER BY id ASC; +-- name: GetWorkspaceAgentStartupLogsEOF :one +SELECT CASE WHEN EXISTS ( + SELECT + * + FROM + workspace_agent_startup_logs + WHERE + agent_id = $1 + AND eof = true + LIMIT 1 +) THEN TRUE ELSE FALSE END; + -- name: InsertWorkspaceAgentStartupLogs :many WITH new_length AS ( UPDATE workspace_agents SET diff --git a/coderd/workspaceagents.go b/coderd/workspaceagents.go index 82b129172be6e..f02a3c28e54f0 100644 --- a/coderd/workspaceagents.go +++ b/coderd/workspaceagents.go @@ -260,9 +260,15 @@ func (api *API) patchWorkspaceAgentStartupLogs(rw http.ResponseWriter, r *http.R output := make([]string, 0) level := make([]database.LogLevel, 0) eof := make([]bool, 0) - var endLog agentsdk.StartupLog outputLength := 0 - for _, logEntry := range req.Logs { + for i, logEntry := range req.Logs { + if logEntry.EOF && i != len(req.Logs)-1 { + httpapi.Write(ctx, rw, http.StatusBadRequest, codersdk.Response{ + Message: "EOF log must be the last log entry.", + }) + return + } + createdAt = append(createdAt, logEntry.CreatedAt) output = append(output, logEntry.Output) outputLength += len(logEntry.Output) @@ -280,19 +286,41 @@ func (api *API) patchWorkspaceAgentStartupLogs(rw http.ResponseWriter, r *http.R } level = append(level, parsedLevel) eof = append(eof, logEntry.EOF) - if logEntry.EOF { - endLog = logEntry - } } - logs, err := api.Database.InsertWorkspaceAgentStartupLogs(ctx, database.InsertWorkspaceAgentStartupLogsParams{ - AgentID: workspaceAgent.ID, - CreatedAt: createdAt, - Output: output, - Level: level, - EOF: eof, - OutputLength: int32(outputLength), - }) + + var logs []database.WorkspaceAgentStartupLog + // Ensure logs are not written after EOF. + eofError := xerrors.New("EOF log already received") + err := api.Database.InTx(func(db database.Store) error { + isEOF, err := db.GetWorkspaceAgentStartupLogsEOF(ctx, workspaceAgent.ID) + if err != nil { + return xerrors.Errorf("EOF status: %w", err) + } + + if isEOF { + // The agent has already sent an EOF log, so we don't need to process + // any more logs. + return eofError + } + + logs, err = db.InsertWorkspaceAgentStartupLogs(ctx, database.InsertWorkspaceAgentStartupLogsParams{ + AgentID: workspaceAgent.ID, + CreatedAt: createdAt, + Output: output, + Level: level, + EOF: eof, + OutputLength: int32(outputLength), + }) + return err + }, nil) if err != nil { + if errors.Is(err, eofError) { + httpapi.Write(ctx, rw, http.StatusBadRequest, codersdk.Response{ + Message: "Startup log has been closed.", + Detail: err.Error(), + }) + return + } if database.IsStartupLogsLimitError(err) { if !workspaceAgent.StartupLogsOverflowed { err := api.Database.UpdateWorkspaceAgentStartupLogOverflowByID(ctx, database.UpdateWorkspaceAgentStartupLogOverflowByIDParams{ @@ -340,11 +368,15 @@ func (api *API) patchWorkspaceAgentStartupLogs(rw http.ResponseWriter, r *http.R return } - lowestID := logs[0].ID + firstLog := logs[0] + lastLog := logs[len(logs)-1] // Publish by the lowest log ID inserted so the // log stream will fetch everything from that point. - api.publishWorkspaceAgentStartupLogsUpdate(ctx, workspaceAgent.ID, agentsdk.StartupLogsNotifyMessage{CreatedAfter: lowestID - 1, EndOfLogs: endLog.EOF}) + api.publishWorkspaceAgentStartupLogsUpdate(ctx, workspaceAgent.ID, agentsdk.StartupLogsNotifyMessage{ + CreatedAfter: firstLog.ID - 1, + EndOfLogs: lastLog.EOF, + }) if workspaceAgent.StartupLogsLength == 0 { // If these are the first logs being appended, we publish a UI update @@ -412,6 +444,9 @@ func (api *API) workspaceAgentStartupLogs(rw http.ResponseWriter, r *http.Reques return } } + if after < 0 { + after = 0 + } logs, err := api.Database.GetWorkspaceAgentStartupLogsAfter(ctx, database.GetWorkspaceAgentStartupLogsAfterParams{ AgentID: workspaceAgent.ID, @@ -431,21 +466,6 @@ func (api *API) workspaceAgentStartupLogs(rw http.ResponseWriter, r *http.Reques logs = []database.WorkspaceAgentStartupLog{} } - var ( - eof = false - lastSentLogID = after // Used further down to avoid fetching the same logs twice. - ) - if len(logs) > 0 { - last := logs[len(logs)-1] - eof = last.EOF - lastSentLogID = last.ID - } - - if eof { - // We don't send the EOF log, it simply indicates we are done. - logs = logs[:len(logs)-1] - } - if !follow { logger.Debug(ctx, "Finished non-follow job logs") httpapi.Write(ctx, rw, http.StatusOK, convertWorkspaceAgentStartupLogs(logs)) @@ -475,15 +495,20 @@ func (api *API) workspaceAgentStartupLogs(rw http.ResponseWriter, r *http.Reques if err != nil { return } - if eof { - // The startup script has finished running, so we can close the connection. - return + + lastSentLogID := after + if len(logs) > 0 { + last := logs[len(logs)-1] + + if last.EOF { + // The startup script has finished running, so we can close the connection. + return + } + lastSentLogID = last.ID } if !codersdk.WorkspaceAgentLifecycle(workspaceAgent.LifecycleState).Starting() { - // Avoid waiting forever in case EOF was lost or the agent is old. - // Note that it's still possible for this websocket to remain - // open indefinitely if either of the above conditions are true - // and this follow request is made while the agent is starting. + // Backwards compatibility: Avoid waiting forever in case this agent was + // created before the current release. return } @@ -493,8 +518,7 @@ func (api *API) workspaceAgentStartupLogs(rw http.ResponseWriter, r *http.Reques notifyCh <- struct{}{} // Subscribe early to prevent missing log events. - closeSubscribe, err := api.Pubsub.Subscribe(agentsdk.StartupLogsNotifyChannel(workspaceAgent.ID), func(ctx context.Context, message []byte) { - logger.Debug(ctx, "received startup log message") + closeSubscribe, err := api.Pubsub.Subscribe(agentsdk.StartupLogsNotifyChannel(workspaceAgent.ID), func(_ context.Context, _ []byte) { // The message is not important, we're tracking lastSentLogID manually. select { case notifyCh <- struct{}{}: @@ -543,22 +567,13 @@ func (api *API) workspaceAgentStartupLogs(rw http.ResponseWriter, r *http.Reques continue } - eof := logs[len(logs)-1].EOF - if eof { - // Discard the EOF message, it's an empty log entry. - logs = logs[:len(logs)-1] - if len(logs) == 0 { - return - } - } - select { case <-ctx.Done(): return case bufferedLogs <- logs: lastSentLogID = logs[len(logs)-1].ID } - if eof { + if logs[len(logs)-1].EOF { return } } @@ -1564,29 +1579,69 @@ func (api *API) workspaceAgentReportLifecycle(rw http.ResponseWriter, r *http.Re return } - api.Logger.Debug(ctx, "workspace agent state report", + logger := api.Logger.With( slog.F("agent", workspaceAgent.ID), slog.F("workspace", workspace.ID), slog.F("payload", req), ) + logger.Debug(ctx, "workspace agent state report") - lifecycleState := database.WorkspaceAgentLifecycleState(req.State) - if !lifecycleState.Valid() { + lifecycleState := req.State + dbLifecycleState := database.WorkspaceAgentLifecycleState(lifecycleState) + if !dbLifecycleState.Valid() { httpapi.Write(ctx, rw, http.StatusBadRequest, codersdk.Response{ Message: "Invalid lifecycle state.", - Detail: fmt.Sprintf("Invalid lifecycle state %q, must be be one of %q.", req.State, database.AllWorkspaceAgentLifecycleStateValues()), + Detail: fmt.Sprintf("Invalid lifecycle state %q, must be be one of %q.", lifecycleState, database.AllWorkspaceAgentLifecycleStateValues()), }) return } err = api.Database.UpdateWorkspaceAgentLifecycleStateByID(ctx, database.UpdateWorkspaceAgentLifecycleStateByIDParams{ ID: workspaceAgent.ID, - LifecycleState: lifecycleState, + LifecycleState: dbLifecycleState, }) if err != nil { httpapi.InternalServerError(rw, err) return } + + if !lifecycleState.Starting() { + var eofLog []database.WorkspaceAgentStartupLog + // Ensure the startup logs are marked as complete if the agent + // is no longer starting. This should be reported by the agent + // itself, but we do it here as a fallback. + err = api.Database.InTx(func(db database.Store) error { + isEOF, err := db.GetWorkspaceAgentStartupLogsEOF(ctx, workspaceAgent.ID) + if err != nil { + return xerrors.Errorf("EOF status: %w", err) + } + if isEOF { + return nil + } + + logger.Debug(ctx, "marking startup logs as complete because agent is no longer starting") + eofLog, err = db.InsertWorkspaceAgentStartupLogs(ctx, database.InsertWorkspaceAgentStartupLogsParams{ + AgentID: workspaceAgent.ID, + CreatedAt: []time.Time{database.Now()}, + Output: []string{""}, + Level: []database.LogLevel{database.LogLevelInfo}, + EOF: []bool{true}, + OutputLength: 0, + }) + return err + }, nil) + if err != nil { + // Not a critical failure, just log it. + logger.Warn(ctx, "failed to mark startup logs as complete", slog.Error(err)) + } + if len(eofLog) > 0 { + api.publishWorkspaceAgentStartupLogsUpdate(ctx, workspaceAgent.ID, agentsdk.StartupLogsNotifyMessage{ + CreatedAfter: eofLog[0].ID - 1, + EndOfLogs: true, + }) + } + } + api.publishWorkspaceUpdate(ctx, workspace.ID) httpapi.Write(ctx, rw, http.StatusNoContent, nil) @@ -2022,6 +2077,7 @@ func convertWorkspaceAgentStartupLog(logEntry database.WorkspaceAgentStartupLog) CreatedAt: logEntry.CreatedAt, Output: logEntry.Output, Level: codersdk.LogLevel(logEntry.Level), + EOF: logEntry.EOF, } } diff --git a/coderd/workspaceagents_test.go b/coderd/workspaceagents_test.go index a3608bfeb3964..0f3301ff0c77f 100644 --- a/coderd/workspaceagents_test.go +++ b/coderd/workspaceagents_test.go @@ -211,14 +211,20 @@ func TestWorkspaceAgentStartupLogs(t *testing.T) { agentClient := agentsdk.New(client.URL) agentClient.SetSessionToken(authToken) err := agentClient.PatchStartupLogs(ctx, agentsdk.PatchStartupLogs{ - Logs: []agentsdk.StartupLog{{ - CreatedAt: database.Now(), - Output: "testing", - }}, + Logs: []agentsdk.StartupLog{ + { + CreatedAt: database.Now(), + Output: "testing", + }, + { + CreatedAt: database.Now(), + Output: "testing2", + }, + }, }) require.NoError(t, err) - logs, closer, err := client.WorkspaceAgentStartupLogsAfter(ctx, build.Resources[0].Agents[0].ID, -500) + logs, closer, err := client.WorkspaceAgentStartupLogsAfter(ctx, build.Resources[0].Agents[0].ID, 0) require.NoError(t, err) defer func() { _ = closer.Close() @@ -229,8 +235,9 @@ func TestWorkspaceAgentStartupLogs(t *testing.T) { case logChunk = <-logs: } require.NoError(t, ctx.Err()) - require.Len(t, logChunk, 1) + require.Len(t, logChunk, 2) // No EOF. require.Equal(t, "testing", logChunk[0].Output) + require.Equal(t, "testing2", logChunk[1].Output) }) t.Run("PublishesOnOverflow", func(t *testing.T) { t.Parallel() @@ -294,7 +301,7 @@ func TestWorkspaceAgentStartupLogs(t *testing.T) { } } }) - t.Run("AllowEOFAfterOverflowAndCloseFollow", func(t *testing.T) { + t.Run("AllowEOFAfterOverflowAndCloseFollowWebsocket", func(t *testing.T) { t.Parallel() ctx := testutil.Context(t, testutil.WaitMedium) client := coderdtest.New(t, &coderdtest.Options{ @@ -340,20 +347,28 @@ func TestWorkspaceAgentStartupLogs(t *testing.T) { Output: "testing", Level: "info", }, + { + CreatedAt: database.Now().Add(time.Minute), + Level: "info", + EOF: true, + }, } agentClient := agentsdk.New(client.URL) agentClient.SetSessionToken(authToken) - var startupLogs []agentsdk.StartupLog + var convertedLogs []agentsdk.StartupLog for _, log := range wantLogs { - startupLogs = append(startupLogs, agentsdk.StartupLog{ + convertedLogs = append(convertedLogs, agentsdk.StartupLog{ CreatedAt: log.CreatedAt, Output: log.Output, Level: log.Level, + EOF: log.EOF, }) } - err = agentClient.PatchStartupLogs(ctx, agentsdk.PatchStartupLogs{Logs: startupLogs}) + initialLogs := convertedLogs[:len(convertedLogs)-1] + eofLog := convertedLogs[len(convertedLogs)-1] + err = agentClient.PatchStartupLogs(ctx, agentsdk.PatchStartupLogs{Logs: initialLogs}) require.NoError(t, err) overflowLogs := []agentsdk.StartupLog{ @@ -361,10 +376,7 @@ func TestWorkspaceAgentStartupLogs(t *testing.T) { CreatedAt: database.Now(), Output: strings.Repeat("a", (1<<20)+1), }, - { - CreatedAt: database.Now(), - EOF: true, - }, + eofLog, // Include EOF which will be discarded due to overflow. } err = agentClient.PatchStartupLogs(ctx, agentsdk.PatchStartupLogs{Logs: overflowLogs}) var apiError *codersdk.Error @@ -386,7 +398,7 @@ func TestWorkspaceAgentStartupLogs(t *testing.T) { } // Now we should still be able to send the EOF. - err = agentClient.PatchStartupLogs(ctx, agentsdk.PatchStartupLogs{Logs: overflowLogs[len(overflowLogs)-1:]}) + err = agentClient.PatchStartupLogs(ctx, agentsdk.PatchStartupLogs{Logs: []agentsdk.StartupLog{eofLog}}) require.NoError(t, err) var gotLogs []codersdk.WorkspaceAgentStartupLog @@ -407,6 +419,133 @@ func TestWorkspaceAgentStartupLogs(t *testing.T) { } require.Equal(t, wantLogs, gotLogs) }) + t.Run("CloseAfterLifecycleStateIsNotRunning", func(t *testing.T) { + t.Parallel() + ctx := testutil.Context(t, testutil.WaitMedium) + client := coderdtest.New(t, &coderdtest.Options{ + IncludeProvisionerDaemon: true, + }) + user := coderdtest.CreateFirstUser(t, client) + authToken := uuid.NewString() + version := coderdtest.CreateTemplateVersion(t, client, user.OrganizationID, &echo.Responses{ + Parse: echo.ParseComplete, + ProvisionPlan: echo.ProvisionComplete, + ProvisionApply: []*proto.Provision_Response{{ + Type: &proto.Provision_Response_Complete{ + Complete: &proto.Provision_Complete{ + Resources: []*proto.Resource{{ + Name: "example", + Type: "aws_instance", + Agents: []*proto.Agent{{ + Id: uuid.NewString(), + Auth: &proto.Agent_Token{ + Token: authToken, + }, + }}, + }}, + }, + }, + }}, + }) + template := coderdtest.CreateTemplate(t, client, user.OrganizationID, version.ID) + coderdtest.AwaitTemplateVersionJob(t, client, version.ID) + workspace := coderdtest.CreateWorkspace(t, client, user.OrganizationID, template.ID) + build := coderdtest.AwaitWorkspaceBuildJob(t, client, workspace.LatestBuild.ID) + + agentClient := agentsdk.New(client.URL) + agentClient.SetSessionToken(authToken) + + logs, closer, err := client.WorkspaceAgentStartupLogsAfter(ctx, build.Resources[0].Agents[0].ID, 0) + require.NoError(t, err) + defer func() { + _ = closer.Close() + }() + + err = agentClient.PatchStartupLogs(ctx, agentsdk.PatchStartupLogs{ + Logs: []agentsdk.StartupLog{ + { + CreatedAt: database.Now(), + Output: "testing", + }, + }, + }) + require.NoError(t, err) + + err = agentClient.PostLifecycle(ctx, agentsdk.PostLifecycleRequest{ + State: codersdk.WorkspaceAgentLifecycleReady, + }) + require.NoError(t, err) + + for { + select { + case <-ctx.Done(): + require.Fail(t, "timed out waiting for logs EOF") + case l := <-logs: + for _, log := range l { + if log.EOF { + // Success. + return + } + } + } + } + }) + t.Run("NoLogAfterEOF", func(t *testing.T) { + t.Parallel() + ctx := testutil.Context(t, testutil.WaitMedium) + client := coderdtest.New(t, &coderdtest.Options{ + IncludeProvisionerDaemon: true, + }) + user := coderdtest.CreateFirstUser(t, client) + authToken := uuid.NewString() + version := coderdtest.CreateTemplateVersion(t, client, user.OrganizationID, &echo.Responses{ + Parse: echo.ParseComplete, + ProvisionPlan: echo.ProvisionComplete, + ProvisionApply: []*proto.Provision_Response{{ + Type: &proto.Provision_Response_Complete{ + Complete: &proto.Provision_Complete{ + Resources: []*proto.Resource{{ + Name: "example", + Type: "aws_instance", + Agents: []*proto.Agent{{ + Id: uuid.NewString(), + Auth: &proto.Agent_Token{ + Token: authToken, + }, + }}, + }}, + }, + }, + }}, + }) + template := coderdtest.CreateTemplate(t, client, user.OrganizationID, version.ID) + coderdtest.AwaitTemplateVersionJob(t, client, version.ID) + workspace := coderdtest.CreateWorkspace(t, client, user.OrganizationID, template.ID) + _ = coderdtest.AwaitWorkspaceBuildJob(t, client, workspace.LatestBuild.ID) + + agentClient := agentsdk.New(client.URL) + agentClient.SetSessionToken(authToken) + + err := agentClient.PatchStartupLogs(ctx, agentsdk.PatchStartupLogs{ + Logs: []agentsdk.StartupLog{ + { + CreatedAt: database.Now(), + EOF: true, + }, + }, + }) + require.NoError(t, err) + + err = agentClient.PatchStartupLogs(ctx, agentsdk.PatchStartupLogs{ + Logs: []agentsdk.StartupLog{ + { + CreatedAt: database.Now(), + Output: "testing", + }, + }, + }) + require.Error(t, err, "insert after EOF should not succeed") + }) } func TestWorkspaceAgentListen(t *testing.T) { diff --git a/codersdk/workspaceagents.go b/codersdk/workspaceagents.go index 26b4fa7284720..7f5619b0ec8ed 100644 --- a/codersdk/workspaceagents.go +++ b/codersdk/workspaceagents.go @@ -604,6 +604,7 @@ type WorkspaceAgentStartupLog struct { CreatedAt time.Time `json:"created_at" format:"date-time"` Output string `json:"output"` Level LogLevel `json:"level"` + EOF bool `json:"eof"` // EOF indicates that this is the last log entry and the file is closed. } type AgentSubsystem string diff --git a/docs/api/agents.md b/docs/api/agents.md index b748a2b299dfb..7964b3fcd67a0 100644 --- a/docs/api/agents.md +++ b/docs/api/agents.md @@ -702,6 +702,7 @@ curl -X GET http://coder-server:8080/api/v2/workspaceagents/{workspaceagent}/sta [ { "created_at": "2019-08-24T14:15:22Z", + "eof": true, "id": 0, "level": "trace", "output": "string" @@ -719,13 +720,14 @@ curl -X GET http://coder-server:8080/api/v2/workspaceagents/{workspaceagent}/sta Status Code **200** -| Name | Type | Required | Restrictions | Description | -| -------------- | ------------------------------------------------ | -------- | ------------ | ----------- | -| `[array item]` | array | false | | | -| `» created_at` | string(date-time) | false | | | -| `» id` | integer | false | | | -| `» level` | [codersdk.LogLevel](schemas.md#codersdkloglevel) | false | | | -| `» output` | string | false | | | +| Name | Type | Required | Restrictions | Description | +| -------------- | ------------------------------------------------ | -------- | ------------ | --------------------------------------------------------------------- | +| `[array item]` | array | false | | | +| `» created_at` | string(date-time) | false | | | +| `» eof` | boolean | false | | Eof indicates that this is the last log entry and the file is closed. | +| `» id` | integer | false | | | +| `» level` | [codersdk.LogLevel](schemas.md#codersdkloglevel) | false | | | +| `» output` | string | false | | | #### Enumerated Values diff --git a/docs/api/schemas.md b/docs/api/schemas.md index e5dd503186424..b05444c94696a 100644 --- a/docs/api/schemas.md +++ b/docs/api/schemas.md @@ -4844,6 +4844,7 @@ AuthorizationObject can represent a "set" of objects, such as: all workspaces in ```json { "created_at": "2019-08-24T14:15:22Z", + "eof": true, "id": 0, "level": "trace", "output": "string" @@ -4852,12 +4853,13 @@ AuthorizationObject can represent a "set" of objects, such as: all workspaces in ### Properties -| Name | Type | Required | Restrictions | Description | -| ------------ | -------------------------------------- | -------- | ------------ | ----------- | -| `created_at` | string | false | | | -| `id` | integer | false | | | -| `level` | [codersdk.LogLevel](#codersdkloglevel) | false | | | -| `output` | string | false | | | +| Name | Type | Required | Restrictions | Description | +| ------------ | -------------------------------------- | -------- | ------------ | --------------------------------------------------------------------- | +| `created_at` | string | false | | | +| `eof` | boolean | false | | Eof indicates that this is the last log entry and the file is closed. | +| `id` | integer | false | | | +| `level` | [codersdk.LogLevel](#codersdkloglevel) | false | | | +| `output` | string | false | | | ## codersdk.WorkspaceAgentStartupScriptBehavior diff --git a/site/src/api/typesGenerated.ts b/site/src/api/typesGenerated.ts index 84171129fe2ba..961cc8f16e455 100644 --- a/site/src/api/typesGenerated.ts +++ b/site/src/api/typesGenerated.ts @@ -1144,6 +1144,7 @@ export interface WorkspaceAgentStartupLog { readonly created_at: string readonly output: string readonly level: LogLevel + readonly eof: boolean } // From codersdk/workspaceapps.go diff --git a/site/src/testHelpers/entities.ts b/site/src/testHelpers/entities.ts index 6697f83c8ddb2..dd4d8565e2278 100644 --- a/site/src/testHelpers/entities.ts +++ b/site/src/testHelpers/entities.ts @@ -1649,6 +1649,7 @@ export const MockStartupLogs: TypesGen.WorkspaceAgentStartupLog[] = [ created_at: "2023-05-04T11:30:41.402072Z", output: "+ curl -fsSL https://code-server.dev/install.sh", level: "info", + eof: false, }, { id: 166664, @@ -1656,18 +1657,28 @@ export const MockStartupLogs: TypesGen.WorkspaceAgentStartupLog[] = [ output: "+ sh -s -- --method=standalone --prefix=/tmp/code-server --version 4.8.3", level: "info", + eof: false, }, { id: 166665, created_at: "2023-05-04T11:30:42.590731Z", output: "Ubuntu 22.04.2 LTS", level: "info", + eof: false, }, { id: 166666, created_at: "2023-05-04T11:30:42.593686Z", output: "Installing v4.8.3 of the amd64 release from GitHub.", level: "info", + eof: false, + }, + { + id: 166667, + created_at: "2023-05-04T11:30:42.599999Z", + output: "", + level: "info", + eof: true, }, ] From 033262e960c2ea75bf7b40847c62d80f5c4f74c4 Mon Sep 17 00:00:00 2001 From: Mathias Fredriksson Date: Fri, 16 Jun 2023 12:45:04 +0000 Subject: [PATCH 3/9] fix(codersdk): Fix startup log channel corruption --- codersdk/workspaceagents.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/codersdk/workspaceagents.go b/codersdk/workspaceagents.go index 7f5619b0ec8ed..89396406962ae 100644 --- a/codersdk/workspaceagents.go +++ b/codersdk/workspaceagents.go @@ -553,8 +553,8 @@ func (c *Client) WorkspaceAgentStartupLogsAfter(ctx context.Context, agentID uui defer close(closed) defer close(logChunks) defer conn.Close(websocket.StatusGoingAway, "") - var logs []WorkspaceAgentStartupLog for { + var logs []WorkspaceAgentStartupLog err = decoder.Decode(&logs) if err != nil { return From 1b589712f972ccec0733e8135a9e6ce2ef005564 Mon Sep 17 00:00:00 2001 From: Mathias Fredriksson Date: Fri, 16 Jun 2023 13:12:37 +0000 Subject: [PATCH 4/9] fix(site): Unshow the eof log line from WebUI --- site/src/components/Resources/AgentRow.tsx | 13 +++++++++---- .../workspaceAgentLogsXService.ts | 11 +++++++---- 2 files changed, 16 insertions(+), 8 deletions(-) diff --git a/site/src/components/Resources/AgentRow.tsx b/site/src/components/Resources/AgentRow.tsx index 1d87ac91e1f26..bc2e43e697230 100644 --- a/site/src/components/Resources/AgentRow.tsx +++ b/site/src/components/Resources/AgentRow.tsx @@ -26,7 +26,7 @@ import { FixedSizeList as List, ListOnScrollProps } from "react-window" import { colors } from "theme/colors" import { combineClasses } from "utils/combineClasses" import { - LineWithID, + LineWithIDAndEOF, workspaceAgentLogsMachine, } from "xServices/workspaceAgentLogs/workspaceAgentLogsXService" import { @@ -54,7 +54,7 @@ export interface AgentRowProps { hideVSCodeDesktopButton?: boolean serverVersion: string onUpdateAgent: () => void - storybookStartupLogs?: LineWithID[] + storybookStartupLogs?: LineWithIDAndEOF[] storybookAgentMetadata?: WorkspaceAgentMetadata[] } @@ -98,7 +98,8 @@ export const AgentRow: FC = ({ const { proxy } = useProxy() const [showStartupLogs, setShowStartupLogs] = useState( - agent.lifecycle_state !== "ready" && hasStartupFeatures, + ["starting", "start_timeout"].includes(agent.lifecycle_state) && + hasStartupFeatures, ) useEffect(() => { setShowStartupLogs(agent.lifecycle_state !== "ready" && hasStartupFeatures) @@ -123,13 +124,17 @@ export const AgentRow: FC = ({ const startupLogs = useMemo(() => { const allLogs = logsMachine.context.startupLogs || [] - const logs = [...allLogs] + // Filter out eof, since we don't want to show an empty line to the + // user. The timesetamp could be used to show when the log ended in + // the future. + const logs = [...allLogs.filter((log) => !log.eof)] if (agent.startup_logs_overflowed) { logs.push({ id: -1, level: "error", output: "Startup logs exceeded the max size of 1MB!", time: new Date().toISOString(), + eof: false, }) } return logs diff --git a/site/src/xServices/workspaceAgentLogs/workspaceAgentLogsXService.ts b/site/src/xServices/workspaceAgentLogs/workspaceAgentLogsXService.ts index 37ca026533e7a..c9aac20eb64bf 100644 --- a/site/src/xServices/workspaceAgentLogs/workspaceAgentLogsXService.ts +++ b/site/src/xServices/workspaceAgentLogs/workspaceAgentLogsXService.ts @@ -6,8 +6,9 @@ import { Line } from "components/Logs/Logs" // Logs are stored as the Line interface to make rendering // much more efficient. Instead of mapping objects each time, we're // able to just pass the array of logs to the component. -export interface LineWithID extends Line { +export interface LineWithIDAndEOF extends Line { id: number + eof: boolean } export const workspaceAgentLogsMachine = createMachine( @@ -18,7 +19,7 @@ export const workspaceAgentLogsMachine = createMachine( events: {} as | { type: "ADD_STARTUP_LOGS" - logs: LineWithID[] + logs: LineWithIDAndEOF[] } | { type: "FETCH_STARTUP_LOGS" @@ -28,11 +29,11 @@ export const workspaceAgentLogsMachine = createMachine( }, context: {} as { agentID: string - startupLogs?: LineWithID[] + startupLogs?: LineWithIDAndEOF[] }, services: {} as { getStartupLogs: { - data: LineWithID[] + data: LineWithIDAndEOF[] } }, }, @@ -82,6 +83,7 @@ export const workspaceAgentLogsMachine = createMachine( level: log.level || "info", output: log.output, time: log.created_at, + eof: log.eof, })), ), streamStartupLogs: (ctx) => async (callback) => { @@ -100,6 +102,7 @@ export const workspaceAgentLogsMachine = createMachine( level: "info" as TypesGen.LogLevel, output: log.output, time: log.created_at, + eof: log.eof, })), }) }, From bcbec3e7b45932345c29d98bab941ade8711f9eb Mon Sep 17 00:00:00 2001 From: Mathias Fredriksson Date: Fri, 16 Jun 2023 13:23:18 +0000 Subject: [PATCH 5/9] Fix lint --- coderd/database/dbfake/dbfake.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/coderd/database/dbfake/dbfake.go b/coderd/database/dbfake/dbfake.go index ad7aa81c3bf35..ede8c6cef69d7 100644 --- a/coderd/database/dbfake/dbfake.go +++ b/coderd/database/dbfake/dbfake.go @@ -2730,7 +2730,7 @@ func (q *fakeQuerier) GetWorkspaceAgentStartupLogsAfter(_ context.Context, arg d return logs, nil } -func (q *fakeQuerier) GetWorkspaceAgentStartupLogsEOF(ctx context.Context, agentID uuid.UUID) (bool, error) { +func (q *fakeQuerier) GetWorkspaceAgentStartupLogsEOF(_ context.Context, agentID uuid.UUID) (bool, error) { q.mutex.RLock() defer q.mutex.RUnlock() From eb7a7a366589c5d13e78e0bdc7ab7077135c2d8d Mon Sep 17 00:00:00 2001 From: Mathias Fredriksson Date: Fri, 16 Jun 2023 13:40:12 +0000 Subject: [PATCH 6/9] Make EOF during lifecycle change mandatory --- coderd/workspaceagents.go | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/coderd/workspaceagents.go b/coderd/workspaceagents.go index f02a3c28e54f0..be827e4b78009 100644 --- a/coderd/workspaceagents.go +++ b/coderd/workspaceagents.go @@ -1628,11 +1628,13 @@ func (api *API) workspaceAgentReportLifecycle(rw http.ResponseWriter, r *http.Re EOF: []bool{true}, OutputLength: 0, }) - return err + return xerrors.Errorf("write EOF log entry", err) }, nil) if err != nil { - // Not a critical failure, just log it. - logger.Warn(ctx, "failed to mark startup logs as complete", slog.Error(err)) + // If this fails, we want the agent to keep trying so that the + // startup log is eventually marked as complete. + httpapi.InternalServerError(rw, err) + return } if len(eofLog) > 0 { api.publishWorkspaceAgentStartupLogsUpdate(ctx, workspaceAgent.ID, agentsdk.StartupLogsNotifyMessage{ From 0dcfd731ef39fc3c68ab0ebc9f06906a029fb473 Mon Sep 17 00:00:00 2001 From: Mathias Fredriksson Date: Fri, 16 Jun 2023 13:43:47 +0000 Subject: [PATCH 7/9] Fix --- coderd/workspaceagents.go | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/coderd/workspaceagents.go b/coderd/workspaceagents.go index be827e4b78009..a2223a1d1d06a 100644 --- a/coderd/workspaceagents.go +++ b/coderd/workspaceagents.go @@ -1628,9 +1628,10 @@ func (api *API) workspaceAgentReportLifecycle(rw http.ResponseWriter, r *http.Re EOF: []bool{true}, OutputLength: 0, }) - return xerrors.Errorf("write EOF log entry", err) + return xerrors.Errorf("write EOF log entry: %w", err) }, nil) if err != nil { + logger.Warn(ctx, "failed to mark startup logs as complete", slog.Error(err)) // If this fails, we want the agent to keep trying so that the // startup log is eventually marked as complete. httpapi.InternalServerError(rw, err) From a1a40f37f72ee37ddb808ed7024815ad099b4cd0 Mon Sep 17 00:00:00 2001 From: Mathias Fredriksson Date: Fri, 16 Jun 2023 13:46:34 +0000 Subject: [PATCH 8/9] Fix after qp --- coderd/workspaceagents.go | 9 +++------ 1 file changed, 3 insertions(+), 6 deletions(-) diff --git a/coderd/workspaceagents.go b/coderd/workspaceagents.go index a2223a1d1d06a..0ff3b87e13a4e 100644 --- a/coderd/workspaceagents.go +++ b/coderd/workspaceagents.go @@ -434,19 +434,16 @@ func (api *API) workspaceAgentStartupLogs(rw http.ResponseWriter, r *http.Reques if afterRaw != "" { var err error after, err = strconv.ParseInt(afterRaw, 10, 64) - if err != nil { + if err != nil || after < 0 { httpapi.Write(ctx, rw, http.StatusBadRequest, codersdk.Response{ - Message: "Query param \"after\" must be an integer.", + Message: "Query param \"after\" must be an integer greater than zero.", Validations: []codersdk.ValidationError{ - {Field: "after", Detail: "Must be an integer"}, + {Field: "after", Detail: "Must be an integer greater than zero"}, }, }) return } } - if after < 0 { - after = 0 - } logs, err := api.Database.GetWorkspaceAgentStartupLogsAfter(ctx, database.GetWorkspaceAgentStartupLogsAfterParams{ AgentID: workspaceAgent.ID, From 71f476acc24a592aed6df8996255c331d5e03c61 Mon Sep 17 00:00:00 2001 From: Mathias Fredriksson Date: Fri, 16 Jun 2023 13:56:06 +0000 Subject: [PATCH 9/9] Fix --- coderd/workspaceagents.go | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/coderd/workspaceagents.go b/coderd/workspaceagents.go index 0ff3b87e13a4e..dd01e26c8c0fe 100644 --- a/coderd/workspaceagents.go +++ b/coderd/workspaceagents.go @@ -436,9 +436,9 @@ func (api *API) workspaceAgentStartupLogs(rw http.ResponseWriter, r *http.Reques after, err = strconv.ParseInt(afterRaw, 10, 64) if err != nil || after < 0 { httpapi.Write(ctx, rw, http.StatusBadRequest, codersdk.Response{ - Message: "Query param \"after\" must be an integer greater than zero.", + Message: "Query param \"after\" must be an integer greater than or equal to zero.", Validations: []codersdk.ValidationError{ - {Field: "after", Detail: "Must be an integer greater than zero"}, + {Field: "after", Detail: "Must be an integer greater than or equal to zero"}, }, }) return @@ -1625,7 +1625,10 @@ func (api *API) workspaceAgentReportLifecycle(rw http.ResponseWriter, r *http.Re EOF: []bool{true}, OutputLength: 0, }) - return xerrors.Errorf("write EOF log entry: %w", err) + if err != nil { + return xerrors.Errorf("write EOF log entry: %w", err) + } + return nil }, nil) if err != nil { logger.Warn(ctx, "failed to mark startup logs as complete", slog.Error(err))