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

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< 17AE /td>

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
6851
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