From b47e376e2b17e5fe36e89372a764aea7d46d1a28 Mon Sep 17 00:00:00 2001 From: Raphael Simon Date: Tue, 5 Sep 2023 19:57:26 -0700 Subject: [PATCH] Update HTTP and gRPC log middleware/interceptor to log each request and response status. This replaces the use of the Goa HTTP middleware and adds logs for gRPC. This PR also switches to golangci-lint for linting. --- debug/debug.go | 7 +- debug/debug_test.go | 6 +- debug/goa_test.go | 8 +- debug/grpc.go | 4 +- debug/grpc_test.go | 8 +- debug/http_test.go | 18 +- debug/options.go | 3 +- .../forecaster/cmd/forecaster/main.go | 11 +- .../front/clients/forecaster/client.go | 2 +- .../weather/services/front/cmd/front/main.go | 8 +- .../services/locator/cmd/locator/main.go | 11 +- .../weather/services/locator/locator_test.go | 2 +- health/handler.go | 2 +- internal/testsvc/grpc_testing.go | 2 +- log/adapt_test.go | 2 +- log/format.go | 24 +- log/grpc.go | 125 +++++++--- log/grpc_test.go | 234 +++++++++++++----- log/http.go | 56 ++++- log/http_test.go | 67 +++-- log/keys.go | 2 + log/log.go | 6 +- log/log_test.go | 2 +- log/options_test.go | 2 +- metrics/grpc_test.go | 2 +- scripts/cibuild | 4 +- scripts/setup | 9 +- scripts/test | 10 +- trace/grpc_test.go | 6 +- trace/options.go | 14 +- trace/options_test.go | 13 +- 31 files changed, 467 insertions(+), 203 deletions(-) diff --git a/debug/debug.go b/debug/debug.go index b27fd847..4915c183 100644 --- a/debug/debug.go +++ b/debug/debug.go @@ -22,9 +22,6 @@ type Muxer interface { var ( // debugLogs is true if debug logs should be enabled. debugLogs bool - - // pprofEnabled is true if pprof handlers are enabled. - pprofEnabled bool ) // MountDebugLogEnabler mounts an endpoint under "/debug" and returns a HTTP @@ -54,9 +51,9 @@ func MountDebugLogEnabler(mux Muxer, opts ...DebugLogEnablerOption) { debugLogs = false } if debugLogs { - w.Write([]byte(fmt.Sprintf(`{"%s":"%s"}`, o.query, o.onval))) + w.Write([]byte(fmt.Sprintf(`{"%s":"%s"}`, o.query, o.onval))) // nolint: errcheck } else { - w.Write([]byte(fmt.Sprintf(`{"%s":"%s"}`, o.query, o.offval))) + w.Write([]byte(fmt.Sprintf(`{"%s":"%s"}`, o.query, o.offval))) // nolint: errcheck } })) } diff --git a/debug/debug_test.go b/debug/debug_test.go index b5fe500d..49570e46 100644 --- a/debug/debug_test.go +++ b/debug/debug_test.go @@ -85,7 +85,7 @@ func TestMountPprofHandlers(t *testing.T) { return } w.WriteHeader(http.StatusOK) - w.Write([]byte("OK")) + w.Write([]byte("OK")) // nolint: errcheck }) mux.Handle("/", handler) ts := httptest.NewServer(mux) @@ -159,7 +159,7 @@ func TestDebugPayloads(t *testing.T) { for _, c := range cases { t.Run(c.name, func(t *testing.T) { buf.Reset() - svc.HTTPFunc = func(ctx context.Context, f *testsvc.Fields) (*testsvc.Fields, error) { + svc.HTTPFunc = func(_ context.Context, f *testsvc.Fields) (*testsvc.Fields, error) { if c.expectedErr != "" { return nil, errors.New(c.expectedErr) } @@ -209,6 +209,6 @@ func makeRequest(t *testing.T, url string) (int, string) { } defer res.Body.Close() buf := new(bytes.Buffer) - buf.ReadFrom(res.Body) + buf.ReadFrom(res.Body) // nolint: errcheck return res.StatusCode, buf.String() } diff --git a/debug/goa_test.go b/debug/goa_test.go index 3b4c0af3..548a999a 100644 --- a/debug/goa_test.go +++ b/debug/goa_test.go @@ -12,13 +12,13 @@ import ( func TestAdapt(t *testing.T) { mux := goahttp.NewMuxer() adapted := Adapt(mux) - adapted.HandleFunc("/", func(w http.ResponseWriter, r *http.Request) { + adapted.HandleFunc("/", func(w http.ResponseWriter, _ *http.Request) { w.WriteHeader(http.StatusOK) - w.Write([]byte("OK")) + w.Write([]byte("OK")) // nolint: errcheck }) - adapted.Handle("/foo", http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + adapted.Handle("/foo", http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { w.WriteHeader(http.StatusOK) - w.Write([]byte("FOO")) + w.Write([]byte("FOO")) // nolint: errcheck })) req := &http.Request{Method: "GET", URL: &url.URL{Path: "/"}} w := httptest.NewRecorder() diff --git a/debug/grpc.go b/debug/grpc.go index 9b3fdd88..3d48e1d3 100644 --- a/debug/grpc.go +++ b/debug/grpc.go @@ -15,7 +15,7 @@ func UnaryServerInterceptor() grpc.UnaryServerInterceptor { return func( ctx context.Context, req interface{}, - info *grpc.UnaryServerInfo, + _ *grpc.UnaryServerInfo, handler grpc.UnaryHandler, ) (interface{}, error) { if debugLogs { @@ -35,7 +35,7 @@ func StreamServerInterceptor() grpc.StreamServerInterceptor { return func( srv interface{}, stream grpc.ServerStream, - info *grpc.StreamServerInfo, + _ *grpc.StreamServerInfo, handler grpc.StreamHandler, ) error { ctx := stream.Context() diff --git a/debug/grpc_test.go b/debug/grpc_test.go index 6512a19e..b902983b 100644 --- a/debug/grpc_test.go +++ b/debug/grpc_test.go @@ -17,7 +17,9 @@ func TestUnaryServerInterceptor(t *testing.T) { var buf bytes.Buffer ctx := log.Context(context.Background(), log.WithOutput(&buf), log.WithFormat(logKeyValsOnly)) cli, stop := testsvc.SetupGRPC(t, - testsvc.WithServerOptions(grpc.ChainUnaryInterceptor(log.UnaryServerInterceptor(ctx), UnaryServerInterceptor())), + testsvc.WithServerOptions(grpc.ChainUnaryInterceptor( + log.UnaryServerInterceptor(ctx, log.WithDisableCallLogging()), + UnaryServerInterceptor())), testsvc.WithUnaryFunc(logUnaryMethod)) defer stop() mux := http.NewServeMux() @@ -59,7 +61,9 @@ func TestStreamServerInterceptor(t *testing.T) { var buf bytes.Buffer ctx := log.Context(context.Background(), log.WithOutput(&buf), log.WithFormat(logKeyValsOnly)) cli, stop := testsvc.SetupGRPC(t, - testsvc.WithServerOptions(grpc.ChainStreamInterceptor(log.StreamServerInterceptor(ctx), StreamServerInterceptor())), + testsvc.WithServerOptions(grpc.ChainStreamInterceptor( + log.StreamServerInterceptor(ctx, log.WithDisableCallLogging()), + StreamServerInterceptor())), testsvc.WithStreamFunc(echoMethod)) defer stop() steps := []struct { diff --git a/debug/http_test.go b/debug/http_test.go index 9c0cdf4a..3148e1e3 100644 --- a/debug/http_test.go +++ b/debug/http_test.go @@ -11,6 +11,12 @@ import ( ) func TestHTTP(t *testing.T) { + // Create log context + var buf bytes.Buffer + ctx := log.Context(context.Background(), log.WithOutput(&buf), log.WithFormat(logKeyValsOnly)) + log.FlushAndDisableBuffering(ctx) + + // Create HTTP handler mux := http.NewServeMux() var handler http.Handler = http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { if r.URL.Path != "/" { @@ -20,17 +26,19 @@ func TestHTTP(t *testing.T) { 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")) + w.Write([]byte("OK")) // nolint: errcheck }) + + // Mount debug handler and log middleware MountDebugLogEnabler(mux) - var buf bytes.Buffer - ctx := log.Context(context.Background(), log.WithOutput(&buf), log.WithFormat(logKeyValsOnly)) - log.FlushAndDisableBuffering(ctx) handler = HTTP()(handler) - handler = log.HTTP(ctx)(handler) + handler = log.HTTP(ctx, log.WithDisableRequestLogging())(handler) + + // Start test server mux.Handle("/", handler) ts := httptest.NewServer(mux) defer ts.Close() + steps := []struct { name string on bool diff --git a/debug/options.go b/debug/options.go index d49f853f..cd8d2a33 100644 --- a/debug/options.go +++ b/debug/options.go @@ -27,7 +27,6 @@ type ( maxsize int // maximum number of bytes in a single log message or value format FormatFunc client bool - prefix string } dleOptions struct { @@ -108,7 +107,7 @@ func WithOffValue(offval string) DebugLogEnablerOption { } // FormatJSON returns a function that formats the given value as JSON. -func FormatJSON(ctx context.Context, v interface{}) string { +func FormatJSON(_ context.Context, v interface{}) string { js, err := json.Marshal(v) if err != nil { return fmt.Sprintf("", err) diff --git a/example/weather/services/forecaster/cmd/forecaster/main.go b/example/weather/services/forecaster/cmd/forecaster/main.go index 28ae6d45..d313502b 100644 --- a/example/weather/services/forecaster/cmd/forecaster/main.go +++ b/example/weather/services/forecaster/cmd/forecaster/main.go @@ -12,7 +12,6 @@ import ( "syscall" "time" - grpcmiddleware "github.com/grpc-ecosystem/go-grpc-middleware" "goa.design/clue/debug" "goa.design/clue/health" "goa.design/clue/log" @@ -45,7 +44,7 @@ func main() { format = log.FormatTerminal } ctx := log.Context(context.Background(), log.WithFormat(format), log.WithFunc(trace.Log)) - ctx = log.With(ctx, log.KV{"svc", genforecaster.ServiceName}) + ctx = log.With(ctx, log.KV{K: "svc", V: genforecaster.ServiceName}) if *debugf { ctx = log.Context(ctx, log.WithDebug()) log.Debugf(ctx, "debug logs enabled") @@ -83,7 +82,7 @@ func main() { // 6. Create transport server := gengrpc.New(endpoints, nil) grpcsvr := grpc.NewServer( - grpcmiddleware.WithUnaryServerChain( + grpc.ChainUnaryInterceptor( goagrpcmiddleware.UnaryRequestID(), log.UnaryServerInterceptor(ctx), debug.UnaryServerInterceptor(), @@ -95,7 +94,7 @@ func main() { reflection.Register(grpcsvr) for svc, info := range grpcsvr.GetServiceInfo() { for _, m := range info.Methods { - log.Print(ctx, log.KV{"method", svc + "/" + m.Name}) + log.Print(ctx, log.KV{K: "method", V: svc + "/" + m.Name}) } } @@ -147,7 +146,9 @@ func main() { defer cancel() grpcsvr.GracefulStop() - httpsvr.Shutdown(ctx) + if err := httpsvr.Shutdown(ctx); err != nil { + log.Errorf(ctx, err, "failed to shutdown HTTP server") + } }() // Cleanup diff --git a/example/weather/services/front/clients/forecaster/client.go b/example/weather/services/front/clients/forecaster/client.go index 2c010af1..94ccf325 100644 --- a/example/weather/services/front/clients/forecaster/client.go +++ b/example/weather/services/front/clients/forecaster/client.go @@ -69,7 +69,7 @@ func New(cc *grpc.ClientConn) Client { // Forecast returns the forecast for the given location or current location if // lat or long are nil. func (c *client) GetForecast(ctx context.Context, lat, long float64) (*Forecast, error) { - res, err := c.forecast(ctx, &genforecast.ForecastPayload{lat, long}) + res, err := c.forecast(ctx, &genforecast.ForecastPayload{Lat: lat, Long: long}) if err != nil { return nil, err } diff --git a/example/weather/services/front/cmd/front/main.go b/example/weather/services/front/cmd/front/main.go index d29caa1b..0bb9987c 100644 --- a/example/weather/services/front/cmd/front/main.go +++ b/example/weather/services/front/cmd/front/main.go @@ -161,8 +161,12 @@ func main() { ctx, cancel := context.WithTimeout(context.Background(), 30*time.Second) defer cancel() - httpServer.Shutdown(ctx) - metricsServer.Shutdown(ctx) + if err := httpServer.Shutdown(ctx); err != nil { + log.Errorf(ctx, err, "failed to shutdown HTTP server") + } + if err := metricsServer.Shutdown(ctx); err != nil { + log.Errorf(ctx, err, "failed to shutdown metrics server") + } }() // Cleanup diff --git a/example/weather/services/locator/cmd/locator/main.go b/example/weather/services/locator/cmd/locator/main.go index 401a0fb9..04b27c52 100644 --- a/example/weather/services/locator/cmd/locator/main.go +++ b/example/weather/services/locator/cmd/locator/main.go @@ -12,7 +12,6 @@ import ( "syscall" "time" - grpcmiddleware "github.com/grpc-ecosystem/go-grpc-middleware" "goa.design/clue/debug" "goa.design/clue/health" "goa.design/clue/log" @@ -45,7 +44,7 @@ func main() { format = log.FormatTerminal } ctx := log.Context(context.Background(), log.WithFormat(format), log.WithFunc(trace.Log)) - ctx = log.With(ctx, log.KV{"svc", genlocator.ServiceName}) + ctx = log.With(ctx, log.KV{K: "svc", V: genlocator.ServiceName}) if *debugf { ctx = log.Context(ctx, log.WithDebug()) log.Debugf(ctx, "debug logs enabled") @@ -83,7 +82,7 @@ func main() { // 6. Create transport server := gengrpc.New(endpoints, nil) grpcsvr := grpc.NewServer( - grpcmiddleware.WithUnaryServerChain( + grpc.ChainUnaryInterceptor( goagrpcmiddleware.UnaryRequestID(), log.UnaryServerInterceptor(ctx), debug.UnaryServerInterceptor(), @@ -95,7 +94,7 @@ func main() { reflection.Register(grpcsvr) for svc, info := range grpcsvr.GetServiceInfo() { for _, m := range info.Methods { - log.Print(ctx, log.KV{"method", svc + "/" + m.Name}) + log.Print(ctx, log.KV{K: "method", V: svc + "/" + m.Name}) } } @@ -147,7 +146,9 @@ func main() { defer cancel() grpcsvr.GracefulStop() - httpsvr.Shutdown(ctx) + if err := httpsvr.Shutdown(ctx); err != nil { + log.Errorf(ctx, err, "failed to shutdown HTTP server") + } }() // Cleanup diff --git a/example/weather/services/locator/locator_test.go b/example/weather/services/locator/locator_test.go index db218ff0..cc2de40f 100644 --- a/example/weather/services/locator/locator_test.go +++ b/example/weather/services/locator/locator_test.go @@ -21,7 +21,7 @@ func TestGetIPLocation(t *testing.T) { // location then failing. ipc := mockipapi.NewClient(t) ipc.AddGetLocation(func(ctx context.Context, ip string) (*ipapi.WorldLocation, error) { - return &ipapi.WorldLocation{testLat, testLong, testCity, testRegion, testCountry}, nil + return &ipapi.WorldLocation{Lat: testLat, Long: testLong, City: testCity, Region: testRegion, Country: testCountry}, nil }) ipc.AddGetLocation(func(ctx context.Context, ip string) (*ipapi.WorldLocation, error) { return nil, fmt.Errorf("test failure") diff --git a/health/handler.go b/health/handler.go index 84bc083d..761b00e7 100644 --- a/health/handler.go +++ b/health/handler.go @@ -18,6 +18,6 @@ func Handler(chk Checker) http.HandlerFunc { } else { w.WriteHeader(http.StatusServiceUnavailable) } - w.Write(b) + w.Write(b) // nolint: errcheck }) } diff --git a/internal/testsvc/grpc_testing.go b/internal/testsvc/grpc_testing.go index af8b5f36..6e9ceac0 100644 --- a/internal/testsvc/grpc_testing.go +++ b/internal/testsvc/grpc_testing.go @@ -59,7 +59,7 @@ func SetupGRPC(t *testing.T, opts ...GRPCOption) (c GRPClient, stop func()) { if err != nil { t.Fatal(err) } - go server.Serve(l) + go server.Serve(l) // nolint: errcheck // Connect to in-memory server dialOptions := append(options.dialOptions, grpc.WithTransportCredentials(insecure.NewCredentials())) diff --git a/log/adapt_test.go b/log/adapt_test.go index 784df88b..41b47b26 100644 --- a/log/adapt_test.go +++ b/log/adapt_test.go @@ -18,7 +18,7 @@ func TestAsGoaMiddlwareLogger(t *testing.T) { var buf bytes.Buffer ctx := Context(context.Background(), WithOutput(&buf)) logger := AsGoaMiddlewareLogger(ctx) - logger.Log("msg", "hello world") + assert.NoError(t, logger.Log("msg", "hello world")) want := "time=2022-01-09T20:29:45Z level=info msg=\"hello world\"\n" assert.Equal(t, buf.String(), want) } diff --git a/log/format.go b/log/format.go index e5d2074a..3bdc91dc 100644 --- a/log/format.go +++ b/log/format.go @@ -27,7 +27,7 @@ var TimestampFormatLayout = time.RFC3339 // FormatText is the default log formatter when not running in a terminal, it // prints entries using the logfmt format: // -// time=TIME level=SEVERITY KEY=VAL KEY=VAL ... +// time=TIME level=SEVERITY KEY=VAL KEY=VAL ... // // Where TIME is the UTC timestamp in RFC3339 format, SEVERITY is one of // "debug", "info" or "error", and KEY=VAL are the entry key/value pairs. @@ -38,8 +38,8 @@ var TimestampFormatLayout = time.RFC3339 func FormatText(e *Entry) []byte { var b bytes.Buffer enc := logfmt.NewEncoder(&b) - enc.EncodeKeyval(TimestampKey, e.Time.Format(TimestampFormatLayout)) - enc.EncodeKeyval(SeverityKey, e.Severity) + enc.EncodeKeyval(TimestampKey, e.Time.Format(TimestampFormatLayout)) // nolint: errcheck + enc.EncodeKeyval(SeverityKey, e.Severity) // nolint: errcheck for _, kv := range e.KeyVals { // Make logfmt format slices v := kv.V @@ -49,7 +49,7 @@ func FormatText(e *Entry) []byte { writeJSON(kv.V, &buf) v = buf.String() } - enc.EncodeKeyval(kv.K, v) + enc.EncodeKeyval(kv.K, v) // nolint: errcheck } b.WriteByte('\n') return b.Bytes() @@ -58,13 +58,13 @@ func FormatText(e *Entry) []byte { // FormatJSON is a log formatter that prints entries using JSON. Entries are // formatted as follows: // -// { -// "time": "TIMESTAMP", // UTC timestamp in RFC3339 format -// "level": "SEVERITY", // one of DEBUG, INFO or ERROR -// "key1": "val1", // entry key/value pairs -// "key2": "val2", -// ... -// } +// { +// "time": "TIMESTAMP", // UTC timestamp in RFC3339 format +// "level": "SEVERITY", // one of DEBUG, INFO or ERROR +// "key1": "val1", // entry key/value pairs +// "key2": "val2", +// ... +// } // // note: the implementation avoids using reflection (and thus the json package) // for efficiency. @@ -101,7 +101,7 @@ func FormatJSON(e *Entry) []byte { // FormatTerminal is a log formatter that prints entries suitable for terminal // that supports colors. It prints entries in the following format: // -// SEVERITY[seconds] key=val key=val ... +// SEVERITY[seconds] key=val key=val ... // // Where SEVERITY is one of DEBG, INFO or ERRO, seconds is the number of seconds // since the application started, message is the log message, and key=val are diff --git a/log/grpc.go b/log/grpc.go index 94f573fd..5154f4e7 100644 --- a/log/grpc.go +++ b/log/grpc.go @@ -12,20 +12,31 @@ import ( ) type ( + // GRPCLogOption is a function that applies a configuration option + // to a GRPC interceptor logger. + GRPCLogOption func(*grpcOptions) + // GRPCClientLogOption is a function that applies a configuration option // to a GRPC client interceptor logger. - GRPCClientLogOption func(*grpcOptions) + // Deprecated: Use GRPCLogOption instead. + GRPCClientLogOption = GRPCLogOption grpcOptions struct { - iserr func(codes.Code) bool + iserr func(codes.Code) bool + disableCallLogging bool } ) -// UnaryServerInterceptor return an interceptor that configured the request -// context with the logger contained in logCtx. It panics if logCtx was not -// initialized with Context. -func UnaryServerInterceptor(logCtx context.Context) grpc.UnaryServerInterceptor { +// UnaryServerInterceptor returns a unary interceptor that performs two tasks: +// 1. Enriches the request context with the logger specified in logCtx. +// 2. Logs details of the unary call, unless the WithDisableCallLogging option is provided. +// UnaryServerInterceptor panics if logCtx was not created with Context. +func UnaryServerInterceptor(logCtx context.Context, opts ...GRPCLogOption) grpc.UnaryServerInterceptor { MustContainLogger(logCtx) + o := defaultGRPCOptions() + for _, opt := range opts { + opt(o) + } return func( ctx context.Context, req interface{}, @@ -36,15 +47,40 @@ func UnaryServerInterceptor(logCtx context.Context) grpc.UnaryServerInterceptor if reqID := ctx.Value(goamiddleware.RequestIDKey); reqID != nil { ctx = With(ctx, KV{RequestIDKey, reqID}) } - return handler(ctx, req) + if o.disableCallLogging { + return handler(ctx, req) + } + then := time.Now() + svcKV := KV{K: GRPCServiceKey, V: path.Dir(info.FullMethod)[1:]} + methKV := KV{K: GRPCMethodKey, V: path.Base(info.FullMethod)} + Print(ctx, KV{MessageKey, "start"}, svcKV, methKV) + + res, err := handler(ctx, req) + + stat, _ := status.FromError(err) + ms := timeSince(then).Milliseconds() + codeKV := KV{K: GRPCCodeKey, V: stat.Code()} + durKV := KV{K: GRPCDurationKey, V: ms} + if o.iserr(stat.Code()) { + statKV := KV{K: GRPCStatusKey, V: stat.Message()} + Error(ctx, err, svcKV, methKV, statKV, codeKV, durKV) + return res, err + } + Print(ctx, KV{MessageKey, "end"}, svcKV, methKV, codeKV, durKV) + return res, err } } -// StreamServerInterceptor returns a stream interceptor that configures the -// request context with the logger contained in logCtx. It panics if logCtx -// was not initialized with Context. -func StreamServerInterceptor(logCtx context.Context) grpc.StreamServerInterceptor { +// StreamServerInterceptor returns a stream interceptor that performs two tasks: +// 1. Enriches the request context with the logger specified in logCtx. +// 2. Logs details of the stream call, unless the WithDisableCallLogging option is provided. +// StreamServerInterceptor panics if logCtx was not created with Context. +func StreamServerInterceptor(logCtx context.Context, opts ...GRPCLogOption) grpc.StreamServerInterceptor { MustContainLogger(logCtx) + o := defaultGRPCOptions() + for _, opt := range opts { + opt(o) + } return func( srv interface{}, stream grpc.ServerStream, @@ -55,13 +91,34 @@ func StreamServerInterceptor(logCtx context.Context) grpc.StreamServerIntercepto if reqID := ctx.Value(goamiddleware.RequestIDKey); reqID != nil { ctx = With(ctx, KV{RequestIDKey, reqID}) } - return handler(srv, &streamWithContext{stream, ctx}) + stream = &streamWithContext{stream, ctx} + if o.disableCallLogging { + return handler(srv, stream) + } + then := time.Now() + svcKV := KV{K: GRPCServiceKey, V: path.Dir(info.FullMethod)[1:]} + methKV := KV{K: GRPCMethodKey, V: path.Base(info.FullMethod)} + Print(ctx, KV{MessageKey, "start"}, svcKV, methKV) + + err := handler(srv, stream) + + stat, _ := status.FromError(err) + ms := timeSince(then).Milliseconds() + codeKV := KV{K: GRPCCodeKey, V: stat.Code()} + durKV := KV{K: GRPCDurationKey, V: ms} + if o.iserr(stat.Code()) { + statKV := KV{K: GRPCStatusKey, V: stat.Message()} + Error(ctx, err, svcKV, methKV, statKV, codeKV, durKV) + return err + } + Print(ctx, KV{MessageKey, "end"}, svcKV, methKV, codeKV, durKV) + return err } } // UnaryClientInterceptor returns a unary interceptor that logs the request with // the logger contained in the request context if any. -func UnaryClientInterceptor(opts ...GRPCClientLogOption) grpc.UnaryClientInterceptor { +func UnaryClientInterceptor(opts ...GRPCLogOption) grpc.UnaryClientInterceptor { o := defaultGRPCOptions() for _, opt := range opts { opt(o) @@ -75,29 +132,29 @@ func UnaryClientInterceptor(opts ...GRPCClientLogOption) grpc.UnaryClientInterce opts ...grpc.CallOption, ) error { then := time.Now() - service := path.Dir(fullmethod)[1:] - method := path.Base(fullmethod) + svcKV := KV{K: GRPCServiceKey, V: path.Dir(fullmethod)[1:]} + methKV := KV{K: GRPCMethodKey, V: path.Base(fullmethod)} + Print(ctx, KV{K: MessageKey, V: "start"}, svcKV, methKV) + err := invoker(ctx, fullmethod, req, reply, cc, opts...) + stat, _ := status.FromError(err) ms := timeSince(then).Milliseconds() - msgKV := KV{K: MessageKey, V: "finished client unary call"} - svcKV := KV{K: GRPCServiceKey, V: service} - methKV := KV{K: GRPCMethodKey, V: method} codeKV := KV{K: GRPCCodeKey, V: stat.Code()} durKV := KV{K: GRPCDurationKey, V: ms} if o.iserr(stat.Code()) { statKV := KV{K: GRPCStatusKey, V: stat.Message()} - Error(ctx, err, msgKV, svcKV, methKV, statKV, codeKV, durKV) + Error(ctx, err, svcKV, methKV, statKV, codeKV, durKV) return err } - Print(ctx, msgKV, svcKV, methKV, codeKV, durKV) + Print(ctx, KV{K: MessageKey, V: "end"}, svcKV, methKV, codeKV, durKV) return err } } // StreamClientInterceptor returns a stream interceptor that logs the request // with the logger contained in the request context if any. -func StreamClientInterceptor(opts ...GRPCClientLogOption) grpc.StreamClientInterceptor { +func StreamClientInterceptor(opts ...GRPCLogOption) grpc.StreamClientInterceptor { o := defaultGRPCOptions() for _, opt := range opts { opt(o) @@ -111,32 +168,42 @@ func StreamClientInterceptor(opts ...GRPCClientLogOption) grpc.StreamClientInter opts ...grpc.CallOption, ) (grpc.ClientStream, error) { then := time.Now() - service := path.Dir(fullmethod)[1:] - method := path.Base(fullmethod) + svcKV := KV{K: GRPCServiceKey, V: path.Dir(fullmethod)[1:]} + methKV := KV{K: GRPCMethodKey, V: path.Base(fullmethod)} + Print(ctx, KV{K: MessageKey, V: "start"}, svcKV, methKV) + stream, err := streamer(ctx, desc, cc, fullmethod, opts...) + stat, _ := status.FromError(err) ms := timeSince(then).Milliseconds() - msgKV := KV{K: MessageKey, V: "finished client streaming call"} - svcKV := KV{K: GRPCServiceKey, V: service} - methKV := KV{K: GRPCMethodKey, V: method} codeKV := KV{K: GRPCCodeKey, V: stat.Code()} durKV := KV{K: GRPCDurationKey, V: ms} if o.iserr(stat.Code()) { statKV := KV{K: GRPCStatusKey, V: stat.Message()} - Error(ctx, err, msgKV, svcKV, methKV, statKV, codeKV, durKV) + Error(ctx, err, svcKV, methKV, statKV, codeKV, durKV) return stream, err } - Print(ctx, msgKV, svcKV, methKV, codeKV, durKV) + Print(ctx, KV{K: MessageKey, V: "end"}, svcKV, methKV, codeKV, durKV) return stream, err } } -func WithErrorFunc(iserr func(codes.Code) bool) GRPCClientLogOption { +// WithErrorFunc returns a GRPC logger option that configures the logger to +// consider the given function to determine if a GRPC status code is an error. +func WithErrorFunc(iserr func(codes.Code) bool) GRPCLogOption { return func(o *grpcOptions) { o.iserr = iserr } } +// WithDisableCallLogging returns a GRPC logger option that disables call +// logging. +func WithDisableCallLogging() GRPCLogOption { + return func(o *grpcOptions) { + o.disableCallLogging = true + } +} + func defaultGRPCOptions() *grpcOptions { return &grpcOptions{ iserr: func(c codes.Code) bool { diff --git a/log/grpc_test.go b/log/grpc_test.go index 9d80362c..2d2844d4 100644 --- a/log/grpc_test.go +++ b/log/grpc_test.go @@ -9,11 +9,13 @@ import ( "time" "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" "goa.design/clue/internal/testsvc" grpcmiddleware "goa.design/goa/v3/grpc/middleware" - "goa.design/goa/v3/middleware" + goamiddleware "goa.design/goa/v3/middleware" "google.golang.org/grpc" "google.golang.org/grpc/codes" + "google.golang.org/grpc/status" ) func TestUnaryServerInterceptor(t *testing.T) { @@ -21,28 +23,62 @@ func TestUnaryServerInterceptor(t *testing.T) { timeNow = func() time.Time { return time.Date(2022, time.January, 9, 20, 29, 45, 0, time.UTC) } defer func() { timeNow = now }() - var buf bytes.Buffer - ctx := Context(context.Background(), WithOutput(&buf), WithFormat(FormatJSON)) - logInterceptor := UnaryServerInterceptor(ctx) - requestIDInterceptor := grpcmiddleware.UnaryRequestID() - cli, stop := testsvc.SetupGRPC(t, - testsvc.WithServerOptions(grpc.ChainUnaryInterceptor(requestIDInterceptor, logInterceptor)), - testsvc.WithUnaryFunc(logUnaryMethod)) - f, err := cli.GRPCMethod(context.Background(), &testsvc.Fields{}) - if err != nil { - t.Errorf("unexpected error: %v", err) + testRequestID := "test-request-id" + requestIDInterceptor := unaryStaticRequestIDInterceptor(testRequestID) + + prefix := `{"time":"2022-01-09T20:29:45Z","level":"info","request-id":"test-request-id","msg":"start","grpc.service":"test.Test","grpc.method":"GrpcMethod"}` + logged := `{"time":"2022-01-09T20:29:45Z","level":"info","request-id":"test-request-id","key1":"value1","key2":"value2"}` + suffix := `{"time":"2022-01-09T20:29:45Z","level":"info","request-id":"test-request-id","msg":"end","grpc.service":"test.Test","grpc.method":"GrpcMethod","grpc.code":"OK","grpc.time_ms":0}` + errors := `{"time":"2022-01-09T20:29:45Z","level":"error","request-id":"test-request-id","err":"rpc error: code = Unknown desc = test-error","grpc.service":"test.Test","grpc.method":"GrpcMethod","grpc.status":"test-error","grpc.code":"Unknown","grpc.time_ms":0}` + + cases := []struct { + name string + options []GRPCLogOption + method func(context.Context, *testsvc.Fields) (*testsvc.Fields, error) + expected string + expectedErr string + }{ + { + name: "default", + options: nil, + method: logUnaryMethod, + expected: prefix + "\n" + logged + "\n" + suffix + "\n", + }, + { + name: "with error", + options: []GRPCLogOption{WithErrorFunc(func(codes.Code) bool { return true })}, + method: errorMethod, + expected: prefix + "\n" + errors + "\n", + expectedErr: `rpc error: code = Unknown desc = test-error`, + }, + { + name: "with disable call logging", + options: []GRPCLogOption{WithDisableCallLogging()}, + method: logUnaryMethod, + expected: logged + "\n", + }, } - stop() + for _, c := range cases { + t.Run(c.name, func(t *testing.T) { + var buf bytes.Buffer + ctx := Context(context.Background(), WithOutput(&buf), WithFormat(FormatJSON)) + logInterceptor := UnaryServerInterceptor(ctx, c.options...) + cli, stop := testsvc.SetupGRPC(t, + testsvc.WithServerOptions(grpc.ChainUnaryInterceptor(requestIDInterceptor, logInterceptor)), + testsvc.WithUnaryFunc(c.method)) - expected := fmt.Sprintf("{%s,%s,%s%q,%s,%s}\n", - `"time":"2022-01-09T20:29:45Z"`, - `"level":"info"`, - `"request-id":`, - *f.S, - `"key1":"value1"`, - `"key2":"value2"`) + _, err := cli.GRPCMethod(context.Background(), &testsvc.Fields{}) - assert.Equal(t, expected, buf.String()) + if c.expectedErr != "" { + require.Error(t, err) + assert.Equal(t, c.expectedErr, err.Error()) + } else { + require.NoError(t, err) + } + assert.Equal(t, c.expected, buf.String()) + stop() + }) + } } func TestStreamServerTrace(t *testing.T) { @@ -50,53 +86,100 @@ func TestStreamServerTrace(t *testing.T) { timeNow = func() time.Time { return time.Date(2022, time.January, 9, 20, 29, 45, 0, time.UTC) } defer func() { timeNow = now }() - var buf bytes.Buffer - ctx := Context(context.Background(), WithOutput(&buf), WithFormat(FormatJSON)) - traceInterceptor := StreamServerInterceptor(ctx) - requestIDInterceptor := grpcmiddleware.StreamRequestID() - cli, stop := testsvc.SetupGRPC(t, - testsvc.WithServerOptions(grpc.ChainStreamInterceptor(requestIDInterceptor, traceInterceptor)), - testsvc.WithStreamFunc(echoMethod)) - stream, err := cli.GRPCStream(context.Background()) - if err != nil { - t.Errorf("unexpected stream error: %v", err) - } - if err := stream.Send(&testsvc.Fields{}); err != nil { - t.Errorf("unexpected send error: %v", err) + testRequestID := "test-request-id" + requestIDInterceptor := streamStaticRequestIDInterceptor(testRequestID) + + prefix := `{"time":"2022-01-09T20:29:45Z","level":"info","request-id":"test-request-id","msg":"start","grpc.service":"test.Test","grpc.method":"GrpcStream"}` + logged := `{"time":"2022-01-09T20:29:45Z","level":"info","request-id":"test-request-id","key1":"value1","key2":"value2"}` + suffix := `{"time":"2022-01-09T20:29:45Z","level":"info","request-id":"test-request-id","msg":"end","grpc.service":"test.Test","grpc.method":"GrpcStream","grpc.code":"OK","grpc.time_ms":0}` + errors := `{"time":"2022-01-09T20:29:45Z","level":"error","request-id":"test-request-id","err":"rpc error: code = Unknown desc = test-error","grpc.service":"test.Test","grpc.method":"GrpcStream","grpc.status":"test-error","grpc.code":"Unknown","grpc.time_ms":0}` + + cases := []struct { + name string + options []GRPCLogOption + method func(context.Context, testsvc.Stream) error + expected string + expectedErr string + }{ + { + name: "default", + options: nil, + method: echoMethod, + expected: prefix + "\n" + logged + "\n" + suffix + "\n", + }, + { + name: "with error", + options: []GRPCLogOption{WithErrorFunc(func(codes.Code) bool { return true })}, + method: echoErrorMethod, + expected: prefix + "\n" + errors + "\n", + expectedErr: `rpc error: code = Unknown desc = test-error`, + }, + { + name: "with disable call logging", + options: []GRPCLogOption{WithDisableCallLogging()}, + method: echoMethod, + expected: logged + "\n", + }, } - f, err := stream.Recv() - if err != nil { - t.Errorf("unexpected recv error: %v", err) + for _, c := range cases { + t.Run(c.name, func(t *testing.T) { + var buf bytes.Buffer + ctx := Context(context.Background(), WithOutput(&buf), WithFormat(FormatJSON)) + logInterceptor := StreamServerInterceptor(ctx, c.options...) + cli, stop := testsvc.SetupGRPC(t, + testsvc.WithServerOptions(grpc.ChainStreamInterceptor(requestIDInterceptor, logInterceptor)), + testsvc.WithStreamFunc(c.method)) + + stream, err := cli.GRPCStream(context.Background()) + + require.NoError(t, err) + err = stream.Send(&testsvc.Fields{}) + assert.NoError(t, err) + _, err = stream.Recv() + if c.expectedErr != "" { + require.Error(t, err) + assert.Equal(t, c.expectedErr, err.Error()) + } else { + assert.NoError(t, err) + } + stop() + assert.Equal(t, c.expected, buf.String()) + }) } - reqID := *f.S - stop() - - expected := fmt.Sprintf("{%s,%s,%s%q,%s,%s}\n", - `"time":"2022-01-09T20:29:45Z"`, - `"level":"info"`, - `"request-id":`, - reqID, - `"key1":"value1"`, - `"key2":"value2"`) - - assert.Equal(t, expected, buf.String()) } func TestUnaryClientInterceptor(t *testing.T) { - successLogs := `time=2022-01-09T20:29:45Z level=info msg="finished client unary call" grpc.service=test.Test grpc.method=GrpcMethod grpc.code=OK grpc.time_ms=42` - errorLogs := `time=2022-01-09T20:29:45Z level=error err="rpc error: code = Unknown desc = error" msg="finished client unary call" grpc.service=test.Test grpc.method=GrpcMethod grpc.status=error grpc.code=Unknown grpc.time_ms=42` - statusLogs := `time=2022-01-09T20:29:45Z level=error err="rpc error: code = Unknown desc = error" msg="finished client unary call" grpc.service=test.Test grpc.method=GrpcMethod grpc.status=error grpc.code=Unknown grpc.time_ms=42` + startLog := `time=2022-01-09T20:29:45Z level=info msg=start grpc.service=test.Test grpc.method=GrpcMethod` + endLog := `time=2022-01-09T20:29:45Z level=info msg=end grpc.service=test.Test grpc.method=GrpcMethod grpc.code=OK grpc.time_ms=42` + errorLog := `time=2022-01-09T20:29:45Z level=error err="rpc error: code = Unknown desc = error" grpc.service=test.Test grpc.method=GrpcMethod grpc.status=error grpc.code=Unknown grpc.time_ms=42` + statusLog := `time=2022-01-09T20:29:45Z level=error err="rpc error: code = Unknown desc = error" grpc.service=test.Test grpc.method=GrpcMethod grpc.status=error grpc.code=Unknown grpc.time_ms=42` cases := []struct { name string noLog bool clientErr error - opt GRPCClientLogOption + opt GRPCLogOption expected string }{ - {"no logger", true, nil, nil, ""}, - {"success", false, nil, nil, successLogs}, - {"error", false, fmt.Errorf("error"), nil, errorLogs}, - {"with status", false, fmt.Errorf("error"), WithErrorFunc(func(codes.Code) bool { return true }), statusLogs}, + { + name: "no logger", + noLog: true, + expected: "", + }, + { + name: "success", + expected: startLog + "\n" + endLog, + }, + { + name: "error", + clientErr: fmt.Errorf("error"), + expected: startLog + "\n" + errorLog, + }, + { + name: "with status", + clientErr: fmt.Errorf("error"), + opt: WithErrorFunc(func(codes.Code) bool { return true }), + expected: startLog + "\n" + statusLog, + }, } now := timeNow timeNow = func() time.Time { return time.Date(2022, time.January, 9, 20, 29, 45, 0, time.UTC) } @@ -122,23 +205,24 @@ func TestUnaryClientInterceptor(t *testing.T) { grpc.WithUnaryInterceptor(UnaryClientInterceptor()))) } cli, stop := testsvc.SetupGRPC(t, opts...) - cli.GRPCMethod(ctx, &testsvc.Fields{}) + cli.GRPCMethod(ctx, &testsvc.Fields{}) // nolint:errcheck stop() - assert.Equal(t, strings.TrimSpace(buf.String()), c.expected) + assert.Equal(t, c.expected, strings.TrimSpace(buf.String())) }) } } func TestStreamClientInterceptor(t *testing.T) { - successLogs := `time=2022-01-09T20:29:45Z level=info msg="finished client streaming call" grpc.service=test.Test grpc.method=GrpcStream grpc.code=OK grpc.time_ms=42` + startLog := `time=2022-01-09T20:29:45Z level=info msg=start grpc.service=test.Test grpc.method=GrpcStream` + endLog := `time=2022-01-09T20:29:45Z level=info msg=end grpc.service=test.Test grpc.method=GrpcStream grpc.code=OK grpc.time_ms=42` cases := []struct { name string noLog bool expected string }{ {"no logger", true, ""}, - {"success", false, successLogs}, + {"success", false, startLog + "\n" + endLog}, } now := timeNow timeNow = func() time.Time { return time.Date(2022, time.January, 9, 20, 29, 45, 0, time.UTC) } @@ -172,17 +256,21 @@ func TestStreamClientInterceptor(t *testing.T) { func logUnaryMethod(ctx context.Context, _ *testsvc.Fields) (*testsvc.Fields, error) { Print(ctx, KV{"key1", "value1"}, KV{"key2", "value2"}) - reqID := ctx.Value(middleware.RequestIDKey).(string) + reqID := ctx.Value(goamiddleware.RequestIDKey).(string) return &testsvc.Fields{S: &reqID}, nil } +func errorMethod(ctx context.Context, _ *testsvc.Fields) (*testsvc.Fields, error) { + return nil, status.Error(codes.Unknown, "test-error") +} + func echoMethod(ctx context.Context, stream testsvc.Stream) (err error) { Print(ctx, KV{"key1", "value1"}, KV{"key2", "value2"}) f, err := stream.Recv() if err != nil { return err } - reqID := ctx.Value(middleware.RequestIDKey).(string) + reqID := ctx.Value(goamiddleware.RequestIDKey).(string) f.S = &reqID if err := stream.Send(f); err != nil { return err @@ -190,6 +278,13 @@ func echoMethod(ctx context.Context, stream testsvc.Stream) (err error) { return stream.Close() } +func echoErrorMethod(ctx context.Context, stream testsvc.Stream) error { + if _, err := stream.Recv(); err != nil { + return err + } + return status.Error(codes.Unknown, "test-error") +} + func dummyMethod(err error) func(context.Context, *testsvc.Fields) (*testsvc.Fields, error) { return func(ctx context.Context, _ *testsvc.Fields) (*testsvc.Fields, error) { return &testsvc.Fields{}, err @@ -201,3 +296,18 @@ func dummyStreamMethod() func(context.Context, testsvc.Stream) error { return stream.Close() } } + +func unaryStaticRequestIDInterceptor(id string) grpc.UnaryServerInterceptor { + return func(ctx context.Context, req interface{}, _ *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (interface{}, error) { + ctx = context.WithValue(ctx, goamiddleware.RequestIDKey, id) // nolint:staticcheck + return handler(ctx, req) + } +} + +func streamStaticRequestIDInterceptor(id string) grpc.StreamServerInterceptor { + return func(srv interface{}, stream grpc.ServerStream, _ *grpc.StreamServerInfo, handler grpc.StreamHandler) error { + ctx := context.WithValue(stream.Context(), goamiddleware.RequestIDKey, id) // nolint:staticcheck + wss := grpcmiddleware.NewWrappedServerStream(ctx, stream) + return handler(srv, wss) + } +} diff --git a/log/http.go b/log/http.go index 0d51a04b..9f3363ac 100644 --- a/log/http.go +++ b/log/http.go @@ -5,9 +5,11 @@ import ( "context" "fmt" "io" + "net" "net/http" "regexp" + goahttpmiddleware "goa.design/goa/v3/http/middleware" "goa.design/goa/v3/middleware" goa "goa.design/goa/v3/pkg" ) @@ -22,7 +24,8 @@ type ( HTTPClientLogOption func(*httpClientOptions) httpLogOptions struct { - pathFilters []*regexp.Regexp + pathFilters []*regexp.Regexp + disableRequestLogging bool } httpClientOptions struct { @@ -37,13 +40,19 @@ type ( } ) -// HTTP returns a HTTP middleware that initializes the logger context. It -// panics if logCtx was not initialized with Context. +// HTTP returns a HTTP middleware that performs two tasks: +// 1. Enriches the request context with the logger specified in logCtx. +// 2. Logs HTTP request details, except when WithDisableRequestLogging is set or +// URL path matches a WithPathFilter regex. +// +// HTTP panics if logCtx was not created with Context. func HTTP(logCtx context.Context, opts ...HTTPLogOption) func(http.Handler) http.Handler { MustContainLogger(logCtx) var options httpLogOptions for _, o := range opts { - o(&options) + if o != nil { + o(&options) + } } return func(h http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) { @@ -57,7 +66,23 @@ func HTTP(logCtx context.Context, opts ...HTTPLogOption) func(http.Handler) http if requestID := req.Context().Value(middleware.RequestIDKey); requestID != nil { ctx = With(ctx, KV{RequestIDKey, requestID}) } - h.ServeHTTP(w, req.WithContext(ctx)) + if options.disableRequestLogging { + h.ServeHTTP(w, req.WithContext(ctx)) + return + } + methKV := KV{K: HTTPMethodKey, V: req.Method} + urlKV := KV{K: HTTPURLKey, V: req.URL.String()} + fromKV := KV{K: HTTPFromKey, V: from(req)} + Print(ctx, KV{K: MessageKey, V: "start"}, methKV, urlKV, fromKV) + + rw := goahttpmiddleware.CaptureResponse(w) + started := timeNow() + h.ServeHTTP(rw, req.WithContext(ctx)) + + statusKV := KV{K: HTTPStatusKey, V: rw.StatusCode} + durKV := KV{K: HTTPDurationKey, V: timeSince(started).Milliseconds()} + bytesKV := KV{K: HTTPBytesKey, V: rw.ContentLength} + Print(ctx, KV{K: MessageKey, V: "end"}, methKV, urlKV, statusKV, durKV, bytesKV) }) } } @@ -113,6 +138,14 @@ func WithLogBodyOnError() HTTPClientLogOption { } } +// WithDisableRequestLogging returns a HTTP middleware option that disables +// logging of HTTP requests. +func WithDisableRequestLogging() HTTPLogOption { + return func(o *httpLogOptions) { + o.disableRequestLogging = true + } +} + // RoundTrip executes the given HTTP request and logs the request and response. The // request context must be initialized with a clue logger. func (c *client) RoundTrip(req *http.Request) (resp *http.Response, err error) { @@ -145,3 +178,16 @@ func (c *client) RoundTrip(req *http.Request) (resp *http.Response, err error) { Print(req.Context(), msgKV, methKV, urlKV, statusKV, durKV) return } + +// from returns the client address from the request. +func from(req *http.Request) string { + if f := req.Header.Get("X-Forwarded-For"); f != "" { + return f + } + f := req.RemoteAddr + ip, _, err := net.SplitHostPort(f) + if err != nil { + return f + } + return ip +} diff --git a/log/http_test.go b/log/http_test.go index 11608b13..2907fd45 100644 --- a/log/http_test.go +++ b/log/http_test.go @@ -20,36 +20,58 @@ func TestHTTP(t *testing.T) { now := timeNow timeNow = func() time.Time { return time.Date(2022, time.January, 9, 20, 29, 45, 0, time.UTC) } defer func() { timeNow = now }() + timeSince = func(_ time.Time) time.Duration { return 42 * time.Millisecond } + defer func() { timeSince = time.Since }() - var handler http.Handler = http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) { - Print(req.Context(), KV{"key1", "value1"}, KV{"key2", "value2"}) - }) - var buf bytes.Buffer - ctx := Context(context.Background(), WithOutput(&buf), WithFormat(FormatJSON)) + prefix := `{"time":"2022-01-09T20:29:45Z","level":"info","request-id":"request-id","msg":"start","http.method":"GET","http.url":"http://example.com","http.remote_addr":""}` + entry := `{"time":"2022-01-09T20:29:45Z","level":"info","request-id":"request-id","key1":"value1","key2":"value2"}` + suffix := `{"time":"2022-01-09T20:29:45Z","level":"info","request-id":"request-id","msg":"end","http.method":"GET","http.url":"http://example.com","http.status":0,"http.time_ms":42,"http.bytes":0}` - handler = HTTP(ctx)(handler) + cases := []struct { + name string + opt HTTPLogOption + expected string + }{ + { + name: "default", + expected: prefix + "\n" + entry + "\n" + suffix + "\n", + }, + { + name: "with path filter", + opt: WithPathFilter(regexp.MustCompile("")), + }, + { + name: "with disable request logging", + opt: WithDisableRequestLogging(), + expected: entry + "\n", + }, + } + for _, c := range cases { + t.Run(c.name, func(t *testing.T) { + var handler http.Handler = http.HandlerFunc(func(_ http.ResponseWriter, req *http.Request) { + Print(req.Context(), KV{"key1", "value1"}, KV{"key2", "value2"}) + }) + var buf bytes.Buffer + ctx := Context(context.Background(), WithOutput(&buf), WithFormat(FormatJSON)) - requestIDCtx := context.WithValue(ctx, middleware.RequestIDKey, "request-id") - req, _ := http.NewRequest("GET", "http://example.com", nil) - req = req.WithContext(requestIDCtx) + handler = HTTP(ctx, c.opt)(handler) - handler.ServeHTTP(nil, req) + requestIDCtx := context.WithValue(context.Background(), middleware.RequestIDKey, "request-id") //nolint:staticcheck + req, _ := http.NewRequest("GET", "http://example.com", nil) + req = req.WithContext(requestIDCtx) - expected := fmt.Sprintf("{%s,%s,%s,%s,%s}\n", - `"time":"2022-01-09T20:29:45Z"`, - `"level":"info"`, - `"request-id":"request-id"`, - `"key1":"value1"`, - `"key2":"value2"`) + handler.ServeHTTP(nil, req) - assert.Equal(t, expected, buf.String()) + assert.Equal(t, c.expected, buf.String()) + }) + } } func TestEndpoint(t *testing.T) { now := timeNow timeNow = func() time.Time { return time.Date(2022, time.January, 9, 20, 29, 45, 0, time.UTC) } defer func() { timeNow = now }() - endpoint := func(ctx context.Context, req interface{}) (interface{}, error) { + endpoint := func(ctx context.Context, _ interface{}) (interface{}, error) { Printf(ctx, "test") return nil, nil } @@ -75,7 +97,8 @@ func TestEndpoint(t *testing.T) { ctx = context.WithValue(ctx, goa.MethodKey, c.mname) } - Endpoint(endpoint)(ctx, nil) + _, err := Endpoint(endpoint)(ctx, nil) + assert.NoError(t, err) assert.Equal(t, c.expected+"\n", buf.String()) }) @@ -112,7 +135,7 @@ func TestClient(t *testing.T) { if c.noLog { ctx = context.Background() } - server := httptest.NewServer(http.HandlerFunc(func(rw http.ResponseWriter, _ *http.Request) { rw.Write([]byte(`OK`)) })) + server := httptest.NewServer(http.HandlerFunc(func(rw http.ResponseWriter, _ *http.Request) { rw.Write([]byte(`OK`)) })) //nolint:errcheck defer server.Close() client := server.Client() if c.clientErr != nil { @@ -127,7 +150,7 @@ func TestClient(t *testing.T) { req, _ := http.NewRequest("GET", server.URL, nil) req = req.WithContext(ctx) - client.Do(req) + client.Do(req) // nolint:errcheck expected := strings.ReplaceAll(c.expected, "$URL", server.URL) assert.Equal(t, strings.TrimSpace(buf.String()), expected) @@ -136,7 +159,7 @@ func TestClient(t *testing.T) { } func TestWithPathFilter(t *testing.T) { - var handler http.Handler = http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) { + var handler http.Handler = http.HandlerFunc(func(_ http.ResponseWriter, req *http.Request) { Print(req.Context(), KV{"key1", "value1"}, KV{"key2", "value2"}) }) var buf bytes.Buffer diff --git a/log/keys.go b/log/keys.go index fe862f98..5f0e5578 100644 --- a/log/keys.go +++ b/log/keys.go @@ -10,8 +10,10 @@ var ( SeverityKey = "level" HTTPMethodKey = "http.method" HTTPURLKey = "http.url" + HTTPFromKey = "http.remote_addr" HTTPStatusKey = "http.status" HTTPDurationKey = "http.time_ms" + HTTPBytesKey = "http.bytes" HTTPBodyKey = "http.body" GRPCServiceKey = "grpc.service" GRPCMethodKey = "grpc.method" diff --git a/log/log.go b/log/log.go index ec695b0c..0794aaa0 100644 --- a/log/log.go +++ b/log/log.go @@ -162,7 +162,7 @@ func (l *logger) flush() { return } for _, e := range l.entries { - l.options.w.Write(l.options.format(e)) + l.options.w.Write(l.options.format(e)) // nolint: errcheck } l.entries = nil // free up memory l.flushed = true @@ -195,7 +195,7 @@ func log(ctx context.Context, sev Severity, buffer bool, fielders []Fielder) { e := &Entry{timeNow().UTC(), sev, keyvals} if l.flushed || !buffer { - l.options.w.Write(l.options.format(e)) + l.options.w.Write(l.options.format(e)) // nolint: errcheck return } l.entries = append(l.entries, e) @@ -300,7 +300,7 @@ func (lw *limitWriter) Write(b []byte) (int, error) { newLen := lw.n + len(b) if newLen > lw.max { b = b[:lw.max-lw.n] - lw.Writer.Write(b) + lw.Writer.Write(b) // nolint: errcheck return lw.max - lw.n, errTruncated } lw.n = newLen diff --git a/log/log_test.go b/log/log_test.go index fb4dcd90..75c30d5b 100644 --- a/log/log_test.go +++ b/log/log_test.go @@ -171,7 +171,7 @@ func TestBufferingWithDisableBufferingFunc(t *testing.T) { func TestFatal(t *testing.T) { var exitCalled bool - osExit = func(code int) { exitCalled = true } + osExit = func(_ int) { exitCalled = true } defer func() { osExit = os.Exit }() var buf bytes.Buffer ctx := Context(context.Background(), WithOutput(&buf), WithFormat(testFormat)) diff --git a/log/options_test.go b/log/options_test.go index 6f82812c..adebba33 100644 --- a/log/options_test.go +++ b/log/options_test.go @@ -67,7 +67,7 @@ func TestIsTracing(t *testing.T) { } exp, _ := stdouttrace.New(stdouttrace.WithWriter(io.Discard)) tp := trace.NewTracerProvider(trace.WithBatcher(exp)) - defer tp.Shutdown(context.Background()) + defer tp.Shutdown(context.Background()) // nolint:errcheck otel.SetTracerProvider(tp) ctx, span := otel.Tracer("test").Start(context.Background(), "test") defer span.End() diff --git a/metrics/grpc_test.go b/metrics/grpc_test.go index dec3fd36..5e7b97c8 100644 --- a/metrics/grpc_test.go +++ b/metrics/grpc_test.go @@ -131,7 +131,7 @@ func TestUnaryServerInterceptorActiveRequests(t *testing.T) { testsvc.WithUnaryFunc(waitMethod(&running, &done, chstop))) for i := 0; i < c.numReqs; i++ { - go cli.GRPCMethod(context.Background(), &testsvc.Fields{}) + go cli.GRPCMethod(context.Background(), &testsvc.Fields{}) // nolint: errcheck } running.Wait() diff --git a/scripts/cibuild b/scripts/cibuild index e09fad91..e31f9c5f 100755 --- a/scripts/cibuild +++ b/scripts/cibuild @@ -3,9 +3,9 @@ set -e GIT_ROOT=$(git rev-parse --show-toplevel) -pushd ${GIT_ROOT} +pushd ${GIT_ROOT} > /dev/null ./scripts/setup ./scripts/test -popd +popd > /dev/null diff --git a/scripts/setup b/scripts/setup index 4f3bd333..7dfcd6ca 100755 --- a/scripts/setup +++ b/scripts/setup @@ -3,7 +3,9 @@ set -e GIT_ROOT=$(git rev-parse --show-toplevel) -pushd ${GIT_ROOT} +GOLANGCI_VER=1.53.3 + +pushd ${GIT_ROOT} > /dev/null source ./scripts/utils/common.sh @@ -11,7 +13,6 @@ if [[ "$CI" == "" ]]; then check_required_cmd "tmux" fi -go mod download -go install honnef.co/go/tools/cmd/staticcheck@latest +curl -sSfL https://raw.githubusercontent.com/golangci/golangci-lint/master/install.sh | sh -s -- -b $(go env GOPATH)/bin v${GOLANGCI_VER} -popd +popd > /dev/null diff --git a/scripts/test b/scripts/test index 23ebea48..743cf5f4 100755 --- a/scripts/test +++ b/scripts/test @@ -2,13 +2,13 @@ set -e -echo "Running tests..." - GIT_ROOT=$(git rev-parse --show-toplevel) -pushd ${GIT_ROOT} +pushd ${GIT_ROOT} > /dev/null -staticcheck ./... +echo "Running static analysis..." +golangci-lint run +echo "Running tests..." go test -race -coverprofile=coverage.out -covermode=atomic ./... -popd +popd > /dev/null diff --git a/trace/grpc_test.go b/trace/grpc_test.go index 262fe252..1a248383 100644 --- a/trace/grpc_test.go +++ b/trace/grpc_test.go @@ -89,7 +89,7 @@ func TestStreamServerTrace(t *testing.T) { if err := stream.Send(&testsvc.Fields{}); err != nil { t.Errorf("unexpected send error: %v", err) } - stream.Recv() + stream.Recv() // nolint: errcheck stop() spans := exporter.GetSpans() if len(spans) != 1 { @@ -121,7 +121,7 @@ func TestStreamServerTraceNoRequestID(t *testing.T) { if err := stream.Send(&testsvc.Fields{}); err != nil { t.Errorf("unexpected send error: %v", err) } - stream.Recv() + stream.Recv() // nolint: errcheck stop() spans := exporter.GetSpans() if len(spans) != 1 { @@ -160,7 +160,7 @@ func TestStreamClientTrace(t *testing.T) { if err := stream.Send(&testsvc.Fields{}); err != nil { t.Errorf("unexpected send error: %v", err) } - stream.Recv() + stream.Recv() // nolint: errcheck cancel() stop() spans := exporter.GetSpans() diff --git a/trace/options.go b/trace/options.go index 0ffdb1a8..e6327e4e 100644 --- a/trace/options.go +++ b/trace/options.go @@ -36,7 +36,7 @@ func defaultOptions() *options { // WithMaxSamplingRate sets the maximum sampling rate in requests per second. func WithMaxSamplingRate(rate int) TraceOption { - return func(ctx context.Context, opts *options) error { + return func(_ context.Context, opts *options) error { opts.maxSamplingRate = rate return nil } @@ -45,7 +45,7 @@ func WithMaxSamplingRate(rate int) TraceOption { // WithSampleSize sets the number of requests between two adjustments of the // sampling rate. func WithSampleSize(size int) TraceOption { - return func(ctx context.Context, opts *options) error { + return func(_ context.Context, opts *options) error { opts.sampleSize = size return nil } @@ -53,7 +53,7 @@ func WithSampleSize(size int) TraceOption { // WithDisabled disables tracing, not for use in production. func WithDisabled() TraceOption { - return func(ctx context.Context, opts *options) error { + return func(_ context.Context, opts *options) error { opts.disabled = true return nil } @@ -61,7 +61,7 @@ func WithDisabled() TraceOption { // WithExporter sets the exporter to use. func WithExporter(exporter sdktrace.SpanExporter) TraceOption { - return func(ctx context.Context, opts *options) error { + return func(_ context.Context, opts *options) error { opts.exporter = exporter return nil } @@ -69,7 +69,7 @@ func WithExporter(exporter sdktrace.SpanExporter) TraceOption { // WithParentSamplerOptions to set the options for sdktrace.ParentBased sampler. func WithParentSamplerOptions(samplerOptions ...sdktrace.ParentBasedSamplerOption) TraceOption { - return func(ctx context.Context, opts *options) error { + return func(_ context.Context, opts *options) error { opts.parentSamplerOptions = samplerOptions return nil } @@ -77,7 +77,7 @@ func WithParentSamplerOptions(samplerOptions ...sdktrace.ParentBasedSamplerOptio // WithResource sets the underlying opentelemetry resource. func WithResource(res *resource.Resource) TraceOption { - return func(ctx context.Context, opts *options) error { + return func(_ context.Context, opts *options) error { opts.resource = res return nil } @@ -85,7 +85,7 @@ func WithResource(res *resource.Resource) TraceOption { // WithPropagator sets the otel propagators func WithPropagator(propagator propagation.TextMapPropagator) TraceOption { - return func(ctx context.Context, opts *options) error { + return func(_ context.Context, opts *options) error { opts.propagator = propagator return nil } diff --git a/trace/options_test.go b/trace/options_test.go index 65268e8b..1a053c0e 100644 --- a/trace/options_test.go +++ b/trace/options_test.go @@ -4,6 +4,7 @@ import ( "context" "testing" + "github.com/stretchr/testify/assert" "go.opentelemetry.io/otel/sdk/resource" sdktrace "go.opentelemetry.io/otel/sdk/trace" "go.opentelemetry.io/otel/sdk/trace/tracetest" @@ -19,27 +20,27 @@ func TestOptions(t *testing.T) { if options.sampleSize != 10 { t.Errorf("got %d, want 10", options.sampleSize) } - WithMaxSamplingRate(3)(ctx, options) + assert.NoError(t, WithMaxSamplingRate(3)(ctx, options)) if options.maxSamplingRate != 3 { t.Errorf("got %d sampling rate, want 3", options.maxSamplingRate) } - WithSampleSize(20)(ctx, options) + assert.NoError(t, WithSampleSize(20)(ctx, options)) if options.sampleSize != 20 { t.Errorf("got %d sample size, want 20", options.sampleSize) } - WithDisabled()(ctx, options) + assert.NoError(t, WithDisabled()(ctx, options)) if !options.disabled { t.Error("expected disabled to be true") } - WithExporter(tracetest.NewInMemoryExporter())(ctx, options) + assert.NoError(t, WithExporter(tracetest.NewInMemoryExporter())(ctx, options)) if options.exporter == nil { t.Error("got nil exporter, want non-nil") } - WithResource(&resource.Resource{})(ctx, options) + assert.NoError(t, WithResource(&resource.Resource{})(ctx, options)) if options.resource == nil { t.Error("got nil resource, want non-nil") } - WithParentSamplerOptions(sdktrace.WithRemoteParentSampled(nil))(ctx, options) + assert.NoError(t, WithParentSamplerOptions(sdktrace.WithRemoteParentSampled(nil))(ctx, options)) if total := len(options.parentSamplerOptions); total != 1 { t.Errorf("got %d parent sampler options, expected 1", total) }