Skip to content

fix: avoid missed logs when streaming startup logs #8029

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 our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 12 commits into from
Jun 16, 2023
13 changes: 13 additions & 0 deletions agent/agent.go
Original file line number Diff line number Diff line change
Expand Up @@ -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
}
}
Expand Down Expand Up @@ -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 {
Expand Down
4 changes: 3 additions & 1 deletion agent/agent_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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!
Expand Down
7 changes: 7 additions & 0 deletions coderd/apidoc/docs.go

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

7 changes: 7 additions & 0 deletions coderd/apidoc/swagger.json

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

8 changes: 8 additions & 0 deletions coderd/database/dbauthz/dbauthz.go
Original file line number Diff line number Diff line change
Expand Up @@ -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)
}
Expand Down
21 changes: 19 additions & 2 deletions coderd/database/dbfake/dbfake.go
Original file line number Diff line number Diff line change
Expand Up @@ -2722,14 +2722,30 @@ 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)
}
return logs, nil
}

func (q *fakeQuerier) GetWorkspaceAgentStartupLogsEOF(_ 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()
Expand Down Expand Up @@ -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
}
Expand All @@ -4026,6 +4042,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))
}
Expand Down
7 changes: 7 additions & 0 deletions coderd/database/dbmetrics/dbmetrics.go

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

15 changes: 15 additions & 0 deletions coderd/database/dbmock/dbmock.go

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

5 changes: 4 additions & 1 deletion coderd/database/dump.sql

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

Original file line number Diff line number Diff line change
@@ -0,0 +1 @@
ALTER TABLE workspace_agent_startup_logs DROP COLUMN eof;
3 changes: 3 additions & 0 deletions coderd/database/migrations/000127_add_startup_logs_eof.up.sql
Original file line number Diff line number Diff line change
@@ -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';
2 changes: 2 additions & 0 deletions coderd/database/models.go

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

1 change: 1 addition & 0 deletions coderd/database/querier.go

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

2 changes: 2 additions & 0 deletions coderd/database/querier_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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,
})
Expand All @@ -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))
Expand Down
35 changes: 30 additions & 5 deletions coderd/database/queries.sql.go

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

17 changes: 15 additions & 2 deletions coderd/database/queries/workspaceagents.sql
Original file line number Diff line number Diff line change
Expand Up @@ -146,18 +146,31 @@ 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
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.
Expand Down
1 change: 1 addition & 0 deletions coderd/database/sqlc.yaml
Original file line number Diff line number Diff line change
Expand Up @@ -55,6 +55,7 @@ overrides:
uuid: UUID
failure_ttl: FailureTTL
inactivity_ttl: InactivityTTL
eof: EOF

sql:
- schema: "./dump.sql"
Expand Down
Loading