Merge pull request #10438 from owncloud/log-grpc-requests

log grpc requests in debug mode

changelog/unreleased/log-grpc-requests.md

@@ -0,0 +1,5 @@
+Bugfix: Log GRPC requests in debug mode
+
+When log level is set to debug we will now also log grpc requests.
+
+https://github.com/owncloud/ocis/pull/10438

ocis-pkg/service/grpc/service.go

@@ -1,20 +1,26 @@
 package grpc
 
 import (
+	"context"
 	"crypto/tls"
 	"fmt"
 	"strings"
+	"time"
 
 	mgrpcs "github.com/go-micro/plugins/v4/server/grpc"
 	"github.com/go-micro/plugins/v4/wrapper/monitoring/prometheus"
 	mtracer "github.com/go-micro/plugins/v4/wrapper/trace/opentelemetry"
-	ociscrypto "github.com/owncloud/ocis/v2/ocis-pkg/crypto"
+	"github.com/rs/zerolog"
-	"github.com/owncloud/ocis/v2/ocis-pkg/registry"
 	"go-micro.dev/v4"
 	"go-micro.dev/v4/client"
 	"go-micro.dev/v4/server"
+	"go.opentelemetry.io/otel/trace"
 	"google.golang.org/grpc"
 	"google.golang.org/grpc/keepalive"
+
+	ociscrypto "github.com/owncloud/ocis/v2/ocis-pkg/crypto"
+	"github.com/owncloud/ocis/v2/ocis-pkg/log"
+	"github.com/owncloud/ocis/v2/ocis-pkg/registry"
 )
 
 // Service simply wraps the go-micro grpc service.
@@ -54,6 +60,16 @@ func NewServiceWithClient(client client.Client, opts ...Option) (Service, error)
 		mServer = mgrpcs.NewServer(mgrpcs.Options(keepaliveParams))
 	}
 
+	handlerWrappers := []server.HandlerWrapper{
+		mtracer.NewHandlerWrapper(
+			mtracer.WithTraceProvider(sopts.TraceProvider),
+		),
+	}
+	if sopts.Logger.GetLevel() == zerolog.DebugLevel {
+		handlerWrappers = append(handlerWrappers, LogHandler(&sopts.Logger))
+	}
+	handlerWrappers = append(handlerWrappers, sopts.HandlerWrappers...)
+
 	mopts := []micro.Option{
 		// first add a server because it will reset any options
 		micro.Server(mServer),
@@ -70,10 +86,7 @@ func NewServiceWithClient(client client.Client, opts ...Option) (Service, error)
 		micro.WrapClient(mtracer.NewClientWrapper(
 			mtracer.WithTraceProvider(sopts.TraceProvider),
 		)),
-		micro.WrapHandler(mtracer.NewHandlerWrapper(
+		micro.WrapHandler(handlerWrappers...),
-			mtracer.WithTraceProvider(sopts.TraceProvider),
-		)),
-		micro.WrapHandler(sopts.HandlerWrappers...),
 		micro.WrapSubscriber(mtracer.NewSubscriberWrapper(
 			mtracer.WithTraceProvider(sopts.TraceProvider),
 		)),
@@ -81,3 +94,26 @@ func NewServiceWithClient(client client.Client, opts ...Option) (Service, error)
 
 	return Service{micro.NewService(mopts...)}, nil
 }
+
+// If used with tracing, please ensure this is registered (by micro.WrapHandler()) after
+// micro-plugin's opentracing wrapper: `opentracing.NewHandlerWrapper()`
+func LogHandler(l *log.Logger) func(fn server.HandlerFunc) server.HandlerFunc {
+	return func(fn server.HandlerFunc) server.HandlerFunc {
+		return func(ctx context.Context, req server.Request, rsp interface{}) error {
+			now := time.Now()
+			spanContext := trace.SpanContextFromContext(ctx)
+			defer func() {
+				l.Debug().
+					Str("traceid", spanContext.TraceID().String()).
+					Str("method", req.Method()).
+					Str("endpoint", req.Endpoint()).
+					Str("content-type", req.ContentType()).
+					Str("service", req.Service()).
+					Interface("headers", req.Header()).
+					Dur("duration", time.Since(now)).
+					Msg("grpc call")
+			}()
+			return fn(ctx, req, rsp)
+		}
+	}
+}