8000 feat: extend request logs with auth & DB info (#17304) · coder/coder@3e61440 · GitHub
[go: up one dir, main page]
Skip to content

Navigation Menu

Sign in
Appearance settings

Search code, repositories, users, issues, pull requests...

Provide feedback

We read every piece of feedback, and take your input very seriously.

Saved searches

Use saved searches to filter your results more quickly
Appearance settings

Commit 3e61440

Browse files
ibetitsmikeibetitsmike
committed
feat: extend request logs with auth & DB info (#17304)
Closes #16903
1 parent 08abd9d commit 3e61440

File tree

18 files changed

+330
-33
lines changed

18 files changed

+330
-33
lines changed

‎Makefile

Lines changed: 4 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -564,7 +564,7 @@ GEN_FILES := \
564564
examples/examples.gen.json \
565565
$(TAILNETTEST_MOCKS) \
566566
coderd/database/pubsub/psmock/psmock.go \
567-
coderd/httpmw/loggermock/loggermock.go
567+
coderd/httpmw/loggermw/loggermock/loggermock.go
568568

569569
# all gen targets should be added here and to gen/mark-fresh
570570
gen: gen/db $(GEN_FILES)
@@ -598,7 +598,7 @@ gen/mark-fresh:
598598
examples/examples.gen.json \
599599
$(TAILNETTEST_MOCKS) \
600600
coderd/database/pubsub/psmock/psmock.go \
601-
coderd/httpmw/loggermock/loggermock.go \
601+
coderd/httpmw/loggermw/loggermock/loggermock.go \
602602
"
603603

604604
for file in $$files; do
@@ -630,9 +630,8 @@ coderd/database/dbmock/dbmock.go: coderd/database/db.go coderd/database/querier.
630630
coderd/database/pubsub/psmock/psmock.go: coderd/database/pubsub/pubsub.go
631631
go generate ./coderd/database/pubsub/psmock
632632

633-
coderd/httpmw/loggermock/loggermock.go: coderd/httpmw/logger.go
634-
go generate ./coderd/httpmw/loggermock/
635-
touch "$@"
633+
coderd/httpmw/loggermw/loggermock/loggermock.go: coderd/httpmw/loggermw/logger.go
634+
go generate ./coderd/httpmw/loggermw/loggermock/
636635

637636
$(TAILNETTEST_MOCKS): tailnet/coordinator.go tailnet/service.go
638637
go generate ./tailnet/tailnettest/

‎coderd/coderd.go

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -63,6 +63,7 @@ import (
6363
"github.com/coder/coder/v2/coderd/healthcheck/derphealth"
6464
"github.com/coder/coder/v2/coderd/httpapi"
6565
"github.com/coder/coder/v2/coderd/httpmw"
66+
"github.com/coder/coder/v2/coderd/httpmw/loggermw"
6667
"github.com/coder/coder/v2/coderd/metricscache"
6768
"github.com/coder/coder/v2/coderd/notifications"
6869
"github.com/coder/coder/v2/coderd/portsharing"
@@ -787,7 +788,7 @@ func New(options *Options) *API {
787788
tracing.Middleware(api.TracerProvider),
788789
httpmw.AttachRequestID,
789790
httpmw.ExtractRealIP(api.RealIPConfig),
790-
httpmw.Logger(api.Logger),
791+
loggermw.Logger(api.Logger),
791792
rolestore.CustomRoleMW,
792793
prometheusMW,
793794
// Build-Version is helpful for debugging.

‎coderd/database/dbauthz/dbauthz.go

Lines changed: 20 additions & 8 deletions
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{
@@ -193,6 +195,7 @@ var (
193195
}.WithCachedASTValue()
194196

195197
subjectAutostart = rbac.Subject{
198+
Type: rbac.SubjectTypeAutostart,
196199
FriendlyName: "Autostart",
197200
ID: uuid.Nil.String(),
198201
Roles: rbac.Roles([]rbac.Role{
@@ -216,6 +219,7 @@ var (
216219

217220
// See unhanger package.
218221
subjectHangDetector = rbac.Subject{
222+
Type: rbac.SubjectTypeHangDetector,
219223
FriendlyName: "Hang Detector",
220224
ID: uuid.Nil.String(),
221225
Roles: rbac.Roles([]rbac.Role{
@@ -236,6 +240,7 @@ var (
236240

237241
// See cryptokeys package.
238242
subjectCryptoKeyRotator = rbac.Subject{
243+
Type: rbac.SubjectTypeCryptoKeyRotator,
239244
FriendlyName: "Crypto Key Rotator",
240245
ID: uuid.Nil.String(),
241246
Roles: rbac.Roles([]rbac.Role{
@@ -254,6 +259,7 @@ var (
254259

255260
// See cryptokeys package.
256261
subjectCryptoKeyReader = rbac.Subject{
262+
Type: rbac.SubjectTypeCryptoKeyReader,
257263
FriendlyName: "Crypto Key Reader",
258264
ID: uuid.Nil.String(),
259265
Roles: rbac.Roles([]rbac.Role{
@@ -271,6 +277,7 @@ var (
271277
}.WithCachedASTValue()
272278

273279
subjectNotifier = rbac.Subject{
280+
Type: rbac.SubjectTypeNotifier,
274281
FriendlyName: "Notifier",
275282
ID: uuid.Nil.String(),
276283
Roles: rbac.Roles([]rbac.Role{
@@ -288,6 +295,7 @@ var (
288295
}.WithCachedASTValue()
289296

290297
subjectSystemRestricted = rbac.Subject{
298+
Type: rbac.SubjectTypeSystemRestricted,
291299
FriendlyName: "System",
292300
ID: uuid.Nil.String(),
293301
Roles: rbac.Roles([]rbac.Role{
@@ -323,6 +331,7 @@ var (
323331
}.WithCachedASTValue()
324332

325333
subjectSystemReadProvisionerDaemons = rbac.Subject{
334+
Type: rbac.SubjectTypeSystemReadProvisionerDaemons,
326335
FriendlyName: "Provisioner Daemons Reader",
327336
ID: uuid.Nil.String(),
328337
Roles: rbac.Roles([]rbac.Role{
@@ -343,47 +352,47 @@ var (
343352
// AsProvisionerd returns a context with an actor that has permissions required
344353
// for provisionerd to function.
345354
func AsProvisionerd(ctx context.Context) context.Context {
346-
return context.WithValue(ctx, authContextKey{}, subjectProvisionerd)
355+
return As(ctx, subjectProvisionerd)
347356
}
348357

349358
// AsAutostart returns a context with an actor that has permissions required
350359
// for autostart to function.
351360
func AsAutostart(ctx context.Context) context.Context {
352-
return context.WithValue(ctx, authContextKey{}, subjectAutostart)
361+
return As(ctx, subjectAutostart)
353362
}
354363

355364
// AsHangDetector returns a context with an actor that has permissions required
356365
// for unhanger.Detector to function.
357366
func AsHangDetector(ctx context.Context) context.Context {
358-
return context.WithValue(ctx, authContextKey{}, subjectHangDetector)
367+
return As(ctx, subjectHangDetector)
359368
}
360369

361370
// AsKeyRotator returns a context with an actor that has permissions required for rotating crypto keys.
362371
func AsKeyRotator(ctx context.Context) context.Context {
363-
return context.WithValue(ctx, authContextKey{}, subjectCryptoKeyRotator)
372+
return As(ctx, subjectCryptoKeyRotator)
364373
}
365374

366375
// AsKeyReader returns a context with an actor that has permissions required for reading crypto keys.
367376
func AsKeyReader(ctx context.Context) context.Context {
368-
return context.WithValue(ctx, authContextKey{}, subjectCryptoKeyReader)
377+
return As(ctx, subjectCryptoKeyReader)
369378
}
370379

371380
// AsNotifier returns a context with an actor that has permissions required for
372381
// creating/reading/updating/deleting notifications.
373382
func AsNotifier(ctx context.Context) context.Context {
374-
return context.WithValue(ctx, authContextKey{}, subjectNotifier)
383+
return As(ctx, subjectNotifier)
375384
}
376385

377386
// AsSystemRestricted returns a context with an actor that has permissions
378387
// required for various system operations (login, logout, metrics cache).
379388
func AsSystemRestricted(ctx context.Context) context.Context {
380-
return context.WithValue(ctx, authContextKey{}, subjectSystemRestricted)
389+
return As(ctx, subjectSystemRestricted)
381390
}
382391

383392
// AsSystemReadProvisionerDaemons returns a context with an actor that has permissions
384393
// to read provisioner daemons.
385394
func AsSystemReadProvisionerDaemons(ctx context.Context) context.Context {
386-
return context.WithValue(ctx, authContextKey{}, subjectSystemReadProvisionerDaemons)
395+
return As(ctx, subjectSystemReadProvisionerDaemons)
387396
}
388397

389398
var AsRemoveActor = rbac.Subject{
@@ -401,6 +410,9 @@ func As(ctx context.Context, actor rbac.Subject) context.Context {
401410
// should be removed from the context.
402411
return context.WithValue(ctx, authContextKey{}, nil)
403412
}
413+
if rlogger := loggermw.RequestLoggerFromContext(ctx); rlogger != nil {
414+
rlogger.WithAuthContext(actor)
415+
}
404416
return context.WithValue(ctx, authContextKey{}, actor)
405417
}
406418

‎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
@@ -244,10 +244,10 @@ WHERE
244244
-- This function returns roles for authorization purposes. Implied member roles
245245
-- are included.
246246
SELECT
247-
-- username is returned just to help for logging purposes
247+
-- username and email are returned just to help for logging purposes
248248
-- status is used to enforce 'suspended' users, as all roles are ignored
249249
-- when suspended.
250-
id, username, status,
250+
id, username, status, email,
251251
-- All user roles, including their org roles.
252252
array_cat(
253253
-- 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)
0