fix: improve structured logging (ory#1935)

Closes ory#1683

consent/strategy_default.go

@@ -636,7 +636,7 @@ func (s *DefaultStrategy) generateFrontChannelLogoutURLs(ctx context.Context, su
 	return urls, nil
 }
 
-func (s *DefaultStrategy) executeBackChannelLogout(ctx context.Context, subject, sid string) error {
+func (s *DefaultStrategy) executeBackChannelLogout(ctx context.Context, r *http.Request, subject, sid string) error {
 	clients, err := s.r.ConsentManager().ListUserAuthenticatedClientsWithBackChannelLogout(ctx, subject, sid)
 	if err != nil {
 		return err
@@ -691,19 +691,20 @@ func (s *DefaultStrategy) executeBackChannelLogout(ctx context.Context, subject,
 
 		res, err := hc.PostForm(t.url, url.Values{"logout_token": {t.token}})
 		if err != nil {
-			s.r.Logger().WithError(err).
+			s.r.Logger().WithRequest(r).WithError(err).
 				WithField("client_id", t.clientID).
 				WithField("backchannel_logout_url", t.url).
-				Warnf("Unable to execute OpenID Connect Back-Channel Logout Request")
+				Error("Unable to execute OpenID Connect Back-Channel Logout Request")
 			return
 		}
 		defer res.Body.Close()
 
 		if res.StatusCode != http.StatusOK {
 			s.r.Logger().WithError(errors.Errorf("expected HTTP status code %d but got %d", http.StatusOK, res.StatusCode)).
+				WithRequest(r).
 				WithField("client_id", t.clientID).
 				WithField("backchannel_logout_url", t.url).
-				Warnf("Unable to execute OpenID Connect Back-Channel Logout Request")
+				Error("Unable to execute OpenID Connect Back-Channel Logout Request")
 			return
 		}
 	}
@@ -937,7 +938,7 @@ func (s *DefaultStrategy) completeLogout(w http.ResponseWriter, r *http.Request)
 		return nil, err
 	}
 
-	if err := s.executeBackChannelLogout(r.Context(), lr.Subject, lr.SessionID); err != nil {
+	if err := s.executeBackChannelLogout(r.Context(), r, lr.Subject, lr.SessionID); err != nil {
 		return nil, err
 	}
 

driver/registry_base.go

@@ -131,7 +131,7 @@ func (m *RegistryBase) WithConfig(c configuration.Provider) Registry {
 
 func (m *RegistryBase) Writer() herodot.Writer {
 	if m.writer == nil {
-		h := herodot.NewJSONWriter(m.Logger().Logger)
+		h := herodot.NewJSONWriter(m.Logger())
 		h.ErrorEnhancer = serverx.ErrorEnhancerRFC6749
 		m.writer = h
 	}

go.mod

@@ -37,9 +37,9 @@ require (
 	github.com/ory/fosite v0.32.2
 	github.com/ory/go-acc v0.2.2
 	github.com/ory/graceful v0.1.1
-	github.com/ory/herodot v0.8.3
+	github.com/ory/herodot v0.9.1
 	github.com/ory/viper v1.7.5
-	github.com/ory/x v0.0.132
+	github.com/ory/x v0.0.136
 	github.com/pborman/uuid v1.2.0
 	github.com/phayes/freeport v0.0.0-20171002181615-b8543db493a5
 	github.com/pkg/errors v0.9.1

go.sum

@@ -896,6 +896,8 @@ github.com/ory/herodot v0.7.0 h1:DGPUyPDBZwQSaQzci4UW/edjG6OWixZTwXyfjBgEVgs=
 github.com/ory/herodot v0.7.0/go.mod h1:YXKOfAXYdQojDP5sD8m0ajowq3+QXNdtxA+QiUXBwn0=
 github.com/ory/herodot v0.8.3 h1:lNsrWg0qrsf7vYEDBjKJ8DlCypw87rkjqukp22xnl14=
 github.com/ory/herodot v0.8.3/go.mod h1:rvLjxOAlU5omtmgjCfazQX2N82EpMfl3BytBWc1jjsk=
+github.com/ory/herodot v0.9.1 h1:GkyXUfAN4oyW6jTE4FgJkpPTBr1FTN0zx/cet6IsJMI=
+github.com/ory/herodot v0.9.1/go.mod h1:GYF7mp8/WFRYDYJBR989lipjgx3NTjjdVdUC+hpB8mc=
 github.com/ory/jsonschema/v3 v3.0.1 h1:xzV7w2rt/Qn+jvh71joIXNKKOCqqNyTlaIxdxU0IQJc=
 github.com/ory/jsonschema/v3 v3.0.1/go.mod h1:jgLHekkFk0uiGdEWGleC+tOm6JSSP8cbf17PnBuGXlw=
 github.com/ory/viper v1.5.6/go.mod h1:TYmpFpKLxjQwvT4f0QPpkOn4sDXU1kDgAwJpgLYiQ28=
@@ -907,10 +909,11 @@ github.com/ory/x v0.0.84/go.mod h1:RXLPBG7B+hAViONVg0sHwK+U/ie1Y/NeXrq1JcARfoE=
 github.com/ory/x v0.0.85/go.mod h1:s44V8t3xyjWZREcU+mWlp4h302rTuM4aLXcW+y5FbQ8=
 github.com/ory/x v0.0.93/go.mod h1:lfcTaGXpTZs7IEQAW00r9EtTCOxD//SiP5uWtNiz31g=
 github.com/ory/x v0.0.110/go.mod h1:DJfkE3GdakhshNhw4zlKoRaL/ozg/lcTahA9OCih2BE=
+github.com/ory/x v0.0.127/go.mod h1:FwUujfFuCj5d+xgLn4fGMYPnzriR5bdAIulFXMtnK0M=
 github.com/ory/x v0.0.128 h1:sArBGCH5s+0Zv0jD+t639Vy22URAD6XskBnD9r0+ESk=
 github.com/ory/x v0.0.128/go.mod h1:ykx1XOsl9taQtoW2yNvuxl/feEfTfrZTcbY1U7841tI=
-github.com/ory/x v0.0.132 h1:5UNshjgbu0NJhnGq6NstC4+Ds3b4JQv4MdnDj9WU1+s=
-github.com/ory/x v0.0.132/go.mod h1:BMzD4kJYW5/GHoBJndjO0lFy7igXz81UfpXzBQplscQ=
+github.com/ory/x v0.0.136 h1:cDXTSIRLAuya2oqm4VtieHoSg9sTc6cYzfvtrYdVW3Q=
+github.com/ory/x v0.0.136/go.mod h1:BMzD4kJYW5/GHoBJndjO0lFy7igXz81UfpXzBQplscQ=
 github.com/parnurzeal/gorequest v0.2.15/go.mod h1:3Kh2QUMJoqw3icWAecsyzkpY7UzRfDhbRdTjtNwNiUE=
 github.com/pascaldekloe/goe v0.0.0-20180627143212-57f6aae5913c/go.mod h1:lzWF7FIEvWOWxwDKqyGYQf6ZUaNfKdP144TG7ZOy1lc=
 github.com/pborman/uuid v1.2.0 h1:J7Q5mO4ysT1dv8hyrUGHb9+ooztCXu1D8MY8DZYsu3g=

oauth2/handler_fallback_endpoints.go

@@ -76,7 +76,7 @@ func (h *Handler) fallbackHandler(title, heading string, sc int, configKey strin
 }
 
 func (h *Handler) DefaultErrorHandler(w http.ResponseWriter, r *http.Request, _ httprouter.Params) {
-	h.r.Logger().Warnln("A client requested the default error URL, environment variable OAUTH2_ERROR_URL is probably not set.")
+	h.r.Logger().WithRequest(r).Error("A client requested the default error URL, environment variable OAUTH2_ERROR_URL is probably not set.")
 
 	t, err := template.New("consent").Parse(`
 <html>

x/tls_termination.go

@@ -57,25 +57,25 @@ func RejectInsecureRequests(reg tlsRegistry, c tlsConfig) negroni.HandlerFunc {
 		}
 
 		if len(c.AllowTLSTerminationFrom()) == 0 {
-			reg.Logger().WithError(errors.New("TLS termination is not enabled")).Warnln("Could not serve http connection")
+			reg.Logger().WithRequest(r).WithError(errors.New("TLS termination is not enabled")).Error("Could not serve http connection")
 			reg.Writer().WriteErrorCode(rw, r, http.StatusBadGateway, errors.New("can not serve request over insecure http"))
 			return
 		}
 
 		ranges := c.AllowTLSTerminationFrom()
 		if err := MatchesRange(r, ranges); err != nil {
-			reg.Logger().WithError(err).Warnln("Could not serve http connection")
+			reg.Logger().WithRequest(r).WithError(err).Warnln("Could not serve http connection")
 			reg.Writer().WriteErrorCode(rw, r, http.StatusBadGateway, errors.New("can not serve request over insecure http"))
 			return
 		}
 
 		proto := r.Header.Get("X-Forwarded-Proto")
 		if proto == "" {
-			reg.Logger().WithError(errors.New("X-Forwarded-Proto header is missing")).Warnln("Could not serve http connection")
+			reg.Logger().WithRequest(r).WithError(errors.New("X-Forwarded-Proto header is missing")).Error("Could not serve http connection")
 			reg.Writer().WriteErrorCode(rw, r, http.StatusBadGateway, errors.New("can not serve request over insecure http"))
 			return
 		} else if proto != "https" {
-			reg.Logger().WithError(errors.New("X-Forwarded-Proto header is missing")).Warnln("Could not serve http connection")
+			reg.Logger().WithRequest(r).WithError(errors.New("X-Forwarded-Proto header is missing")).Error("Could not serve http connection")
 			reg.Writer().WriteErrorCode(rw, r, http.StatusBadGateway, errors.Errorf("expected X-Forwarded-Proto header to be https but got: %s", proto))
 			return
 		}