Skip to content

Commit

Permalink
refactored debug logging
Browse files Browse the repository at this point in the history 
* relinted debugLog as debugLogf
* fixes go-openapi#244 (use logger.Debugf rather than logger.Printf)
* fixes go-openapi#118 (added support for injectable logger in Context and DefaultRouter)
* removed global debug logger

Signed-off-by: Frederic BIDON <[email protected]>
  • Loading branch information
@fredbi
fredbi committed Dec 14, 2023
1 parent 442694d commit 9a714db
Show file tree
Hide file tree
Showing 4 changed files with 151 additions and 58 deletions.
76 changes: 55 additions & 21 deletions middleware/context.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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 {
Expand Down Expand Up @@ -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 {
Expand All @@ -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
}

Expand Down Expand Up @@ -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()
Expand All @@ -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)
}
Expand Down Expand Up @@ -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
}

Expand Down Expand Up @@ -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...)
}
Expand All @@ -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
}

Expand All @@ -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() {
Expand All @@ -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)
Expand Down
21 changes: 17 additions & 4 deletions middleware/request.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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.
Expand All @@ -44,6 +45,7 @@ func NewUntypedRequestBinder(parameters map[string]spec.Parameter, spec *spec.Sw
paramBinders: binders,
Spec: spec,
Formats: formats,
debugLogf: debugLogfFunc(nil),
}
}

Expand All @@ -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
Expand Down Expand Up @@ -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
}
Loading

0 comments on commit 9a714db

Please sign in to comment.