diff --git a/coderd/autobuild/lifecycle_executor.go b/coderd/autobuild/lifecycle_executor.go index 4e0ae5aacf..8095666554 100644 --- a/coderd/autobuild/lifecycle_executor.go +++ b/coderd/autobuild/lifecycle_executor.go @@ -45,7 +45,7 @@ func NewExecutor(ctx context.Context, db database.Store, tss *atomic.Pointer[sch db: db, templateScheduleStore: tss, tick: tick, - log: log, + log: log.Named("autobuild"), } return le } @@ -166,7 +166,7 @@ func (e *Executor) runOnce(t time.Time) Stats { Reason(reason) if _, _, err := builder.Build(e.ctx, tx, nil); err != nil { - log.Error(e.ctx, "unable to transition workspace", + log.Error(e.ctx, "workspace build error", slog.F("transition", nextTransition), slog.Error(err), ) diff --git a/coderd/prometheusmetrics/aggregator.go b/coderd/prometheusmetrics/aggregator.go index b236bac5f6..7704f5cfae 100644 --- a/coderd/prometheusmetrics/aggregator.go +++ b/coderd/prometheusmetrics/aggregator.go @@ -22,6 +22,8 @@ const ( ) const ( + loggerName = "prometheusmetrics" + sizeCollectCh = 10 sizeUpdateCh = 1024 @@ -118,7 +120,7 @@ func NewMetricsAggregator(logger slog.Logger, registerer prometheus.Registerer, } return &MetricsAggregator{ - log: logger, + log: logger.Named(loggerName), metricsCleanupInterval: metricsCleanupInterval, collectCh: make(chan (chan []prometheus.Metric), sizeCollectCh), @@ -141,7 +143,7 @@ func (ma *MetricsAggregator) Run(ctx context.Context) func() { for { select { case req := <-ma.updateCh: - ma.log.Debug(ctx, "metrics aggregator: update metrics") + ma.log.Debug(ctx, "update metrics") timer := prometheus.NewTimer(ma.updateHistogram) UpdateLoop: @@ -167,7 +169,7 @@ func (ma *MetricsAggregator) Run(ctx context.Context) func() { timer.ObserveDuration() case outputCh := <-ma.collectCh: - ma.log.Debug(ctx, "metrics aggregator: collect metrics") + ma.log.Debug(ctx, "collect metrics") output := make([]prometheus.Metric, 0, len(ma.queue)) for _, m := range ma.queue { @@ -181,7 +183,7 @@ func (ma *MetricsAggregator) Run(ctx context.Context) func() { outputCh <- output close(outputCh) case <-cleanupTicker.C: - ma.log.Debug(ctx, "metrics aggregator: clean expired metrics") + ma.log.Debug(ctx, "clean expired metrics") timer := prometheus.NewTimer(ma.cleanupHistogram) @@ -209,7 +211,7 @@ func (ma *MetricsAggregator) Run(ctx context.Context) func() { cleanupTicker.Reset(ma.metricsCleanupInterval) case <-ctx.Done(): - ma.log.Debug(ctx, "metrics aggregator: is stopped") + ma.log.Debug(ctx, "metrics aggregator is stopped") return } } @@ -233,7 +235,7 @@ func (ma *MetricsAggregator) Collect(ch chan<- prometheus.Metric) { select { case ma.collectCh <- output: default: - ma.log.Error(context.Background(), "metrics aggregator: collect queue is full") + ma.log.Error(context.Background(), "collect queue is full") return } @@ -255,9 +257,9 @@ func (ma *MetricsAggregator) Update(ctx context.Context, username, workspaceName timestamp: time.Now(), }: case <-ctx.Done(): - ma.log.Debug(ctx, "metrics aggregator: update request is canceled") + ma.log.Debug(ctx, "update request is canceled") default: - ma.log.Error(ctx, "metrics aggregator: update queue is full") + ma.log.Error(ctx, "update queue is full") } } diff --git a/coderd/provisionerdserver/provisionerdserver.go b/coderd/provisionerdserver/provisionerdserver.go index 6188ba8428..23a1f08463 100644 --- a/coderd/provisionerdserver/provisionerdserver.go +++ b/coderd/provisionerdserver/provisionerdserver.go @@ -506,7 +506,7 @@ func (server *Server) UpdateJob(ctx context.Context, request *proto.UpdateJobReq err = server.Pubsub.Publish(provisionersdk.ProvisionerJobLogsNotifyChannel(parsedID), data) if err != nil { server.Logger.Error(ctx, "failed to publish job logs", slog.F("job_id", parsedID), slog.Error(err)) - return nil, xerrors.Errorf("publish job log: %w", err) + return nil, xerrors.Errorf("publish job logs: %w", err) } server.Logger.Debug(ctx, "published job logs", slog.F("job_id", parsedID)) } diff --git a/coderd/userauth.go b/coderd/userauth.go index 22b4350d01..6eec0ece0e 100644 --- a/coderd/userauth.go +++ b/coderd/userauth.go @@ -30,6 +30,10 @@ import ( "github.com/coder/coder/codersdk" ) +const ( + userAuthLoggerName = "userauth" +) + // Authenticates the user with an email and password. // // @Summary Log in user @@ -59,11 +63,14 @@ func (api *API) postLogin(rw http.ResponseWriter, r *http.Request) { return } + logger := api.Logger.Named(userAuthLoggerName) + //nolint:gocritic // In order to login, we need to get the user first! user, err := api.Database.GetUserByEmailOrUsername(dbauthz.AsSystemRestricted(ctx), database.GetUserByEmailOrUsernameParams{ Email: loginWithPassword.Email, }) if err != nil && !xerrors.Is(err, sql.ErrNoRows) { + logger.Error(ctx, "unable to fetch user by email", slog.Error(err)) httpapi.Write(ctx, rw, http.StatusInternalServerError, codersdk.Response{ Message: "Internal error.", }) @@ -75,6 +82,7 @@ func (api *API) postLogin(rw http.ResponseWriter, r *http.Request) { // If the user doesn't exist, it will be a default struct. equal, err := userpassword.Compare(string(user.HashedPassword), loginWithPassword.Password) if err != nil { + logger.Error(ctx, "unable to compare passwords", slog.Error(err)) httpapi.Write(ctx, rw, http.StatusInternalServerError, codersdk.Response{ Message: "Internal error.", }) @@ -108,6 +116,7 @@ func (api *API) postLogin(rw http.ResponseWriter, r *http.Request) { //nolint:gocritic // System needs to fetch user roles in order to login user. roles, err := api.Database.GetAuthorizationUserRoles(dbauthz.AsSystemRestricted(ctx), user.ID) if err != nil { + logger.Error(ctx, "unable to fetch authorization user roles", slog.Error(err)) httpapi.Write(ctx, rw, http.StatusInternalServerError, codersdk.Response{ Message: "Internal error.", }) @@ -137,6 +146,7 @@ func (api *API) postLogin(rw http.ResponseWriter, r *http.Request) { DeploymentValues: api.DeploymentValues, }) if err != nil { + logger.Error(ctx, "unable to create API key", slog.Error(err)) httpapi.Write(ctx, rw, http.StatusInternalServerError, codersdk.Response{ Message: "Failed to create API key.", Detail: err.Error(), @@ -188,8 +198,11 @@ func (api *API) postLogout(rw http.ResponseWriter, r *http.Request) { apiKey := httpmw.APIKey(r) aReq.Old = apiKey + logger := api.Logger.Named(userAuthLoggerName) + err := api.Database.DeleteAPIKeyByID(ctx, apiKey.ID) if err != nil { + logger.Error(ctx, "unable to delete API key", slog.F("api_key", apiKey.ID), slog.Error(err)) httpapi.Write(ctx, rw, http.StatusInternalServerError, codersdk.Response{ Message: "Internal error deleting API key.", Detail: err.Error(), @@ -203,6 +216,7 @@ func (api *API) postLogout(rw http.ResponseWriter, r *http.Request) { // to access the app again. err = api.Database.DeleteApplicationConnectAPIKeysByUserID(ctx, apiKey.UserID) if err != nil { + logger.Error(ctx, "unable to invalidate subdomain app tokens", slog.F("user_id", apiKey.UserID), slog.Error(err)) httpapi.Write(ctx, rw, http.StatusInternalServerError, codersdk.Response{ Message: "Internal error deleting app tokens.", Detail: err.Error(), @@ -293,11 +307,14 @@ func (api *API) userOAuth2Github(rw http.ResponseWriter, r *http.Request) { oauthClient := oauth2.NewClient(ctx, oauth2.StaticTokenSource(state.Token)) + logger := api.Logger.Named(userAuthLoggerName) + var selectedMemberships []*github.Membership var organizationNames []string if !api.GithubOAuth2Config.AllowEveryone { memberships, err := api.GithubOAuth2Config.ListOrganizationMemberships(ctx, oauthClient) if err != nil { + logger.Error(ctx, "unable to list organization members", slog.Error(err)) httpapi.Write(ctx, rw, http.StatusInternalServerError, codersdk.Response{ Message: "Internal error fetching authenticated Github user organizations.", Detail: err.Error(), @@ -328,6 +345,7 @@ func (api *API) userOAuth2Github(rw http.ResponseWriter, r *http.Request) { ghUser, err := api.GithubOAuth2Config.AuthenticatedUser(ctx, oauthClient) if err != nil { + logger.Error(ctx, "oauth2: unable to fetch authenticated user", slog.Error(err)) httpapi.Write(ctx, rw, http.StatusInternalServerError, codersdk.Response{ Message: "Internal error fetching authenticated Github user.", Detail: err.Error(), @@ -366,6 +384,7 @@ func (api *API) userOAuth2Github(rw http.ResponseWriter, r *http.Request) { emails, err := api.GithubOAuth2Config.ListEmails(ctx, oauthClient) if err != nil { + logger.Error(ctx, "oauth2: unable to list emails", slog.Error(err)) httpapi.Write(ctx, rw, http.StatusInternalServerError, codersdk.Response{ Message: "Internal error fetching personal Github user.", Detail: err.Error(), @@ -390,6 +409,7 @@ func (api *API) userOAuth2Github(rw http.ResponseWriter, r *http.Request) { user, link, err := findLinkedUser(ctx, api.Database, githubLinkedID(ghUser), verifiedEmail.GetEmail()) if err != nil { + logger.Error(ctx, "oauth2: unable to find linked user", slog.F("gh_user", ghUser.Name), slog.Error(err)) httpapi.Write(ctx, rw, http.StatusInternalServerError, codersdk.Response{ Message: "Failed to find linked user.", Detail: err.Error(), @@ -423,6 +443,7 @@ func (api *API) userOAuth2Github(rw http.ResponseWriter, r *http.Request) { return } if err != nil { + logger.Error(ctx, "oauth2: login failed", slog.F("user", user.Username), slog.Error(err)) httpapi.Write(ctx, rw, http.StatusInternalServerError, codersdk.Response{ Message: "Failed to process OAuth login.", Detail: err.Error(), @@ -521,12 +542,15 @@ func (api *API) userOIDC(rw http.ResponseWriter, r *http.Request) { return } + logger := api.Logger.Named(userAuthLoggerName) + // "email_verified" is an optional claim that changes the behavior // of our OIDC handler, so each property must be pulled manually out // of the claim mapping. claims := map[string]interface{}{} err = idToken.Claims(&claims) if err != nil { + logger.Error(ctx, "oauth2: unable to extract OIDC claims", slog.Error(err)) httpapi.Write(ctx, rw, http.StatusInternalServerError, codersdk.Response{ Message: "Failed to extract OIDC claims.", Detail: err.Error(), @@ -534,7 +558,7 @@ func (api *API) userOIDC(rw http.ResponseWriter, r *http.Request) { return } - api.Logger.Debug(ctx, "got oidc claims", + logger.Debug(ctx, "got oidc claims", slog.F("source", "id_token"), slog.F("claim_fields", claimFields(claims)), slog.F("blank", blankFields(claims)), @@ -556,13 +580,14 @@ func (api *API) userOIDC(rw http.ResponseWriter, r *http.Request) { userInfoClaims := map[string]interface{}{} err = userInfo.Claims(&userInfoClaims) if err != nil { + logger.Error(ctx, "oauth2: unable to unmarshal user info claims", slog.Error(err)) httpapi.Write(ctx, rw, http.StatusInternalServerError, codersdk.Response{ Message: "Failed to unmarshal user info claims.", Detail: err.Error(), }) return } - api.Logger.Debug(ctx, "got oidc claims", + logger.Debug(ctx, "got oidc claims", slog.F("source", "userinfo"), slog.F("claim_fields", claimFields(userInfoClaims)), slog.F("blank", blankFields(userInfoClaims)), @@ -573,12 +598,13 @@ func (api *API) userOIDC(rw http.ResponseWriter, r *http.Request) { claims = mergeClaims(claims, userInfoClaims) // Log all of the field names after merging. - api.Logger.Debug(ctx, "got oidc claims", + logger.Debug(ctx, "got oidc claims", slog.F("source", "merged"), slog.F("claim_fields", claimFields(claims)), slog.F("blank", blankFields(claims)), ) } else if !strings.Contains(err.Error(), "user info endpoint is not supported by this provider") { + logger.Error(ctx, "oauth2: unable to obtain user information claims", slog.Error(err)) httpapi.Write(ctx, rw, http.StatusInternalServerError, codersdk.Response{ Message: "Failed to obtain user information claims.", Detail: "The attempt to fetch claims via the UserInfo endpoint failed: " + err.Error(), @@ -588,7 +614,7 @@ func (api *API) userOIDC(rw http.ResponseWriter, r *http.Request) { // The OIDC provider does not support the UserInfo endpoint. // This is not an error, but we should log it as it may mean // that some claims are missing. - api.Logger.Warn(ctx, "OIDC provider does not support the user info endpoint, ensure that all required claims are present in the id_token") + logger.Warn(ctx, "OIDC provider does not support the user info endpoint, ensure that all required claims are present in the id_token") } } @@ -632,7 +658,7 @@ func (api *API) userOIDC(rw http.ResponseWriter, r *http.Request) { }) return } - api.Logger.Warn(ctx, "allowing unverified oidc email %q") + logger.Warn(ctx, "allowing unverified oidc email %q") } } @@ -647,7 +673,7 @@ func (api *API) userOIDC(rw http.ResponseWriter, r *http.Request) { // Convert the []interface{} we get to a []string. groupsInterface, ok := groupsRaw.([]interface{}) if ok { - api.Logger.Debug(ctx, "groups returned in oidc claims", + logger.Debug(ctx, "groups returned in oidc claims", slog.F("len", len(groupsInterface)), slog.F("groups", groupsInterface), ) @@ -668,7 +694,7 @@ func (api *API) userOIDC(rw http.ResponseWriter, r *http.Request) { groups = append(groups, group) } } else { - api.Logger.Debug(ctx, "groups field was an unknown type", + logger.Debug(ctx, "groups field was an unknown type", slog.F("type", fmt.Sprintf("%T", groupsRaw)), ) } @@ -678,7 +704,7 @@ func (api *API) userOIDC(rw http.ResponseWriter, r *http.Request) { // This conditional is purely to warn the user they might have misconfigured their OIDC // configuration. if _, groupClaimExists := claims["groups"]; !usingGroups && groupClaimExists { - api.Logger.Debug(ctx, "claim 'groups' was returned, but 'oidc-group-field' is not set, check your coder oidc settings") + logger.Debug(ctx, "claim 'groups' was returned, but 'oidc-group-field' is not set, check your coder oidc settings") } // The username is a required property in Coder. We make a best-effort @@ -719,6 +745,7 @@ func (api *API) userOIDC(rw http.ResponseWriter, r *http.Request) { user, link, err := findLinkedUser(ctx, api.Database, oidcLinkedID(idToken), email) if err != nil { + logger.Error(ctx, "oauth2: unable to find linked user", slog.F("email", email), slog.Error(err)) httpapi.Write(ctx, rw, http.StatusInternalServerError, codersdk.Response{ Message: "Failed to find linked user.", Detail: err.Error(), @@ -754,6 +781,7 @@ func (api *API) userOIDC(rw http.ResponseWriter, r *http.Request) { return } if err != nil { + logger.Error(ctx, "oauth2: login failed", slog.F("user", user.Username), slog.Error(err)) httpapi.Write(ctx, rw, http.StatusInternalServerError, codersdk.Response{ Message: "Failed to process OAuth login.", Detail: err.Error(), diff --git a/coderd/userauth_test.go b/coderd/userauth_test.go index 4af69271cf..e8b6f08a97 100644 --- a/coderd/userauth_test.go +++ b/coderd/userauth_test.go @@ -18,6 +18,8 @@ import ( "golang.org/x/oauth2" "golang.org/x/xerrors" + "cdr.dev/slog/sloggers/slogtest" + "github.com/coder/coder/coderd" "github.com/coder/coder/coderd/audit" "github.com/coder/coder/coderd/coderdtest" @@ -747,9 +749,11 @@ func TestUserOIDC(t *testing.T) { config.IgnoreEmailVerified = tc.IgnoreEmailVerified config.IgnoreUserInfo = tc.IgnoreUserInfo + logger := slogtest.Make(t, &slogtest.Options{IgnoreErrors: true}) client := coderdtest.New(t, &coderdtest.Options{ Auditor: auditor, OIDCConfig: config, + Logger: &logger, }) numLogs := len(auditor.AuditLogs()) diff --git a/coderd/workspacebuilds.go b/coderd/workspacebuilds.go index 856aae4bed..32956ed794 100644 --- a/coderd/workspacebuilds.go +++ b/coderd/workspacebuilds.go @@ -14,6 +14,8 @@ import ( "golang.org/x/exp/slices" "golang.org/x/xerrors" + "cdr.dev/slog" + "github.com/coder/coder/coderd/database" "github.com/coder/coder/coderd/database/db2sdk" "github.com/coder/coder/coderd/database/dbauthz" @@ -348,6 +350,10 @@ func (api *API) postWorkspaceBuilds(rw http.ResponseWriter, r *http.Request) { ) var buildErr wsbuilder.BuildError if xerrors.As(err, &buildErr) { + if buildErr.Status == http.StatusInternalServerError { + api.Logger.Error(ctx, "workspace build error", slog.Error(buildErr.Wrapped)) + } + httpapi.Write(ctx, rw, buildErr.Status, codersdk.Response{ Message: buildErr.Message, Detail: buildErr.Error(), diff --git a/coderd/workspaces.go b/coderd/workspaces.go index 9f499394f7..447c8403e2 100644 --- a/coderd/workspaces.go +++ b/coderd/workspaces.go @@ -454,6 +454,10 @@ func (api *API) postWorkspacesByOrganization(rw http.ResponseWriter, r *http.Req }, nil) var bldErr wsbuilder.BuildError if xerrors.As(err, &bldErr) { + if bldErr.Status == http.StatusInternalServerError { + api.Logger.Error(ctx, "workspace build error", slog.Error(bldErr.Wrapped)) + } + httpapi.Write(ctx, rw, bldErr.Status, codersdk.Response{ Message: bldErr.Message, Detail: bldErr.Error(),