Skip to content

Commit

Permalink
Allow for more customization
Browse files Browse the repository at this point in the history
* Add options to configure debug log enabled
* Add separate middleware for configuring logger
* Add option to configure pprof handler prefixes.
* Update README
  • Loading branch information
raphael committed Jan 15, 2023
1 parent 64d6679 commit 775b8fc
Show file tree
Hide file tree
Showing 12 changed files with 438 additions and 137 deletions.
76 changes: 60 additions & 16 deletions debug/README.md
Original file line number Diff line number Diff line change
Expand Up @@ -13,25 +13,60 @@ the content of request and result payloads, and to profile a microservice.

### Toggling Debug Logs

The `debug` package provides a `MountDebugLogEnabler` function which accepts a
URL prefix, a mux and returns a HTTP middleware. The function configures the mux
to add a handler at the given URL prefix that accepts requests of the form
`/<prefix>?enable=on` and `/<prefix>?enable=off` to turn debug logs on and off.

The function returns a middleware that should be used on all the handlers that
should support toggling debug logs. The package also include unary and stream
gRPC interceptors that should be used on all methods that should support
toggling debug logs. Note that gRPC services must still expose HTTP endpoints
to enable toggling debug logs, the interceptor merely configures the log level
for each request.
The `debug` package provides a `MountDebugLogEnabler` function which adds a
handler to the given mux under the `/debug` path that accepts requests of the
form `/debug?debug-logs=on` and `/debug?debug-logs=off` to manage debug logs
state. The handler returns the current state of debug logs in the response body
and does not change the state if the request does not contain a `debug-logs`
query parameter. The path, query parameter name and value can be customized by
passing options to the `MountDebugLogEnabler` function.

Note that for the debug log state to take effect, HTTP servers must use handlers
returned by the HTTP function and gRPC servers must make use of the
UnaryInterceptor or StreamInterceptor interceptors. Also note that gRPC
services must expose an HTTP endpoint to control the debug log state.

```go
// HTTP
mux := http.NewServeMux()
debug.MountDebugLogEnabler(mux)
// ... configure mux with other handlers
srv := &http.Server{Handler: debug.HTTP(mux)}
srv.ListenAndServe()
```

```go
// gRPC
mux := http.NewServeMux()
debug.MountDebugLogEnabler(mux)
srv := &http.Server{Handler: mux}
go srv.ListenAndServe()
gsrv := grpc.NewServer(grpc.UnaryInterceptor(debug.UnaryInterceptor))
lis, _ := net.Listen("tcp", ":8080")
gsrv.Serve(lis)
```

The package also provides a Goa muxer adapter that can be used to mount the
debug log enabler handler on a Goa muxer.

```go
mux := goa.NewMuxer()
debug.MountDebugLogEnabler(debug.Adapt(mux))
```

### Logging Request and Result Payloads

The `debug` package provides a `LogPayloads` Goa endpoint middleware that logs
the content of request and result payloads. The middleware can be used with the
generated `Use` functions on `Endpoint` structs. The middleware is a no-op if
generated `Use` functions on `Endpoints` structs. The middleware is a no-op if
debug logs are disabled.

```go
endpoints := genforecaster.NewEndpoints(svc)
endpoints.Use(debug.LogPayloads())
endpoints.Use(log.Endpoint)
```

### Profiling

The `debug` package provides a `MountPprofHandlers` function which configures a
Expand All @@ -53,6 +88,15 @@ list of handlers is:
See the [net/http/pprof](https://pkg.go.dev/net/http/pprof) package
documentation for more information.

The path prefix can be customized by passing an option to the
`MountPprofHandlers` function.

```go
mux := http.NewServeMux()
debug.MountPprofHandlers(mux)
// ... configure mux with other handlers
```

### Example

The weather example illustrates how to make use of this package. In particular
Expand All @@ -69,7 +113,7 @@ Additionally the two "back" services (which would not be exposed to the internet
in production) also mount the pprof handlers (see
[here](https://github.com/goadesign/clue/blob/main/example/weather/services/forecaster/cmd/forecaster/main.go#L105)).
With this setup, requests made to the HTTP servers of each service of the form
`/debug?enable=on` turn on debug logs and requests of the form
`/debug?enable=off` turns them back off. Requests made to `/debug/pprof/` return
the pprof package index page while a request to `/debug/pprof/profile` profile
the service for 30s.
`/debug?debug-logs=on` turn on debug logs and requests of the form
`/debug?debug-logs=off` turns them back off. Requests made to `/debug/pprof/`
return the pprof package index page while a request to `/debug/pprof/profile`
profile the service for 30s.
82 changes: 47 additions & 35 deletions debug/debug.go
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,7 @@ import (
"fmt"
"net/http"
"net/http/pprof"
"strings"

goa "goa.design/goa/v3/pkg"

Expand All @@ -26,38 +27,38 @@ var (
pprofEnabled bool
)

// MountDebugLogEnabler mounts an endpoint under the given prefix and returns a
// HTTP middleware that manages debug logs. The endpoint accepts a single query
// parameter "debug-logs". If the parameter is set to "true" then debug logs are
// enabled for requests made to handlers returned by the middleware. If the
// parameter is set to "false" then debug logs are disabled. In all other cases
// the endpoint returns the current debug logs status.
func MountDebugLogEnabler(prefix string, mux Muxer) func(http.Handler) http.Handler {
mux.Handle(prefix, http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
switch r.URL.Query().Get("debug-logs") {
case "true":
// MountDebugLogEnabler mounts an endpoint under "/debug" and returns a HTTP
// middleware that manages the status of debug logs. The endpoint accepts a
// single query parameter "debug-logs". If the parameter is set to "on" then
// debug logs are enabled. If the parameter is set to "off" then debug logs are
// disabled. In all other cases the endpoint returns the current debug logs
// status. The path, query parameter name and values can be changed using the
// WithPath, WithQuery, WithOnValue and WithOffValue options.
//
// Note: the endpoint merely controls the status of debug logs. It does not
// actually configure the current logger. The logger is configured by the
// middleware returned by the HTTP function or by the gRPC interceptors returned
// by the UnaryServerInterceptor and StreamServerInterceptor functions.
func MountDebugLogEnabler(mux Muxer, opts ...DebugLogEnablerOption) {
o := defaultDebugLogEnablerOptions()
for _, opt := range opts {
opt(o)
}
if !strings.HasPrefix(o.path, "/") {
o.path = "/" + o.path
}
mux.Handle(o.path, http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
if q := r.URL.Query().Get(o.query); q == o.onval {
debugLogs = true
w.Write([]byte(`{"debug-logs":true}`))
case "false":
} else if q == o.offval {
debugLogs = false
w.Write([]byte(`{"debug-logs":false}`))
default:
w.Write([]byte(`{"debug-logs":` + fmt.Sprintf("%t", debugLogs) + `}`))
}
if debugLogs {
w.Write([]byte(fmt.Sprintf(`{"%s":"%s"}`, o.query, o.onval)))
} else {
w.Write([]byte(fmt.Sprintf(`{"%s":"%s"}`, o.query, o.offval)))
}
}))
return func(next http.Handler) http.Handler {
handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
if debugLogs {
ctx := log.Context(r.Context(), log.WithDebug())
r = r.WithContext(ctx)
} else {
ctx := log.Context(r.Context(), log.WithNoDebug())
r = r.WithContext(ctx)
}
next.ServeHTTP(w, r)
})
return handler
}
}

// MountPprofHandlers mounts pprof handlers under /debug/pprof/. The list of
Expand All @@ -77,14 +78,25 @@ func MountDebugLogEnabler(prefix string, mux Muxer) func(http.Handler) http.Hand
//
// See the pprof package documentation for more information.
//
// The path prefix ("/debug/pprof/") can be changed using WithPprofPrefix.
// Note: do not call this function on production servers accessible to the
// public! It exposes sensitive information about the server.
func MountPprofHandlers(mux Muxer) {
mux.HandleFunc("/debug/pprof/", pprof.Index)
mux.HandleFunc("/debug/pprof/cmdline", pprof.Cmdline)
mux.HandleFunc("/debug/pprof/profile", pprof.Profile)
mux.HandleFunc("/debug/pprof/symbol", pprof.Symbol)
mux.HandleFunc("/debug/pprof/trace", pprof.Trace)
func MountPprofHandlers(mux Muxer, opts ...PprofOption) {
o := defaultPprofOptions()
for _, opt := range opts {
opt(o)
}
if !strings.HasPrefix(o.prefix, "/") {
o.prefix = "/" + o.prefix
}
if !strings.HasSuffix(o.prefix, "/") {
o.prefix = o.prefix + "/"
}
mux.HandleFunc(o.prefix, pprof.Index)
mux.HandleFunc(o.prefix+"cmdline", pprof.Cmdline)
mux.HandleFunc(o.prefix+"profile", pprof.Profile)
mux.HandleFunc(o.prefix+"symbol", pprof.Symbol)
mux.HandleFunc(o.prefix+"trace", pprof.Trace)
}

// LogPayloads returns a Goa endpoint middleware that logs request payloads and
Expand All @@ -94,7 +106,7 @@ func MountPprofHandlers(mux Muxer) {
// standard JSON marshaller. It only marshals if debug logs are enabled.
func LogPayloads(opts ...LogPayloadsOption) func(goa.Endpoint) goa.Endpoint {
return func(next goa.Endpoint) goa.Endpoint {
options := defaultOptions()
options := defaultLogPayloadsOptions()
for _, opt := range opts {
if opt != nil {
opt(options)
Expand Down
96 changes: 46 additions & 50 deletions debug/debug_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -15,75 +15,70 @@ import (
)

func TestMountDebugLogEnabler(t *testing.T) {
mux := http.NewServeMux()
var handler http.Handler = http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
if r.URL.Path != "/" {
w.WriteHeader(http.StatusNotFound)
return
}
log.Info(r.Context(), log.KV{K: "test", V: "info"})
log.Debug(r.Context(), log.KV{K: "test", V: "debug"})
w.WriteHeader(http.StatusOK)
w.Write([]byte("OK"))
})
handler = MountDebugLogEnabler("/debug", mux)(handler)
var buf bytes.Buffer
ctx := log.Context(context.Background(), log.WithOutput(&buf), log.WithFormat(logKeyValsOnly))
log.FlushAndDisableBuffering(ctx)
handler = log.HTTP(ctx)(handler)
mux.Handle("/", handler)
ts := httptest.NewServer(mux)
defer ts.Close()

steps := []struct {
cases := []struct {
name string
enable bool
disable bool
prefix string
query string
onval string
offval string
url string
expectedResp string
expectedLogs string
}{
{"default", false, false, "", "test=info "},
{"enable debug", true, false, `{"debug-logs":true}`, "test=info test=debug "},
{"disable debug", false, true, `{"debug-logs":false}`, "test=info "},
{"defaults", "", "", "", "", "/debug", `{"debug-logs":"off"}`},
{"defaults-enable", "", "", "", "", "/debug?debug-logs=on", `{"debug-logs":"on"}`},
{"defaults-disable", "", "", "", "", "/debug?debug-logs=off", `{"debug-logs":"off"}`},
{"prefix", "test", "", "", "", "/test", `{"debug-logs":"off"}`},
{"prefix-enable", "test", "", "", "", "/test?debug-logs=on", `{"debug-logs":"on"}`},
{"prefix-disable", "test", "", "", "", "/test?debug-logs=off", `{"debug-logs":"off"}`},
{"query", "", "debug", "", "", "/debug", `{"debug":"off"}`},
{"query-enable", "", "debug", "", "", "/debug?debug=on", `{"debug":"on"}`},
{"query-disable", "", "debug", "", "", "/debug?debug=off", `{"debug":"off"}`},
{"onval-enable", "", "", "foo", "", "/debug?debug-logs=foo", `{"debug-logs":"foo"}`},
{"offval-disable", "", "", "", "bar", "/debug?debug-logs=bar", `{"debug-logs":"bar"}`},
{"prefix-query-enable", "test", "debug", "", "", "/test?debug=on", `{"debug":"on"}`},
{"prefix-query-disable", "test", "debug", "", "", "/test?debug=off", `{"debug":"off"}`},
{"prefix-onval-enable", "test", "", "foo", "", "/test?debug-logs=foo", `{"debug-logs":"foo"}`},
{"prefix-offval-disable", "test", "", "", "bar", "/test?debug-logs=bar", `{"debug-logs":"bar"}`},
{"prefix-query-onval-enable", "test", "debug", "foo", "", "/test?debug=foo", `{"debug":"foo"}`},
{"prefix-query-offval-disable", "test", "debug", "", "bar", "/test?debug=bar", `{"debug":"bar"}`},
}

for _, c := range steps {
if c.enable {
status, resp := makeRequest(t, ts.URL+"/debug?debug-logs=true")
if status != http.StatusOK {
t.Errorf("%s: got status %d, expected %d", c.name, status, http.StatusOK)
for _, c := range cases {
t.Run(c.name, func(t *testing.T) {
mux := http.NewServeMux()
var options []DebugLogEnablerOption
if c.prefix != "" {
options = append(options, WithPath(c.prefix))
}
if resp != c.expectedResp {
t.Errorf("%s: got body %q, expected %q", c.name, resp, c.expectedResp)
if c.query != "" {
options = append(options, WithQuery(c.query))
}
}
if c.disable {
status, resp := makeRequest(t, ts.URL+"/debug?debug-logs=false")
if c.onval != "" {
options = append(options, WithOnValue(c.onval))
}
if c.offval != "" {
options = append(options, WithOffValue(c.offval))
}
MountDebugLogEnabler(mux, options...)
ts := httptest.NewServer(mux)
defer ts.Close()

status, resp := makeRequest(t, ts.URL+c.url)

if status != http.StatusOK {
t.Errorf("%s: got status %d, expected %d", c.name, status, http.StatusOK)
}
if resp != c.expectedResp {
t.Errorf("%s: got body %q, expected %q", c.name, resp, c.expectedResp)
}
}
buf.Reset()

status, resp := makeRequest(t, ts.URL)
if status != http.StatusOK {
t.Errorf("%s: got status %d, expected %d", c.name, status, http.StatusOK)
}
if resp != "OK" {
t.Errorf("%s: got body %q, expected %q", c.name, resp, "OK")
}
if buf.String() != c.expectedLogs {
t.Errorf("%s: got logs %q, expected %q", c.name, buf.String(), c.expectedLogs)
}
})
}
}

func TestMountPprofHandlers(t *testing.T) {
mux := http.NewServeMux()
MountPprofHandlers(mux)
MountPprofHandlers(mux, WithPrefix("test"))
var handler http.Handler = http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
if r.URL.Path != "/" {
w.WriteHeader(http.StatusNotFound)
Expand All @@ -106,6 +101,7 @@ func TestMountPprofHandlers(t *testing.T) {

paths := []string{
"/debug/pprof/",
"/test/",
"/debug/pprof/allocs",
"/debug/pprof/block",
"/debug/pprof/cmdline",
Expand Down
6 changes: 4 additions & 2 deletions debug/grpc.go
Original file line number Diff line number Diff line change
Expand Up @@ -9,7 +9,8 @@ import (
)

// UnaryServerInterceptor return an interceptor that manages whether debug log
// entries are written.
// entries are written. This interceptor should be used in conjunction with the
// MountDebugLogEnabler function.
func UnaryServerInterceptor() grpc.UnaryServerInterceptor {
return func(
ctx context.Context,
Expand All @@ -28,7 +29,8 @@ func UnaryServerInterceptor() grpc.UnaryServerInterceptor {

// StreamServerInterceptor returns a stream interceptor that manages whether
// debug log entries are written. Note: a change in the debug setting is
// effective only for the next stream request.
// effective only for the next stream request. This interceptor should be used
// in conjunction with the MountDebugLogEnabler function.
func StreamServerInterceptor() grpc.StreamServerInterceptor {
return func(
srv interface{},
Expand Down
Loading

0 comments on commit 775b8fc

Please sign in to comment.