Skip to content

Commit c266bb8

Browse files
code-ashercode-asher
authored
chore: add debug logging and recovery to agent api requests (#20785)
This is to debug context timeouts on API requests to the agent. Because rbac and database cannot be imported in slim, split the logger middleware into slim and non-slim versions and break out the recovery middleware.
1 parent b0e8384 commit c266bb8

File tree

9 files changed

+162
-81
lines changed

9 files changed

+162
-81
lines changed

‎agent/api.go‎

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -7,12 +7,20 @@ import (
77
"github.com/google/uuid"
88

99
"github.com/coder/coder/v2/coderd/httpapi"
10+
"github.com/coder/coder/v2/coderd/httpmw/loggermw"
11+
"github.com/coder/coder/v2/coderd/tracing"
1012
"github.com/coder/coder/v2/codersdk"
1113
"github.com/coder/coder/v2/codersdk/workspacesdk"
14+
"github.com/coder/coder/v2/httpmw"
1215
)
1316

1417
func (a *agent) apiHandler() http.Handler {
1518
r := chi.NewRouter()
19+
r.Use(
20+
httpmw.Recover(a.logger),
21+
tracing.StatusWriterMiddleware,
22+
loggermw.Logger(a.logger),
23+
)
1624
r.Get("/", func(rw http.ResponseWriter, r *http.Request) {
1725
httpapi.Write(r.Context(), rw, http.StatusOK, codersdk.Response{
1826
Message: "Hello from the agent!",

‎coderd/coderd.go‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -99,6 +99,7 @@ import (
9999
"github.com/coder/coder/v2/coderd/workspacestats"
100100
"github.com/coder/coder/v2/codersdk"
101101
"github.com/coder/coder/v2/codersdk/healthsdk"
102+
sharedhttpmw "github.com/coder/coder/v2/httpmw"
102103
"github.com/coder/coder/v2/provisionersdk"
103104
"github.com/coder/coder/v2/site"
104105
"github.com/coder/coder/v2/tailnet"
@@ -861,7 +862,7 @@ func New(options *Options) *API {
861862
prometheusMW := httpmw.Prometheus(options.PrometheusRegistry)
862863

863864
r.Use(
864-
httpmw.Recover(api.Logger),
865+
sharedhttpmw.Recover(api.Logger),
865866
httpmw.WithProfilingLabels,
866867
tracing.StatusWriterMiddleware,
867868
tracing.Middleware(api.TracerProvider),

‎coderd/httpmw/loggermw/logger.go‎

Lines changed: 9 additions & 78 deletions
Original file line numberDiff line numberDiff line change
@@ -7,19 +7,17 @@ import (
77
"net/url"
88
"strconv"
99
"strings"
10-
"sync"
1110
"time"
1211

1312
"github.com/go-chi/chi/v5"
1413

1514
"cdr.dev/slog"
1615
"github.com/coder/coder/v2/coderd/httpapi"
17-
"github.com/coder/coder/v2/coderd/rbac"
1816
"github.com/coder/coder/v2/coderd/tracing"
1917
)
2018

2119
var (
22-
safeParams = []string{"page", "limit", "offset"}
20+
safeParams = []string{"page", "limit", "offset", "path"}
2321
countParams = []string{"ids", "template_ids"}
2422
)
2523

@@ -124,95 +122,28 @@ func Logger(log slog.Logger) func(next http.Handler) http.Handler {
124122
}
125123
}
126124

127-
type RequestLogger interface {
128-
WithFields(fields ...slog.Field)
129-
WriteLog(ctx context.Context, status int)
130-
WithAuthContext(actor rbac.Subject)
131-
}
132-
133125
type SlogRequestLogger struct {
134-
log slog.Logger
135-
written bool
136-
message string
137-
start time.Time
138-
// Protects actors map for concurrent writes.
139-
mu sync.RWMutex
140-
actors map[rbac.SubjectType]rbac.Subject
141-
}
142-
143-
var _ RequestLogger = &SlogRequestLogger{}
144-
145-
func NewRequestLogger(log slog.Logger, message string, start time.Time) RequestLogger {
146-
return &SlogRequestLogger{
147-
log: log,
148-
written: false,
149-
message: message,
150-
start: start,
151-
actors: make(map[rbac.SubjectType]rbac.Subject),
152-
}
126+
log slog.Logger
127+
written bool
128+
message string
129+
start time.Time
130+
addFields func()
153131
}
154132

155133
func (c *SlogRequestLogger) WithFields(fields ...slog.Field) {
156134
c.log = c.log.With(fields...)
157135
}
158136

159-
func (c *SlogRequestLogger) WithAuthContext(actor rbac.Subject) {
160-
c.mu.Lock()
161-
defer c.mu.Unlock()
162-
c.actors[actor.Type] = actor
163-
}
164-
165-
func (c *SlogRequestLogger) addAuthContextFields() {
166-
c.mu.RLock()
167-
defer c.mu.RUnlock()
168-
169-
usr, ok := c.actors[rbac.SubjectTypeUser]
170-
if ok {
171-
c.log = c.log.With(
172-
slog.F("requestor_id", usr.ID),
173-
slog.F("requestor_name", usr.FriendlyName),
174-
slog.F("requestor_email", usr.Email),
175-
)
176-
} else {
177-
// If there is no user, we log the requestor name for the first
178-
// actor in a defined order.
179-
for _, v := range actorLogOrder {
180-
subj, ok := c.actors[v]
181-
if !ok {
182-
continue
183-
}
184-
c.log = c.log.With(
185-
slog.F("requestor_name", subj.FriendlyName),
186-
)
187-
break
188-
}
189-
}
190-
}
191-
192-
var actorLogOrder = []rbac.SubjectType{
193-
rbac.SubjectTypeAutostart,
194-
rbac.SubjectTypeCryptoKeyReader,
195-
rbac.SubjectTypeCryptoKeyRotator,
196-
rbac.SubjectTypeJobReaper,
197-
rbac.SubjectTypeNotifier,
198-
rbac.SubjectTypePrebuildsOrchestrator,
199-
rbac.SubjectTypeSubAgentAPI,
200-
rbac.SubjectTypeProvisionerd,
201-
rbac.SubjectTypeResourceMonitor,
202-
rbac.SubjectTypeSystemReadProvisionerDaemons,
203-
rbac.SubjectTypeSystemRestricted,
204-
}
205-
206137
func (c *SlogRequestLogger) WriteLog(ctx context.Context, status int) {
207138
if c.written {
208139
return
209140
}
210141
c.written = true
211142
end := time.Now()
212143

213-
// Right before we write the log, we try to find the user in the actors
214-
// and add the fields to the log.
215-
c.addAuthContextFields()
144+
if c.addFields != nil {
145+
c.addFields()
146+
}
216147

217148
logger := c.log.With(
218149
slog.F("took", end.Sub(c.start)),

‎coderd/httpmw/loggermw/logger_full.go‎

Lines changed: 88 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,88 @@
1+
//go:build !slim
2+
3+
package loggermw
4+
5+
import (
6+
"context"
7+
"sync"
8+
"time"
9+
10+
"cdr.dev/slog"
11+
"github.com/coder/coder/v2/coderd/rbac"
12+
)
13+
14+
type RequestLogger interface {
15+
WithFields(fields ...slog.Field)
16+
WriteLog(ctx context.Context, status int)
17+
WithAuthContext(actor rbac.Subject)
18+
}
19+
20+
type RbacSlogRequestLogger struct {
21+
SlogRequestLogger
22+
// Protects actors map for concurrent writes.
23+
mu sync.RWMutex
24+
actors map[rbac.SubjectType]rbac.Subject
25+
}
26+
27+
var _ RequestLogger = &RbacSlogRequestLogger{}
28+
29+
func NewRequestLogger(log slog.Logger, message string, start time.Time) RequestLogger {
30+
rlogger := &RbacSlogRequestLogger{
31+
SlogRequestLogger: SlogRequestLogger{
32+
log: log,
33+
written: false,
34+
message: message,
35+
start: start,
36+
},
37+
actors: make(map[rbac.SubjectType]rbac.Subject),
38+
}
39+
rlogger.addFields = rlogger.addAuthContextFields
40+
return rlogger
41+
}
42+
43+
func (c *RbacSlogRequestLogger) WithAuthContext(actor rbac.Subject) {
44+
c.mu.Lock()
45+
defer c.mu.Unlock()
46+
c.actors[actor.Type] = actor
47+
}
48+
49+
var actorLogOrder = []rbac.SubjectType{
50+
rbac.SubjectTypeAutostart,
51+
rbac.SubjectTypeCryptoKeyReader,
52+
rbac.SubjectTypeCryptoKeyRotator,
53+
rbac.SubjectTypeJobReaper,
54+
rbac.SubjectTypeNotifier,
55+
rbac.SubjectTypePrebuildsOrchestrator,
56+
rbac.SubjectTypeSubAgentAPI,
57+
rbac.SubjectTypeProvisionerd,
58+
rbac.SubjectTypeResourceMonitor,
59+
rbac.SubjectTypeSystemReadProvisionerDaemons,
60+
rbac.SubjectTypeSystemRestricted,
61+
}
62+
63+
func (c *RbacSlogRequestLogger) addAuthContextFields() {
64+
c.mu.RLock()
65+
defer c.mu.RUnlock()
66+
67+
usr, ok := c.actors[rbac.SubjectTypeUser]
68+
if ok {
69+
c.log = c.log.With(
70+
slog.F("requestor_id", usr.ID),
71+
slog.F("requestor_name", usr.FriendlyName),
72+
slog.F("requestor_email", usr.Email),
73+
)
74+
} else {
75+
// If there is no user, we log the requestor name for the first
76+
// actor in a defined order.
77+
for _, v := range actorLogOrder {
78+
subj, ok := c.actors[v]
79+
if !ok {
80+
continue
81+
}
82+
c.log = c.log.With(
83+
slog.F("requestor_name", subj.FriendlyName),
84+
)
85+
break
86+
}
87+
}
88+
}

‎coderd/httpmw/loggermw/logger_internal_test.go‎

Lines changed: 26 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -16,6 +16,7 @@ import (
1616
"github.com/stretchr/testify/require"
1717

1818
"cdr.dev/slog"
19+
"github.com/coder/coder/v2/coderd/rbac"
1920
"github.com/coder/coder/v2/coderd/tracing"
2021
"github.com/coder/coder/v2/testutil"
2122
"github.com/coder/websocket"
@@ -363,6 +364,31 @@ func TestSafeQueryParams(t *testing.T) {
363364
}
364365
}
365366

367+
func TestRequestLogger_AuthContext(t *testing.T) {
368+
t.Parallel()
369+
ctx := context.Background()
370+
371+
sink := &fakeSink{}
372+
logger := slog.Make(sink)
373+
logger = logger.Leveled(slog.LevelDebug)
374+
logCtx := NewRequestLogger(logger, "GET", time.Now())
375+
376+
logCtx.WithAuthContext(rbac.Subject{
377+
ID: "test-user-id",
378+
FriendlyName: "test name",
379+
Email: "test@coder.com",
380+
Type: rbac.SubjectTypeUser,
381+
})
382+
383+
logCtx.WriteLog(ctx, http.StatusOK)
384+
385+
require.Len(t, sink.entries, 1, "log was written twice")
386+
require.Equal(t, sink.entries[0].Message, "GET")
387+
require.Equal(t, sink.entries[0].Fields[0].Value, "test-user-id")
388+
require.Equal(t, sink.entries[0].Fields[1].Value, "test name")
389+
require.Equal(t, sink.entries[0].Fields[2].Value, "test@coder.com")
390+
}
391+
366392
type fakeSink struct {
367393
entries []slog.SinkEntry
368394
newEntries chan slog.SinkEntry

‎coderd/httpmw/loggermw/logger_slim.go‎

Lines changed: 26 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,26 @@
1+
//go:build slim
2+
3+
package loggermw
4+
5+
import (
6+
"context"
7+
"time"
8+
9+
"cdr.dev/slog"
10+
)
11+
12+
type RequestLogger interface {
13+
WithFields(fields ...slog.Field)
14+
WriteLog(ctx context.Context, status int)
15+
}
16+
17+
var _ RequestLogger = &SlogRequestLogger{}
18+
19+
func NewRequestLogger(log slog.Logger, message string, start time.Time) RequestLogger {
20+
return &SlogRequestLogger{
21+
log: log,
22+
written: false,
23+
message: message,
24+
start: start,
25+
}
26+
}

‎enterprise/wsproxy/wsproxy.go‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -39,6 +39,7 @@ import (
3939
"github.com/coder/coder/v2/enterprise/derpmesh"
4040
"github.com/coder/coder/v2/enterprise/replicasync"
4141
"github.com/coder/coder/v2/enterprise/wsproxy/wsproxysdk"
42+
sharedhttpmw "github.com/coder/coder/v2/httpmw"
4243
"github.com/coder/coder/v2/site"
4344
"github.com/coder/coder/v2/tailnet"
4445
)
@@ -328,7 +329,7 @@ func New(ctx context.Context, opts *Options) (*Server, error) {
328329
// Persistent middlewares to all routes
329330
r.Use(
330331
// TODO: @emyrk Should we standardize these in some other package?
331-
httpmw.Recover(s.Logger),
332+
sharedhttpmw.Recover(s.Logger),
332333
httpmw.WithProfilingLabels,
333334
tracing.StatusWriterMiddleware,
334335
tracing.Middleware(s.TracerProvider),

coderd/httpmw/recover.go renamed to httpmw/recover.go

File renamed without changes.

coderd/httpmw/recover_test.go renamed to httpmw/recover_test.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -7,8 +7,8 @@ import (
77

88
"github.com/stretchr/testify/require"
99

10-
"github.com/coder/coder/v2/coderd/httpmw"
1110
"github.com/coder/coder/v2/coderd/tracing"
11+
"github.com/coder/coder/v2/httpmw"
1212
"github.com/coder/coder/v2/testutil"
1313
)
1414

0 commit comments

Comments
 (0)