Skip to content

Commit 776c144

Browse files
johnstcnjohnstcn
authored
fix(coderd): ensure agent timings are non-zero on insert (coder#18065)
Relates to coder#15432 Ensures that no workspace build timings with zero values for started_at or ended_at are inserted into the DB or returned from the API.
1 parent 5f34d01 commit 776c144

File tree

8 files changed

+217
-25
lines changed

8 files changed

+217
-25
lines changed

‎agent/agentscripts/agentscripts_test.go

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -144,6 +144,12 @@ func TestScriptReportsTiming(t *testing.T) {
144144

145145
timing := timings[0]
146146
require.Equal(t, int32(0), timing.ExitCode)
147+
if assert.True(t, timing.Start.IsValid(), "start time should be valid") {
148+
require.NotZero(t, timing.Start.AsTime(), "start time should not be zero")
149+
}
150+
if assert.True(t, timing.End.IsValid(), "end time should be valid") {
151+
require.NotZero(t, timing.End.AsTime(), "end time should not be zero")
152+
}
147153
require.GreaterOrEqual(t, timing.End.AsTime(), timing.Start.AsTime())
148154
}
149155

‎coderd/agentapi/scripts.go

Lines changed: 19 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -18,11 +18,29 @@ type ScriptsAPI struct {
1818
func (s *ScriptsAPI) ScriptCompleted(ctx context.Context, req *agentproto.WorkspaceAgentScriptCompletedRequest) (*agentproto.WorkspaceAgentScriptCompletedResponse, error) {
1919
res := &agentproto.WorkspaceAgentScriptCompletedResponse{}
2020

21-
scriptID, err := uuid.FromBytes(req.Timing.ScriptId)
21+
if req.GetTiming() == nil {
22+
return nil, xerrors.New("script timing is required")
23+
}
24+
25+
scriptID, err := uuid.FromBytes(req.GetTiming().GetScriptId())
2226
if err != nil {
2327
return nil, xerrors.Errorf("script id from bytes: %w", err)
2428
}
2529

30+
scriptStart := req.GetTiming().GetStart()
31+
if !scriptStart.IsValid() || scriptStart.AsTime().IsZero() {
32+
return nil, xerrors.New("script start time is required and cannot be zero")
33+
}
34+
35+
scriptEnd := req.GetTiming().GetEnd()
36+
if !scriptEnd.IsValid() || scriptEnd.AsTime().IsZero() {
37+
return nil, xerrors.New("script end time is required and cannot be zero")
38+
}
39+
40+
if scriptStart.AsTime().After(scriptEnd.AsTime()) {
41+
return nil, xerrors.New("script start time cannot be after end time")
42+
}
43+
2644
var stage database.WorkspaceAgentScriptTimingStage
2745
switch req.Timing.Stage {
2846
case agentproto.Timing_START:

‎coderd/agentapi/scripts_test.go

Lines changed: 86 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,7 @@ import (
66
"time"
77

88
"github.com/google/uuid"
9+
"github.com/stretchr/testify/require"
910
"go.uber.org/mock/gomock"
1011
"google.golang.org/protobuf/types/known/timestamppb"
1112

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

2223
tests := []struct {
23-
scriptID uuid.UUID
24-
timing *agentproto.Timing
24+
scriptID uuid.UUID
25+
timing *agentproto.Timing
26+
expectInsert bool
27+
expectError string
2528
}{
2629
{
2730
scriptID: uuid.New(),
@@ -32,6 +35,7 @@ func TestScriptCompleted(t *testing.T) {
3235
Status: agentproto.Timing_OK,
3336
ExitCode: 0,
3437
},
38+
expectInsert: true,
3539
},
3640
{
3741
scriptID: uuid.New(),
@@ -42,6 +46,7 @@ func TestScriptCompleted(t *testing.T) {
4246
Status: agentproto.Timing_OK,
4347
ExitCode: 0,
4448
},
49+
expectInsert: true,
4550
},
4651
{
4752
scriptID: uuid.New(),
@@ -52,6 +57,7 @@ func TestScriptCompleted(t *testing.T) {
5257
Status: agentproto.Timing_OK,
5358
ExitCode: 0,
5459
},
60+
expectInsert: true,
5561
},
5662
{
5763
scriptID: uuid.New(),
@@ -62,6 +68,7 @@ func TestScriptCompleted(t *testing.T) {
6268
Status: agentproto.Timing_TIMED_OUT,
6369
ExitCode: 255,
6470
},
71+
expectInsert: true,
6572
},
6673
{
6774
scriptID: uuid.New(),
@@ -72,6 +79,67 @@ func TestScriptCompleted(t *testing.T) {
7279
Status: agentproto.Timing_EXIT_FAILURE,
7380
ExitCode: 1,
7481
},
82+
expectInsert: true,
83+
},
84+
{
85+
scriptID: uuid.New(),
86+
timing: &agentproto.Timing{
87+
Stage: agentproto.Timing_START,
88+
Start: nil,
89+
End: timestamppb.New(dbtime.Now().Add(time.Second)),
90+
Status: agentproto.Timing_OK,
91+
ExitCode: 0,
92+
},
93+
expectInsert: false,
94+
expectError: "script start time is required and cannot be zero",
95+
},
96+
{
97+
scriptID: uuid.New(),
98+
timing: &agentproto.Timing{
99+
Stage: agentproto.Timing_START,
100+
Start: timestamppb.New(dbtime.Now()),
101+
End: nil,
102+
Status: agentproto.Timing_OK,
103+
ExitCode: 0,
104+
},
105+
expectInsert: false,
106+
expectError: "script end time is required and cannot be zero",
107+
},
108+
{
109+
scriptID: uuid.New(),
110+
timing: &agentproto.Timing{
111+
Stage: agentproto.Timing_START,
112+
Start: timestamppb.New(time.Time{}),
113+
End: timestamppb.New(dbtime.Now()),
114+
Status: agentproto.Timing_OK,
115+
ExitCode: 0,
116+
},
117+
expectInsert: false,
118+
expectError: "script start time is required and cannot be zero",
119+
},
120+
{
121+
scriptID: uuid.New(),
122+
timing: &agentproto.Timing{
123+
Stage: agentproto.Timing_START,
124+
Start: timestamppb.New(dbtime.Now()),
125+
End: timestamppb.New(time.Time{}),
126+
Status: agentproto.Timing_OK,
127+
ExitCode: 0,
128+
},
129+
expectInsert: false,
130+
expectError: "script end time is required and cannot be zero",
131+
},
132+
{
133+
scriptID: uuid.New(),
134+
timing: &agentproto.Timing{
135+
Stage: agentproto.Timing_START,
136+
Start: timestamppb.New(dbtime.Now()),
137+
End: timestamppb.New(dbtime.Now().Add(-time.Second)),
138+
Status: agentproto.Timing_OK,
139+
ExitCode: 0,
140+
},
141+
expectInsert: false,
142+
expectError: "script start time cannot be after end time",
75143
},
76144
}
77145

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

82150
mDB := dbmock.NewMockStore(gomock.NewController(t))
83-
mDB.EXPECT().InsertWorkspaceAgentScriptTimings(gomock.Any(), database.InsertWorkspaceAgentScriptTimingsParams{
84-
ScriptID: tt.scriptID,
85-
Stage: protoScriptTimingStageToDatabase(tt.timing.Stage),
86-
Status: protoScriptTimingStatusToDatabase(tt.timing.Status),
87-
StartedAt: tt.timing.Start.AsTime(),
88-
EndedAt: tt.timing.End.AsTime(),
89-
ExitCode: tt.timing.ExitCode,
90-
})
151+
if tt.expectInsert {
152+
mDB.EXPECT().InsertWorkspaceAgentScriptTimings(gomock.Any(), database.InsertWorkspaceAgentScriptTimingsParams{
153+
ScriptID: tt.scriptID,
154+
Stage: protoScriptTimingStageToDatabase(tt.timing.Stage),
155+
Status: protoScriptTimingStatusToDatabase(tt.timing.Status),
156+
StartedAt: tt.timing.Start.AsTime(),
157+
EndedAt: tt.timing.End.AsTime(),
158+
ExitCode: tt.timing.ExitCode,
159+
})
160+
}
91161

92162
api := &agentapi.ScriptsAPI{Database: mDB}
93-
api.ScriptCompleted(context.Background(), &agentproto.WorkspaceAgentScriptCompletedRequest{
163+
_, err := api.ScriptCompleted(context.Background(), &agentproto.WorkspaceAgentScriptCompletedRequest{
94164
Timing: tt.timing,
95165
})
166+
if tt.expectError != "" {
167+
require.Contains(t, err.Error(), tt.expectError, "expected error did not match")
168+
} else {
169+
require.NoError(t, err, "expected no error but got one")
170+
}
96171
}
97172
}
98173

‎coderd/database/dbgen/dbgen.go

Lines changed: 11 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -215,6 +215,17 @@ func WorkspaceAgent(t testing.TB, db database.Store, orig database.WorkspaceAgen
215215
APIKeyScope: takeFirst(orig.APIKeyScope, database.AgentKeyScopeEnumAll),
216216
})
217217
require.NoError(t, err, "insert workspace agent")
218+
if orig.FirstConnectedAt.Valid || orig.LastConnectedAt.Valid || orig.DisconnectedAt.Valid || orig.LastConnectedReplicaID.Valid {
219+
err = db.UpdateWorkspaceAgentConnectionByID(genCtx, database.UpdateWorkspaceAgentConnectionByIDParams{
220+
ID: agt.ID,
221+
FirstConnectedAt: takeFirst(orig.FirstConnectedAt, agt.FirstConnectedAt),
222+
LastConnectedAt: takeFirst(orig.LastConnectedAt, agt.LastConnectedAt),
223+
DisconnectedAt: takeFirst(orig.DisconnectedAt, agt.DisconnectedAt),
224+
LastConnectedReplicaID: takeFirst(orig.LastConnectedReplicaID, agt.LastConnectedReplicaID),
225+
UpdatedAt: takeFirst(orig.UpdatedAt, agt.UpdatedAt),
226+
})
227+
require.NoError(t, err, "update workspace agent first connected at")
228+
}
218229
return agt
219230
}
220231

‎coderd/provisionerdserver/provisionerdserver.go

Lines changed: 10 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -1741,8 +1741,15 @@ func (s *server) completeWorkspaceBuildJob(ctx context.Context, job database.Pro
17411741
JobID: jobID,
17421742
}
17431743
for _, t := range jobType.WorkspaceBuild.Timings {
1744-
if t.Start == nil || t.End == nil {
1745-
s.Logger.Warn(ctx, "timings entry has nil start or end time", slog.F("entry", t.String()))
1744+
start := t.GetStart()
1745+
if !start.IsValid() || start.AsTime().IsZero() {
1746+
s.Logger.Warn(ctx, "timings entry has nil or zero start time", slog.F("job_id", job.ID.String()), slog.F("workspace_id", workspace.ID), slog.F("workspace_build_id", workspaceBuild.ID), slog.F("user_id", workspace.OwnerID))
1747+
continue
1748+
}
1749+
1750+
end := t.GetEnd()
1751+
if !end.IsValid() || end.AsTime().IsZero() {
1752+
s.Logger.Warn(ctx, "timings entry has nil or zero end time, skipping", slog.F("job_id", job.ID.String()), slog.F("workspace_id", workspace.ID), slog.F("workspace_build_id", workspaceBuild.ID), slog.F("user_id", workspace.OwnerID))
17461753
continue
17471754
}
17481755

@@ -1771,7 +1778,7 @@ func (s *server) completeWorkspaceBuildJob(ctx context.Context, job database.Pro
17711778
// after being started.
17721779
//
17731780
// Agent timeouts could be minutes apart, resulting in an unresponsive
1774-
// experience, so we'll notify after every unique timeout seconds.
1781+
// experience, so we'll notify after every unique timeout seconds
17751782
if !input.DryRun && workspaceBuild.Transition == database.WorkspaceTransitionStart && len(agentTimeouts) > 0 {
17761783
timeouts := maps.Keys(agentTimeouts)
17771784
slices.Sort(timeouts)

‎coderd/provisionerdserver/provisionerdserver_test.go

Lines changed: 51 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -1301,14 +1301,57 @@ func TestCompleteJob(t *testing.T) {
13011301
Name: "test-workspace-resource",
13021302
Type: "aws_instance",
13031303
}},
1304-
Timings: []*sdkproto.Timing{{
1305-
Stage: "test",
1306-
Source: "test-source",
1307-
Resource: "test-resource",
1308-
Action: "test-action",
1309-
Start: timestamppb.Now(),
1310-
End: timestamppb.Now(),
1311-
}},
1304+
Timings: []*sdkproto.Timing{
1305+
{
1306+
Stage: "test",
1307+
Source: "test-source",
1308+
Resource: "test-resource",
1309+
Action: "test-action",
1310+
Start: timestamppb.Now(),
1311+
End: timestamppb.Now(),
1312+
},
1313+
{
1314+
Stage: "test2",
1315+
Source: "test-source2",
1316+
Resource: "test-resource2",
1317+
Action: "test-action2",
1318+
// Start: omitted
1319+
// End: omitted
1320+
},
1321+
{
1322+
Stage: "test3",
1323+
Source: "test-source3",
1324+
Resource: "test-resource3",
1325+
Action: "test-action3",
1326+
Start: timestamppb.Now(),
1327+
End: nil,
1328+
},
1329+
{
1330+
Stage: "test3",
1331+
Source: "test-source3",
1332+
Resource: "test-resource3",
1333+
Action: "test-action3",
1334+
Start: nil,
1335+
End: timestamppb.Now(),
1336+
},
1337+
{
1338+
Stage: "test4",
1339+
Source: "test-source4",
1340+
Resource: "test-resource4",
1341+
Action: "test-action4",
1342+
Start: timestamppb.New(time.Time{}),
1343+
End: timestamppb.Now(),
1344+
},
1345+
{
1346+
Stage: "test5",
1347+
Source: "test-source5",
1348+
Resource: "test-resource5",
1349+
Action: "test-action5",
1350+
Start: timestamppb.Now(),
1351+
End: timestamppb.New(time.Time{}),
1352+
},
1353+
nil, // nil timing should be ignored
1354+
},
13121355
},
13131356
},
13141357
})

‎coderd/workspacebuilds.go

Lines changed: 29 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1179,6 +1179,16 @@ func (api *API) buildTimings(ctx context.Context, build database.WorkspaceBuild)
11791179
}
11801180

11811181
for _, t := range provisionerTimings {
1182+
// Ref: #15432: agent script timings must not have a zero start or end time.
1183+
if t.StartedAt.IsZero() || t.EndedAt.IsZero() {
1184+
api.Logger.Debug(ctx, "ignoring provisioner timing with zero start or end time",
1185+
slog.F("workspace_id", build.WorkspaceID),
1186+
slog.F("workspace_build_id", build.ID),
1187+
slog.F("provisioner_job_id", t.JobID),
1188+
)
1189+
continue
1190+
}
1191+
11821192
res.ProvisionerTimings = append(res.ProvisionerTimings, codersdk.ProvisionerTiming{
11831193
JobID: t.JobID,
11841194
Stage: codersdk.TimingStage(t.Stage),
@@ -1190,6 +1200,17 @@ func (api *API) buildTimings(ctx context.Context, build database.WorkspaceBuild)
11901200
})
11911201
}
11921202
for _, t := range agentScriptTimings {
1203+
// Ref: #15432: agent script timings must not have a zero start or end time.
1204+
if t.StartedAt.IsZero() || t.EndedAt.IsZero() {
1205+
api.Logger.Debug(ctx, "ignoring agent script timing with zero start or end time",
1206+
slog.F("workspace_id", build.WorkspaceID),
1207+
slog.F("workspace_agent_id", t.WorkspaceAgentID),
1208+
slog.F("workspace_build_id", build.ID),
1209+
slog.F("workspace_agent_script_id", t.ScriptID),
1210+
)
1211+
continue
1212+
}
1213+
11931214
res.AgentScriptTimings = append(res.AgentScriptTimings, codersdk.AgentScriptTiming{
11941215
StartedAt: t.StartedAt,
11951216
EndedAt: t.EndedAt,
@@ -1202,6 +1223,14 @@ func (api *API) buildTimings(ctx context.Context, build database.WorkspaceBuild)
12021223
})
12031224
}
12041225
for _, agent := range agents {
1226+
if agent.FirstConnectedAt.Time.IsZero() {
1227+
api.Logger.Debug(ctx, "ignoring agent connection timing with zero first connected time",
1228+
slog.F("workspace_id", build.WorkspaceID),
1229+
slog.F("workspace_agent_id", agent.ID),
1230+
slog.F("workspace_build_id", build.ID),
1231+
)
1232+
continue
1233+
}
12051234
res.AgentConnectionTimings = append(res.AgentConnectionTimings, codersdk.AgentConnectionTiming{
12061235
WorkspaceAgentID: agent.ID.String(),
12071236
WorkspaceAgentName: agent.Name,

‎coderd/workspacebuilds_test.go

Lines changed: 5 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,7 @@ package coderd_test
22

33
import (
44
"context"
5+
"database/sql"
56
"errors"
67
"fmt"
78
"net/http"
@@ -1736,7 +1737,8 @@ func TestWorkspaceBuildTimings(t *testing.T) {
17361737
JobID: build.JobID,
17371738
})
17381739
agent := dbgen.WorkspaceAgent(t, db, database.WorkspaceAgent{
1739-
ResourceID: resource.ID,
1740+
ResourceID: resource.ID,
1741+
FirstConnectedAt: sql.NullTime{Valid: true, Time: dbtime.Now().Add(-time.Hour)},
17401742
})
17411743

17421744
// When: fetching timings for the build
@@ -1767,7 +1769,8 @@ func TestWorkspaceBuildTimings(t *testing.T) {
17671769
agents := make([]database.WorkspaceAgent, 5)
17681770
for i := range agents {
17691771
agents[i] = dbgen.WorkspaceAgent(t, db, database.WorkspaceAgent{
1770-
ResourceID: resource.ID,
1772+
ResourceID: resource.ID,
1773+
FirstConnectedAt: sql.NullTime{Valid: true, Time: dbtime.Now().Add(-time.Duration(i) * time.Hour)},
17711774
})
17721775
}
17731776

0 commit comments

Comments
 (0)