8000 fix(coderd): ensure agent timings are non-zero on insert by johnstcn · Pull Request #18065 · coder/coder · GitHub
[go: up one dir, main page]
Skip to content

fix(coderd): ensure agent timings are non-zero on insert #18065

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 7 commits into from
May 29, 2025
Merged

fix(coderd): ensure agent timings are non-zero on insert #18065

Show file tree
Hide file tree
Changes from 3 commits
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
c148d0d
fix(coderd): ensure agent timings are present on insert
johnstcn May 27, 2025
6afbafe
skip timings for agents that never connected
johnstcn May 28, 2025
db019ea
add missing require.NoError
johnstcn May 28, 2025
1b83778
fix tests
johnstcn May 28, 2025
afe791f
address suggestion
johnstcn May 28, 2025
e2a6e5e
another test update
johnstcn May 29, 2025
1f1ceb1
more paranoia
johnstcn May 29, 2025
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
26 changes: 25 additions & 1 deletion coderd/agentapi/scripts.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -18,11 +18,35 @@ type ScriptsAPI struct {
func (s *ScriptsAPI) ScriptCompleted(ctx context.Context, req *agentproto.WorkspaceAgentScriptCompletedRequest) (*agentproto.WorkspaceAgentScriptCompletedResponse, error) {
res := &agentproto.WorkspaceAgentScriptCompletedResponse{}

scriptID, err := uuid.FromBytes(req.Timing.ScriptId)
if req.GetTiming() == nil {
return nil, xerrors.New("script timing is required")
}

scriptID, err := uuid.FromBytes(req.GetTiming().GetScriptId())
if err != nil {
return nil, xerrors.Errorf("script id from bytes: %w", err)
}

if req.GetTiming().GetStart() == nil {
return nil, xerrors.New("script start time is required")
}

if req.GetTiming().GetEnd() == nil {
return nil, xerrors.New("script end time is required")
}

if req.GetTiming().GetStart().AsTime().IsZero() {
return nil, xerrors.New("script start time cannot be zero")
}

if req.GetTiming().GetEnd().AsTime().IsZero() {
return nil, xerrors.New("script end time cannot be zero")
}

if req.GetTiming().GetStart().AsTime().After(req.GetTiming().GetEnd().AsTime()) {
return nil, xerrors.New("script start time cannot be after end time")
}

var stage database.WorkspaceAgentScriptTimingStage
switch req.Timing.Stage {
case agentproto.Timing_START:
Expand Down
97 changes: 86 additions & 11 deletions coderd/agentapi/scripts_test.go
View file
Open in desktop
10000
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,7 @@ import (
"time"

"github.com/google/uuid"
"github.com/stretchr/testify/require"
"go.uber.org/mock/gomock"
"google.golang.org/protobuf/types/known/timestamppb"

Expand All @@ -20,8 +21,10 @@ func TestScriptCompleted(t *testing.T) {
t.Parallel()

tests := []struct {
scriptID uuid.UUID
timing *agentproto.Timing
scriptID uuid.UUID
timing *agentproto.Timing
expectInsert bool
expectError string
}{
{
scriptID: uuid.New(),
Expand All @@ -32,6 +35,7 @@ func TestScriptCompleted(t *testing.T) {
Status: agentproto.Timing_OK,
ExitCode: 0,
},
expectInsert: true,
},
{
scriptID: uuid.New(),
Expand All @@ -42,6 +46,7 @@ func TestScriptCompleted(t *testing.T) {
Status: agentproto.Timing_OK,
ExitCode: 0,
},
expectInsert: true,
},
{
scriptID: uuid.New(),
Expand All @@ -52,6 +57,7 @@ func TestScriptCompleted(t *testing.T) {
Status: agentproto.Timing_OK,
ExitCode: 0,
},
expectInsert: true,
},
{
scriptID: uuid.New(),
Expand All @@ -62,6 +68,7 @@ func TestScriptCompleted(t *testing.T) {
Status: agentproto.Timing_TIMED_OUT,
ExitCode: 255,
},
expectInsert: true,
},
{
scriptID: uuid.New(),
Expand All @@ -72,6 +79,67 @@ func TestScriptCompleted(t *testing.T) {
Status: agentproto.Timing_EXIT_FAILURE,
ExitCode: 1,
},
expectInsert: true,
},
{
scriptID: uuid.New(),
timing: &agentproto.Timing{
Stage: agentproto.Timing_START,
Start: nil,
End: timestamppb.New(dbtime.Now().Add(time.Second)),
Status: agentproto.Timing_OK,
ExitCode: 0,
},
expectInsert: false,
expectError: "script start time is required",
},
{
scriptID: uuid.New(),
timing: &agentproto.Timing{
Stage: agentproto.Timing_START,
Start: timestamppb.New(dbtime.Now()),
End: nil,
Status: agentproto.Timing_OK,
ExitCode: 0,
},
expectInsert: false,
expectError: "script end time is required",
},
{
scriptID: uuid.New(),
timing: &agentproto.Timing{
Stage: agentproto.Timing_START,
Start: timestamppb.New(time.Time{}),
End: timestamppb.New(dbtime.Now()),
Status: agentproto.Timing_OK,
ExitCode: 0,
},
expectInsert: false,
expectError: "script start time cannot be zero",
},
{
scriptID: uuid.New(),
timing: &agentproto.Timing{
Stage: agentproto.Timing_START,
Start: timestamppb.New(dbtime.Now()),
End: timestamppb.New(time.Time{}),
Status: agentproto.Timing_OK,
ExitCode: 0,
},
expectInsert: false,
expectError: "script end time cannot be zero",
},
{
scriptID: uuid.New(),
timing: &agentproto.Timing{
Stage: agentproto.Timing_START,
Start: timestamppb.New(dbtime.Now()),
End: timestamppb.New(dbtime.Now().Add(-time.Second)),
Status: agentproto.Timing_OK,
ExitCode: 0,
},
expectInsert: false,
expectError: "script start time cannot be after end time",
},
}

Expand All @@ -80,19 +148,26 @@ func TestScriptCompleted(t *testing.T) {
tt.timing.ScriptId = tt.scriptID[:]

mDB := dbmock.NewMockStore(gomock.NewController(t))
mDB.EXPECT().InsertWorkspaceAgentScriptTimings(gomock.Any(), database.InsertWorkspaceAgentScriptTimingsParams{
ScriptID: tt.scriptID,
Stage: protoScriptTimingStageToDatabase(tt.timing.Stage),
Status: protoScriptTimingStatusToDatabase(tt.timing.Status),
StartedAt: tt.timing.Start.AsTime(),
EndedAt: tt.timing.End.AsTime(),
ExitCode: tt.timing.ExitCode,
})
if tt.expectInsert {
mDB.EXPECT().InsertWorkspaceAgentScriptTimings(gomock.Any(), database.InsertWorkspaceAgentScriptTimingsParams{
ScriptID: tt.scriptID,
Stage: protoScriptTimingStageToDatabase(tt.timing.Stage),
Status: protoScriptTimingStatusToDatabase(tt.timing.Status),
StartedAt: tt.timing.Start.AsTime(),
EndedAt: tt.timing.End.AsTime(),
ExitCode: tt.timing.ExitCode,
})
}

api := &agentapi.ScriptsAPI{Database: mDB}
api.ScriptCompleted(context.Background(), &agentproto.WorkspaceAgentScriptCompletedRequest{
_, err := api.ScriptCompleted(context.Background(), &agentproto.WorkspaceAgentScriptCompletedRequest{
Timing: tt.timing,
} EDBE )
if tt.expectError != "" {
require.Contains(t, err.Error(), tt.expectError, "expected error did not match")
} else {
require.NoError(t, err, "expected no error but got one")
}
}
}

Expand Down
5 changes: 5 additions & 0 deletions coderd/provisionerdserver/provisionerdserver.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1746,6 +1746,11 @@ func (s *server) completeWorkspaceBuildJob(ctx context.Context, job database.Pro
continue
}

if t.Start.AsTime().IsZero() || t.End.AsTime().IsZero() {
s.Logger.Warn(ctx, "timings entry has zero start or end time, skipping", slog.F("entry", t.String()))
continue
}

var stg database.ProvisionerJobTimingStage
if err := stg.Scan(t.Stage); err != nil {
s.Logger.Warn(ctx, "failed to parse timings stage, skipping", slog.F("value", t.Stage))
Expand Down
29 changes: 29 additions & 0 deletions coderd/workspacebuilds.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1176,6 +1176,16 @@ func (api *API) buildTimings(ctx context.Context, build database.WorkspaceBuild)
}

for _, t := range provisionerTimings {
// Ref: #15432: agent script timings must not have a zero start or end time.
if t.StartedAt.IsZero() || t.EndedAt.IsZero() {
api.Logger.Debug(ctx, "ignoring provisioner timing with zero start or end time",
slog.F("workspace_id", build.WorkspaceID),
slog.F("workspace_build_id", build.ID),
slog.F("provisioner_job_id", t.JobID),
)
continue
}

res.ProvisionerTimings = append(res.ProvisionerTimings, codersdk.ProvisionerTiming{
JobID: t.JobID,
Stage: codersdk.TimingStage(t.Stage),
Expand All @@ -1187,6 +1197,17 @@ func (api *API) buildTimings(ctx context.Context, build database.WorkspaceBuild)
})
}
for _, t := range agentScriptTimings {
// Ref: #15432: agent script timings must not have a zero start or end time.
if t.StartedAt.IsZero() || t.EndedAt.IsZero() {
api.Logger.Debug(ctx, "ignoring agent script timing with zero start or end time",
slog.F("workspace_id", build.WorkspaceID),
slog.F("workspace_agent_id", t.WorkspaceAgentID),
slog.F("workspace_build_id", build.ID),
slog.F("workspace_agent_script_id", t.ScriptID),
)
continue
}

Copy link
Member
@mafredri mafredri May 28, 2025 •
edited
Loading

Choose a reason for hiding this comment

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

The issue referenced in #15432 originates from the codersdk.TimingStageConnect timing that's further down, but that one doesn't seem addressed?

The agent.FirstConnectedAt.Time is used unconditionally, but may be null. Do we have a way to represent this better?

We could always omit the entry, but personally I'd like to see it in the graph as an unterminated starting point, would give an indication we're waiting for something.

Copy link
Member Author

Choose a reason for hiding this comment

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

We could represent both of these as codersdk.NullTime instead.

Copy link
Member Author

Choose a reason for hiding this comment

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

It turns out the timings chart is built to render with a "loading" state until all of provisioner timings, script timings, and connection timings are populated with at least one value. The assumption here is that timings are only useful after a build has completed.

My previous change (#18058) adds a check in the UI so that causes a time range with a zero time to be rendered as an "instant" with an "Invalid" label.

I think that, for now, it makes sense to simply exclude the agent connection timing if !FirstConnectedAt.Valid. Does that sound alright?

Copy link
Member

Choose a reason for hiding this comment

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

I'm fine with that if it can show up later if the agent finally connects 👍🏻

res.AgentScriptTimings = append(res.AgentScriptTimings, codersdk.AgentScriptTiming{
StartedAt: t.StartedAt,
EndedAt: t.EndedAt,
Expand All @@ -1199,6 +1220,14 @@ func (api *API) buildTimings(ctx context.Context, build database.WorkspaceBuild)
})
}
for _, agent := range agents {
if agent.FirstConnectedAt.Time.IsZero() {
api.Logger.Debug(ctx, "ignoring agent connection timing with zero first connected time",
slog.F("workspace_id", build.WorkspaceID),
slog.F("workspace_agent_id", agent.ID),
slog.F("workspace_build_id", build.ID),
)
continue
}
res.AgentConnectionTimings = append(res.AgentConnectionTimings, codersdk.AgentConnectionTiming{
WorkspaceAgentID: agent.ID.String(),
WorkspaceAgentName: agent.Name,
Expand Down
Loading
0