chore: add more rules to ensure logs consistency

coder · mtojek · Jun 21, 2023 · Jun 20, 2023 · Jun 20, 2023 · Jun 21, 2023
commit 1bc6e9380554a44f60950324714ff7eaeecd3c91
diff --git a/agent/agent.go b/agent/agent.go
@@ -330,7 +330,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:
 		}
@@ -453,7 +453,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))
 		}
 	}
 }
@@ -835,7 +835,7 @@ func (a *agent) runScript(ctx context.Context, lifecycle, script string) error {
 		return nil
 	}
 
-	a.logger.Info(ctx, "running script", slog.F("lifecycle", lifecycle), slog.F("script", script))
+	a.logger.Debug(ctx, "running script", slog.F("lifecycle", lifecycle), slog.F("script", script))
 	fileWriter, err := a.filesystem.OpenFile(filepath.Join(a.logDir, fmt.Sprintf("coder-%s-script.log", lifecycle)), os.O_CREATE|os.O_RDWR, 0o600)
 	if err != nil {
 		return xerrors.Errorf("open %s script log file: %w", lifecycle, err)
@@ -1326,7 +1326,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

diff --git a/agent/agentssh/agentssh.go b/agent/agentssh/agentssh.go
@@ -337,7 +337,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 {
@@ -406,7 +406,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 {

diff --git a/coderd/audit.go b/coderd/audit.go
@@ -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, "can't 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, "can't 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, "can't fetch workspace", slog.Error(err))
 		}
 		return workspace.Deleted
 	case database.ResourceTypeWorkspaceBuild:
@@ -311,15 +311,15 @@ 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, "can't fetch workspace build", slog.Error(err))
 		}
 		// We use workspace as a proxy for workspace build here
 		workspace, err := api.Database.GetWorkspaceByID(ctx, workspaceBuild.WorkspaceID)
 		if err != nil {
 			if xerrors.Is(err, sql.ErrNoRows) {
 				return true
 			}
-			api.Logger.Error(ctx, "fetch workspace", slog.Error(err))
+			api.Logger.Error(ctx, "can't fetch workspace", slog.Error(err))
 		}
 		return workspace.Deleted
 	default:

diff --git a/coderd/authorize.go b/coderd/authorize.go
@@ -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),

diff --git a/coderd/csp.go b/coderd/csp.go
@@ -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")
 }
diff --git a/coderd/provisionerdserver/provisionerdserver.go b/coderd/provisionerdserver/provisionerdserver.go
@@ -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
 }
 

diff --git a/coderd/telemetry/telemetry.go b/coderd/telemetry/telemetry.go
@@ -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, "can't 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, "can't create deployment snapshot", slog.Error(err))
 		return
 	}
 	r.reportSync(snapshot)

diff --git a/coderd/userauth.go b/coderd/userauth.go
@@ -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

diff --git a/coderd/workspaceagents.go b/coderd/workspaceagents.go
@@ -980,7 +980,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),

diff --git a/enterprise/derpmesh/derpmesh.go b/enterprise/derpmesh/derpmesh.go
@@ -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, "can't 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, "can't parse DERP address with /derp", slog.F("address", addressURL.String()), slog.Error(err))
 			continue
 		}
 		address = derpURL.String()

diff --git a/provisionerd/provisionerd.go b/provisionerd/provisionerd.go
@@ -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 can't 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
 	}

diff --git a/provisionerd/runner/runner.go b/provisionerd/runner/runner.go
@@ -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),
 			)
 

diff --git a/scripts/rules.go b/scripts/rules.go
@@ -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(