From 1d8835c30e33b511f4eb73bf612e731f0d1ffa67 Mon Sep 17 00:00:00 2001
From: Doria Keung <doriable@users.noreply.github.com>
Date: Mon, 25 Nov 2024 17:39:29 -0500
Subject: [PATCH] Add debug logging interceptor for RPC logs (#3496)

Co-authored-by: Edward McFarlane <3036610+emcfarlane@users.noreply.github.com>
---
 private/buf/bufcli/connectclient_config.go |  1 +
 private/bufpkg/bufconnect/interceptors.go  | 54 ++++++++++++++++++++++
 2 files changed, 55 insertions(+)

diff --git a/private/buf/bufcli/connectclient_config.go b/private/buf/bufcli/connectclient_config.go
index b7548e6ba3..0bd0083b00 100644
--- a/private/buf/bufcli/connectclient_config.go
+++ b/private/buf/bufcli/connectclient_config.go
@@ -81,6 +81,7 @@ func newConnectClientConfigWithOptions(container appext.Container, opts ...conne
 				bufconnect.NewAugmentedConnectErrorInterceptor(),
 				bufconnect.NewSetCLIVersionInterceptor(Version),
 				bufconnect.NewCLIWarningInterceptor(container),
+				bufconnect.NewDebugLoggingInterceptor(container),
 				otelconnectInterceptor,
 			},
 		),
diff --git a/private/bufpkg/bufconnect/interceptors.go b/private/bufpkg/bufconnect/interceptors.go
index eb44224d5b..922004033e 100644
--- a/private/bufpkg/bufconnect/interceptors.go
+++ b/private/bufpkg/bufconnect/interceptors.go
@@ -18,10 +18,14 @@ import (
 	"context"
 	"errors"
 	"fmt"
+	"log/slog"
 	"net/http"
+	"strings"
+	"time"
 
 	"connectrpc.com/connect"
 	"github.com/bufbuild/buf/private/pkg/app/appext"
+	"google.golang.org/protobuf/proto"
 )
 
 const (
@@ -140,3 +144,53 @@ func NewAuthorizationInterceptorProvider(tokenProviders ...TokenProvider) func(s
 		return interceptor
 	}
 }
+
+// NewDebugLoggingInterceptor returns a new Connect Interceptor that adds debug log
+// statements for each rpc call.
+//
+// The following information is collected for logging: duration, status code, peer name,
+// rpc system, request size, and response size.
+func NewDebugLoggingInterceptor(container appext.LoggerContainer) connect.UnaryInterceptorFunc {
+	interceptor := func(next connect.UnaryFunc) connect.UnaryFunc {
+		return func(ctx context.Context, req connect.AnyRequest) (connect.AnyResponse, error) {
+			var requestSize int
+			if req.Any() != nil {
+				msg, ok := req.Any().(proto.Message)
+				if ok {
+					requestSize = proto.Size(msg)
+				}
+			}
+			startTime := time.Now()
+			resp, err := next(ctx, req)
+			duration := time.Since(startTime)
+			var status connect.Code
+			if err != nil {
+				status = connect.CodeOf(err)
+			}
+			var responseSize int
+			if resp != nil && resp.Any() != nil {
+				msg, ok := resp.Any().(proto.Message)
+				if ok {
+					responseSize = proto.Size(msg)
+				}
+			}
+			attrs := []slog.Attr{
+				slog.Duration("duration", duration),
+				slog.String("status", status.String()),
+				slog.String("net.peer.name", req.Peer().Addr),
+				slog.String("rpc.system", req.Peer().Protocol),
+				slog.Int("message.sent.uncompressed_size", requestSize),
+				slog.Int("message.received.uncompressed_size", responseSize),
+			}
+			container.Logger().LogAttrs(
+				ctx,
+				slog.LevelDebug,
+				// Remove the leading "/" from Procedure name
+				strings.TrimPrefix(req.Spec().Procedure, "/"),
+				attrs...,
+			)
+			return resp, err
+		}
+	}
+	return interceptor
+}