Skip to content

fix(coderd): subscribe to workspace when streaming agent logs to detect outdated build #9729

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.

Sign up for GitHub

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 4 commits into from
Sep 19, 2023
Merged

fix(coderd): subscribe to workspace when streaming agent logs to detect outdated build #9729

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
96a912c
fix(coderd): Subscribe to workspace when streaming agent logs to dete…
mafredri Sep 18, 2023
2de6c3a
Update workspaceagents.go
mafredri Sep 18, 2023
e0c0a70
add debug logs and sql no rows handling
mafredri Sep 19, 2023
6e41ada
Merge branch 'main' into mafredri/fix-workspace-agent-log-close-on-ne…
mafredri Sep 19, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
49 changes: 46 additions & 3 deletions coderd/workspaceagents.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -570,11 +570,27 @@ func (api *API) workspaceAgentLogs(rw http.ResponseWriter, r *http.Request) {
lastSentLogID = logs[len(logs)-1].ID
}

workspaceNotifyCh := make(chan struct{}, 1)
notifyCh := make(chan struct{}, 1)
// Allow us to immediately check if we missed any logs
// between initial fetch and subscribe.
notifyCh <- struct{}{}

// Subscribe to workspace to detect new builds.
closeSubscribeWorkspace, err := api.Pubsub.Subscribe(codersdk.WorkspaceNotifyChannel(workspace.ID), func(_ context.Context, _ []byte) {
select {
case workspaceNotifyCh <- struct{}{}:
default:
}
})
if err != nil {
httpapi.Write(ctx, rw, http.StatusInternalServerError, codersdk.Response{
Message: "Failed to subscribe to workspace for log streaming.",
Detail: err.Error(),
})
return
}
defer closeSubscribeWorkspace()
// Subscribe early to prevent missing log events.
closeSubscribe, err := api.Pubsub.Subscribe(agentsdk.LogsNotifyChannel(workspaceAgent.ID), func(_ context.Context, _ []byte) {
// The message is not important, we're tracking lastSentLogID manually.
Expand All @@ -585,7 +601,7 @@ func (api *API) workspaceAgentLogs(rw http.ResponseWriter, r *http.Request) {
})
if err != nil {
httpapi.Write(ctx, rw, http.StatusInternalServerError, codersdk.Response{
Message: "Failed to subscribe to logs.",
Message: "Failed to subscribe to agent for log streaming.",
Detail: err.Error(),
})
return
Expand All @@ -600,20 +616,33 @@ func (api *API) workspaceAgentLogs(rw http.ResponseWriter, r *http.Request) {
defer t.Stop()

go func() {
defer close(bufferedLogs)
defer func() {
logger.Debug(ctx, "end log streaming loop")
close(bufferedLogs)
}()
logger.Debug(ctx, "start log streaming loop", slog.F("last_sent_log_id", lastSentLogID))

keepGoing := true
for keepGoing {
var (
debugTriggeredBy string
onlyCheckLatestBuild bool
)
select {
case <-ctx.Done():
return
case <-t.C:
debugTriggeredBy = "timer"
case <-workspaceNotifyCh:
debugTriggeredBy = "workspace"
onlyCheckLatestBuild = true
case <-notifyCh:
debugTriggeredBy = "log"
t.Reset(recheckInterval)
}

agents, err := api.Database.GetWorkspaceAgentsInLatestBuildByWorkspaceID(ctx, workspace.ID)
if err != nil {
if err != nil && !xerrors.Is(err, sql.ErrNoRows) {
if xerrors.Is(err, context.Canceled) {
return
}
Expand All @@ -624,6 +653,20 @@ func (api *API) workspaceAgentLogs(rw http.ResponseWriter, r *http.Request) {
// checking once.
keepGoing = slices.ContainsFunc(agents, func(agent database.WorkspaceAgent) bool { return agent.ID == workspaceAgent.ID })

logger.Debug(
ctx,
"checking for new logs",
slog.F("triggered_by", debugTriggeredBy),
slog.F("only_check_latest_build", onlyCheckLatestBuild),
slog.F("keep_going", keepGoing),
slog.F("last_sent_log_id", lastSentLogID),
slog.F("workspace_has_agents", len(agents) > 0),
)

if onlyCheckLatestBuild && keepGoing {
continue
}

logs, err := api.Database.GetWorkspaceAgentLogsAfter(ctx, database.GetWorkspaceAgentLogsAfterParams{
AgentID: workspaceAgent.ID,
CreatedAfter: lastSentLogID,
Expand Down
22 changes: 1 addition & 21 deletions coderd/workspaceagents_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -385,34 +385,14 @@ func TestWorkspaceAgentStartupLogs(t *testing.T) {
_ = closer.Close()
}()

first := make(chan struct{})
go func() {
select {
case <-ctx.Done():
assert.Fail(t, "context done while waiting in goroutine")
case <-logs:
close(first)
}
}()
select {
case <-ctx.Done():
require.FailNow(t, "context done while waiting for first log")
case <-first:
case <-logs:
}

_ = coderdtest.CreateWorkspaceBuild(t, client, workspace, database.WorkspaceTransitionStart)

// Send a new log message to trigger a re-check.
err = agentClient.PatchLogs(ctx, agentsdk.PatchLogs{
Logs: []agentsdk.Log{
{
CreatedAt: dbtime.Now(),
Output: "testing2",
},
},
})
require.NoError(t, err)

select {
case <-ctx.Done():
require.FailNow(t, "context done while waiting for logs close")
Expand Down
2 changes: 1 addition & 1 deletion codersdk/workspaceagents.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -703,7 +703,7 @@ func (c *Client) WorkspaceAgentLogsAfter(ctx context.Context, agentID uuid.UUID,
}
return nil, nil, ReadBodyAsError(res)
}
logChunks := make(chan []WorkspaceAgentLog)
logChunks := make(chan []WorkspaceAgentLog, 1)
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Review: Bonus change to speed up detection of closed connection.

closed := make(chan struct{})
ctx, wsNetConn := websocketNetConn(ctx, conn, websocket.MessageText)
decoder := json.NewDecoder(wsNetConn)
Expand Down