diff --git a/example/server/exampleop/op.go b/example/server/exampleop/op.go index 8c1b56f..6334ebf 100644 --- a/example/server/exampleop/op.go +++ b/example/server/exampleop/op.go @@ -4,13 +4,15 @@ import ( "crypto/sha256" "log" "net/http" - "os" + "strconv" + "sync/atomic" "time" "github.com/go-chi/chi" "golang.org/x/exp/slog" "golang.org/x/text/language" + "github.com/zitadel/logging" "github.com/zitadel/oidc/v3/example/server/storage" "github.com/zitadel/oidc/v3/pkg/op" ) @@ -33,15 +35,25 @@ type Storage interface { deviceAuthenticate } +// simple request id counter +var requestID atomic.Uint64 + // SetupServer creates an OIDC server with Issuer=http://localhost: // // Use one of the pre-made clients in storage/clients.go or register a new one. -func SetupServer(issuer string, storage Storage) chi.Router { +func SetupServer(issuer string, storage Storage, logger *slog.Logger) chi.Router { // the OpenID Provider requires a 32-byte key for (token) encryption // be sure to create a proper crypto random key and manage it securely! key := sha256.Sum256([]byte("test")) router := chi.NewRouter() + // Enable request logging on INFO level + router.Use(logging.Middleware( + logging.MiddlewareWithLoggerOption(logger), + logging.MiddlewareWithIDOption(func() string { + return strconv.FormatUint(requestID.Add(1), 10) + }), + )) // for simplicity, we provide a very small default page for users who have signed out router.HandleFunc(pathLoggedOut, func(w http.ResponseWriter, req *http.Request) { @@ -50,7 +62,7 @@ func SetupServer(issuer string, storage Storage) chi.Router { }) // creation of the OpenIDProvider with the just created in-memory Storage - provider, err := newOP(storage, issuer, key) + provider, err := newOP(storage, issuer, key, logger) if err != nil { log.Fatal(err) } @@ -80,7 +92,7 @@ func SetupServer(issuer string, storage Storage) chi.Router { // newOP will create an OpenID Provider for localhost on a specified port with a given encryption key // and a predefined default logout uri // it will enable all options (see descriptions) -func newOP(storage op.Storage, issuer string, key [32]byte) (op.OpenIDProvider, error) { +func newOP(storage op.Storage, issuer string, key [32]byte, logger *slog.Logger) (op.OpenIDProvider, error) { config := &op.Config{ CryptoKey: key, @@ -117,12 +129,8 @@ func newOP(storage op.Storage, issuer string, key [32]byte) (op.OpenIDProvider, op.WithAllowInsecure(), // as an example on how to customize an endpoint this will change the authorization_endpoint from /authorize to /auth op.WithCustomAuthEndpoint(op.NewEndpoint("auth")), - op.WithLogger(slog.New( - slog.NewTextHandler(os.Stderr, &slog.HandlerOptions{ - AddSource: true, - Level: slog.LevelDebug, - }), - )), + // Pass our logger to the OP + op.WithLogger(logger.WithGroup("op")), ) if err != nil { return nil, err diff --git a/example/server/main.go b/example/server/main.go index ee27bba..c7711f3 100644 --- a/example/server/main.go +++ b/example/server/main.go @@ -4,9 +4,12 @@ import ( "fmt" "log" "net/http" + "os" + "github.com/zitadel/logging" "github.com/zitadel/oidc/v3/example/server/exampleop" "github.com/zitadel/oidc/v3/example/server/storage" + "golang.org/x/exp/slog" ) func main() { @@ -20,14 +23,24 @@ func main() { // in this example it will be handled in-memory storage := storage.NewStorage(storage.NewUserStore(issuer)) - router := exampleop.SetupServer(issuer, storage) + // Using our wrapped logging handler, + // data set to the context gets printed + // as part of the log output. + // This helps us tie log output to requests. + logger := slog.New(logging.WrapHandler( + slog.NewTextHandler(os.Stderr, &slog.HandlerOptions{ + AddSource: true, + Level: slog.LevelDebug, + }), + logging.HandlerWithCTXGroupName("ctx"), + )) + router := exampleop.SetupServer(issuer, storage, logger) server := &http.Server{ Addr: ":" + port, Handler: router, } - log.Printf("server listening on http://localhost:%s/", port) - log.Println("press ctrl+c to stop") + logger.Info("server listening, press ctrl+c to stop", "addr", fmt.Sprintf("http://localhost:%s/", port)) err := server.ListenAndServe() if err != nil { log.Fatal(err) diff --git a/go.mod b/go.mod index c2f95de..c4f1d87 100644 --- a/go.mod +++ b/go.mod @@ -11,9 +11,9 @@ require ( github.com/jeremija/gosubmit v0.2.7 github.com/muhlemmer/gu v0.3.1 github.com/rs/cors v1.9.0 - github.com/rs/xid v1.5.0 - github.com/sirupsen/logrus v1.9.0 + github.com/sirupsen/logrus v1.9.3 github.com/stretchr/testify v1.8.2 + github.com/zitadel/logging v0.3.5-0.20230824152050-9b8a8a0bdf73 github.com/zitadel/schema v1.3.0 golang.org/x/exp v0.0.0-20230817173708-d852ddb80c63 golang.org/x/oauth2 v0.7.0 @@ -22,6 +22,7 @@ require ( ) require ( + github.com/benbjohnson/clock v1.3.5 // indirect github.com/davecgh/go-spew v1.1.1 // indirect github.com/golang/protobuf v1.5.3 // indirect github.com/google/go-cmp v0.5.9 // indirect diff --git a/go.sum b/go.sum index 573fdc0..9188041 100644 --- a/go.sum +++ b/go.sum @@ -1,3 +1,5 @@ +github.com/benbjohnson/clock v1.3.5 h1:VvXlSJBzZpA/zum6Sj74hxwYI2DIxRWuNIoXAzHZz5o= +github.com/benbjohnson/clock v1.3.5/go.mod h1:J11/hYXuz8f4ySSvYwY0FKfm+ezbsZBKZxNJlLklBHA= github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c= github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= @@ -36,10 +38,8 @@ github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZb github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= github.com/rs/cors v1.9.0 h1:l9HGsTsHJcvW14Nk7J9KFz8bzeAWXn3CG6bgt7LsrAE= github.com/rs/cors v1.9.0/go.mod h1:XyqrcTp5zjWr1wsJ8PIRZssZ8b/WMcMf71DJnit4EMU= -github.com/rs/xid v1.5.0 h1:mKX4bl4iPYJtEIxp6CYiUuLQ/8DYMoz0PUdtGgMFRVc= -github.com/rs/xid v1.5.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg= -github.com/sirupsen/logrus v1.9.0 h1:trlNQbNUG3OdDrDil03MCb1H2o9nJ1x4/5LYw7byDE0= -github.com/sirupsen/logrus v1.9.0/go.mod h1:naHLuLoDiP4jHNo9R0sCBMtWGeIprob74mVsIT4qYEQ= +github.com/sirupsen/logrus v1.9.3 h1:dueUQJ1C2q9oE3F7wvmSGAaVtTmUizReu6fjN8uqzbQ= +github.com/sirupsen/logrus v1.9.3/go.mod h1:naHLuLoDiP4jHNo9R0sCBMtWGeIprob74mVsIT4qYEQ= github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= github.com/stretchr/objx v0.4.0/go.mod h1:YvHI0jy2hoMjB+UWwv71VJQ9isScKT/TqJzVSSt89Yw= github.com/stretchr/objx v0.5.0/go.mod h1:Yh+to48EsGEfYuaHDzXPcE3xhTkx73EhmCGUpEOglKo= @@ -49,6 +49,8 @@ github.com/stretchr/testify v1.8.0/go.mod h1:yNjHg4UonilssWZ8iaSj1OCr/vHnekPRkoO github.com/stretchr/testify v1.8.2 h1:+h33VjcLVPDHtOdpUCuF+7gSuG3yGIftsP1YvFihtJ8= github.com/stretchr/testify v1.8.2/go.mod h1:w2LPCIKwWwSfY2zedu0+kehJoqGctiVI29o6fzry7u4= github.com/yuin/goldmark v1.3.5/go.mod h1:mwnBkeHKe2W/ZEtQ+71ViKU8L12m81fl3OWwC1Zlc8k= +github.com/zitadel/logging v0.3.5-0.20230824152050-9b8a8a0bdf73 h1:vYoTHKhD3upeAXNTBcoSmdZkRF9WOcJzozJX/1SiXUI= +github.com/zitadel/logging v0.3.5-0.20230824152050-9b8a8a0bdf73/go.mod h1:p1XQg2/CP5BGGwTrZ2thanc3cvGpkHALLCrMiO+ULsY= github.com/zitadel/schema v1.3.0 h1:kQ9W9tvIwZICCKWcMvCEweXET1OcOyGEuFbHs4o5kg0= github.com/zitadel/schema v1.3.0/go.mod h1:NptN6mkBDFvERUCvZHlvWmmME+gmZ44xzwRXwhzsbtc= golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w= @@ -104,6 +106,7 @@ gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c h1:Hei/4ADfdWqJk1ZMxUNpqntN gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c/go.mod h1:JHkPIbrfpd72SG/EVd6muEfDQjcINNoR0C8j2r3qZ4Q= gopkg.in/square/go-jose.v2 v2.6.0 h1:NGk74WTnPKBNUhNzQX7PYcTLUjoq7mzKk2OKbvwk2iI= gopkg.in/square/go-jose.v2 v2.6.0/go.mod h1:M9dMgbHiYLoDGQrXy7OpJDJWiKiU//h+vD76mk0e1AI= +gopkg.in/yaml.v2 v2.2.8 h1:obN1ZagJSUGI0Ek/LBmuj4SNLPfIny3KsKFopxRdj10= gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= gopkg.in/yaml.v3 v3.0.1 h1:fxVm/GzAzEWqLHuvctI91KS9hhNmmWOoWu0XTYJS7CA= gopkg.in/yaml.v3 v3.0.1/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= diff --git a/pkg/op/error.go b/pkg/op/error.go index ccb9000..4898e69 100644 --- a/pkg/op/error.go +++ b/pkg/op/error.go @@ -20,7 +20,7 @@ func AuthRequestError(w http.ResponseWriter, r *http.Request, authReq ErrAuthReq logger := authorizer.Logger().With("oidc_error", e) if authReq == nil { - logger.Log(r.Context(), e.LogLevel(), "auth request nil") + logger.Log(r.Context(), e.LogLevel(), "auth request") http.Error(w, err.Error(), http.StatusBadRequest) return } @@ -42,7 +42,7 @@ func AuthRequestError(w http.ResponseWriter, r *http.Request, authReq ErrAuthReq http.Error(w, err.Error(), http.StatusBadRequest) return } - logger.Log(r.Context(), e.LogLevel(), "auth request error") + logger.Log(r.Context(), e.LogLevel(), "auth request") http.Redirect(w, r, url, http.StatusFound) } diff --git a/pkg/op/logger.go b/pkg/op/logger.go deleted file mode 100644 index ea1251b..0000000 --- a/pkg/op/logger.go +++ /dev/null @@ -1,114 +0,0 @@ -package op - -import ( - "context" - "net/http" - "time" - - "github.com/rs/xid" - "golang.org/x/exp/slog" -) - -func newLogger(logger *slog.Logger) *slog.Logger { - if logger == nil { - logger = slog.Default() - } - return slog.New(&logHandler{ - handler: logger.Handler(), - }) -} - -type LogKey int - -const ( - RequestID LogKey = iota - - maxLogKey -) - -type logHandler struct { - handler slog.Handler -} - -func (h *logHandler) Enabled(ctx context.Context, level slog.Level) bool { - return h.handler.Enabled(ctx, level) -} - -type logAttributes []slog.Attr - -func (attrs *logAttributes) appendFromContext(ctx context.Context, ctxKey any, logKey string) { - v := ctx.Value(RequestID) - if v == nil { - return - } - *attrs = append(*attrs, slog.Group("request", slog.Attr{ - Key: "id", - Value: slog.AnyValue(v), - })) -} - -func (h *logHandler) Handle(ctx context.Context, record slog.Record) error { - attrs := make(logAttributes, 0, maxLogKey) - attrs.appendFromContext(ctx, RequestID, "id") - - handler := h.handler.WithAttrs(attrs) - - return handler.Handle(ctx, record) -} - -func (h *logHandler) WithAttrs(attrs []slog.Attr) slog.Handler { - return &logHandler{ - handler: h.handler.WithAttrs(attrs), - } -} - -func (h *logHandler) WithGroup(name string) slog.Handler { - return &logHandler{ - handler: h.handler.WithGroup(name), - } -} - -func (o *Provider) LogMiddleware() func(http.Handler) http.Handler { - return func(next http.Handler) http.Handler { - return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - start := time.Now() - r = r.WithContext(context.WithValue(r.Context(), RequestID, xid.New())) - lw := &loggedWriter{ - ResponseWriter: w, - } - next.ServeHTTP(lw, r) - logger := o.logger.With( - slog.Group("request", "method", r.Method, "url", r.URL), - slog.Group("response", "duration", time.Since(start), "status", lw.statusCode, "written", lw.written), - ) - if lw.err != nil { - logger.ErrorContext(r.Context(), "response writer", "error", lw.err) - return - } - logger.InfoContext(r.Context(), "done") - }) - } -} - -type loggedWriter struct { - http.ResponseWriter - - statusCode int - written int - err error -} - -func (w *loggedWriter) WriteHeader(statusCode int) { - w.statusCode = statusCode - w.ResponseWriter.WriteHeader(statusCode) -} - -func (w *loggedWriter) Write(b []byte) (int, error) { - if w.statusCode == 0 { - w.WriteHeader(http.StatusOK) - } - n, err := w.ResponseWriter.Write(b) - w.written += n - w.err = err - return n, err -} diff --git a/pkg/op/op.go b/pkg/op/op.go index 8d9c57a..26f731e 100644 --- a/pkg/op/op.go +++ b/pkg/op/op.go @@ -87,9 +87,8 @@ type OpenIDProvider interface { type HttpInterceptor func(http.Handler) http.Handler -func CreateRouter(o *Provider, interceptors ...HttpInterceptor) chi.Router { +func CreateRouter(o OpenIDProvider, interceptors ...HttpInterceptor) chi.Router { router := chi.NewRouter() - router.Use(o.LogMiddleware()) router.Use(cors.New(defaultCORSOptions).Handler) router.Use(intercept(o.IssuerFromRequest, interceptors...)) router.HandleFunc(healthEndpoint, healthHandler) @@ -534,7 +533,7 @@ func WithIDTokenHintVerifierOpts(opts ...IDTokenHintVerifierOpt) Option { func WithLogger(logger *slog.Logger) Option { return func(o *Provider) error { - o.logger = newLogger(logger) + o.logger = logger return nil } }