From cbad637ddad36ae7fd771916545001eaeb5c3d1e Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?J=C3=B6rn=20Friedrich=20Dreyer?= <jfd@butonic.de>
Date: Tue, 29 Oct 2024 12:39:25 +0100
Subject: [PATCH] log grpc requests in debug mode
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

Signed-off-by: Jörn Friedrich Dreyer <jfd@butonic.de>
---
 changelog/unreleased/log-grpc-requests.md |  5 +++
 ocis-pkg/service/grpc/service.go          | 43 ++++++++++++++++++++---
 2 files changed, 44 insertions(+), 4 deletions(-)
 create mode 100644 changelog/unreleased/log-grpc-requests.md

diff --git a/changelog/unreleased/log-grpc-requests.md b/changelog/unreleased/log-grpc-requests.md
new file mode 100644
index 00000000000..61ccd7b9fae
--- /dev/null
+++ b/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
diff --git a/ocis-pkg/service/grpc/service.go b/ocis-pkg/service/grpc/service.go
index 97edbb8594a..1cc6bb572b5 100644
--- a/ocis-pkg/service/grpc/service.go
+++ b/ocis-pkg/service/grpc/service.go
@@ -1,18 +1,23 @@
 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/owncloud/ocis/v2/ocis-pkg/log"
 	"github.com/owncloud/ocis/v2/ocis-pkg/registry"
+	"github.com/rs/zerolog"
 	"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"
 )
@@ -54,6 +59,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 +85,7 @@ func NewServiceWithClient(client client.Client, opts ...Option) (Service, error)
 		micro.WrapClient(mtracer.NewClientWrapper(
 			mtracer.WithTraceProvider(sopts.TraceProvider),
 		)),
-		micro.WrapHandler(mtracer.NewHandlerWrapper(
-			mtracer.WithTraceProvider(sopts.TraceProvider),
-		)),
-		micro.WrapHandler(sopts.HandlerWrappers...),
+		micro.WrapHandler(handlerWrappers...),
 		micro.WrapSubscriber(mtracer.NewSubscriberWrapper(
 			mtracer.WithTraceProvider(sopts.TraceProvider),
 		)),
@@ -81,3 +93,26 @@ func NewServiceWithClient(client client.Client, opts ...Option) (Service, error)
 
 	return Service{micro.NewService(mopts...)}, nil
 }
+
+// If used with tracing, please ensure this is registerd (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)
+		}
+	}
+}