Skip to content

Commit 06d3915

Browse files
ibetitsmikeibetitsmike
authored
feat: extend request logs with auth & DB info (#17304)
Closes #16903
1 parent 979687c commit 06d3915

File tree

19 files changed

+336
-35
lines changed

19 files changed

+336
-35
lines changed

‎Makefile‎

Lines changed: 4 additions & 4 deletions
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‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -65,6 +65,7 @@ import (
6565
"github.com/coder/coder/v2/coderd/healthcheck/derphealth"
6666
"github.com/coder/coder/v2/coderd/httpapi"
6767
"github.com/coder/coder/v2/coderd/httpmw"
68+
"github.com/coder/coder/v2/coderd/httpmw/loggermw"
6869
"github.com/coder/coder/v2/coderd/metricscache"
6970
"github.com/coder/coder/v2/coderd/notifications"
7071
"github.com/coder/coder/v2/coderd/portsharing"
@@ -811,7 +812,7 @@ func New(options *Options) *API {
811812
tracing.Middleware(api.TracerProvider),
812813
httpmw.AttachRequestID,
813814
httpmw.ExtractRealIP(api.RealIPConfig),
814-
httpmw.Logger(api.Logger),
815+
loggermw.Logger(api.Logger),
815816
singleSlashMW,
816817
rolestore.CustomRoleMW,
817818
prometheusMW,

‎coderd/database/dbauthz/dbauthz.go‎

Lines changed: 24 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -25,6 +25,7 @@ import (
2525
"github.com/coder/coder/v2/coderd/database"
2626
"github.com/coder/coder/v2/coderd/database/dbtime"
2727
"github.com/coder/coder/v2/coderd/httpapi/httpapiconstraints"
28+
"github.com/coder/coder/v2/coderd/httpmw/loggermw"
2829
"github.com/coder/coder/v2/coderd/rbac"
2930
"github.com/coder/coder/v2/coderd/util/slice"
3031
"github.com/coder/coder/v2/provisionersdk"
@@ -163,6 +164,7 @@ func ActorFromContext(ctx context.Context) (rbac.Subject, bool) {
163164

164165
var (
165166
subjectProvisionerd = rbac.Subject{
167+
Type: rbac.SubjectTypeProvisionerd,
166168
FriendlyName: "Provisioner Daemon",
167169
ID: uuid.Nil.String(),
168170
Roles: rbac.Roles([]rbac.Role{
@@ -197,6 +199,7 @@ var (
197199
}.WithCachedASTValue()
198200

199201
subjectAutostart = rbac.Subject{
202+
Type: rbac.SubjectTypeAutostart,
200203
FriendlyName: "Autostart",
201204
ID: uuid.Nil.String(),
202205
Roles: rbac.Roles([]rbac.Role{
@@ -220,6 +223,7 @@ var (
220223

221224
// See unhanger package.
222225
subjectHangDetector = rbac.Subject{
226+
Type: rbac.SubjectTypeHangDetector,
223227
FriendlyName: "Hang Detector",
224228
ID: uuid.Nil.String(),
225229
Roles: rbac.Roles([]rbac.Role{
@@ -240,6 +244,7 @@ var (
240244

241245
// See cryptokeys package.
242246
subjectCryptoKeyRotator = rbac.Subject{
247+
Type: rbac.SubjectTypeCryptoKeyRotator,
243248
FriendlyName: "Crypto Key Rotator",
244249
ID: uuid.Nil.String(),
245250
Roles: rbac.Roles([]rbac.Role{
@@ -258,6 +263,7 @@ var (
258263

259264
// See cryptokeys package.
260265
subjectCryptoKeyReader = rbac.Subject{
266+
Type: rbac.SubjectTypeCryptoKeyReader,
261267
FriendlyName: "Crypto Key Reader",
262268
ID: uuid.Nil.String(),
263269
Roles: rbac.Roles([]rbac.Role{
@@ -275,6 +281,7 @@ var (
275281
}.WithCachedASTValue()
276282

277283
subjectNotifier = rbac.Subject{
284+
Type: rbac.SubjectTypeNotifier,
278285
FriendlyName: "Notifier",
279286
ID: uuid.Nil.String(),
280287
Roles: rbac.Roles([]rbac.Role{
@@ -295,6 +302,7 @@ var (
295302
}.WithCachedASTValue()
296303

297304
subjectResourceMonitor = rbac.Subject{
305+
Type: rbac.SubjectTypeResourceMonitor,
298306
FriendlyName: "Resource Monitor",
299307
ID: uuid.Nil.String(),
300308
Roles: rbac.Roles([]rbac.Role{
@@ -313,6 +321,7 @@ var (
313321
}.WithCachedASTValue()
314322

315323
subjectSystemRestricted = rbac.Subject{
324+
Type: rbac.SubjectTypeSystemRestricted,
316325
FriendlyName: "System",
317326
ID: uuid.Nil.String(),
318327
Roles: rbac.Roles([]rbac.Role{
@@ -347,6 +356,7 @@ var (
347356
}.WithCachedASTValue()
348357

349358
subjectSystemReadProvisionerDaemons = rbac.Subject{
359+
Type: rbac.SubjectTypeSystemReadProvisionerDaemons,
350360
FriendlyName: "Provisioner Daemons Reader",
351361
ID: uuid.Nil.String(),
352362
Roles: rbac.Roles([]rbac.Role{
@@ -364,6 +374,7 @@ var (
364374
}.WithCachedASTValue()
365375

366376
subjectPrebuildsOrchestrator = rbac.Subject{
377+
Type: rbac.SubjectTypePrebuildsOrchestrator,
367378
FriendlyName: "Prebuilds Orchestrator",
368379
ID: prebuilds.SystemUserID.String(),
369380
Roles: rbac.Roles([]rbac.Role{
@@ -388,59 +399,59 @@ var (
388399
// AsProvisionerd returns a context with an actor that has permissions required
389400
// for provisionerd to function.
390401
func AsProvisionerd(ctx context.Context) context.Context {
391-
return context.WithValue(ctx, authContextKey{}, subjectProvisionerd)
402+
return As(ctx, subjectProvisionerd)
392403
}
393404

394405
// AsAutostart returns a context with an actor that has permissions required
395406
// for autostart to function.
396407
func AsAutostart(ctx context.Context) context.Context {
397-
return context.WithValue(ctx, authContextKey{}, subjectAutostart)
408+
return As(ctx, subjectAutostart)
398409
}
399410

400411
// AsHangDetector returns a context with an actor that has permissions required
401412
// for unhanger.Detector to function.
402413
func AsHangDetector(ctx context.Context) context.Context {
403-
return context.WithValue(ctx, authContextKey{}, subjectHangDetector)
414+
return As(ctx, subjectHangDetector)
404415
}
405416

406417
// AsKeyRotator returns a context with an actor that has permissions required for rotating crypto keys.
407418
func AsKeyRotator(ctx context.Context) context.Context {
408-
return context.WithValue(ctx, authContextKey{}, subjectCryptoKeyRotator)
419+
return As(ctx, subjectCryptoKeyRotator)
409420
}
410421

411422
// AsKeyReader returns a context with an actor that has permissions required for reading crypto keys.
412423
func AsKeyReader(ctx context.Context) context.Context {
413-
return context.WithValue(ctx, authContextKey{}, subjectCryptoKeyReader)
424+
return As(ctx, subjectCryptoKeyReader)
414425
}
415426

416427
// AsNotifier returns a context with an actor that has permissions required for
417428
// creating/reading/updating/deleting notifications.
418429
func AsNotifier(ctx context.Context) context.Context {
419-
return context.WithValue(ctx, authContextKey{}, subjectNotifier)
430+
return As(ctx, subjectNotifier)
420431
}
421432

422433
// AsResourceMonitor returns a context with an actor that has permissions required for
423434
// updating resource monitors.
424435
func AsResourceMonitor(ctx context.Context) context.Context {
425-
return context.WithValue(ctx, authContextKey{}, subjectResourceMonitor)
436+
return As(ctx, subjectResourceMonitor)
426437
}
427438

428439
// AsSystemRestricted returns a context with an actor that has permissions
429440
// required for various system operations (login, logout, metrics cache).
430441
func AsSystemRestricted(ctx context.Context) context.Context {
431-
return context.WithValue(ctx, authContextKey{}, subjectSystemRestricted)
442+
return As(ctx, subjectSystemRestricted)
432443
}
433444

434445
// AsSystemReadProvisionerDaemons returns a context with an actor that has permissions
435446
// to read provisioner daemons.
436447
func AsSystemReadProvisionerDaemons(ctx context.Context) context.Context {
437-
return context.WithValue(ctx, authContextKey{}, subjectSystemReadProvisionerDaemons)
448+
return As(ctx, subjectSystemReadProvisionerDaemons)
438449
}
439450

440451
// AsPrebuildsOrchestrator returns a context with an actor that has permissions
441452
// to read orchestrator workspace prebuilds.
442453
func AsPrebuildsOrchestrator(ctx context.Context) context.Context {
443-
return context.WithValue(ctx, authContextKey{}, subjectPrebuildsOrchestrator)
454+
return As(ctx, subjectPrebuildsOrchestrator)
444455
}
445456

446457
var AsRemoveActor = rbac.Subject{
@@ -458,6 +469,9 @@ func As(ctx context.Context, actor rbac.Subject) context.Context {
458469
// should be removed from the context.
459470
return context.WithValue(ctx, authContextKey{}, nil)
460471
}
472+
if rlogger := loggermw.RequestLoggerFromContext(ctx); rlogger != nil {
473+
rlogger.WithAuthContext(actor)
474+
}
461475
return context.WithValue(ctx, authContextKey{}, actor)
462476
}
463477

‎coderd/database/queries.sql.go‎

Lines changed: 4 additions & 2 deletions
Some generated files are not rendered by default. Learn more about customizing how changed files appear on GitHub.

‎coderd/database/queries/users.sql‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -300,10 +300,10 @@ WHERE
300300
-- This function returns roles for authorization purposes. Implied member roles
301301
-- are included.
302302
SELECT
303-
-- username is returned just to help for logging purposes
303+
-- username and email are returned just to help for logging purposes
304304
-- status is used to enforce 'suspended' users, as all roles are ignored
305305
-- when suspended.
306-
id, username, status,
306+
id, username, status, email,
307307
-- All user roles, including their org roles.
308308
array_cat(
309309
-- All users are members

‎coderd/httpmw/apikey.go‎

Lines changed: 2 additions & 0 deletions
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

Lines changed: 77 additions & 1 deletion
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)