Skip to content

Commit 4fb4c9b

Browse files
mtojekmtojek
authored
chore: add more rules to ensure logs consistency (coder#8104)
1 parent 1c8f564 commit 4fb4c9b

File tree

13 files changed

+65
-41
lines changed

13 files changed

+65
-41
lines changed

‎agent/agent.go

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -332,7 +332,7 @@ func (a *agent) reportMetadataLoop(ctx context.Context) {
332332
lastCollectedAts[mr.key] = mr.result.CollectedAt
333333
err := a.client.PostMetadata(ctx, mr.key, *mr.result)
334334
if err != nil {
335-
a.logger.Error(ctx, "report metadata", slog.Error(err))
335+
a.logger.Error(ctx, "agent failed to report metadata", slog.Error(err))
336336
}
337337
case <-baseTicker.C:
338338
}
@@ -462,7 +462,7 @@ func (a *agent) reportLifecycleLoop(ctx context.Context) {
462462
return
463463
}
464464
// If we fail to report the state we probably shouldn't exit, log only.
465-
a.logger.Error(ctx, "post state", slog.Error(err))
465+
a.logger.Error(ctx, "agent failed to report the lifecycle state", slog.Error(err))
466466
}
467467
}
468468
}
@@ -1365,7 +1365,7 @@ func (a *agent) startReportingConnectionStats(ctx context.Context) {
13651365
)
13661366
})
13671367
if err != nil {
1368-
a.logger.Error(ctx, "report stats", slog.Error(err))
1368+
a.logger.Error(ctx, "agent failed to report stats", slog.Error(err))
13691369
} else {
13701370
if err = a.trackConnGoroutine(func() {
13711371
// This is OK because the agent never re-creates the tailnet

‎agent/agentssh/agentssh.go

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -341,7 +341,7 @@ func (s *Server) startPTYSession(session ptySession, magicTypeLabel string, cmd
341341
if manifest != nil {
342342
err := showMOTD(session, manifest.MOTDFile)
343343
if err != nil {
344-
s.logger.Error(ctx, "show MOTD", slog.Error(err))
344+
s.logger.Error(ctx, "agent failed to show MOTD", slog.Error(err))
345345
s.metrics.sessionErrors.WithLabelValues(magicTypeLabel, "yes", "motd").Add(1)
346346
}
347347
} else {
@@ -410,7 +410,7 @@ func (s *Server) startPTYSession(session ptySession, magicTypeLabel string, cmd
410410
// ExitErrors just mean the command we run returned a non-zero exit code, which is normal
411411
// and not something to be concerned about. But, if it's something else, we should log it.
412412
if err != nil && !xerrors.As(err, &exitErr) {
413-
s.logger.Warn(ctx, "wait error", slog.Error(err))
413+
s.logger.Warn(ctx, "process wait exited with error", slog.Error(err))
414414
s.metrics.sessionErrors.WithLabelValues(magicTypeLabel, "yes", "wait").Add(1)
415415
}
416416
if err != nil {

‎coderd/audit.go

Lines changed: 5 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -284,7 +284,7 @@ func (api *API) auditLogIsResourceDeleted(ctx context.Context, alog database.Get
284284
if xerrors.Is(err, sql.ErrNoRows) {
285285
return true
286286
}
287-
api.Logger.Error(ctx, "fetch template", slog.Error(err))
287+
api.Logger.Error(ctx, "unable to fetch template", slog.Error(err))
288288
}
289289
return template.Deleted
290290
case database.ResourceTypeUser:
@@ -293,7 +293,7 @@ func (api *API) auditLogIsResourceDeleted(ctx context.Context, alog database.Get
293293
if xerrors.Is(err, sql.ErrNoRows) {
294294
return true
295295
}
296-
api.Logger.Error(ctx, "fetch user", slog.Error(err))
296+
api.Logger.Error(ctx, "unable to fetch user", slog.Error(err))
297297
}
298298
return user.Deleted
299299
case database.ResourceTypeWorkspace:
@@ -302,7 +302,7 @@ func (api *API) auditLogIsResourceDeleted(ctx context.Context, alog database.Get
302302
if xerrors.Is(err, sql.ErrNoRows) {
303303
return true
304304
}
305-
api.Logger.Error(ctx, "fetch workspace", slog.Error(err))
305+
api.Logger.Error(ctx, "unable to fetch workspace", slog.Error(err))
306306
}
307307
return workspace.Deleted
308308
case database.ResourceTypeWorkspaceBuild:
@@ -311,15 +311,15 @@ func (api *API) auditLogIsResourceDeleted(ctx context.Context, alog database.Get
311311
if xerrors.Is(err, sql.ErrNoRows) {
312312
return true
313313
}
314-
api.Logger.Error(ctx, "fetch workspace build", slog.Error(err))
314+
api.Logger.Error(ctx, "unable to fetch workspace build", slog.Error(err))
315315
}
316316
// We use workspace as a proxy for workspace build here
317317
workspace, err := api.Database.GetWorkspaceByID(ctx, workspaceBuild.WorkspaceID)
318318
if err != nil {
319319
if xerrors.Is(err, sql.ErrNoRows) {
320320
return true
321321
}
322-
api.Logger.Error(ctx, "fetch workspace", slog.Error(err))
322+
api.Logger.Error(ctx, "unable to fetch workspace", slog.Error(err))
323323
}
324324
return workspace.Deleted
325325
default:

‎coderd/authorize.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -22,7 +22,7 @@ func AuthorizeFilter[O rbac.Objecter](h *HTTPAuthorizer, r *http.Request, action
2222
objects, err := rbac.Filter(r.Context(), h.Authorizer, roles.Actor, action, objects)
2323
if err != nil {
2424
// Log the error as Filter should not be erroring.
25-
h.Logger.Error(r.Context(), "filter failed",
25+
h.Logger.Error(r.Context(), "authorization filter failed",
2626
slog.Error(err),
2727
slog.F("user_id", roles.Actor.ID),
2828
slog.F("username", roles.ActorName),

‎coderd/csp.go

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -31,7 +31,7 @@ func (api *API) logReportCSPViolations(rw http.ResponseWriter, r *http.Request)
3131
dec := json.NewDecoder(r.Body)
3232
err := dec.Decode(&v)
3333
if err != nil {
34-
api.Logger.Warn(ctx, "csp violation", slog.Error(err))
34+
api.Logger.Warn(ctx, "CSP violation reported", slog.Error(err))
3535
httpapi.Write(ctx, rw, http.StatusBadRequest, codersdk.Response{
3636
Message: "Failed to read body, invalid json.",
3737
Detail: err.Error(),
@@ -43,7 +43,7 @@ func (api *API) logReportCSPViolations(rw http.ResponseWriter, r *http.Request)
4343
for k, v := range v.Report {
4444
fields = append(fields, slog.F(k, v))
4545
}
46-
api.Logger.Debug(ctx, "csp violation", fields...)
46+
api.Logger.Debug(ctx, "CSP violation reported", fields...)
4747

4848
httpapi.Write(ctx, rw, http.StatusOK, "ok")
4949
}

‎coderd/provisionerdserver/provisionerdserver.go

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -445,7 +445,7 @@ func (server *Server) UpdateJob(ctx context.Context, request *proto.UpdateJobReq
445445
if err != nil {
446446
return nil, xerrors.Errorf("parse job id: %w", err)
447447
}
448-
server.Logger.Debug(ctx, "UpdateJob starting", slog.F("job_id", parsedID))
448+
server.Logger.Debug(ctx, "stage UpdateJob starting", slog.F("job_id", parsedID))
449449
job, err := server.Database.GetProvisionerJobByID(ctx, parsedID)
450450
if err != nil {
451451
return nil, xerrors.Errorf("get job: %w", err)
@@ -592,7 +592,7 @@ func (server *Server) FailJob(ctx context.Context, failJob *proto.FailedJob) (*p
592592
if err != nil {
593593
return nil, xerrors.Errorf("parse job id: %w", err)
594594
}
595-
server.Logger.Debug(ctx, "FailJob starting", slog.F("job_id", jobID))
595+
server.Logger.Debug(ctx, "stage FailJob starting", slog.F("job_id", jobID))
596596
job, err := server.Database.GetProvisionerJobByID(ctx, jobID)
597597
if err != nil {
598598
return nil, xerrors.Errorf("get provisioner job: %w", err)
@@ -746,7 +746,7 @@ func (server *Server) CompleteJob(ctx context.Context, completed *proto.Complete
746746
if err != nil {
747747
return nil, xerrors.Errorf("parse job id: %w", err)
748748
}
749-
server.Logger.Debug(ctx, "CompleteJob starting", slog.F("job_id", jobID))
749+
server.Logger.Debug(ctx, "stage CompleteJob starting", slog.F("job_id", jobID))
750750
job, err := server.Database.GetProvisionerJobByID(ctx, jobID)
751751
if err != nil {
752752
return nil, xerrors.Errorf("get job by id: %w", err)
@@ -1121,7 +1121,7 @@ func (server *Server) CompleteJob(ctx context.Context, completed *proto.Complete
11211121
return nil, xerrors.Errorf("publish end of job logs: %w", err)
11221122
}
11231123

1124-
server.Logger.Debug(ctx, "CompleteJob done", slog.F("job_id", jobID))
1124+
server.Logger.Debug(ctx, "stage CompleteJob done", slog.F("job_id", jobID))
11251125
return &proto.Empty{}, nil
11261126
}
11271127

‎coderd/telemetry/telemetry.go

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -125,7 +125,7 @@ func (r *remoteReporter) reportSync(snapshot *Snapshot) {
125125
}
126126
req, err := http.NewRequestWithContext(r.ctx, "POST", r.snapshotURL.String(), bytes.NewReader(data))
127127
if err != nil {
128-
r.options.Logger.Error(r.ctx, "create request", slog.Error(err))
128+
r.options.Logger.Error(r.ctx, "unable to create snapshot request", slog.Error(err))
129129
return
130130
}
131131
req.Header.Set(VersionHeader, buildinfo.Version())
@@ -197,7 +197,7 @@ func (r *remoteReporter) reportWithDeployment() {
197197
// Submit deployment information before creating a snapshot!
198198
// This is separated from the snapshot API call to reduce
199199
// duplicate data from being inserted. Snapshot may be called
200-
// numerous times simaltanously if there is lots of activity!
200+
// numerous times simultaneously if there is lots of activity!
201201
err := r.deployment()
202202
if err != nil {
203203
r.options.Logger.Debug(r.ctx, "update deployment", slog.Error(err))
@@ -208,7 +208,7 @@ func (r *remoteReporter) reportWithDeployment() {
208208
return
209209
}
210210
if err != nil {
211-
r.options.Logger.Error(r.ctx, "create snapshot", slog.Error(err))
211+
r.options.Logger.Error(r.ctx, "unable to create deployment snapshot", slog.Error(err))
212212
return
213213
}
214214
r.reportSync(snapshot)

‎coderd/userauth.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -678,7 +678,7 @@ func (api *API) userOIDC(rw http.ResponseWriter, r *http.Request) {
678678
// This conditional is purely to warn the user they might have misconfigured their OIDC
679679
// configuration.
680680
if _, groupClaimExists := claims["groups"]; !usingGroups && groupClaimExists {
681-
api.Logger.Debug(ctx, "'groups' claim was returned, but 'oidc-group-field' is not set, check your coder oidc settings.")
681+
api.Logger.Debug(ctx, "claim 'groups' was returned, but 'oidc-group-field' is not set, check your coder oidc settings")
682682
}
683683

684684
// The username is a required property in Coder. We make a best-effort

‎coderd/workspaceagents.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -999,7 +999,7 @@ func (api *API) workspaceAgentCoordinate(rw http.ResponseWriter, r *http.Request
999999
}
10001000
api.publishWorkspaceUpdate(ctx, build.WorkspaceID)
10011001

1002-
api.Logger.Info(ctx, "accepting agent",
1002+
api.Logger.Debug(ctx, "accepting agent",
10031003
slog.F("owner", owner.Username),
10041004
slog.F("workspace", workspace.Name),
10051005
slog.F("name", workspaceAgent.Name),

‎enterprise/derpmesh/derpmesh.go

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -51,12 +51,12 @@ func (m *Mesh) SetAddresses(addresses []string, connect bool) {
5151
for _, address := range addresses {
5252
addressURL, err := url.Parse(address)
5353
if err != nil {
54-
m.logger.Error(m.ctx, "invalid address", slog.F("address", address), slog.Error(err))
54+
m.logger.Error(m.ctx, "unable to parse DERP address", slog.F("address", address), slog.Error(err))
5555
continue
5656
}
5757
derpURL, err := addressURL.Parse("/derp")
5858
if err != nil {
59-
m.logger.Error(m.ctx, "parse derp", slog.F("address", addressURL.String()), slog.Error(err))
59+
m.logger.Error(m.ctx, "unable to parse DERP address with /derp", slog.F("address", addressURL.String()), slog.Error(err))
6060
continue
6161
}
6262
address = derpURL.String()

‎provisionerd/provisionerd.go

Lines changed: 5 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -190,7 +190,7 @@ func (p *Server) connect(ctx context.Context) {
190190
if p.isClosed() {
191191
return
192192
}
193-
p.opts.Logger.Warn(context.Background(), "failed to dial", slog.Error(err))
193+
p.opts.Logger.Warn(context.Background(), "coderd client failed to dial", slog.Error(err))
194194
continue
195195
}
196196
// Ensure connection is not left hanging during a race between
@@ -303,7 +303,7 @@ func (p *Server) acquireJob(ctx context.Context) {
303303
return
304304
}
305305
if p.isShutdown() {
306-
p.opts.Logger.Debug(context.Background(), "skipping acquire; provisionerd is shutting down...")
306+
p.opts.Logger.Debug(context.Background(), "skipping acquire; provisionerd is shutting down")
307307
return
308308
}
309309

@@ -333,7 +333,7 @@ func (p *Server) acquireJob(ctx context.Context) {
333333
return
334334
}
335335

336-
p.opts.Logger.Warn(ctx, "acquire job", slog.Error(err))
336+
p.opts.Logger.Warn(ctx, "provisionerd was unable to acquire job", slog.Error(err))
337337
return
338338
}
339339
if job.JobId == "" {
@@ -384,7 +384,7 @@ func (p *Server) acquireJob(ctx context.Context) {
384384
)
385385
}
386386

387-
p.opts.Logger.Info(ctx, "acquired job", fields...)
387+
p.opts.Logger.Debug(ctx, "acquired job", fields...)
388388

389389
provisioner, ok := p.opts.Provisioners[job.Provisioner]
390390
if !ok {
@@ -393,7 +393,7 @@ func (p *Server) acquireJob(ctx context.Context) {
393393
Error: fmt.Sprintf("no provisioner %s", job.Provisioner),
394394
})
395395
if err != nil {
396-
p.opts.Logger.Error(ctx, "fail job", slog.F("job_id", job.JobId), slog.Error(err))
396+
p.opts.Logger.Error(ctx, "provisioner job failed", slog.F("job_id", job.JobId), slog.Error(err))
397397
}
398398
return
399399
}

‎provisionerd/runner/runner.go

Lines changed: 6 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -223,17 +223,17 @@ func (r *Runner) Run() {
223223
r.logger.Debug(ctx, "sending FailedJob")
224224
err := r.sender.FailJob(ctx, r.failedJob)
225225
if err != nil {
226-
r.logger.Error(ctx, "send FailJob", slog.Error(err))
226+
r.logger.Error(ctx, "sending FailJob failed", slog.Error(err))
227227
} else {
228-
r.logger.Info(ctx, "sent FailedJob")
228+
r.logger.Debug(ctx, "sent FailedJob")
229229
}
230230
} else {
231231
r.logger.Debug(ctx, "sending CompletedJob")
232232
err := r.sender.CompleteJob(ctx, r.completedJob)
233233
if err != nil {
234-
r.logger.Error(ctx, "send CompletedJob", slog.Error(err))
234+
r.logger.Error(ctx, "sending CompletedJob failed", slog.Error(err))
235235
} else {
236-
r.logger.Info(ctx, "sent CompletedJob")
236+
r.logger.Debug(ctx, "sent CompletedJob")
237237
}
238238
}
239239
close(r.done)
@@ -553,7 +553,7 @@ func (r *Runner) heartbeatRoutine(ctx context.Context) {
553553
timer := time.NewTimer(r.forceCancelInterval)
554554
select {
555555
case <-timer.C:
556-
r.logger.Warn(ctx, "Cancel timed out")
556+
r.logger.Debug(ctx, "cancel timed out")
557557
err := r.Fail(ctx, r.failedJobf("Cancel timed out"))
558558
if err != nil {
559559
r.logger.Warn(ctx, "failed to call FailJob", slog.Error(err))
@@ -706,7 +706,7 @@ func (r *Runner) runTemplateImportParse(ctx context.Context) ([]*sdkproto.Templa
706706
Stage: "Parse parameters",
707707
})
708708
case *sdkproto.Parse_Response_Complete:
709-
r.logger.Info(context.Background(), "parse complete",
709+
r.logger.Debug(context.Background(), "parse complete",
710710
slog.F("template_variables", msgType.Complete.TemplateVariables),
711711
)
712712

‎scripts/rules.go

Lines changed: 30 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -319,13 +319,24 @@ func slogMessageFormat(m dsl.Matcher) {
319319
m.Import("cdr.dev/slog")
320320
m.Match(
321321
`logger.Error($ctx, $message, $*args)`,
322-
`Logger.Error($ctx, $message, $*args)`,
323322
`logger.Warn($ctx, $message, $*args)`,
324-
`Logger.Warn($ctx, $message, $*args)`,
325323
`logger.Info($ctx, $message, $*args)`,
326-
`Logger.Info($ctx, $message, $*args)`,
327324
`logger.Debug($ctx, $message, $*args)`,
325+
326+
`$foo.logger.Error($ctx, $message, $*args)`,
327+
`$foo.logger.Warn($ctx, $message, $*args)`,
328+
`$foo.logger.Info($ctx, $message, $*args)`,
329+
`$foo.logger.Debug($ctx, $message, $*args)`,
330+
331+
`Logger.Error($ctx, $message, $*args)`,
332+
`Logger.Warn($ctx, $message, $*args)`,
333+
`Logger.Info($ctx, $message, $*args)`,
328334
`Logger.Debug($ctx, $message, $*args)`,
335+
336+
`$foo.Logger.Error($ctx, $message, $*args)`,
337+
`$foo.Logger.Warn($ctx, $message, $*args)`,
338+
`$foo.Logger.Info($ctx, $message, $*args)`,
339+
`$foo.Logger.Debug($ctx, $message, $*args)`,
329340
).
330341
Where(
331342
(
@@ -334,7 +345,10 @@ func slogMessageFormat(m dsl.Matcher) {
334345
// it starts with lowercase:
335346
m["message"].Text.Matches(`^"[A-Z]{1}`) &&
336347
// but there are exceptions:
337-
!m["message"].Text.Matches(`^"Prometheus`))).
348+
!m["message"].Text.Matches(`^"Prometheus`) &&
349+
!m["message"].Text.Matches(`^"X11`) &&
350+
!m["message"].Text.Matches(`^"CSP`) &&
351+
!m["message"].Text.Matches(`^"OIDC`))).
338352
Report(`Message $message must start with lowercase, and does not end with a special characters.`)
339353
}
340354

@@ -343,11 +357,21 @@ func slogMessageLength(m dsl.Matcher) {
343357
m.Import("cdr.dev/slog")
344358
m.Match(
345359
`logger.Error($ctx, $message, $*args)`,
346-
`Logger.Error($ctx, $message, $*args)`,
347360
`logger.Warn($ctx, $message, $*args)`,
348-
`Logger.Warn($ctx, $message, $*args)`,
349361
`logger.Info($ctx, $message, $*args)`,
362+
363+
`$foo.logger.Error($ctx, $message, $*args)`,
364+
`$foo.logger.Warn($ctx, $message, $*args)`,
365+
`$foo.logger.Info($ctx, $message, $*args)`,
366+
367+
`Logger.Error($ctx, $message, $*args)`,
368+
`Logger.Warn($ctx, $message, $*args)`,
350369
`Logger.Info($ctx, $message, $*args)`,
370+
371+
`$foo.Logger.Error($ctx, $message, $*args)`,
372+
`$foo.Logger.Warn($ctx, $message, $*args)`,
373+
`$foo.Logger.Info($ctx, $message, $*args)`,
374+
351375
// no debug
352376
).
353377
Where(

0 commit comments

Comments
 (0)