Skip to content

Commit 8ade135

Browse files
mtojekpull[bot]
mtojek
authored and
pull[bot]
committed
chore: ensure logs consistency across Coder (#8083)
1 parent e095076 commit 8ade135

File tree

19 files changed

+132
-57
lines changed

19 files changed

+132
-57
lines changed

‎agent/agent.go

Lines changed: 9 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -1017,7 +1017,7 @@ func (a *agent) handleReconnectingPTY(ctx context.Context, logger slog.Logger, m
10171017
defer a.connCountReconnectingPTY.Add(-1)
10181018

10191019
connectionID := uuid.NewString()
1020-
logger = logger.With(slog.F("id", msg.ID), slog.F("connection_id", connectionID))
1020+
logger = logger.With(slog.F("message_id", msg.ID), slog.F("connection_id", connectionID))
10211021
logger.Debug(ctx, "starting handler")
10221022

10231023
defer func() {
@@ -1029,9 +1029,9 @@ func (a *agent) handleReconnectingPTY(ctx context.Context, logger slog.Logger, m
10291029
// If the agent is closed, we don't want to
10301030
// log this as an error since it's expected.
10311031
if closed {
1032-
logger.Debug(ctx, "session error after agent close", slog.Error(err))
1032+
logger.Debug(ctx, "reconnecting PTY failed with session error (agent closed)", slog.Error(err))
10331033
} else {
1034-
logger.Error(ctx, "session error", slog.Error(err))
1034+
logger.Error(ctx, "reconnecting PTY failed with session error", slog.Error(err))
10351035
}
10361036
}
10371037
logger.Debug(ctx, "session closed")
@@ -1107,9 +1107,9 @@ func (a *agent) handleReconnectingPTY(ctx context.Context, logger slog.Logger, m
11071107
// When the PTY is closed, this is triggered.
11081108
// Error is typically a benign EOF, so only log for debugging.
11091109
if errors.Is(err, io.EOF) {
1110-
logger.Debug(ctx, "unable to read pty output, command exited?", slog.Error(err))
1110+
logger.Debug(ctx, "unable to read pty output, command might have exited", slog.Error(err))
11111111
} else {
1112-
logger.Warn(ctx, "unable to read pty output, command exited?", slog.Error(err))
1112+
logger.Warn(ctx, "unable to read pty output, command might have exited", slog.Error(err))
11131113
a.metrics.reconnectingPTYErrors.WithLabelValues("output_reader").Add(1)
11141114
}
11151115
break
@@ -1154,7 +1154,7 @@ func (a *agent) handleReconnectingPTY(ctx context.Context, logger slog.Logger, m
11541154
err := rpty.ptty.Resize(msg.Height, msg.Width)
11551155
if err != nil {
11561156
// We can continue after this, it's not fatal!
1157-
logger.Error(ctx, "resize", slog.Error(err))
1157+
logger.Error(ctx, "reconnecting PTY initial resize failed, but will continue", slog.Error(err))
11581158
a.metrics.reconnectingPTYErrors.WithLabelValues("resize").Add(1)
11591159
}
11601160
// Write any previously stored data for the TTY.
@@ -1213,12 +1213,12 @@ func (a *agent) handleReconnectingPTY(ctx context.Context, logger slog.Logger, m
12131213
return nil
12141214
}
12151215
if err != nil {
1216-
logger.Warn(ctx, "read conn", slog.Error(err))
1216+
logger.Warn(ctx, "reconnecting PTY failed with read error", slog.Error(err))
12171217
return nil
12181218
}
12191219
_, err = rpty.ptty.InputWriter().Write([]byte(req.Data))
12201220
if err != nil {
1221-
logger.Warn(ctx, "write to pty", slog.Error(err))
1221+
logger.Warn(ctx, "reconnecting PTY failed with write error", slog.Error(err))
12221222
a.metrics.reconnectingPTYErrors.WithLabelValues("input_writer").Add(1)
12231223
return nil
12241224
}
@@ -1229,7 +1229,7 @@ func (a *agent) handleReconnectingPTY(ctx context.Context, logger slog.Logger, m
12291229
err = rpty.ptty.Resize(req.Height, req.Width)
12301230
if err != nil {
12311231
// We can continue after this, it's not fatal!
1232-
logger.Error(ctx, "resize", slog.Error(err))
1232+
logger.Error(ctx, "reconnecting PTY resize failed, but will continue", slog.Error(err))
12331233
a.metrics.reconnectingPTYErrors.WithLabelValues("resize").Add(1)
12341234
}
12351235
}

‎agent/agentssh/agentssh.go

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -120,8 +120,8 @@ func NewServer(ctx context.Context, logger slog.Logger, prometheusRegistry *prom
120120
LocalPortForwardingCallback: func(ctx ssh.Context, destinationHost string, destinationPort uint32) bool {
121121
// Allow local port forwarding all!
122122
s.logger.Debug(ctx, "local port forward",
123-
slog.F("destination-host", destinationHost),
124-
slog.F("destination-port", destinationPort))
123+
slog.F("destination_host", destinationHost),
124+
slog.F("destination_port", destinationPort))
125125
return true
126126
},
127127
PtyCallback: func(ctx ssh.Context, pty ssh.Pty) bool {
@@ -130,8 +130,8 @@ func NewServer(ctx context.Context, logger slog.Logger, prometheusRegistry *prom
130130
ReversePortForwardingCallback: func(ctx ssh.Context, bindHost string, bindPort uint32) bool {
131131
// Allow reverse port forwarding all!
132132
s.logger.Debug(ctx, "local port forward",
133-
slog.F("bind-host", bindHost),
134-
slog.F("bind-port", bindPort))
133+
slog.F("bind_host", bindHost),
134+
slog.F("bind_port", bindPort))
135135
return true
136136
},
137137
RequestHandlers: map[string]ssh.RequestHandler{

‎cli/agent.go

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -126,7 +126,7 @@ func (r *RootCmd) workspaceAgent() *clibase.Cmd {
126126
reaper.WithCatchSignals(InterruptSignals...),
127127
)
128128
if err != nil {
129-
logger.Error(ctx, "failed to reap", slog.Error(err))
129+
logger.Error(ctx, "agent process reaper unable to fork", slog.Error(err))
130130
return xerrors.Errorf("fork reap: %w", err)
131131
}
132132

@@ -163,7 +163,7 @@ func (r *RootCmd) workspaceAgent() *clibase.Cmd {
163163
logger := slog.Make(sinks...).Leveled(slog.LevelDebug)
164164

165165
version := buildinfo.Version()
166-
logger.Info(ctx, "starting agent",
166+
logger.Info(ctx, "agent is starting now",
167167
slog.F("url", r.agentURL),
168168
slog.F("auth", auth),
169169
slog.F("version", version),

‎cli/agent_test.go

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -54,7 +54,7 @@ func TestWorkspaceAgent(t *testing.T) {
5454

5555
clitest.Start(t, inv)
5656
ctx := inv.Context()
57-
pty.ExpectMatchContext(ctx, "starting agent")
57+
pty.ExpectMatchContext(ctx, "agent is starting now")
5858

5959
coderdtest.AwaitWorkspaceAgents(t, client, workspace.ID)
6060

@@ -270,7 +270,7 @@ func TestWorkspaceAgent(t *testing.T) {
270270
pty := ptytest.New(t).Attach(inv)
271271

272272
clitest.Start(t, inv)
273-
pty.ExpectMatchContext(inv.Context(), "starting agent")
273+
pty.ExpectMatchContext(inv.Context(), "agent is starting now")
274274

275275
resources := coderdtest.AwaitWorkspaceAgents(t, client, workspace.ID)
276276
require.Len(t, resources, 1)

‎cli/ssh.go

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -455,7 +455,7 @@ func watchAndClose(ctx context.Context, closer func() error, logger slog.Logger,
455455

456456
startWatchLoop:
457457
for {
458-
logger.Debug(ctx, "(re)connecting to the coder server to watch workspace events.")
458+
logger.Debug(ctx, "connecting to the coder server to watch workspace events")
459459
var wsWatch <-chan codersdk.Workspace
460460
var err error
461461
for r := retry.New(time.Second, 15*time.Second); r.Wait(ctx); {
@@ -464,15 +464,15 @@ startWatchLoop:
464464
break
465465
}
466466
if ctx.Err() != nil {
467-
logger.Info(ctx, "context expired", slog.Error(ctx.Err()))
467+
logger.Debug(ctx, "context expired", slog.Error(ctx.Err()))
468468
return
469469
}
470470
}
471471

472472
for {
473473
select {
474474
case <-ctx.Done():
475-
logger.Info(ctx, "context expired", slog.Error(ctx.Err()))
475+
logger.Debug(ctx, "context expired", slog.Error(ctx.Err()))
476476
return
477477
case w, ok := <-wsWatch:
478478
if !ok {

‎coderd/authorize.go

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -71,11 +71,11 @@ func (h *HTTPAuthorizer) Authorize(r *http.Request, action rbac.Action, object r
7171
internalError := new(rbac.UnauthorizedError)
7272
logger := h.Logger
7373
if xerrors.As(err, internalError) {
74-
logger = h.Logger.With(slog.F("internal", internalError.Internal()))
74+
logger = h.Logger.With(slog.F("internal_error", internalError.Internal()))
7575
}
7676
// Log information for debugging. This will be very helpful
7777
// in the early days
78-
logger.Warn(r.Context(), "unauthorized",
78+
logger.Warn(r.Context(), "requester is not authorized to access the object",
7979
slog.F("roles", roles.Actor.SafeRoleNames()),
8080
slog.F("actor_id", roles.Actor.ID),
8181
slog.F("actor_name", roles.ActorName),

‎coderd/coderd.go

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -245,9 +245,9 @@ func New(options *Options) *API {
245245
options.TracerProvider = trace.NewNoopTracerProvider()
246246
}
247247
if options.SetUserGroups == nil {
248-
options.SetUserGroups = func(ctx context.Context, _ database.Store, id uuid.UUID, groups []string) error {
248+
options.SetUserGroups = func(ctx context.Context, _ database.Store, userID uuid.UUID, groups []string) error {
249249
options.Logger.Warn(ctx, "attempted to assign OIDC groups without enterprise license",
250-
slog.F("id", id), slog.F("groups", groups),
250+
slog.F("user_id", userID), slog.F("groups", groups),
251251
)
252252
return nil
253253
}

‎coderd/database/dbauthz/dbauthz.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -69,7 +69,7 @@ func logNotAuthorizedError(ctx context.Context, logger slog.Logger, err error) e
6969
return &contextError
7070
}
7171
logger.Debug(ctx, "unauthorized",
72-
slog.F("internal", internalError.Internal()),
72+
slog.F("internal_error", internalError.Internal()),
7373
slog.F("input", internalError.Input()),
7474
slog.Error(err),
7575
)

‎coderd/httpmw/clitelemetry.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -50,7 +50,7 @@ func ReportCLITelemetry(log slog.Logger, rep telemetry.Reporter) func(http.Handl
5050
log.Error(
5151
r.Context(),
5252
"base64 decode",
53-
slog.F("error", err),
53+
slog.Error(err),
5454
)
5555
return
5656
}

‎coderd/prometheusmetrics/prometheusmetrics.go

Lines changed: 5 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -222,7 +222,7 @@ func Agents(ctx context.Context, logger slog.Logger, registerer prometheus.Regis
222222
case <-ticker.C:
223223
}
224224

225-
logger.Debug(ctx, "Agent metrics collection is starting")
225+
logger.Debug(ctx, "agent metrics collection is starting")
226226
timer := prometheus.NewTimer(metricsCollectorAgents)
227227

228228
workspaceRows, err := db.GetWorkspaces(ctx, database.GetWorkspacesParams{
@@ -236,7 +236,7 @@ func Agents(ctx context.Context, logger slog.Logger, registerer prometheus.Regis
236236
for _, workspace := range workspaceRows {
237237
user, err := db.GetUserByID(ctx, workspace.OwnerID)
238238
if err != nil {
239-
logger.Error(ctx, "can't get user", slog.F("user_id", workspace.OwnerID), slog.Error(err))
239+
logger.Error(ctx, "can't get user from the database", slog.F("user_id", workspace.OwnerID), slog.Error(err))
240240
agentsGauge.WithLabelValues(VectorOperationAdd, 0, user.Username, workspace.Name)
241241
continue
242242
}
@@ -314,7 +314,7 @@ func Agents(ctx context.Context, logger slog.Logger, registerer prometheus.Regis
314314
agentsAppsGauge.Commit()
315315

316316
done:
317-
logger.Debug(ctx, "Agent metrics collection is done")
317+
logger.Debug(ctx, "agent metrics collection is done")
318318
timer.ObserveDuration()
319319
ticker.Reset(duration)
320320
}
@@ -447,7 +447,7 @@ func AgentStats(ctx context.Context, logger slog.Logger, registerer prometheus.R
447447
case <-ticker.C:
448448
}
449449

450-
logger.Debug(ctx, "Agent metrics collection is starting")
450+
logger.Debug(ctx, "agent metrics collection is starting")
451451
timer := prometheus.NewTimer(metricsCollectorAgentStats)
452452

453453
checkpoint := time.Now()
@@ -482,7 +482,7 @@ func AgentStats(ctx context.Context, logger slog.Logger, registerer prometheus.R
482482
}
483483
}
484484

485-
logger.Debug(ctx, "Agent metrics collection is done", slog.F("len", len(stats)))
485+
logger.Debug(ctx, "agent metrics collection is done", slog.F("len", len(stats)))
486486
timer.ObserveDuration()
487487

488488
createdAfter = checkpoint

‎coderd/provisionerdserver/provisionerdserver.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -108,7 +108,7 @@ func (server *Server) AcquireJob(ctx context.Context, _ *proto.Empty) (*proto.Ac
108108
if err != nil {
109109
return nil, xerrors.Errorf("acquire job: %w", err)
110110
}
111-
server.Logger.Debug(ctx, "locked job from database", slog.F("id", job.ID))
111+
server.Logger.Debug(ctx, "locked job from database", slog.F("job_id", job.ID))
112112

113113
// Marks the acquired job as failed with the error message provided.
114114
failJob := func(errorMessage string) error {

‎coderd/provisionerjobs.go

Lines changed: 3 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -56,7 +56,7 @@ func (api *API) provisionerJobLogs(rw http.ResponseWriter, r *http.Request, job
5656
}
5757

5858
if !follow {
59-
fetchAndWriteLogs(ctx, logger, api.Database, job.ID, after, rw)
59+
fetchAndWriteLogs(ctx, api.Database, job.ID, after, rw)
6060
return
6161
}
6262

@@ -222,7 +222,7 @@ func convertProvisionerJob(provisionerJob database.ProvisionerJob) codersdk.Prov
222222
return job
223223
}
224224

225-
func fetchAndWriteLogs(ctx context.Context, logger slog.Logger, db database.Store, jobID uuid.UUID, after int64, rw http.ResponseWriter) {
225+
func fetchAndWriteLogs(ctx context.Context, db database.Store, jobID uuid.UUID, after int64, rw http.ResponseWriter) {
226226
logs, err := db.GetProvisionerLogsAfterID(ctx, database.GetProvisionerLogsAfterIDParams{
227227
JobID: jobID,
228228
CreatedAfter: after,
@@ -237,8 +237,6 @@ func fetchAndWriteLogs(ctx context.Context, logger slog.Logger, db database.Stor
237237
if logs == nil {
238238
logs = []database.ProvisionerJobLog{}
239239
}
240-
241-
logger.Debug(ctx, "Finished non-follow job logs")
242240
httpapi.Write(ctx, rw, http.StatusOK, convertProvisionerJobLogs(logs))
243241
}
244242

@@ -259,7 +257,7 @@ func jobIsComplete(logger slog.Logger, job database.ProvisionerJob) bool {
259257
return false
260258
default:
261259
logger.Error(context.Background(),
262-
"unknown status",
260+
"can't convert the provisioner job status",
263261
slog.F("job_id", job.ID), slog.F("status", status))
264262
return false
265263
}

‎coderd/workspaceagents.go

Lines changed: 8 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -464,7 +464,6 @@ func (api *API) workspaceAgentStartupLogs(rw http.ResponseWriter, r *http.Reques
464464
}
465465

466466
if !follow {
467-
logger.Debug(ctx, "Finished non-follow job logs")
468467
httpapi.Write(ctx, rw, http.StatusOK, convertWorkspaceAgentStartupLogs(logs))
469468
return
470469
}
@@ -967,7 +966,7 @@ func (api *API) workspaceAgentCoordinate(rw http.ResponseWriter, r *http.Request
967966
if !xerrors.Is(err, context.Canceled) && !database.IsQueryCanceledError(err) {
968967
api.Logger.Error(ctx, "failed to update agent disconnect time",
969968
slog.Error(err),
970-
slog.F("workspace", build.WorkspaceID),
969+
slog.F("workspace_id", build.WorkspaceID),
971970
)
972971
}
973972
}
@@ -1256,8 +1255,8 @@ func (api *API) workspaceAgentReportStats(rw http.ResponseWriter, r *http.Reques
12561255

12571256
api.Logger.Debug(ctx, "read stats report",
12581257
slog.F("interval", api.AgentStatsRefreshInterval),
1259-
slog.F("agent", workspaceAgent.ID),
1260-
slog.F("workspace", workspace.ID),
1258+
slog.F("workspace_agent_id", workspaceAgent.ID),
1259+
slog.F("workspace_id", workspace.ID),
12611260
slog.F("payload", req),
12621261
)
12631262

@@ -1267,7 +1266,7 @@ func (api *API) workspaceAgentReportStats(rw http.ResponseWriter, r *http.Reques
12671266

12681267
payload, err := json.Marshal(req.ConnectionsByProto)
12691268
if err != nil {
1270-
api.Logger.Error(ctx, "marshal agent connections by proto", slog.F("workspace_agent", workspaceAgent.ID), slog.Error(err))
1269+
api.Logger.Error(ctx, "marshal agent connections by proto", slog.F("workspace_agent_id", workspaceAgent.ID), slog.Error(err))
12711270
payload = json.RawMessage("{}")
12721271
}
12731272

@@ -1399,8 +1398,8 @@ func (api *API) workspaceAgentPostMetadata(rw http.ResponseWriter, r *http.Reque
13991398

14001399
api.Logger.Debug(
14011400
ctx, "accepted metadata report",
1402-
slog.F("agent", workspaceAgent.ID),
1403-
slog.F("workspace", workspace.ID),
1401+
slog.F("workspace_agent_id", workspaceAgent.ID),
1402+
slog.F("workspace_id", workspace.ID),
14041403
slog.F("collected_at", datum.CollectedAt),
14051404
slog.F("key", datum.Key),
14061405
)
@@ -1577,8 +1576,8 @@ func (api *API) workspaceAgentReportLifecycle(rw http.ResponseWriter, r *http.Re
15771576
}
15781577

15791578
logger := api.Logger.With(
1580-
slog.F("agent", workspaceAgent.ID),
1581-
slog.F("workspace", workspace.ID),
1579+
slog.F("workspace_agent_id", workspaceAgent.ID),
1580+
slog.F("workspace_id", workspace.ID),
15821581
slog.F("payload", req),
15831582
)
15841583
logger.Debug(ctx, "workspace agent state report")

‎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", err), slog.Error(err))
54+
m.logger.Error(m.ctx, "invalid 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", err), slog.Error(err))
59+
m.logger.Error(m.ctx, "parse derp", slog.F("address", addressURL.String()), slog.Error(err))
6060
continue
6161
}
6262
address = derpURL.String()

‎provisionerd/provisionerd_test.go

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -1009,7 +1009,7 @@ func TestProvisionerd(t *testing.T) {
10091009
acquireJob: func(ctx context.Context, _ *proto.Empty) (*proto.AcquiredJob, error) {
10101010
m.Lock()
10111011
defer m.Unlock()
1012-
logger.Info(ctx, "AcquiredJob called.")
1012+
logger.Info(ctx, "provisioner stage: AcquiredJob")
10131013
if len(ops) > 0 {
10141014
return &proto.AcquiredJob{}, nil
10151015
}
@@ -1031,7 +1031,7 @@ func TestProvisionerd(t *testing.T) {
10311031
updateJob: func(ctx context.Context, update *proto.UpdateJobRequest) (*proto.UpdateJobResponse, error) {
10321032
m.Lock()
10331033
defer m.Unlock()
1034-
logger.Info(ctx, "UpdateJob called.")
1034+
logger.Info(ctx, "provisioner stage: UpdateJob")
10351035
ops = append(ops, "UpdateJob")
10361036
for _, log := range update.Logs {
10371037
ops = append(ops, fmt.Sprintf("Log: %s | %s", log.Stage, log.Output))
@@ -1041,15 +1041,15 @@ func TestProvisionerd(t *testing.T) {
10411041
completeJob: func(ctx context.Context, job *proto.CompletedJob) (*proto.Empty, error) {
10421042
m.Lock()
10431043
defer m.Unlock()
1044-
logger.Info(ctx, "CompleteJob called.")
1044+
logger.Info(ctx, "provisioner stage: CompleteJob")
10451045
ops = append(ops, "CompleteJob")
10461046
completeOnce.Do(func() { close(completeChan) })
10471047
return &proto.Empty{}, nil
10481048
},
10491049
failJob: func(ctx context.Context, job *proto.FailedJob) (*proto.Empty, error) {
10501050
m.Lock()
10511051
defer m.Unlock()
1052-
logger.Info(ctx, "FailJob called.")
1052+
logger.Info(ctx, "provisioner stage: FailJob")
10531053
ops = append(ops, "FailJob")
10541054
return &proto.Empty{}, nil
10551055
},

0 commit comments

Comments
 (0)