From 0d66801936d0776f0c9e865d81b2e4a1775df577 Mon Sep 17 00:00:00 2001 From: Frederic BIDON Date: Wed, 13 Dec 2023 12:42:39 +0100 Subject: [PATCH] refactored debug logging * relinted debugLog as debugLogf * fixes #244 (use logger.Debugf rather than logger.Printf) * fixes #118 (added support for injectable logger in Context and DefaultRouter) * removed global debug logger Signed-off-by: Frederic BIDON --- middleware/context.go | 76 +++++++++++++++++++++-------- middleware/request.go | 21 ++++++-- middleware/router.go | 100 +++++++++++++++++++++++++++------------ middleware/validation.go | 12 +++-- 4 files changed, 151 insertions(+), 58 deletions(-) diff --git a/middleware/context.go b/middleware/context.go index 5e9ecf55..44cecf11 100644 --- a/middleware/context.go +++ b/middleware/context.go @@ -37,12 +37,21 @@ import ( // Debug when true turns on verbose logging var Debug = logger.DebugEnabled() + +// Logger is the standard libray logger used for printing debug messages var Logger logger.Logger = logger.StandardLogger{} -func debugLog(format string, args ...interface{}) { //nolint:goprintffuncname - if Debug { - Logger.Printf(format, args...) +func debugLogfFunc(lg logger.Logger) func(string, ...any) { + if logger.DebugEnabled() { + if lg == nil { + return Logger.Debugf + } + + return lg.Debugf } + + // muted logger + return func(_ string, _ ...any) {} } // A Builder can create middlewares @@ -75,10 +84,11 @@ func (fn ResponderFunc) WriteResponse(rw http.ResponseWriter, pr runtime.Produce // used throughout to store request context with the standard context attached // to the http.Request type Context struct { - spec *loads.Document - analyzer *analysis.Spec - api RoutableAPI - router Router + spec *loads.Document + analyzer *analysis.Spec + api RoutableAPI + router Router + debugLogf func(string, ...any) // a logging function to debug context and all components using it } type routableUntypedAPI struct { @@ -191,7 +201,9 @@ func (r *routableUntypedAPI) DefaultConsumes() string { return r.defaultConsumes } -// NewRoutableContext creates a new context for a routable API +// NewRoutableContext creates a new context for a routable API. +// +// If a nil Router is provided, the DefaultRouter (denco-based) will be used. func NewRoutableContext(spec *loads.Document, routableAPI RoutableAPI, routes Router) *Context { var an *analysis.Spec if spec != nil { @@ -201,26 +213,40 @@ func NewRoutableContext(spec *loads.Document, routableAPI RoutableAPI, routes Ro return NewRoutableContextWithAnalyzedSpec(spec, an, routableAPI, routes) } -// NewRoutableContextWithAnalyzedSpec is like NewRoutableContext but takes in input the analysed spec too +// NewRoutableContextWithAnalyzedSpec is like NewRoutableContext but takes as input an already analysed spec. +// +// If a nil Router is provided, the DefaultRouter (denco-based) will be used. func NewRoutableContextWithAnalyzedSpec(spec *loads.Document, an *analysis.Spec, routableAPI RoutableAPI, routes Router) *Context { // Either there are no spec doc and analysis, or both of them. if !((spec == nil && an == nil) || (spec != nil && an != nil)) { panic(errors.New(http.StatusInternalServerError, "routable context requires either both spec doc and analysis, or none of them")) } - ctx := &Context{spec: spec, api: routableAPI, analyzer: an, router: routes} - return ctx + return &Context{ + spec: spec, + api: routableAPI, + analyzer: an, + router: routes, + debugLogf: debugLogfFunc(nil), + } } -// NewContext creates a new context wrapper +// NewContext creates a new context wrapper. +// +// If a nil Router is provided, the DefaultRouter (denco-based) will be used. func NewContext(spec *loads.Document, api *untyped.API, routes Router) *Context { var an *analysis.Spec if spec != nil { an = analysis.New(spec.Spec()) } - ctx := &Context{spec: spec, analyzer: an} + ctx := &Context{ + spec: spec, + analyzer: an, + router: routes, + debugLogf: debugLogfFunc(nil), + } ctx.api = newRoutableUntypedAPI(spec, api, ctx) - ctx.router = routes + return ctx } @@ -284,6 +310,13 @@ func (c *Context) BasePath() string { return c.spec.BasePath() } +// SetLogger allows for injecting a logger to catch debug entries. +// +// The logger is enabled in DEBUG mode only. +func (c *Context) SetLogger(lg logger.Logger) { + c.debugLogf = debugLogfFunc(lg) +} + // RequiredProduces returns the accepted content types for responses func (c *Context) RequiredProduces() []string { return c.analyzer.RequiredProduces() @@ -301,6 +334,7 @@ func (c *Context) BindValidRequest(request *http.Request, route *MatchedRoute, b if err != nil { res = append(res, err) } else { + c.debugLogf("validating content type for %q against [%s]", ct, strings.Join(route.Consumes, ", ")) if err := validateContentType(route.Consumes, ct); err != nil { res = append(res, err) } @@ -399,16 +433,16 @@ func (c *Context) ResponseFormat(r *http.Request, offers []string) (string, *htt var rCtx = r.Context() if v, ok := rCtx.Value(ctxResponseFormat).(string); ok { - debugLog("[%s %s] found response format %q in context", r.Method, r.URL.Path, v) + c.debugLogf("[%s %s] found response format %q in context", r.Method, r.URL.Path, v) return v, r } format := NegotiateContentType(r, offers, "") if format != "" { - debugLog("[%s %s] set response format %q in context", r.Method, r.URL.Path, format) + c.debugLogf("[%s %s] set response format %q in context", r.Method, r.URL.Path, format) r = r.WithContext(stdContext.WithValue(rCtx, ctxResponseFormat, format)) } - debugLog("[%s %s] negotiated response format %q", r.Method, r.URL.Path, format) + c.debugLogf("[%s %s] negotiated response format %q", r.Method, r.URL.Path, format) return format, r } @@ -471,7 +505,7 @@ func (c *Context) BindAndValidate(request *http.Request, matched *MatchedRoute) var rCtx = request.Context() if v, ok := rCtx.Value(ctxBoundParams).(*validation); ok { - debugLog("got cached validation (valid: %t)", len(v.result) == 0) + c.debugLogf("got cached validation (valid: %t)", len(v.result) == 0) if len(v.result) > 0 { return v.bound, request, errors.CompositeValidationError(v.result...) } @@ -483,7 +517,7 @@ func (c *Context) BindAndValidate(request *http.Request, matched *MatchedRoute) if len(result.result) > 0 { return result.bound, request, errors.CompositeValidationError(result.result...) } - debugLog("no validation errors found") + c.debugLogf("no validation errors found") return result.bound, request, nil } @@ -494,7 +528,7 @@ func (c *Context) NotFound(rw http.ResponseWriter, r *http.Request) { // Respond renders the response after doing some content negotiation func (c *Context) Respond(rw http.ResponseWriter, r *http.Request, produces []string, route *MatchedRoute, data interface{}) { - debugLog("responding to %s %s with produces: %v", r.Method, r.URL.Path, produces) + c.debugLogf("responding to %s %s with produces: %v", r.Method, r.URL.Path, produces) offers := []string{} for _, mt := range produces { if mt != c.api.DefaultProduces() { @@ -503,7 +537,7 @@ func (c *Context) Respond(rw http.ResponseWriter, r *http.Request, produces []st } // the default producer is last so more specific producers take precedence offers = append(offers, c.api.DefaultProduces()) - debugLog("offers: %v", offers) + c.debugLogf("offers: %v", offers) var format string format, r = c.ResponseFormat(r, offers) diff --git a/middleware/request.go b/middleware/request.go index d4b9fc6a..82e14366 100644 --- a/middleware/request.go +++ b/middleware/request.go @@ -19,10 +19,10 @@ import ( "reflect" "github.com/go-openapi/errors" + "github.com/go-openapi/runtime" + "github.com/go-openapi/runtime/logger" "github.com/go-openapi/spec" "github.com/go-openapi/strfmt" - - "github.com/go-openapi/runtime" ) // UntypedRequestBinder binds and validates the data from a http request @@ -31,6 +31,7 @@ type UntypedRequestBinder struct { Parameters map[string]spec.Parameter Formats strfmt.Registry paramBinders map[string]*untypedParamBinder + debugLogf func(string, ...any) // a logging function to debug context and all components using it } // NewUntypedRequestBinder creates a new binder for reading a request. @@ -44,6 +45,7 @@ func NewUntypedRequestBinder(parameters map[string]spec.Parameter, spec *spec.Sw paramBinders: binders, Spec: spec, Formats: formats, + debugLogf: debugLogfFunc(nil), } } @@ -52,10 +54,10 @@ func (o *UntypedRequestBinder) Bind(request *http.Request, routeParams RoutePara val := reflect.Indirect(reflect.ValueOf(data)) isMap := val.Kind() == reflect.Map var result []error - debugLog("binding %d parameters for %s %s", len(o.Parameters), request.Method, request.URL.EscapedPath()) + o.debugLogf("binding %d parameters for %s %s", len(o.Parameters), request.Method, request.URL.EscapedPath()) for fieldName, param := range o.Parameters { binder := o.paramBinders[fieldName] - debugLog("binding parameter %s for %s %s", fieldName, request.Method, request.URL.EscapedPath()) + o.debugLogf("binding parameter %s for %s %s", fieldName, request.Method, request.URL.EscapedPath()) var target reflect.Value if !isMap { binder.Name = fieldName @@ -102,3 +104,14 @@ func (o *UntypedRequestBinder) Bind(request *http.Request, routeParams RoutePara return nil } + +// SetLogger allows for injecting a logger to catch debug entries. +// +// The logger is enabled in DEBUG mode only. +func (o *UntypedRequestBinder) SetLogger(lg logger.Logger) { + o.debugLogf = debugLogfFunc(lg) +} + +func (o *UntypedRequestBinder) setDebugLogf(fn func(string, ...any)) { + o.debugLogf = fn +} diff --git a/middleware/router.go b/middleware/router.go index f7b58698..3a6aee90 100644 --- a/middleware/router.go +++ b/middleware/router.go @@ -22,6 +22,7 @@ import ( "regexp" "strings" + "github.com/go-openapi/runtime/logger" "github.com/go-openapi/runtime/security" "github.com/go-openapi/swag" @@ -68,10 +69,10 @@ func (r RouteParams) GetOK(name string) ([]string, bool, bool) { return nil, false, false } -// NewRouter creates a new context aware router middleware +// NewRouter creates a new context-aware router middleware func NewRouter(ctx *Context, next http.Handler) http.Handler { if ctx.router == nil { - ctx.router = DefaultRouter(ctx.spec, ctx.api) + ctx.router = DefaultRouter(ctx.spec, ctx.api, WithDefaultRouterLoggerFunc(ctx.debugLogf)) } return http.HandlerFunc(func(rw http.ResponseWriter, r *http.Request) { @@ -104,41 +105,75 @@ type RoutableAPI interface { DefaultConsumes() string } -// Router represents a swagger aware router +// Router represents a swagger-aware router type Router interface { Lookup(method, path string) (*MatchedRoute, bool) OtherMethods(method, path string) []string } type defaultRouteBuilder struct { - spec *loads.Document - analyzer *analysis.Spec - api RoutableAPI - records map[string][]denco.Record + spec *loads.Document + analyzer *analysis.Spec + api RoutableAPI + records map[string][]denco.Record + debugLogf func(string, ...any) // a logging function to debug context and all components using it } type defaultRouter struct { - spec *loads.Document - routers map[string]*denco.Router + spec *loads.Document + routers map[string]*denco.Router + debugLogf func(string, ...any) // a logging function to debug context and all components using it } -func newDefaultRouteBuilder(spec *loads.Document, api RoutableAPI) *defaultRouteBuilder { +func newDefaultRouteBuilder(spec *loads.Document, api RoutableAPI, opts ...DefaultRouterOpt) *defaultRouteBuilder { + var o defaultRouterOpts + for _, apply := range opts { + apply(&o) + } + if o.debugLogf == nil { + o.debugLogf = debugLogfFunc(nil) // defaults to standard logger + } + return &defaultRouteBuilder{ - spec: spec, - analyzer: analysis.New(spec.Spec()), - api: api, - records: make(map[string][]denco.Record), + spec: spec, + analyzer: analysis.New(spec.Spec()), + api: api, + records: make(map[string][]denco.Record), + debugLogf: o.debugLogf, } } -// DefaultRouter creates a default implemenation of the router -func DefaultRouter(spec *loads.Document, api RoutableAPI) Router { - builder := newDefaultRouteBuilder(spec, api) +// DefaultRouterOpt allows to inject optional behavior to the default router. +type DefaultRouterOpt func(*defaultRouterOpts) + +type defaultRouterOpts struct { + debugLogf func(string, ...any) +} + +// WithDefaultRouterLogger sets the debug logger for the default router. +// +// This is enabled only in DEBUG mode. +func WithDefaultRouterLogger(lg logger.Logger) DefaultRouterOpt { + return func(o *defaultRouterOpts) { + o.debugLogf = debugLogfFunc(lg) + } +} + +// WithDefaultRouterLoggerFunc sets a logging debug method for the default router. +func WithDefaultRouterLoggerFunc(fn func(string, ...any)) DefaultRouterOpt { + return func(o *defaultRouterOpts) { + o.debugLogf = fn + } +} + +// DefaultRouter creates a default implementation of the router +func DefaultRouter(spec *loads.Document, api RoutableAPI, opts ...DefaultRouterOpt) Router { + builder := newDefaultRouteBuilder(spec, api, opts...) if spec != nil { for method, paths := range builder.analyzer.Operations() { for path, operation := range paths { fp := fpath.Join(spec.BasePath(), path) - debugLog("adding route %s %s %q", method, fp, operation.ID) + builder.debugLogf("adding route %s %s %q", method, fp, operation.ID) builder.AddRoute(method, fp, operation) } } @@ -320,24 +355,24 @@ func (m *MatchedRoute) NeedsAuth() bool { func (d *defaultRouter) Lookup(method, path string) (*MatchedRoute, bool) { mth := strings.ToUpper(method) - debugLog("looking up route for %s %s", method, path) + d.debugLogf("looking up route for %s %s", method, path) if Debug { if len(d.routers) == 0 { - debugLog("there are no known routers") + d.debugLogf("there are no known routers") } for meth := range d.routers { - debugLog("got a router for %s", meth) + d.debugLogf("got a router for %s", meth) } } if router, ok := d.routers[mth]; ok { if m, rp, ok := router.Lookup(fpath.Clean(path)); ok && m != nil { if entry, ok := m.(*routeEntry); ok { - debugLog("found a route for %s %s with %d parameters", method, path, len(entry.Parameters)) + d.debugLogf("found a route for %s %s with %d parameters", method, path, len(entry.Parameters)) var params RouteParams for _, p := range rp { v, err := url.PathUnescape(p.Value) if err != nil { - debugLog("failed to escape %q: %v", p.Value, err) + d.debugLogf("failed to escape %q: %v", p.Value, err) v = p.Value } // a workaround to handle fragment/composing parameters until they are supported in denco router @@ -357,10 +392,10 @@ func (d *defaultRouter) Lookup(method, path string) (*MatchedRoute, bool) { return &MatchedRoute{routeEntry: *entry, Params: params}, true } } else { - debugLog("couldn't find a route by path for %s %s", method, path) + d.debugLogf("couldn't find a route by path for %s %s", method, path) } } else { - debugLog("couldn't find a route by method for %s %s", method, path) + d.debugLogf("couldn't find a route by method for %s %s", method, path) } return nil, false } @@ -379,6 +414,10 @@ func (d *defaultRouter) OtherMethods(method, path string) []string { return methods } +func (d *defaultRouter) SetLogger(lg logger.Logger) { + d.debugLogf = debugLogfFunc(lg) +} + // convert swagger parameters per path segment into a denco parameter as multiple parameters per segment are not supported in denco var pathConverter = regexp.MustCompile(`{(.+?)}([^/]*)`) @@ -414,7 +453,7 @@ func (d *defaultRouteBuilder) AddRoute(method, path string, operation *spec.Oper bp = bp[:len(bp)-1] } - debugLog("operation: %#v", *operation) + d.debugLogf("operation: %#v", *operation) if handler, ok := d.api.HandlerFor(method, strings.TrimPrefix(path, bp)); ok { consumes := d.analyzer.ConsumesFor(operation) produces := d.analyzer.ProducesFor(operation) @@ -429,6 +468,8 @@ func (d *defaultRouteBuilder) AddRoute(method, path string, operation *spec.Oper produces = append(produces, defProduces) } + requestBinder := NewUntypedRequestBinder(parameters, d.spec.Spec(), d.api.Formats()) + requestBinder.setDebugLogf(d.debugLogf) record := denco.NewRecord(pathConverter.ReplaceAllString(path, ":$1"), &routeEntry{ BasePath: bp, PathPattern: path, @@ -440,7 +481,7 @@ func (d *defaultRouteBuilder) AddRoute(method, path string, operation *spec.Oper Producers: d.api.ProducersFor(normalizeOffers(produces)), Parameters: parameters, Formats: d.api.Formats(), - Binder: NewUntypedRequestBinder(parameters, d.spec.Spec(), d.api.Formats()), + Binder: requestBinder, Authenticators: d.buildAuthenticators(operation), Authorizer: d.api.Authorizer(), }) @@ -483,7 +524,8 @@ func (d *defaultRouteBuilder) Build() *defaultRouter { routers[method] = router } return &defaultRouter{ - spec: d.spec, - routers: routers, + spec: d.spec, + routers: routers, + debugLogf: d.debugLogf, } } diff --git a/middleware/validation.go b/middleware/validation.go index 1f0135b5..0a5356c6 100644 --- a/middleware/validation.go +++ b/middleware/validation.go @@ -35,7 +35,6 @@ type validation struct { // ContentType validates the content type of a request func validateContentType(allowed []string, actual string) error { - debugLog("validating content type for %q against [%s]", actual, strings.Join(allowed, ", ")) if len(allowed) == 0 { return nil } @@ -57,13 +56,13 @@ func validateContentType(allowed []string, actual string) error { } func validateRequest(ctx *Context, request *http.Request, route *MatchedRoute) *validation { - debugLog("validating request %s %s", request.Method, request.URL.EscapedPath()) validate := &validation{ context: ctx, request: request, route: route, bound: make(map[string]interface{}), } + validate.debugLogf("validating request %s %s", request.Method, request.URL.EscapedPath()) validate.contentType() if len(validate.result) == 0 { @@ -76,8 +75,12 @@ func validateRequest(ctx *Context, request *http.Request, route *MatchedRoute) * return validate } +func (v *validation) debugLogf(format string, args ...any) { + v.context.debugLogf(format, args...) +} + func (v *validation) parameters() { - debugLog("validating request parameters for %s %s", v.request.Method, v.request.URL.EscapedPath()) + v.debugLogf("validating request parameters for %s %s", v.request.Method, v.request.URL.EscapedPath()) if result := v.route.Binder.Bind(v.request, v.route.Params, v.route.Consumer, v.bound); result != nil { if result.Error() == "validation failure list" { for _, e := range result.(*errors.Validation).Value.([]interface{}) { @@ -91,7 +94,7 @@ func (v *validation) parameters() { func (v *validation) contentType() { if len(v.result) == 0 && runtime.HasBody(v.request) { - debugLog("validating body content type for %s %s", v.request.Method, v.request.URL.EscapedPath()) + v.debugLogf("validating body content type for %s %s", v.request.Method, v.request.URL.EscapedPath()) ct, _, req, err := v.context.ContentType(v.request) if err != nil { v.result = append(v.result, err) @@ -100,6 +103,7 @@ func (v *validation) contentType() { } if len(v.result) == 0 { + v.debugLogf("validating content type for %q against [%s]", ct, strings.Join(v.route.Consumes, ", ")) if err := validateContentType(v.route.Consumes, ct); err != nil { v.result = append(v.result, err) }