Skip to content

feat: extend request logs with auth & DB info #17497

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 1 commit into from
Apr 22, 2025
Merged

feat: extend request logs with auth & DB info #17497

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
8 changes: 4 additions & 4 deletions Makefile
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -582,7 +582,7 @@ GEN_FILES := \
coderd/database/pubsub/psmock/psmock.go \
agent/agentcontainers/acmock/acmock.go \
agent/agentcontainers/dcspec/dcspec_gen.go \
coderd/httpmw/loggermock/loggermock.go
coderd/httpmw/loggermw/loggermock/loggermock.go

# all gen targets should be added here and to gen/mark-fresh
gen: gen/db gen/golden-files $(GEN_FILES)
Expand Down Expand Up @@ -631,7 +631,7 @@ gen/mark-fresh:
coderd/database/pubsub/psmock/psmock.go \
agent/agentcontainers/acmock/acmock.go \
agent/agentcontainers/dcspec/dcspec_gen.go \
coderd/httpmw/loggermock/loggermock.go \
coderd/httpmw/loggermw/loggermock/loggermock.go \
"

for file in $$files; do
Expand Down Expand Up @@ -671,8 +671,8 @@ agent/agentcontainers/acmock/acmock.go: agent/agentcontainers/containers.go
go generate ./agent/agentcontainers/acmock/
touch "$@"

coderd/httpmw/loggermock/loggermock.go: coderd/httpmw/logger.go
go generate ./coderd/httpmw/loggermock/
coderd/httpmw/loggermw/loggermock/loggermock.go: coderd/httpmw/loggermw/logger.go
go generate ./coderd/httpmw/loggermw/loggermock/
touch "$@"

agent/agentcontainers/dcspec/dcspec_gen.go: \
Expand Down
3 changes: 2 additions & 1 deletion coderd/coderd.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -64,6 +64,7 @@ import (
"github.com/coder/coder/v2/coderd/healthcheck/derphealth"
"github.com/coder/coder/v2/coderd/httpapi"
"github.com/coder/coder/v2/coderd/httpmw"
"github.com/coder/coder/v2/coderd/httpmw/loggermw"
"github.com/coder/coder/v2/coderd/metricscache"
"github.com/coder/coder/v2/coderd/notifications"
"github.com/coder/coder/v2/coderd/portsharing"
Expand Down Expand Up @@ -801,7 +802,7 @@ func New(options *Options) *API {
tracing.Middleware(api.TracerProvider),
httpmw.AttachRequestID,
httpmw.ExtractRealIP(api.RealIPConfig),
httpmw.Logger(api.Logger),
loggermw.Logger(api.Logger),
singleSlashMW,
rolestore.CustomRoleMW,
prometheusMW,
Expand Down
31 changes: 22 additions & 9 deletions coderd/database/dbauthz/dbauthz.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -24,6 +24,7 @@ import (
"github.com/coder/coder/v2/coderd/database"
"github.com/coder/coder/v2/coderd/database/dbtime"
"github.com/coder/coder/v2/coderd/httpapi/httpapiconstraints"
"github.com/coder/coder/v2/coderd/httpmw/loggermw"
"github.com/coder/coder/v2/coderd/rbac"
"github.com/coder/coder/v2/coderd/util/slice"
"github.com/coder/coder/v2/provisionersdk"
Expand Down Expand Up @@ -162,6 +163,7 @@ func ActorFromContext(ctx context.Context) (rbac.Subject, bool) {

var (
subjectProvisionerd = rbac.Subject{
Type: rbac.SubjectTypeProvisionerd,
FriendlyName: "Provisioner Daemon",
ID: uuid.Nil.String(),
Roles: rbac.Roles([]rbac.Role{
Expand Down Expand Up @@ -196,6 +198,7 @@ var (
}.WithCachedASTValue()

subjectAutostart = rbac.Subject{
Type: rbac.SubjectTypeAutostart,
FriendlyName: "Autostart",
ID: uuid.Nil.String(),
Roles: rbac.Roles([]rbac.Role{
Expand All @@ -219,6 +222,7 @@ var (

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

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

// See cryptokeys package.
subjectCryptoKeyReader = rbac.Subject{
Type: rbac.SubjectTypeCryptoKeyReader,
FriendlyName: "Crypto Key Reader",
ID: uuid.Nil.String(),
Roles: rbac.Roles([]rbac.Role{
Expand All @@ -274,6 +280,7 @@ var (
}.WithCachedASTValue()

subjectNotifier = rbac.Subject{
Type: rbac.SubjectTypeNotifier,
FriendlyName: "Notifier",
ID: uuid.Nil.String(),
Roles: rbac.Roles([]rbac.Role{
Expand All @@ -294,6 +301,7 @@ var (
}.WithCachedASTValue()

subjectResourceMonitor = rbac.Subject{
Type: rbac.SubjectTypeResourceMonitor,
FriendlyName: "Resource Monitor",
ID: uuid.Nil.String(),
Roles: rbac.Roles([]rbac.Role{
Expand All @@ -312,6 +320,7 @@ var (
}.WithCachedASTValue()

subjectSystemRestricted = rbac.Subject{
Type: rbac.SubjectTypeSystemRestricted,
FriendlyName: "System",
ID: uuid.Nil.String(),
Roles: rbac.Roles([]rbac.Role{
Expand Down Expand Up @@ -346,6 +355,7 @@ var (
}.WithCachedASTValue()

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

// AsAutostart returns a context with an actor that has permissions required
// for autostart to function.
func AsAutostart(ctx context.Context) context.Context {
return context.WithValue(ctx, authContextKey{}, subjectAutostart)
return As(ctx, subjectAutostart)
}

// AsHangDetector returns a context with an actor that has permissions required
// for unhanger.Detector to function.
func AsHangDetector(ctx context.Context) context.Context {
return context.WithValue(ctx, authContextKey{}, subjectHangDetector)
return As(ctx, subjectHangDetector)
}

// AsKeyRotator returns a context with an actor that has permissions required for rotating crypto keys.
func AsKeyRotator(ctx context.Context) context.Context {
return context.WithValue(ctx, authContextKey{}, subjectCryptoKeyRotator)
return As(ctx, subjectCryptoKeyRotator)
}

// AsKeyReader returns a context with an actor that has permissions required for reading crypto keys.
func AsKeyReader(ctx context.Context) context.Context {
return context.WithValue(ctx, authContextKey{}, subjectCryptoKeyReader)
return As(ctx, subjectCryptoKeyReader)
}

// AsNotifier returns a context with an actor that has permissions required for
// creating/reading/updating/deleting notifications.
func AsNotifier(ctx context.Context) context.Context {
return context.WithValue(ctx, authContextKey{}, subjectNotifier)
return As(ctx, subjectNotifier)
}

// AsResourceMonitor returns a context with an actor that has permissions required for
// updating resource monitors.
func AsResourceMonitor(ctx context.Context) context.Context {
return context.WithValue(ctx, authContextKey{}, subjectResourceMonitor)
return As(ctx, subjectResourceMonitor)
}

// AsSystemRestricted returns a context with an actor that has permissions
// required for various system operations (login, logout, metrics cache).
func AsSystemRestricted(ctx context.Context) context.Context {
return context.WithValue(ctx, authContextKey{}, subjectSystemRestricted)
return As(ctx, subjectSystemRestricted)
}

// AsSystemReadProvisionerDaemons returns a context with an actor that has permissions
// to read provisioner daemons.
func AsSystemReadProvisionerDaemons(ctx context.Context) context.Context {
return context.WithValue(ctx, authContextKey{}, subjectSystemReadProvisionerDaemons)
return As(ctx, subjectSystemReadProvisionerDaemons)
}

var AsRemoveActor = rbac.Subject{
Expand All @@ -430,6 +440,9 @@ func As(ctx context.Context, actor rbac.Subject) context.Context {
// should be removed from the context.
return context.WithValue(ctx, authContextKey{}, nil)
}
if rlogger := loggermw.RequestLoggerFromContext(ctx); rlogger != nil {
rlogger.WithAuthContext(actor)
}
return context.WithValue(ctx, authContextKey{}, actor)
}

Expand Down
6 changes: 4 additions & 2 deletions coderd/database/queries.sql.go
View file
Open in desktop

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

4 changes: 2 additions & 2 deletions coderd/database/queries/users.sql
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -271,10 +271,10 @@ WHERE
-- This function returns roles for authorization purposes. Implied member roles
-- are included.
SELECT
-- username is returned just to help for logging purposes
-- username and email are returned just to help for logging purposes
-- status is used to enforce 'suspended' users, as all roles are ignored
-- when suspended.
id, username, status,
id, username, status, email,
-- All user roles, including their org roles.
array_cat(
-- All users are members
Expand Down
2 changes: 2 additions & 0 deletions coderd/httpmw/apikey.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -465,7 +465,9 @@ func UserRBACSubject(ctx context.Context, db database.Store, userID uuid.UUID, s
}

actor := rbac.Subject{
Type: rbac.SubjectTypeUser,
FriendlyName: roles.Username,
Email: roles.Email,
ID: userID.String(),
Roles: rbacRoles,
Groups: roles.Groups,
Expand Down
78 changes: 77 additions & 1 deletion coderd/httpmw/logger.go → coderd/httpmw/loggermw/logger.go
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,13 +1,17 @@
package httpmw
package loggermw

import (
"context"
"fmt"
"net/http"
"sync"
"time"

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

"cdr.dev/slog"
"github.com/coder/coder/v2/coderd/httpapi"
"github.com/coder/coder/v2/coderd/rbac"
"github.com/coder/coder/v2/coderd/tracing"
)

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

type SlogRequestLogger struct {
log slog.Logger
written bool
message string
start time.Time
// Protects actors map for concurrent writes.
mu sync.RWMutex
actors map[rbac.SubjectType]rbac.Subject
}

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

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

func (c *SlogRequestLogger) WithAuthContext(actor rbac.Subject) {
c.mu.Lock()
defer c.mu.Unlock()
c.actors[actor.Type] = actor
}

func (c *SlogRequestLogger) addAuthContextFields() {
c.mu.RLock()
defer c.mu.RUnlock()

usr, ok := c.actors[rbac.SubjectTypeUser]
if ok {
c.log = c.log.With(
slog.F("requestor_id", usr.ID),
slog.F("requestor_name", usr.FriendlyName),
slog.F("requestor_email", usr.Email),
)
} else {
// If there is no user, we log the requestor name for the first
// actor in a defined order.
for _, v := range actorLogOrder {
subj, ok := c.actors[v]
if !ok {
continue
}
c.log = c.log.With(
slog.F("requestor_name", subj.FriendlyName),
)
break
}
}
}

var actorLogOrder = []rbac.SubjectType{
rbac.SubjectTypeAutostart,
rbac.SubjectTypeCryptoKeyReader,
rbac.SubjectTypeCryptoKeyRotator,
rbac.SubjectTypeHangDetector,
rbac.SubjectTypeNotifier,
rbac.SubjectTypePrebuildsOrchestrator,
rbac.SubjectTypeProvisionerd,
rbac.SubjectTypeResourceMonitor,
rbac.SubjectTypeSystemReadProvisionerDaemons,
rbac.SubjectTypeSystemRestricted,
}

func (c *SlogRequestLogger) WriteLog(ctx context.Context, status int) {
if c.written {
return
}
c.written = true
end := time.Now()

// Right before we write the log, we try to find the user in the actors
// and add the fields to the log.
c.addAuthContextFields()

logger := c.log.With(
slog.F("took", end.Sub(c.start)),
slog.F("status_code", status),
slog.F("latency_ms", float64(end.Sub(c.start)/time.Millisecond)),
)

// If the request is routed, add the route parameters to the log.
if chiCtx := chi.RouteContext(ctx); chiCtx != nil {
urlParams := chiCtx.URLParams
routeParamsFields := make([]slog.Field, 0, len(urlParams.Keys))

for k, v := range urlParams.Keys {
if urlParams.Values[k] != "" {
routeParamsFields = append(routeParamsFields, slog.F("params_"+v, urlParams.Values[k]))
}
}

if len(routeParamsFields) > 0 {
logger = logger.With(routeParamsFields...)
}
}

// We already capture most of this information in the span (minus
// the response body which we don't want to capture anyways).
tracing.RunWithoutSpan(ctx, func(ctx context.Context) {
Expand Down
Loading
Loading