selfhosted
/
coder
mirror of https://github.com/coder/coder.git
1
0
Fork 0
Code Issues Projects Releases Wiki Activity

chore: add more rules to ensure logs consistency (#8104)

This commit is contained in:
Marcin Tojek 2023-06-21 12:00:38 +02:00 committed by GitHub
parent 1c8f564fdb
commit 4fb4c9b270
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
13 changed files with 65 additions and 41 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

6
agent/agent.go
View File

@ -332,7 +332,7 @@ func (a *agent) reportMetadataLoop(ctx context.Context) {
lastCollectedAts[mr.key] = mr.result.CollectedAt
err := a.client.PostMetadata(ctx, mr.key, *mr.result)
if err != nil {
a.logger.Error(ctx, "report metadata", slog.Error(err))
a.logger.Error(ctx, "agent failed to report metadata", slog.Error(err))
}
case <-baseTicker.C:
}
@ -462,7 +462,7 @@ func (a *agent) reportLifecycleLoop(ctx context.Context) {
return
}
// If we fail to report the state we probably shouldn't exit, log only.
a.logger.Error(ctx, "post state", slog.Error(err))
a.logger.Error(ctx, "agent failed to report the lifecycle state", slog.Error(err))
}
}
}
@ -1365,7 +1365,7 @@ func (a *agent) startReportingConnectionStats(ctx context.Context) {
)
})
if err != nil {
a.logger.Error(ctx, "report stats", slog.Error(err))
a.logger.Error(ctx, "agent failed to report stats", slog.Error(err))
} else {
if err = a.trackConnGoroutine(func() {
// This is OK because the agent never re-creates the tailnet

4
agent/agentssh/agentssh.go
View File

@ -341,7 +341,7 @@ func (s *Server) startPTYSession(session ptySession, magicTypeLabel string, cmd
if manifest != nil {
err := showMOTD(session, manifest.MOTDFile)
if err != nil {
s.logger.Error(ctx, "show MOTD", slog.Error(err))
s.logger.Error(ctx, "agent failed to show MOTD", slog.Error(err))
s.metrics.sessionErrors.WithLabelValues(magicTypeLabel, "yes", "motd").Add(1)
}
} else {
@ -410,7 +410,7 @@ func (s *Server) startPTYSession(session ptySession, magicTypeLabel string, cmd
// ExitErrors just mean the command we run returned a non-zero exit code, which is normal
// and not something to be concerned about. But, if it's something else, we should log it.
if err != nil && !xerrors.As(err, &exitErr) {
s.logger.Warn(ctx, "wait error", slog.Error(err))
s.logger.Warn(ctx, "process wait exited with error", slog.Error(err))
s.metrics.sessionErrors.WithLabelValues(magicTypeLabel, "yes", "wait").Add(1)
}
if err != nil {

10
coderd/audit.go
View File

@ -284,7 +284,7 @@ func (api *API) auditLogIsResourceDeleted(ctx context.Context, alog database.Get
if xerrors.Is(err, sql.ErrNoRows) {
return true
}
api.Logger.Error(ctx, "fetch template", slog.Error(err))
api.Logger.Error(ctx, "unable to fetch template", slog.Error(err))
}
return template.Deleted
case database.ResourceTypeUser:
@ -293,7 +293,7 @@ func (api *API) auditLogIsResourceDeleted(ctx context.Context, alog database.Get
if xerrors.Is(err, sql.ErrNoRows) {
return true
}
api.Logger.Error(ctx, "fetch user", slog.Error(err))
api.Logger.Error(ctx, "unable to fetch user", slog.Error(err))
}
return user.Deleted
case database.ResourceTypeWorkspace:
@ -302,7 +302,7 @@ func (api *API) auditLogIsResourceDeleted(ctx context.Context, alog database.Get
if xerrors.Is(err, sql.ErrNoRows) {
return true
}
api.Logger.Error(ctx, "fetch workspace", slog.Error(err))
api.Logger.Error(ctx, "unable to fetch workspace", slog.Error(err))
}
return workspace.Deleted
case database.ResourceTypeWorkspaceBuild:
@ -311,7 +311,7 @@ func (api *API) auditLogIsResourceDeleted(ctx context.Context, alog database.Get
if xerrors.Is(err, sql.ErrNoRows) {
return true
}
api.Logger.Error(ctx, "fetch workspace build", slog.Error(err))
api.Logger.Error(ctx, "unable to fetch workspace build", slog.Error(err))
}
// We use workspace as a proxy for workspace build here
workspace, err := api.Database.GetWorkspaceByID(ctx, workspaceBuild.WorkspaceID)
@ -319,7 +319,7 @@ func (api *API) auditLogIsResourceDeleted(ctx context.Context, alog database.Get
if xerrors.Is(err, sql.ErrNoRows) {
return true
}
api.Logger.Error(ctx, "fetch workspace", slog.Error(err))
api.Logger.Error(ctx, "unable to fetch workspace", slog.Error(err))
}
return workspace.Deleted
default:

2
coderd/authorize.go
View File

@ -22,7 +22,7 @@ func AuthorizeFilter[O rbac.Objecter](h *HTTPAuthorizer, r *http.Request, action
objects, err := rbac.Filter(r.Context(), h.Authorizer, roles.Actor, action, objects)
if err != nil {
// Log the error as Filter should not be erroring.
h.Logger.Error(r.Context(), "filter failed",
h.Logger.Error(r.Context(), "authorization filter failed",
slog.Error(err),
slog.F("user_id", roles.Actor.ID),
slog.F("username", roles.ActorName),

4
coderd/csp.go
View File

@ -31,7 +31,7 @@ func (api *API) logReportCSPViolations(rw http.ResponseWriter, r *http.Request)
dec := json.NewDecoder(r.Body)
err := dec.Decode(&v)
if err != nil {
api.Logger.Warn(ctx, "csp violation", slog.Error(err))
api.Logger.Warn(ctx, "CSP violation reported", slog.Error(err))
httpapi.Write(ctx, rw, http.StatusBadRequest, codersdk.Response{
Message: "Failed to read body, invalid json.",
Detail: err.Error(),
@ -43,7 +43,7 @@ func (api *API) logReportCSPViolations(rw http.ResponseWriter, r *http.Request)
for k, v := range v.Report {
fields = append(fields, slog.F(k, v))
}
api.Logger.Debug(ctx, "csp violation", fields...)
api.Logger.Debug(ctx, "CSP violation reported", fields...)
httpapi.Write(ctx, rw, http.StatusOK, "ok")
}

8
coderd/provisionerdserver/provisionerdserver.go
View File

@ -445,7 +445,7 @@ func (server *Server) UpdateJob(ctx context.Context, request *proto.UpdateJobReq
if err != nil {
return nil, xerrors.Errorf("parse job id: %w", err)
}
server.Logger.Debug(ctx, "UpdateJob starting", slog.F("job_id", parsedID))
server.Logger.Debug(ctx, "stage UpdateJob starting", slog.F("job_id", parsedID))
job, err := server.Database.GetProvisionerJobByID(ctx, parsedID)
if err != nil {
return nil, xerrors.Errorf("get job: %w", err)
@ -592,7 +592,7 @@ func (server *Server) FailJob(ctx context.Context, failJob *proto.FailedJob) (*p
if err != nil {
return nil, xerrors.Errorf("parse job id: %w", err)
}
server.Logger.Debug(ctx, "FailJob starting", slog.F("job_id", jobID))
server.Logger.Debug(ctx, "stage FailJob starting", slog.F("job_id", jobID))
job, err := server.Database.GetProvisionerJobByID(ctx, jobID)
if err != nil {
return nil, xerrors.Errorf("get provisioner job: %w", err)
@ -746,7 +746,7 @@ func (server *Server) CompleteJob(ctx context.Context, completed *proto.Complete
if err != nil {
return nil, xerrors.Errorf("parse job id: %w", err)
}
server.Logger.Debug(ctx, "CompleteJob starting", slog.F("job_id", jobID))
server.Logger.Debug(ctx, "stage CompleteJob starting", slog.F("job_id", jobID))
job, err := server.Database.GetProvisionerJobByID(ctx, jobID)
if err != nil {
return nil, xerrors.Errorf("get job by id: %w", err)
@ -1121,7 +1121,7 @@ func (server *Server) CompleteJob(ctx context.Context, completed *proto.Complete
return nil, xerrors.Errorf("publish end of job logs: %w", err)
}
server.Logger.Debug(ctx, "CompleteJob done", slog.F("job_id", jobID))
server.Logger.Debug(ctx, "stage CompleteJob done", slog.F("job_id", jobID))
return &proto.Empty{}, nil
}

6
coderd/telemetry/telemetry.go
View File

@ -125,7 +125,7 @@ func (r *remoteReporter) reportSync(snapshot *Snapshot) {
}
req, err := http.NewRequestWithContext(r.ctx, "POST", r.snapshotURL.String(), bytes.NewReader(data))
if err != nil {
r.options.Logger.Error(r.ctx, "create request", slog.Error(err))
r.options.Logger.Error(r.ctx, "unable to create snapshot request", slog.Error(err))
return
}
req.Header.Set(VersionHeader, buildinfo.Version())
@ -197,7 +197,7 @@ func (r *remoteReporter) reportWithDeployment() {
// Submit deployment information before creating a snapshot!
// This is separated from the snapshot API call to reduce
// duplicate data from being inserted. Snapshot may be called
// numerous times simaltanously if there is lots of activity!
// numerous times simultaneously if there is lots of activity!
err := r.deployment()
if err != nil {
r.options.Logger.Debug(r.ctx, "update deployment", slog.Error(err))
@ -208,7 +208,7 @@ func (r *remoteReporter) reportWithDeployment() {
return
}
if err != nil {
r.options.Logger.Error(r.ctx, "create snapshot", slog.Error(err))
r.options.Logger.Error(r.ctx, "unable to create deployment snapshot", slog.Error(err))
return
}
r.reportSync(snapshot)

2
coderd/userauth.go
View File

@ -678,7 +678,7 @@ func (api *API) userOIDC(rw http.ResponseWriter, r *http.Request) {
// This conditional is purely to warn the user they might have misconfigured their OIDC
// configuration.
if _, groupClaimExists := claims["groups"]; !usingGroups && groupClaimExists {
api.Logger.Debug(ctx, "'groups' claim was returned, but 'oidc-group-field' is not set, check your coder oidc settings.")
api.Logger.Debug(ctx, "claim 'groups' was returned, but 'oidc-group-field' is not set, check your coder oidc settings")
}
// The username is a required property in Coder. We make a best-effort

2
coderd/workspaceagents.go
View File

@ -999,7 +999,7 @@ func (api *API) workspaceAgentCoordinate(rw http.ResponseWriter, r *http.Request
}
api.publishWorkspaceUpdate(ctx, build.WorkspaceID)
api.Logger.Info(ctx, "accepting agent",
api.Logger.Debug(ctx, "accepting agent",
slog.F("owner", owner.Username),
slog.F("workspace", workspace.Name),
slog.F("name", workspaceAgent.Name),

4
enterprise/derpmesh/derpmesh.go
View File

@ -51,12 +51,12 @@ func (m *Mesh) SetAddresses(addresses []string, connect bool) {
for _, address := range addresses {
addressURL, err := url.Parse(address)
if err != nil {
m.logger.Error(m.ctx, "invalid address", slog.F("address", address), slog.Error(err))
m.logger.Error(m.ctx, "unable to parse DERP address", slog.F("address", address), slog.Error(err))
continue
}
derpURL, err := addressURL.Parse("/derp")
if err != nil {
m.logger.Error(m.ctx, "parse derp", slog.F("address", addressURL.String()), slog.Error(err))
m.logger.Error(m.ctx, "unable to parse DERP address with /derp", slog.F("address", addressURL.String()), slog.Error(err))
continue
}
address = derpURL.String()

10
provisionerd/provisionerd.go
View File

@ -190,7 +190,7 @@ func (p *Server) connect(ctx context.Context) {
if p.isClosed() {
return
}
p.opts.Logger.Warn(context.Background(), "failed to dial", slog.Error(err))
p.opts.Logger.Warn(context.Background(), "coderd client failed to dial", slog.Error(err))
continue
}
// Ensure connection is not left hanging during a race between
@ -303,7 +303,7 @@ func (p *Server) acquireJob(ctx context.Context) {
return
}
if p.isShutdown() {
p.opts.Logger.Debug(context.Background(), "skipping acquire; provisionerd is shutting down...")
p.opts.Logger.Debug(context.Background(), "skipping acquire; provisionerd is shutting down")
return
}
@ -333,7 +333,7 @@ func (p *Server) acquireJob(ctx context.Context) {
return
}
p.opts.Logger.Warn(ctx, "acquire job", slog.Error(err))
p.opts.Logger.Warn(ctx, "provisionerd was unable to acquire job", slog.Error(err))
return
}
if job.JobId == "" {
@ -384,7 +384,7 @@ func (p *Server) acquireJob(ctx context.Context) {
)
}
p.opts.Logger.Info(ctx, "acquired job", fields...)
p.opts.Logger.Debug(ctx, "acquired job", fields...)
provisioner, ok := p.opts.Provisioners[job.Provisioner]
if !ok {
@ -393,7 +393,7 @@ func (p *Server) acquireJob(ctx context.Context) {
Error: fmt.Sprintf("no provisioner %s", job.Provisioner),
})
if err != nil {
p.opts.Logger.Error(ctx, "fail job", slog.F("job_id", job.JobId), slog.Error(err))
p.opts.Logger.Error(ctx, "provisioner job failed", slog.F("job_id", job.JobId), slog.Error(err))
}
return
}

12
provisionerd/runner/runner.go
View File

@ -223,17 +223,17 @@ func (r *Runner) Run() {
r.logger.Debug(ctx, "sending FailedJob")
err := r.sender.FailJob(ctx, r.failedJob)
if err != nil {
r.logger.Error(ctx, "send FailJob", slog.Error(err))
r.logger.Error(ctx, "sending FailJob failed", slog.Error(err))
} else {
r.logger.Info(ctx, "sent FailedJob")
r.logger.Debug(ctx, "sent FailedJob")
}
} else {
r.logger.Debug(ctx, "sending CompletedJob")
err := r.sender.CompleteJob(ctx, r.completedJob)
if err != nil {
r.logger.Error(ctx, "send CompletedJob", slog.Error(err))
r.logger.Error(ctx, "sending CompletedJob failed", slog.Error(err))
} else {
r.logger.Info(ctx, "sent CompletedJob")
r.logger.Debug(ctx, "sent CompletedJob")
}
}
close(r.done)
@ -553,7 +553,7 @@ func (r *Runner) heartbeatRoutine(ctx context.Context) {
timer := time.NewTimer(r.forceCancelInterval)
select {
case <-timer.C:
r.logger.Warn(ctx, "Cancel timed out")
r.logger.Debug(ctx, "cancel timed out")
err := r.Fail(ctx, r.failedJobf("Cancel timed out"))
if err != nil {
r.logger.Warn(ctx, "failed to call FailJob", slog.Error(err))
@ -706,7 +706,7 @@ func (r *Runner) runTemplateImportParse(ctx context.Context) ([]*sdkproto.Templa
Stage: "Parse parameters",
})
case *sdkproto.Parse_Response_Complete:
r.logger.Info(context.Background(), "parse complete",
r.logger.Debug(context.Background(), "parse complete",
slog.F("template_variables", msgType.Complete.TemplateVariables),
)

36
scripts/rules.go
View File

@ -319,13 +319,24 @@ func slogMessageFormat(m dsl.Matcher) {
m.Import("cdr.dev/slog")
m.Match(
`logger.Error($ctx, $message, $*args)`,
`Logger.Error($ctx, $message, $*args)`,
`logger.Warn($ctx, $message, $*args)`,
`Logger.Warn($ctx, $message, $*args)`,
`logger.Info($ctx, $message, $*args)`,
`Logger.Info($ctx, $message, $*args)`,
`logger.Debug($ctx, $message, $*args)`,
`$foo.logger.Error($ctx, $message, $*args)`,
`$foo.logger.Warn($ctx, $message, $*args)`,
`$foo.logger.Info($ctx, $message, $*args)`,
`$foo.logger.Debug($ctx, $message, $*args)`,
`Logger.Error($ctx, $message, $*args)`,
`Logger.Warn($ctx, $message, $*args)`,
`Logger.Info($ctx, $message, $*args)`,
`Logger.Debug($ctx, $message, $*args)`,
`$foo.Logger.Error($ctx, $message, $*args)`,
`$foo.Logger.Warn($ctx, $message, $*args)`,
`$foo.Logger.Info($ctx, $message, $*args)`,
`$foo.Logger.Debug($ctx, $message, $*args)`,
).
Where(
(
@ -334,7 +345,10 @@ func slogMessageFormat(m dsl.Matcher) {
// it starts with lowercase:
m["message"].Text.Matches(`^"[A-Z]{1}`) &&
// but there are exceptions:
!m["message"].Text.Matches(`^"Prometheus`))).
!m["message"].Text.Matches(`^"Prometheus`) &&
!m["message"].Text.Matches(`^"X11`) &&
!m["message"].Text.Matches(`^"CSP`) &&
!m["message"].Text.Matches(`^"OIDC`))).
Report(`Message $message must start with lowercase, and does not end with a special characters.`)
}
@ -343,11 +357,21 @@ func slogMessageLength(m dsl.Matcher) {
m.Import("cdr.dev/slog")
m.Match(
`logger.Error($ctx, $message, $*args)`,
`Logger.Error($ctx, $message, $*args)`,
`logger.Warn($ctx, $message, $*args)`,
`Logger.Warn($ctx, $message, $*args)`,
`logger.Info($ctx, $message, $*args)`,
`$foo.logger.Error($ctx, $message, $*args)`,
`$foo.logger.Warn($ctx, $message, $*args)`,
`$foo.logger.Info($ctx, $message, $*args)`,
`Logger.Error($ctx, $message, $*args)`,
`Logger.Warn($ctx, $message, $*args)`,
`Logger.Info($ctx, $message, $*args)`,
`$foo.Logger.Error($ctx, $message, $*args)`,
`$foo.Logger.Warn($ctx, $message, $*args)`,
`$foo.Logger.Info($ctx, $message, $*args)`,
// no debug
).
Where(