From 2fc22efc87250940eb0235d4f2231ac5c0bf2eab Mon Sep 17 00:00:00 2001 From: Marcin Tojek Date: Mon, 19 Jun 2023 15:59:39 +0200 Subject: [PATCH 1/6] Field name rules --- agent/agent.go | 2 +- agent/agentssh/agentssh.go | 8 +++---- coderd/coderd.go | 4 ++-- .../provisionerdserver/provisionerdserver.go | 2 +- coderd/workspaceagents.go | 16 ++++++------- scaletest/workspacetraffic/run.go | 2 +- scripts/rules.go | 23 +++++++++++++++++++ 7 files changed, 40 insertions(+), 17 deletions(-) diff --git a/agent/agent.go b/agent/agent.go index a60471c32a7aa..109aebf9d6aa9 100644 --- a/agent/agent.go +++ b/agent/agent.go @@ -1017,7 +1017,7 @@ func (a *agent) handleReconnectingPTY(ctx context.Context, logger slog.Logger, m defer a.connCountReconnectingPTY.Add(-1) connectionID := uuid.NewString() - logger = logger.With(slog.F("id", msg.ID), slog.F("connection_id", connectionID)) + logger = logger.With(slog.F("message_id", msg.ID), slog.F("connection_id", connectionID)) logger.Debug(ctx, "starting handler") defer func() { diff --git a/agent/agentssh/agentssh.go b/agent/agentssh/agentssh.go index 182bfe1883b8c..a271835df0256 100644 --- a/agent/agentssh/agentssh.go +++ b/agent/agentssh/agentssh.go @@ -120,8 +120,8 @@ func NewServer(ctx context.Context, logger slog.Logger, prometheusRegistry *prom LocalPortForwardingCallback: func(ctx ssh.Context, destinationHost string, destinationPort uint32) bool { // Allow local port forwarding all! s.logger.Debug(ctx, "local port forward", - slog.F("destination-host", destinationHost), - slog.F("destination-port", destinationPort)) + slog.F("destination_host", destinationHost), + slog.F("destination_port", destinationPort)) return true }, PtyCallback: func(ctx ssh.Context, pty ssh.Pty) bool { @@ -130,8 +130,8 @@ func NewServer(ctx context.Context, logger slog.Logger, prometheusRegistry *prom ReversePortForwardingCallback: func(ctx ssh.Context, bindHost string, bindPort uint32) bool { // Allow reverse port forwarding all! s.logger.Debug(ctx, "local port forward", - slog.F("bind-host", bindHost), - slog.F("bind-port", bindPort)) + slog.F("bind_host", bindHost), + slog.F("bind_port", bindPort)) return true }, RequestHandlers: map[string]ssh.RequestHandler{ diff --git a/coderd/coderd.go b/coderd/coderd.go index af03f69f8a89f..9a306d1db6279 100644 --- a/coderd/coderd.go +++ b/coderd/coderd.go @@ -245,9 +245,9 @@ func New(options *Options) *API { options.TracerProvider = trace.NewNoopTracerProvider() } if options.SetUserGroups == nil { - options.SetUserGroups = func(ctx context.Context, _ database.Store, id uuid.UUID, groups []string) error { + options.SetUserGroups = func(ctx context.Context, _ database.Store, userID uuid.UUID, groups []string) error { options.Logger.Warn(ctx, "attempted to assign OIDC groups without enterprise license", - slog.F("id", id), slog.F("groups", groups), + slog.F("user_id", userID), slog.F("groups", groups), ) return nil } diff --git a/coderd/provisionerdserver/provisionerdserver.go b/coderd/provisionerdserver/provisionerdserver.go index a33c4a048a6d3..191143fdcde39 100644 --- a/coderd/provisionerdserver/provisionerdserver.go +++ b/coderd/provisionerdserver/provisionerdserver.go @@ -108,7 +108,7 @@ func (server *Server) AcquireJob(ctx context.Context, _ *proto.Empty) (*proto.Ac if err != nil { return nil, xerrors.Errorf("acquire job: %w", err) } - server.Logger.Debug(ctx, "locked job from database", slog.F("id", job.ID)) + server.Logger.Debug(ctx, "locked job from database", slog.F("job_id", job.ID)) // Marks the acquired job as failed with the error message provided. failJob := func(errorMessage string) error { diff --git a/coderd/workspaceagents.go b/coderd/workspaceagents.go index dd01e26c8c0fe..29b08163ab6de 100644 --- a/coderd/workspaceagents.go +++ b/coderd/workspaceagents.go @@ -967,7 +967,7 @@ func (api *API) workspaceAgentCoordinate(rw http.ResponseWriter, r *http.Request if !xerrors.Is(err, context.Canceled) && !database.IsQueryCanceledError(err) { api.Logger.Error(ctx, "failed to update agent disconnect time", slog.Error(err), - slog.F("workspace", build.WorkspaceID), + slog.F("workspace_id", build.WorkspaceID), ) } } @@ -1256,8 +1256,8 @@ func (api *API) workspaceAgentReportStats(rw http.ResponseWriter, r *http.Reques api.Logger.Debug(ctx, "read stats report", slog.F("interval", api.AgentStatsRefreshInterval), - slog.F("agent", workspaceAgent.ID), - slog.F("workspace", workspace.ID), + slog.F("workspace_agent_id", workspaceAgent.ID), + slog.F("workspace_id", workspace.ID), slog.F("payload", req), ) @@ -1267,7 +1267,7 @@ func (api *API) workspaceAgentReportStats(rw http.ResponseWriter, r *http.Reques payload, err := json.Marshal(req.ConnectionsByProto) if err != nil { - api.Logger.Error(ctx, "marshal agent connections by proto", slog.F("workspace_agent", workspaceAgent.ID), slog.Error(err)) + api.Logger.Error(ctx, "marshal agent connections by proto", slog.F("workspace_agent_id", workspaceAgent.ID), slog.Error(err)) payload = json.RawMessage("{}") } @@ -1399,8 +1399,8 @@ func (api *API) workspaceAgentPostMetadata(rw http.ResponseWriter, r *http.Reque api.Logger.Debug( ctx, "accepted metadata report", - slog.F("agent", workspaceAgent.ID), - slog.F("workspace", workspace.ID), + slog.F("workspace_agent_id", workspaceAgent.ID), + slog.F("workspace_id", workspace.ID), slog.F("collected_at", datum.CollectedAt), slog.F("key", datum.Key), ) @@ -1577,8 +1577,8 @@ func (api *API) workspaceAgentReportLifecycle(rw http.ResponseWriter, r *http.Re } logger := api.Logger.With( - slog.F("agent", workspaceAgent.ID), - slog.F("workspace", workspace.ID), + slog.F("workspace_agent_id", workspaceAgent.ID), + slog.F("workspace_id", workspace.ID), slog.F("payload", req), ) logger.Debug(ctx, "workspace agent state report") diff --git a/scaletest/workspacetraffic/run.go b/scaletest/workspacetraffic/run.go index 59bbbc6923820..44128d985faed 100644 --- a/scaletest/workspacetraffic/run.go +++ b/scaletest/workspacetraffic/run.go @@ -70,7 +70,7 @@ func (r *Runner) Run(ctx context.Context, _ string, logs io.Writer) error { logger.Info(ctx, "config", slog.F("agent_id", agentID), - slog.F("reconnect", reconnect), + slog.F("reconnecting_pty_id", reconnect), slog.F("height", height), slog.F("width", width), slog.F("tick_interval", tickInterval), diff --git a/scripts/rules.go b/scripts/rules.go index 414167da15036..4ca4830520307 100644 --- a/scripts/rules.go +++ b/scripts/rules.go @@ -289,3 +289,26 @@ func notImplementsFullResponseWriter(ctx *dsl.VarFilterContext) bool { !(types.Implements(p, flusher) || types.Implements(ctx.Type, flusher)) || !(types.Implements(p, hijacker) || types.Implements(ctx.Type, hijacker)) } + +// slogFieldNameSnakeCase is a lint rule that ensures naming consistency +// of logged field names. +func slogFieldNameSnakeCase(m dsl.Matcher) { + m.Import("cdr.dev/slog") + m.Match( + `slog.F($name, $value)`, + ). + Where(m["name"].Const && !m["name"].Text.Matches(`^"[a-z]+(_[a-z]+)*"$`)). + Report("Field name $name must be snake_case") +} + +// slogUUIDFieldNameHasIDSuffix ensures that "uuid.UUID" field has ID prefix +// in the field name. +func slogUUIDFieldNameHasIDSuffix(m dsl.Matcher) { + m.Import("cdr.dev/slog") + m.Import("github.com/google/uuid") + m.Match( + `slog.F($name, $value)`, + ). + Where(m["value"].Type.Is("uuid.UUID") && !m["name"].Text.Matches(`_id"$`)). + Report(`uuid.UUID field $name must have "_id" suffix`) +} From 1d5a3e86d1599a2a84a144e3893557d4b3ef4963 Mon Sep 17 00:00:00 2001 From: Marcin Tojek Date: Mon, 19 Jun 2023 16:51:33 +0200 Subject: [PATCH 2/6] Message rules --- agent/agent.go | 4 +-- cli/ssh.go | 2 +- coderd/prometheusmetrics/prometheusmetrics.go | 8 ++--- coderd/provisionerjobs.go | 2 -- coderd/workspaceagents.go | 1 - provisionerd/provisionerd_test.go | 8 ++--- scripts/rules.go | 29 +++++++++++++++++-- tailnet/coordinator.go | 4 +-- 8 files changed, 40 insertions(+), 18 deletions(-) diff --git a/agent/agent.go b/agent/agent.go index 109aebf9d6aa9..c732d712b5476 100644 --- a/agent/agent.go +++ b/agent/agent.go @@ -1107,9 +1107,9 @@ func (a *agent) handleReconnectingPTY(ctx context.Context, logger slog.Logger, m // When the PTY is closed, this is triggered. // Error is typically a benign EOF, so only log for debugging. if errors.Is(err, io.EOF) { - logger.Debug(ctx, "unable to read pty output, command exited?", slog.Error(err)) + logger.Debug(ctx, "unable to read pty output, command might have exited", slog.Error(err)) } else { - logger.Warn(ctx, "unable to read pty output, command exited?", slog.Error(err)) + logger.Warn(ctx, "unable to read pty output, command might have exited", slog.Error(err)) a.metrics.reconnectingPTYErrors.WithLabelValues("output_reader").Add(1) } break diff --git a/cli/ssh.go b/cli/ssh.go index 2c516bb1db500..68043eaf62e77 100644 --- a/cli/ssh.go +++ b/cli/ssh.go @@ -455,7 +455,7 @@ func watchAndClose(ctx context.Context, closer func() error, logger slog.Logger, startWatchLoop: for { - logger.Debug(ctx, "(re)connecting to the coder server to watch workspace events.") + logger.Debug(ctx, "connecting to the coder server to watch workspace events") var wsWatch <-chan codersdk.Workspace var err error for r := retry.New(time.Second, 15*time.Second); r.Wait(ctx); { diff --git a/coderd/prometheusmetrics/prometheusmetrics.go b/coderd/prometheusmetrics/prometheusmetrics.go index 4fba21b7c337f..faba55ac9b0d3 100644 --- a/coderd/prometheusmetrics/prometheusmetrics.go +++ b/coderd/prometheusmetrics/prometheusmetrics.go @@ -222,7 +222,7 @@ func Agents(ctx context.Context, logger slog.Logger, registerer prometheus.Regis case <-ticker.C: } - logger.Debug(ctx, "Agent metrics collection is starting") + logger.Debug(ctx, "agent metrics collection is starting") timer := prometheus.NewTimer(metricsCollectorAgents) workspaceRows, err := db.GetWorkspaces(ctx, database.GetWorkspacesParams{ @@ -314,7 +314,7 @@ func Agents(ctx context.Context, logger slog.Logger, registerer prometheus.Regis agentsAppsGauge.Commit() done: - logger.Debug(ctx, "Agent metrics collection is done") + logger.Debug(ctx, "agent metrics collection is done") timer.ObserveDuration() ticker.Reset(duration) } @@ -447,7 +447,7 @@ func AgentStats(ctx context.Context, logger slog.Logger, registerer prometheus.R case <-ticker.C: } - logger.Debug(ctx, "Agent metrics collection is starting") + logger.Debug(ctx, "agent metrics collection is starting") timer := prometheus.NewTimer(metricsCollectorAgentStats) checkpoint := time.Now() @@ -482,7 +482,7 @@ func AgentStats(ctx context.Context, logger slog.Logger, registerer prometheus.R } } - logger.Debug(ctx, "Agent metrics collection is done", slog.F("len", len(stats))) + logger.Debug(ctx, "agent metrics collection is done", slog.F("len", len(stats))) timer.ObserveDuration() createdAfter = checkpoint diff --git a/coderd/provisionerjobs.go b/coderd/provisionerjobs.go index 3926d353d1017..df7fb63d16049 100644 --- a/coderd/provisionerjobs.go +++ b/coderd/provisionerjobs.go @@ -237,8 +237,6 @@ func fetchAndWriteLogs(ctx context.Context, logger slog.Logger, db database.Stor if logs == nil { logs = []database.ProvisionerJobLog{} } - - logger.Debug(ctx, "Finished non-follow job logs") httpapi.Write(ctx, rw, http.StatusOK, convertProvisionerJobLogs(logs)) } diff --git a/coderd/workspaceagents.go b/coderd/workspaceagents.go index 29b08163ab6de..1f7986b38955a 100644 --- a/coderd/workspaceagents.go +++ b/coderd/workspaceagents.go @@ -464,7 +464,6 @@ func (api *API) workspaceAgentStartupLogs(rw http.ResponseWriter, r *http.Reques } if !follow { - logger.Debug(ctx, "Finished non-follow job logs") httpapi.Write(ctx, rw, http.StatusOK, convertWorkspaceAgentStartupLogs(logs)) return } diff --git a/provisionerd/provisionerd_test.go b/provisionerd/provisionerd_test.go index a99fda3e11437..32e70fb8e1483 100644 --- a/provisionerd/provisionerd_test.go +++ b/provisionerd/provisionerd_test.go @@ -1009,7 +1009,7 @@ func TestProvisionerd(t *testing.T) { acquireJob: func(ctx context.Context, _ *proto.Empty) (*proto.AcquiredJob, error) { m.Lock() defer m.Unlock() - logger.Info(ctx, "AcquiredJob called.") + logger.Info(ctx, "provisioner stage: AcquiredJob") if len(ops) > 0 { return &proto.AcquiredJob{}, nil } @@ -1031,7 +1031,7 @@ func TestProvisionerd(t *testing.T) { updateJob: func(ctx context.Context, update *proto.UpdateJobRequest) (*proto.UpdateJobResponse, error) { m.Lock() defer m.Unlock() - logger.Info(ctx, "UpdateJob called.") + logger.Info(ctx, "provisioner stage: UpdateJob") ops = append(ops, "UpdateJob") for _, log := range update.Logs { ops = append(ops, fmt.Sprintf("Log: %s | %s", log.Stage, log.Output)) @@ -1041,7 +1041,7 @@ func TestProvisionerd(t *testing.T) { completeJob: func(ctx context.Context, job *proto.CompletedJob) (*proto.Empty, error) { m.Lock() defer m.Unlock() - logger.Info(ctx, "CompleteJob called.") + logger.Info(ctx, "provisioner stage: CompleteJob") ops = append(ops, "CompleteJob") completeOnce.Do(func() { close(completeChan) }) return &proto.Empty{}, nil @@ -1049,7 +1049,7 @@ func TestProvisionerd(t *testing.T) { failJob: func(ctx context.Context, job *proto.FailedJob) (*proto.Empty, error) { m.Lock() defer m.Unlock() - logger.Info(ctx, "FailJob called.") + logger.Info(ctx, "provisioner stage: FailJob") ops = append(ops, "FailJob") return &proto.Empty{}, nil }, diff --git a/scripts/rules.go b/scripts/rules.go index 4ca4830520307..34d200cba09aa 100644 --- a/scripts/rules.go +++ b/scripts/rules.go @@ -298,7 +298,7 @@ func slogFieldNameSnakeCase(m dsl.Matcher) { `slog.F($name, $value)`, ). Where(m["name"].Const && !m["name"].Text.Matches(`^"[a-z]+(_[a-z]+)*"$`)). - Report("Field name $name must be snake_case") + Report("Field name $name must be snake_case.") } // slogUUIDFieldNameHasIDSuffix ensures that "uuid.UUID" field has ID prefix @@ -310,5 +310,30 @@ func slogUUIDFieldNameHasIDSuffix(m dsl.Matcher) { `slog.F($name, $value)`, ). Where(m["value"].Type.Is("uuid.UUID") && !m["name"].Text.Matches(`_id"$`)). - Report(`uuid.UUID field $name must have "_id" suffix`) + Report(`uuid.UUID field $name must have "_id" suffix.`) +} + +// slogMessageFormat ensures that the log message starts with lowercase, does not +// end with special character, and has at least 16 characters. +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)`, + `Logger.Debug($ctx, $message, $*args)`, + ). + Where( + ( + // It doesn't end with a special character: + m["message"].Text.Matches(`[.!?]"$`) || + // It starts with lowercase: + m["message"].Text.Matches(`^"[A-Z]{1}`) && + // but there are exceptions: + !m["message"].Text.Matches(`^"Prometheus`))). + Report(`Message $message must start with lowercase and does not end with a special character.`) } diff --git a/tailnet/coordinator.go b/tailnet/coordinator.go index 5ee49cd194f16..f0e0c1475b0ef 100644 --- a/tailnet/coordinator.go +++ b/tailnet/coordinator.go @@ -332,7 +332,7 @@ func (c *coordinator) ServeClient(conn net.Conn, id uuid.UUID, agent uuid.UUID) for { err := c.handleNextClientMessage(id, agent, decoder) if err != nil { - logger.Debug(ctx, "unable to read client update; closed conn?", slog.Error(err)) + logger.Debug(ctx, "unable to read client update, connection may be closed", slog.Error(err)) if errors.Is(err, io.EOF) || errors.Is(err, io.ErrClosedPipe) || errors.Is(err, context.Canceled) { return nil } @@ -469,7 +469,7 @@ func (c *coordinator) ServeAgent(conn net.Conn, id uuid.UUID, name string) error for { err := c.handleNextAgentMessage(id, decoder) if err != nil { - logger.Debug(ctx, "unable to read agent update; closed conn?", slog.Error(err)) + logger.Debug(ctx, "unable to read agent update, connection may be closed", slog.Error(err)) if errors.Is(err, io.EOF) || errors.Is(err, io.ErrClosedPipe) || errors.Is(err, context.Canceled) { return nil } From f5cadaaed244b9590e144ff4d4eb8c9d9e9d1402 Mon Sep 17 00:00:00 2001 From: Marcin Tojek Date: Mon, 19 Jun 2023 17:18:07 +0200 Subject: [PATCH 3/6] Message has >=16 chars --- agent/agent.go | 12 ++++---- cli/agent.go | 4 +-- cli/agent_test.go | 4 +-- cli/ssh.go | 4 +-- coderd/authorize.go | 2 +- coderd/prometheusmetrics/prometheusmetrics.go | 2 +- coderd/provisionerjobs.go | 2 +- scaletest/workspacetraffic/run.go | 2 +- scripts/rules.go | 28 ++++++++++++++++--- 9 files changed, 40 insertions(+), 20 deletions(-) diff --git a/agent/agent.go b/agent/agent.go index c732d712b5476..6f81461dc81c4 100644 --- a/agent/agent.go +++ b/agent/agent.go @@ -1029,9 +1029,9 @@ func (a *agent) handleReconnectingPTY(ctx context.Context, logger slog.Logger, m // If the agent is closed, we don't want to // log this as an error since it's expected. if closed { - logger.Debug(ctx, "session error after agent close", slog.Error(err)) + logger.Debug(ctx, "reconnecting PTY failed with session error (agent closed)", slog.Error(err)) } else { - logger.Error(ctx, "session error", slog.Error(err)) + logger.Error(ctx, "reconnecting PTY failed with session error", slog.Error(err)) } } logger.Debug(ctx, "session closed") @@ -1154,7 +1154,7 @@ func (a *agent) handleReconnectingPTY(ctx context.Context, logger slog.Logger, m err := rpty.ptty.Resize(msg.Height, msg.Width) if err != nil { // We can continue after this, it's not fatal! - logger.Error(ctx, "resize", slog.Error(err)) + logger.Error(ctx, "reconnecting PTY failed resizing, but will continue", slog.Error(err)) a.metrics.reconnectingPTYErrors.WithLabelValues("resize").Add(1) } // Write any previously stored data for the TTY. @@ -1213,12 +1213,12 @@ func (a *agent) handleReconnectingPTY(ctx context.Context, logger slog.Logger, m return nil } if err != nil { - logger.Warn(ctx, "read conn", slog.Error(err)) + logger.Warn(ctx, "reconnecting PTY failed with read error", slog.Error(err)) return nil } _, err = rpty.ptty.InputWriter().Write([]byte(req.Data)) if err != nil { - logger.Warn(ctx, "write to pty", slog.Error(err)) + logger.Warn(ctx, "reconnecting PTY failed with write error", slog.Error(err)) a.metrics.reconnectingPTYErrors.WithLabelValues("input_writer").Add(1) return nil } @@ -1229,7 +1229,7 @@ func (a *agent) handleReconnectingPTY(ctx context.Context, logger slog.Logger, m err = rpty.ptty.Resize(req.Height, req.Width) if err != nil { // We can continue after this, it's not fatal! - logger.Error(ctx, "resize", slog.Error(err)) + logger.Error(ctx, "reconnecting PTY failed resizing", slog.Error(err)) a.metrics.reconnectingPTYErrors.WithLabelValues("resize").Add(1) } } diff --git a/cli/agent.go b/cli/agent.go index f895da0927c4d..c59a3b79c9c9f 100644 --- a/cli/agent.go +++ b/cli/agent.go @@ -126,7 +126,7 @@ func (r *RootCmd) workspaceAgent() *clibase.Cmd { reaper.WithCatchSignals(InterruptSignals...), ) if err != nil { - logger.Error(ctx, "failed to reap", slog.Error(err)) + logger.Error(ctx, "agent process reaper failed forking", slog.Error(err)) return xerrors.Errorf("fork reap: %w", err) } @@ -163,7 +163,7 @@ func (r *RootCmd) workspaceAgent() *clibase.Cmd { logger := slog.Make(sinks...).Leveled(slog.LevelDebug) version := buildinfo.Version() - logger.Info(ctx, "starting agent", + logger.Info(ctx, "agent is starting now", slog.F("url", r.agentURL), slog.F("auth", auth), slog.F("version", version), diff --git a/cli/agent_test.go b/cli/agent_test.go index 4b5ded1dadb70..462ef3c204541 100644 --- a/cli/agent_test.go +++ b/cli/agent_test.go @@ -54,7 +54,7 @@ func TestWorkspaceAgent(t *testing.T) { clitest.Start(t, inv) ctx := inv.Context() - pty.ExpectMatchContext(ctx, "starting agent") + pty.ExpectMatchContext(ctx, "agent is starting now") coderdtest.AwaitWorkspaceAgents(t, client, workspace.ID) @@ -270,7 +270,7 @@ func TestWorkspaceAgent(t *testing.T) { pty := ptytest.New(t).Attach(inv) clitest.Start(t, inv) - pty.ExpectMatchContext(inv.Context(), "starting agent") + pty.ExpectMatchContext(inv.Context(), "agent is starting now") resources := coderdtest.AwaitWorkspaceAgents(t, client, workspace.ID) require.Len(t, resources, 1) diff --git a/cli/ssh.go b/cli/ssh.go index 68043eaf62e77..761c521881fd9 100644 --- a/cli/ssh.go +++ b/cli/ssh.go @@ -464,7 +464,7 @@ startWatchLoop: break } if ctx.Err() != nil { - logger.Info(ctx, "context expired", slog.Error(ctx.Err())) + logger.Debug(ctx, "context expired", slog.Error(ctx.Err())) return } } @@ -472,7 +472,7 @@ startWatchLoop: for { select { case <-ctx.Done(): - logger.Info(ctx, "context expired", slog.Error(ctx.Err())) + logger.Debug(ctx, "context expired", slog.Error(ctx.Err())) return case w, ok := <-wsWatch: if !ok { diff --git a/coderd/authorize.go b/coderd/authorize.go index 9dcc7e411298e..ab425e0c4093d 100644 --- a/coderd/authorize.go +++ b/coderd/authorize.go @@ -75,7 +75,7 @@ func (h *HTTPAuthorizer) Authorize(r *http.Request, action rbac.Action, object r } // Log information for debugging. This will be very helpful // in the early days - logger.Warn(r.Context(), "unauthorized", + logger.Warn(r.Context(), "user is not authorized to access the object", slog.F("roles", roles.Actor.SafeRoleNames()), slog.F("actor_id", roles.Actor.ID), slog.F("actor_name", roles.ActorName), diff --git a/coderd/prometheusmetrics/prometheusmetrics.go b/coderd/prometheusmetrics/prometheusmetrics.go index faba55ac9b0d3..6ad5f528db41a 100644 --- a/coderd/prometheusmetrics/prometheusmetrics.go +++ b/coderd/prometheusmetrics/prometheusmetrics.go @@ -236,7 +236,7 @@ func Agents(ctx context.Context, logger slog.Logger, registerer prometheus.Regis for _, workspace := range workspaceRows { user, err := db.GetUserByID(ctx, workspace.OwnerID) if err != nil { - logger.Error(ctx, "can't get user", slog.F("user_id", workspace.OwnerID), slog.Error(err)) + logger.Error(ctx, "can't get user from the database", slog.F("user_id", workspace.OwnerID), slog.Error(err)) agentsGauge.WithLabelValues(VectorOperationAdd, 0, user.Username, workspace.Name) continue } diff --git a/coderd/provisionerjobs.go b/coderd/provisionerjobs.go index df7fb63d16049..c226852c0eeaa 100644 --- a/coderd/provisionerjobs.go +++ b/coderd/provisionerjobs.go @@ -257,7 +257,7 @@ func jobIsComplete(logger slog.Logger, job database.ProvisionerJob) bool { return false default: logger.Error(context.Background(), - "unknown status", + "can't convert the provisioner job status", slog.F("job_id", job.ID), slog.F("status", status)) return false } diff --git a/scaletest/workspacetraffic/run.go b/scaletest/workspacetraffic/run.go index 44128d985faed..6536b5c430824 100644 --- a/scaletest/workspacetraffic/run.go +++ b/scaletest/workspacetraffic/run.go @@ -68,7 +68,7 @@ func (r *Runner) Run(ctx context.Context, _ string, logs io.Writer) error { bytesPerTick = r.cfg.BytesPerTick ) - logger.Info(ctx, "config", + logger.Debug(ctx, "config", slog.F("agent_id", agentID), slog.F("reconnecting_pty_id", reconnect), slog.F("height", height), diff --git a/scripts/rules.go b/scripts/rules.go index 34d200cba09aa..57f6eed05e2dd 100644 --- a/scripts/rules.go +++ b/scripts/rules.go @@ -313,8 +313,8 @@ func slogUUIDFieldNameHasIDSuffix(m dsl.Matcher) { Report(`uuid.UUID field $name must have "_id" suffix.`) } -// slogMessageFormat ensures that the log message starts with lowercase, does not -// end with special character, and has at least 16 characters. +// slogMessageFormat ensures that the log message starts with lowercase, and does not +// end with special character. func slogMessageFormat(m dsl.Matcher) { m.Import("cdr.dev/slog") m.Match( @@ -331,9 +331,29 @@ func slogMessageFormat(m dsl.Matcher) { ( // It doesn't end with a special character: m["message"].Text.Matches(`[.!?]"$`) || - // It starts with lowercase: + // it starts with lowercase: m["message"].Text.Matches(`^"[A-Z]{1}`) && // but there are exceptions: !m["message"].Text.Matches(`^"Prometheus`))). - Report(`Message $message must start with lowercase and does not end with a special character.`) + Report(`Message $message must start with lowercase, and does not end with a special characters.`) +} + +// slogMessageLength ensures that important log messages are meaningful, and must be at least 16 characters long. +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)`, + `Logger.Info($ctx, $message, $*args)`, + // no debug + ). + Where( + // It has at least 16 characters (+ ""): + m["message"].Text.Matches(`^".{0,15}"$`) && + // but there are exceptions: + !m["message"].Text.Matches(`^"command exit"$`)). + Report(`Message $message is too short, it must be at least 16 characters long.`) } From e47ecfd3ebacf13b483c01529f72d7c18145265c Mon Sep 17 00:00:00 2001 From: Marcin Tojek Date: Mon, 19 Jun 2023 17:30:36 +0200 Subject: [PATCH 4/6] Use slog.Error --- coderd/authorize.go | 2 +- coderd/database/dbauthz/dbauthz.go | 2 +- coderd/httpmw/clitelemetry.go | 2 +- enterprise/derpmesh/derpmesh.go | 4 ++-- scripts/rules.go | 10 ++++++++++ tailnet/conn.go | 2 +- 6 files changed, 16 insertions(+), 6 deletions(-) diff --git a/coderd/authorize.go b/coderd/authorize.go index ab425e0c4093d..2c63879400429 100644 --- a/coderd/authorize.go +++ b/coderd/authorize.go @@ -71,7 +71,7 @@ func (h *HTTPAuthorizer) Authorize(r *http.Request, action rbac.Action, object r internalError := new(rbac.UnauthorizedError) logger := h.Logger if xerrors.As(err, internalError) { - logger = h.Logger.With(slog.F("internal", internalError.Internal())) + logger = h.Logger.With(slog.F("internal_error", internalError.Internal())) } // Log information for debugging. This will be very helpful // in the early days diff --git a/coderd/database/dbauthz/dbauthz.go b/coderd/database/dbauthz/dbauthz.go index dc8b10e5a1f27..fdae0c638b842 100644 --- a/coderd/database/dbauthz/dbauthz.go +++ b/coderd/database/dbauthz/dbauthz.go @@ -69,7 +69,7 @@ func logNotAuthorizedError(ctx context.Context, logger slog.Logger, err error) e return &contextError } logger.Debug(ctx, "unauthorized", - slog.F("internal", internalError.Internal()), + slog.F("internal_error", internalError.Internal()), slog.F("input", internalError.Input()), slog.Error(err), ) diff --git a/coderd/httpmw/clitelemetry.go b/coderd/httpmw/clitelemetry.go index 1237c07333448..2262862beba49 100644 --- a/coderd/httpmw/clitelemetry.go +++ b/coderd/httpmw/clitelemetry.go @@ -50,7 +50,7 @@ func ReportCLITelemetry(log slog.Logger, rep telemetry.Reporter) func(http.Handl log.Error( r.Context(), "base64 decode", - slog.F("error", err), + slog.Error(err), ) return } diff --git a/enterprise/derpmesh/derpmesh.go b/enterprise/derpmesh/derpmesh.go index f98dbb30d0ef4..645b96cd31505 100644 --- 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", err), slog.Error(err)) + m.logger.Error(m.ctx, "invalid 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", err), slog.Error(err)) + m.logger.Error(m.ctx, "parse derp", slog.F("address", addressURL.String()), slog.Error(err)) continue } address = derpURL.String() diff --git a/scripts/rules.go b/scripts/rules.go index 57f6eed05e2dd..0f3dffe891be4 100644 --- a/scripts/rules.go +++ b/scripts/rules.go @@ -357,3 +357,13 @@ func slogMessageLength(m dsl.Matcher) { !m["message"].Text.Matches(`^"command exit"$`)). Report(`Message $message is too short, it must be at least 16 characters long.`) } + +// slogErr ensures that errors are logged with "slog.Error" instead of "slog.F" +func slogError(m dsl.Matcher) { + m.Import("cdr.dev/slog") + m.Match( + `slog.F($name, $value)`, + ). + Where(m["name"].Const && m["value"].Type.Is("error") && !m["name"].Text.Matches(`^"internal_error"$`)). + Report(`Error should be logged using "slog.Error" instead.`) +} diff --git a/tailnet/conn.go b/tailnet/conn.go index e36f40d8b2d95..67f9267132250 100644 --- a/tailnet/conn.go +++ b/tailnet/conn.go @@ -231,7 +231,7 @@ func NewConn(options *Options) (conn *Conn, err error) { } }() wireguardEngine.SetStatusCallback(func(s *wgengine.Status, err error) { - server.logger.Debug(context.Background(), "wireguard status", slog.F("status", s), slog.F("err", err)) + server.logger.Debug(context.Background(), "wireguard status", slog.F("status", s), slog.Error(err)) if err != nil { return } From 9bd01c44ae3d6a67dea183f642b67173b1c05216 Mon Sep 17 00:00:00 2001 From: Marcin Tojek Date: Mon, 19 Jun 2023 17:42:18 +0200 Subject: [PATCH 5/6] Remove logger --- coderd/provisionerjobs.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/coderd/provisionerjobs.go b/coderd/provisionerjobs.go index c226852c0eeaa..ba3d2f585c0eb 100644 --- a/coderd/provisionerjobs.go +++ b/coderd/provisionerjobs.go @@ -56,7 +56,7 @@ func (api *API) provisionerJobLogs(rw http.ResponseWriter, r *http.Request, job } if !follow { - fetchAndWriteLogs(ctx, logger, api.Database, job.ID, after, rw) + fetchAndWriteLogs(ctx, api.Database, job.ID, after, rw) return } @@ -222,7 +222,7 @@ func convertProvisionerJob(provisionerJob database.ProvisionerJob) codersdk.Prov return job } -func fetchAndWriteLogs(ctx context.Context, logger slog.Logger, db database.Store, jobID uuid.UUID, after int64, rw http.ResponseWriter) { +func fetchAndWriteLogs(ctx context.Context, db database.Store, jobID uuid.UUID, after int64, rw http.ResponseWriter) { logs, err := db.GetProvisionerLogsAfterID(ctx, database.GetProvisionerLogsAfterIDParams{ JobID: jobID, CreatedAfter: after, From e00052e216c8b0a1dc741abffe8602b7026973e4 Mon Sep 17 00:00:00 2001 From: Marcin Tojek Date: Tue, 20 Jun 2023 12:05:39 +0200 Subject: [PATCH 6/6] Address PR comments --- agent/agent.go | 4 ++-- cli/agent.go | 2 +- coderd/authorize.go | 2 +- 3 files changed, 4 insertions(+), 4 deletions(-) diff --git a/agent/agent.go b/agent/agent.go index 6f81461dc81c4..1215bc973c4e4 100644 --- a/agent/agent.go +++ b/agent/agent.go @@ -1154,7 +1154,7 @@ func (a *agent) handleReconnectingPTY(ctx context.Context, logger slog.Logger, m err := rpty.ptty.Resize(msg.Height, msg.Width) if err != nil { // We can continue after this, it's not fatal! - logger.Error(ctx, "reconnecting PTY failed resizing, but will continue", slog.Error(err)) + logger.Error(ctx, "reconnecting PTY initial resize failed, but will continue", slog.Error(err)) a.metrics.reconnectingPTYErrors.WithLabelValues("resize").Add(1) } // Write any previously stored data for the TTY. @@ -1229,7 +1229,7 @@ func (a *agent) handleReconnectingPTY(ctx context.Context, logger slog.Logger, m err = rpty.ptty.Resize(req.Height, req.Width) if err != nil { // We can continue after this, it's not fatal! - logger.Error(ctx, "reconnecting PTY failed resizing", slog.Error(err)) + logger.Error(ctx, "reconnecting PTY resize failed, but will continue", slog.Error(err)) a.metrics.reconnectingPTYErrors.WithLabelValues("resize").Add(1) } } diff --git a/cli/agent.go b/cli/agent.go index c59a3b79c9c9f..ee7346d237c4b 100644 --- a/cli/agent.go +++ b/cli/agent.go @@ -126,7 +126,7 @@ func (r *RootCmd) workspaceAgent() *clibase.Cmd { reaper.WithCatchSignals(InterruptSignals...), ) if err != nil { - logger.Error(ctx, "agent process reaper failed forking", slog.Error(err)) + logger.Error(ctx, "agent process reaper unable to fork", slog.Error(err)) return xerrors.Errorf("fork reap: %w", err) } diff --git a/coderd/authorize.go b/coderd/authorize.go index 2c63879400429..585450c97297f 100644 --- a/coderd/authorize.go +++ b/coderd/authorize.go @@ -75,7 +75,7 @@ func (h *HTTPAuthorizer) Authorize(r *http.Request, action rbac.Action, object r } // Log information for debugging. This will be very helpful // in the early days - logger.Warn(r.Context(), "user is not authorized to access the object", + logger.Warn(r.Context(), "requester is not authorized to access the object", slog.F("roles", roles.Actor.SafeRoleNames()), slog.F("actor_id", roles.Actor.ID), slog.F("actor_name", roles.ActorName),