Skip to content

Commit f8d3fbf

Browse files
ibetitsmikeibetitsmike
authored
feat: extend request logs with auth & DB info (#17497)
Closes #16903
1 parent 991d38c commit f8d3fbf

19 files changed

+334
-34
lines changed

‎Makefile

+4-4
Original file line numberDiff line numberDiff line change
@@ -582,7 +582,7 @@ GEN_FILES := \
582582
coderd/database/pubsub/psmock/psmock.go \
583583
agent/agentcontainers/acmock/acmock.go \
584584
agent/agentcontainers/dcspec/dcspec_gen.go \
585-
coderd/httpmw/loggermock/loggermock.go
585+
coderd/httpmw/loggermw/loggermock/loggermock.go
586586

587587
# all gen targets should be added here and to gen/mark-fresh
588588
gen: gen/db gen/golden-files $(GEN_FILES)
@@ -631,7 +631,7 @@ gen/mark-fresh:
631631
coderd/database/pubsub/psmock/psmock.go \
632632
agent/agentcontainers/acmock/acmock.go \
633633
agent/agentcontainers/dcspec/dcspec_gen.go \
634-
coderd/httpmw/loggermock/loggermock.go \
634+
coderd/httpmw/loggermw/loggermock/loggermock.go \
635635
"
636636

637637
for file in $$files; do
@@ -671,8 +671,8 @@ agent/agentcontainers/acmock/acmock.go: agent/agentcontainers/containers.go
671671
go generate ./agent/agentcontainers/acmock/
672672
touch "$@"
673673

674-
coderd/httpmw/loggermock/loggermock.go: coderd/httpmw/logger.go
675-
go generate ./coderd/httpmw/loggermock/
674+
coderd/httpmw/loggermw/loggermock/loggermock.go: coderd/httpmw/loggermw/logger.go
675+
go generate ./coderd/httpmw/loggermw/loggermock/
676676
touch "$@"
677677

678678
agent/agentcontainers/dcspec/dcspec_gen.go: \

‎coderd/coderd.go

+2-1
Original file line numberDiff line numberDiff line change
@@ -64,6 +64,7 @@ import (
6464
"github.com/coder/coder/v2/coderd/healthcheck/derphealth"
6565
"github.com/coder/coder/v2/coderd/httpapi"
6666
"github.com/coder/coder/v2/coderd/httpmw"
67+
"github.com/coder/coder/v2/coderd/httpmw/loggermw"
6768
"github.com/coder/coder/v2/coderd/metricscache"
6869
"github.com/coder/coder/v2/coderd/notifications"
6970
"github.com/coder/coder/v2/coderd/portsharing"
@@ -801,7 +802,7 @@ func New(options *Options) *API {
801802
tracing.Middleware(api.TracerProvider),
802803
httpmw.AttachRequestID,
803804
httpmw.ExtractRealIP(api.RealIPConfig),
804-
httpmw.Logger(api.Logger),
805+
loggermw.Logger(api.Logger),
805806
singleSlashMW,
806807
rolestore.CustomRoleMW,
807808
prometheusMW,

‎coderd/database/dbauthz/dbauthz.go

+22-9
Original file line numberDiff line numberDiff line change
@@ -24,6 +24,7 @@ import (
2424
"github.com/coder/coder/v2/coderd/database"
2525
"github.com/coder/coder/v2/coderd/database/dbtime"
2626
"github.com/coder/coder/v2/coderd/httpapi/httpapiconstraints"
27+
"github.com/coder/coder/v2/coderd/httpmw/loggermw"
2728
"github.com/coder/coder/v2/coderd/rbac"
2829
"github.com/coder/coder/v2/coderd/util/slice"
2930
"github.com/coder/coder/v2/provisionersdk"
@@ -162,6 +163,7 @@ func ActorFromContext(ctx context.Context) (rbac.Subject, bool) {
162163

163164
var (
164165
subjectProvisionerd = rbac.Subject{
166+
Type: rbac.SubjectTypeProvisionerd,
165167
FriendlyName: "Provisioner Daemon",
166168
ID: uuid.Nil.String(),
167169
Roles: rbac.Roles([]rbac.Role{
@@ -196,6 +198,7 @@ var (
196198
}.WithCachedASTValue()
197199

198200
subjectAutostart = rbac.Subject{
201+
Type: rbac.SubjectTypeAutostart,
199202
FriendlyName: "Autostart",
200203
ID: uuid.Nil.String(),
201204
Roles: rbac.Roles([]rbac.Role{
@@ -219,6 +222,7 @@ var (
219222

220223
// See unhanger package.
221224
subjectHangDetector = rbac.Subject{
225+
Type: rbac.SubjectTypeHangDetector,
222226
FriendlyName: "Hang Detector",
223227
ID: uuid.Nil.String(),
224228
Roles: rbac.Roles([]rbac.Role{
@@ -239,6 +243,7 @@ var (
239243

240244
// See cryptokeys package.
241245
subjectCryptoKeyRotator = rbac.Subject{
246+
Type: rbac.SubjectTypeCryptoKeyRotator,
242247
FriendlyName: "Crypto Key Rotator",
243248
ID: uuid.Nil.String(),
244249
Roles: rbac.Roles([]rbac.Role{
@@ -257,6 +262,7 @@ var (
257262

258263
// See cryptokeys package.
259264
subjectCryptoKeyReader = rbac.Subject{
265+
Type: rbac.SubjectTypeCryptoKeyReader,
260266
FriendlyName: "Crypto Key Reader",
261267
ID: uuid.Nil.String(),
262268
Roles: rbac.Roles([]rbac.Role{
@@ -274,6 +280,7 @@ var (
274280
}.WithCachedASTValue()
275281

276282
subjectNotifier = rbac.Subject{
283+
Type: rbac.SubjectTypeNotifier,
277284
FriendlyName: "Notifier",
278285
ID: uuid.Nil.String(),
279286
Roles: rbac.Roles([]rbac.Role{
@@ -294,6 +301,7 @@ var (
294301
}.WithCachedASTValue()
295302

296303
subjectResourceMonitor = rbac.Subject{
304+
Type: rbac.SubjectTypeResourceMonitor,
297305
FriendlyName: "Resource Monitor",
298306
ID: uuid.Nil.String(),
299307
Roles: rbac.Roles([]rbac.Role{
@@ -312,6 +320,7 @@ var (
312320
}.WithCachedASTValue()
313321

314322
subjectSystemRestricted = rbac.Subject{
323+
Type: rbac.SubjectTypeSystemRestricted,
315324
FriendlyName: "System",
316325
ID: uuid.Nil.String(),
317326
Roles: rbac.Roles([]rbac.Role{
@@ -346,6 +355,7 @@ var (
346355
}.WithCachedASTValue()
347356

348357
subjectSystemReadProvisionerDaemons = rbac.Subject{
358+
Type: rbac.SubjectTypeSystemReadProvisionerDaemons,
349359
FriendlyName: "Provisioner Daemons Reader",
350360
ID: uuid.Nil.String(),
351361
Roles: rbac.Roles([]rbac.Role{
@@ -366,53 +376,53 @@ var (
366376
// AsProvisionerd returns a context with an actor that has permissions required
367377
// for provisionerd to function.
368378
func AsProvisionerd(ctx context.Context) context.Context {
369-
return context.WithValue(ctx, authContextKey{}, subjectProvisionerd)
379+
return As(ctx, subjectProvisionerd)
370380
}
371381

372382
// AsAutostart returns a context with an actor that has permissions required
373383
// for autostart to function.
374384
func AsAutostart(ctx context.Context) context.Context {
375-
return context.WithValue(ctx, authContextKey{}, subjectAutostart)
385+
return As(ctx, subjectAutostart)
376386
}
377387

378388
// AsHangDetector returns a context with an actor that has permissions required
379389
// for unhanger.Detector to function.
380390
func AsHangDetector(ctx context.Context) context.Context {
381-
return context.WithValue(ctx, authContextKey{}, subjectHangDetector)
391+
return As(ctx, subjectHangDetector)
382392
}
383393

384394
// AsKeyRotator returns a context with an actor that has permissions required for rotating crypto keys.
385395
func AsKeyRotator(ctx context.Context) context.Context {
386-
return context.WithValue(ctx, authContextKey{}, subjectCryptoKeyRotator)
396+
return As(ctx, subjectCryptoKeyRotator)
387397
}
388398

389399
// AsKeyReader returns a context with an actor that has permissions required for reading crypto keys.
390400
func AsKeyReader(ctx context.Context) context.Context {
391-
return context.WithValue(ctx, authContextKey{}, subjectCryptoKeyReader)
401+
return As(ctx, subjectCryptoKeyReader)
392402
}
393403

394404
// AsNotifier returns a context with an actor that has permissions required for
395405
// creating/reading/updating/deleting notifications.
396406
func AsNotifier(ctx context.Context) context.Context {
397-
return context.WithValue(ctx, authContextKey{}, subjectNotifier)
407+
return As(ctx, subjectNotifier)
398408
}
399409

400410
// AsResourceMonitor returns a context with an actor that has permissions required for
401411
// updating resource monitors.
402412
func AsResourceMonitor(ctx context.Context) context.Context {
403-
return context.WithValue(ctx, authContextKey{}, subjectResourceMonitor)
413+
return As(ctx, subjectResourceMonitor)
404414
}
405415

406416
// AsSystemRestricted returns a context with an actor that has permissions
407417
// required for various system operations (login, logout, metrics cache).
408418
func AsSystemRestricted(ctx context.Context) context.Context {
409-
return context.WithValue(ctx, authContextKey{}, subjectSystemRestricted)
419+
return As(ctx, subjectSystemRestricted)
410420
}
411421

412422
// AsSystemReadProvisionerDaemons returns a context with an actor that has permissions
413423
// to read provisioner daemons.
414424
func AsSystemReadProvisionerDaemons(ctx context.Context) context.Context {
415-
return context.WithValue(ctx, authContextKey{}, subjectSystemReadProvisionerDaemons)
425+
return As(ctx, subjectSystemReadProvisionerDaemons)
416426
}
417427

418428
var AsRemoveActor = rbac.Subject{
@@ -430,6 +440,9 @@ func As(ctx context.Context, actor rbac.Subject) context.Context {
430440
// should be removed from the context.
431441
return context.WithValue(ctx, authContextKey{}, nil)
432442
}
443+
if rlogger := loggermw.RequestLoggerFromContext(ctx); rlogger != nil {
444+
rlogger.WithAuthContext(actor)
445+
}
433446
return context.WithValue(ctx, authContextKey{}, actor)
434447
}
435448

‎coderd/database/queries.sql.go

+4-2
Some generated files are not rendered by default. Learn more about customizing how changed files appear on GitHub.

‎coderd/database/queries/users.sql

+2-2
Original file line numberDiff line numberDiff line change
@@ -271,10 +271,10 @@ WHERE
271271
-- This function returns roles for authorization purposes. Implied member roles
272272
-- are included.
273273
SELECT
274-
-- username is returned just to help for logging purposes
274+
-- username and email are returned just to help for logging purposes
275275
-- status is used to enforce 'suspended' users, as all roles are ignored
276276
-- when suspended.
277-
id, username, status,
277+
id, username, status, email,
278278
-- All user roles, including their org roles.
279279
array_cat(
280280
-- All users are members

‎coderd/httpmw/apikey.go

+2
Original file line numberDiff line numberDiff line change
@@ -465,7 +465,9 @@ func UserRBACSubject(ctx context.Context, db database.Store, userID uuid.UUID, s
465465
}
466466

467467
actor := rbac.Subject{
468+
Type: rbac.SubjectTypeUser,
468469
FriendlyName: roles.Username,
470+
Email: roles.Email,
469471
ID: userID.String(),
470472
Roles: rbacRoles,
471473
Groups: roles.Groups,

‎coderd/httpmw/logger.go renamed to ‎coderd/httpmw/loggermw/logger.go

+77-1
Original file line numberDiff line numberDiff line change
@@ -1,13 +1,17 @@
1-
package httpmw
1+
package loggermw
22

33
import (
44
"context"
55
"fmt"
66
"net/http"
7+
"sync"
78
"time"
89

10+
"github.com/go-chi/chi/v5"
11+
912
"cdr.dev/slog"
1013
"github.com/coder/coder/v2/coderd/httpapi"
14+
"github.com/coder/coder/v2/coderd/rbac"
1115
"github.com/coder/coder/v2/coderd/tracing"
1216
)
1317

@@ -62,13 +66,17 @@ func Logger(log slog.Logger) func(next http.Handler) http.Handler {
6266
type RequestLogger interface {
6367
WithFields(fields ...slog.Field)
6468
WriteLog(ctx context.Context, status int)
69+
WithAuthContext(actor rbac.Subject)
6570
}
6671

6772
type SlogRequestLogger struct {
6873
log slog.Logger
6974
written bool
7075
message string
7176
start time.Time
77+
// Protects actors map for concurrent writes.
78+
mu sync.RWMutex
79+
actors map[rbac.SubjectType]rbac.Subject
7280
}
7381

7482
var _ RequestLogger = &SlogRequestLogger{}
@@ -79,25 +87,93 @@ func NewRequestLogger(log slog.Logger, message string, start time.Time) RequestL
7987
written: false,
8088
message: message,
8189
start: start,
90+
actors: make(map[rbac.SubjectType]rbac.Subject),
8291
}
8392
}
8493

8594
func (c *SlogRequestLogger) WithFields(fields ...slog.Field) {
8695
c.log = c.log.With(fields...)
8796
}
8897

98+
func (c *SlogRequestLogger) WithAuthContext(actor rbac.Subject) {
99+
c.mu.Lock()
100+
defer c.mu.Unlock()
101+
c.actors[actor.Type] = actor
102+
}
103+
104+
func (c *SlogRequestLogger) addAuthContextFields() {
105+
c.mu.RLock()
106+
defer c.mu.RUnlock()
107+
108+
usr, ok := c.actors[rbac.SubjectTypeUser]
109+
if ok {
110+
c.log = c.log.With(
111+
slog.F("requestor_id", usr.ID),
112+
slog.F("requestor_name", usr.FriendlyName),
113+
slog.F("requestor_email", usr.Email),
114+
)
115+
} else {
116+
// If there is no user, we log the requestor name for the first
117+
// actor in a defined order.
118+
for _, v := range actorLogOrder {
119+
subj, ok := c.actors[v]
120+
if !ok {
121+
continue
122+
}
123+
c.log = c.log.With(
124+
slog.F("requestor_name", subj.FriendlyName),
125+
)
126+
break
127+
}
128+
}
129+
}
130+
131+
var actorLogOrder = []rbac.SubjectType{
132+
rbac.SubjectTypeAutostart,
133+
rbac.SubjectTypeCryptoKeyReader,
134+
rbac.SubjectTypeCryptoKeyRotator,
135+
rbac.SubjectTypeHangDetector,
136+
rbac.SubjectTypeNotifier,
137+
rbac.SubjectTypePrebuildsOrchestrator,
138+
rbac.SubjectTypeProvisionerd,
139+
rbac.SubjectTypeResourceMonitor,
140+
rbac.SubjectTypeSystemReadProvisionerDaemons,
141+
rbac.SubjectTypeSystemRestricted,
142+
}
143+
89144
func (c *SlogRequestLogger) WriteLog(ctx context.Context, status int) {
90145
if c.written {
91146
return
92147
}
93148
c.written = true
94149
end := time.Now()
95150

151+
// Right before we write the log, we try to find the user in the actors
152+
// and add the fields to the log.
153+
c.addAuthContextFields()
154+
96155
logger := c.log.With(
97156
slog.F("took", end.Sub(c.start)),
98157
slog.F("status_code", status),
99158
slog.F("latency_ms", float64(end.Sub(c.start)/time.Millisecond)),
100159
)
160+
161+
// If the request is routed, add the route parameters to the log.
162+
if chiCtx := chi.RouteContext(ctx); chiCtx != nil {
163+
urlParams := chiCtx.URLParams
164+
routeParamsFields := make([]slog.Field, 0, len(urlParams.Keys))
165+
166+
for k, v := range urlParams.Keys {
167+
if urlParams.Values[k] != "" {
168+
routeParamsFields = append(routeParamsFields, slog.F("params_"+v, urlParams.Values[k]))
169+
}
170+
}
171+
172+
if len(routeParamsFields) > 0 {
173+
logger = logger.With(routeParamsFields...)
174+
}
175+
}
176+
101177
// We already capture most of this information in the span (minus
102178
// the response body which we don't want to capture anyways).
103179
tracing.RunWithoutSpan(ctx, func(ctx context.Context) {

0 commit comments

Comments
 (0)