Repository: go-openapi/runtime
Pull request #282 (2023-12-13 14:35:40)

Fix/debug issues
refactored debug logging

* relinted debugLog as debugLogf
* fixes https://github.com/go-openapi/runtime/issues/244 (use logger.Debugf rather than logger.Printf)
* fixes https://github.com/go-openapi/runtime/issues/118 (added support for injectable logger in Context and DefaultRouter)
* removed global debug logger

Signed-off-by: Frederic BIDON <fredbi@yahoo.com>

codecov[bot]: ## [Codecov](https://app.codecov.io/gh/go-openapi/runtime/pull/282?src=pr&el=h1&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=go-openapi) Report
Attention: `25 lines` in your changes are missing coverage. Please review.
> Comparison is base [(`442694d`)](https://app.codecov.io/gh/go-openapi/runtime/commit/442694d245b6822df8701f363b33b85bc483b5b1?el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=go-openapi) 82.27% compared to head [(`a2dc915`)](https://app.codecov.io/gh/go-openapi/runtime/pull/282?src=pr&el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=go-openapi) 81.96%.

| [Files](https://app.codecov.io/gh/go-openapi/runtime/pull/282?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=go-openapi) | Patch % | Lines |
|---|---|---|
| [middleware/context.go](https://app.codecov.io/gh/go-openapi/runtime/pull/282?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=go-openapi#diff-bWlkZGxld2FyZS9jb250ZXh0Lmdv) | 54.54% | [14 Missing and 1 partial :warning: ](https://app.codecov.io/gh/go-openapi/runtime/pull/282?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=go-openapi) |
| [middleware/router.go](https://app.codecov.io/gh/go-openapi/runtime/pull/282?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=go-openapi#diff-bWlkZGxld2FyZS9yb3V0ZXIuZ28=) | 73.68% | [10 Missing :warning: ](https://app.codecov.io/gh/go-openapi/runtime/pull/282?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=go-openapi) |

<details><summary>Additional details and impacted files</summary>


```diff
@@            Coverage Diff             @@
##           master     #282      +/-   ##
==========================================
- Coverage   82.27%   81.96%   -0.31%     
==========================================
  Files          45       45              
  Lines        3447     3488      +41     
==========================================
+ Hits         2836     2859      +23     
- Misses        499      516      +17     
- Partials      112      113       +1     
```

| [Flag](https://app.codecov.io/gh/go-openapi/runtime/pull/282/flags?src=pr&el=flags&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=go-openapi) | Coverage Δ | |
|---|---|---|
| [oldstable](https://app.codecov.io/gh/go-openapi/runtime/pull/282/flags?src=pr&el=flag&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=go-openapi) | `81.96% <68.35%> (-0.31%)` | :arrow_down: |
| [stable](https://app.codecov.io/gh/go-openapi/runtime/pull/282/flags?src=pr&el=flag&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=go-openapi) | `81.96% <68.35%> (-0.31%)` | :arrow_down: |

Flags with carried forward coverage won't be shown. [Click here](https://docs.codecov.io/docs/carryforward-flags?utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=go-openapi#carryforward-flags-in-the-pull-request-comment) to find out more.


</details>

[:umbrella: View full report in Codecov by Sentry](https://app.codecov.io/gh/go-openapi/runtime/pull/282?src=pr&el=continue&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=go-openapi).   
:loudspeaker: Have feedback on the report? [Share it here](https://about.codecov.io/codecov-pr-comment-feedback/?utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=go-openapi).

fredbi: TODO: need unit tests

Patch:
diff --git a/middleware/context.go b/middleware/context.go
index 5e9ecf5..44cecf1 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/go18.go b/middleware/go18.go
deleted file mode 100644
index 1bf4939..0000000
--- a/middleware/go18.go
+++ /dev/null
@@ -1,10 +0,0 @@
-//go:build go1.8
-// +build go1.8
-
-package middleware
-
-import "net/url"
-
-func pathUnescape(path string) (string, error) {
-	return url.PathUnescape(path)
-}
diff --git a/middleware/pre_go18.go b/middleware/pre_go18.go
deleted file mode 100644
index 0338525..0000000
--- a/middleware/pre_go18.go
+++ /dev/null
@@ -1,9 +0,0 @@
-// +build !go1.8
-
-package middleware
-
-import "net/url"
-
-func pathUnescape(path string) (string, error) {
-	return url.QueryUnescape(path)
-}
diff --git a/middleware/request.go b/middleware/request.go
index d4b9fc6..82e1436 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 46b8f87..3a6aee9 100644
--- a/middleware/router.go
+++ b/middleware/router.go
@@ -17,10 +17,12 @@ package middleware
 import (
 	"fmt"
 	"net/http"
+	"net/url"
 	fpath "path"
 	"regexp"
 	"strings"
 
+	"github.com/go-openapi/runtime/logger"
 	"github.com/go-openapi/runtime/security"
 	"github.com/go-openapi/swag"
 
@@ -67,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) {
@@ -103,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)
 			}
 		}
@@ -319,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 := pathUnescape(p.Value)
+					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
@@ -356,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
 }
@@ -378,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(`{(.+?)}([^/]*)`)
 
@@ -413,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)
@@ -428,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,
@@ -439,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(),
 		})
@@ -482,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 1f0135b..0a5356c 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)
 			}


Test patch:
diff --git a/middleware/debug_test.go b/middleware/debug_test.go
new file mode 100644
index 0000000..088f412
--- /dev/null
+++ b/middleware/debug_test.go
@@ -0,0 +1,122 @@
+package middleware
+
+import (
+	"bytes"
+	stdcontext "context"
+	"log"
+	"net/http"
+	"net/http/httptest"
+	"testing"
+
+	"github.com/go-openapi/runtime/internal/testing/petstore"
+	"github.com/go-openapi/runtime/logger"
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+)
+
+type customLogger struct {
+	logger.StandardLogger
+	lg *log.Logger
+}
+
+func (l customLogger) Debugf(format string, args ...interface{}) {
+	l.lg.Printf(format, args...)
+}
+
+func TestDebugMode(t *testing.T) {
+	t.Run("with normal mode", func(t *testing.T) {
+		t.Setenv("DEBUG", "")
+
+		logFunc := debugLogfFunc(nil)
+		require.NotNil(t, logFunc)
+	})
+
+	t.Run("with debug mode", func(t *testing.T) {
+		t.Setenv("DEBUG", "true")
+
+		t.Run("debugLogFunc with nil logger yields standard logger", func(t *testing.T) {
+			logFunc := debugLogfFunc(nil)
+			require.NotNil(t, logFunc)
+		})
+		t.Run("debugLogFunc with custom logger", func(t *testing.T) {
+			var capture bytes.Buffer
+			logger := customLogger{lg: log.New(&capture, "test", log.Lshortfile)}
+			logFunc := debugLogfFunc(logger)
+			require.NotNil(t, logFunc)
+
+			logFunc("debug")
+			assert.NotEmpty(t, capture.String())
+		})
+	})
+}
+
+func TestDebugRouterOptions(t *testing.T) {
+	t.Run("with normal mode", func(t *testing.T) {
+		t.Setenv("DEBUG", "")
+
+		t.Run("should capture debug from context & router", func(t *testing.T) {
+			var capture bytes.Buffer
+			logger := customLogger{lg: log.New(&capture, "test", log.Lshortfile)}
+
+			t.Run("run some activiy", doCheckWithContext(logger))
+			assert.Empty(t, capture.String())
+		})
+
+		t.Run("should capture debug from standalone DefaultRouter", func(t *testing.T) {
+			var capture bytes.Buffer
+			logger := customLogger{lg: log.New(&capture, "test", log.Lshortfile)}
+
+			t.Run("run some activiy", doCheckWithDefaultRouter(logger))
+			assert.Empty(t, capture.String())
+		})
+	})
+
+	t.Run("with debug mode", func(t *testing.T) {
+		t.Setenv("DEBUG", "1")
+
+		t.Run("should capture debug from context & router", func(t *testing.T) {
+			var capture bytes.Buffer
+			logger := customLogger{lg: log.New(&capture, "test", log.Lshortfile)}
+
+			t.Run("run some activiy", doCheckWithContext(logger))
+			assert.NotEmpty(t, capture.String())
+		})
+
+		t.Run("should capture debug from standalone DefaultRouter", func(t *testing.T) {
+			var capture bytes.Buffer
+			logger := customLogger{lg: log.New(&capture, "test", log.Lshortfile)}
+
+			t.Run("run some activiy", doCheckWithDefaultRouter(logger))
+			assert.NotEmpty(t, capture.String())
+		})
+	})
+}
+
+func doCheckWithContext(logger logger.Logger) func(*testing.T) {
+	return func(t *testing.T) {
+		spec, api := petstore.NewAPI(t)
+		context := NewContext(spec, api, nil)
+		context.SetLogger(logger)
+		mw := NewRouter(context, http.HandlerFunc(terminator))
+
+		recorder := httptest.NewRecorder()
+		request, err := http.NewRequestWithContext(stdcontext.Background(), http.MethodGet, "/api/pets", nil)
+		require.NoError(t, err)
+		mw.ServeHTTP(recorder, request)
+		assert.Equal(t, http.StatusOK, recorder.Code)
+	}
+}
+
+func doCheckWithDefaultRouter(lg logger.Logger) func(*testing.T) {
+	return func(t *testing.T) {
+		spec, api := petstore.NewAPI(t)
+		context := NewContext(spec, api, nil)
+		context.SetLogger(lg)
+		router := DefaultRouter(
+			spec,
+			newRoutableUntypedAPI(spec, api, new(Context)),
+			WithDefaultRouterLogger(lg))
+
+		_ = router.OtherMethods("post", "/api/pets/{id}")
+	}
+}