Move pack-objects logs to gRPC logs

Lately, the pack-objects RPC has been emitting logs that are difficult
to follow as they are each displayed on separate lines. This can be
problematic when attempting to investigate related issues. To address
this, a commit has been made to transfer these logs to gRPC logs. The
fields are stored in command.Stats, a FieldsProducer, and eventually
collated in a gRPC logging middleware.

2 files changed, 28 insertions, 41 deletions

diff --git a/internal/gitaly/service/hook/pack_objects.go b/internal/gitaly/service/hook/pack_objects.go
index 32b209f67..8d1ba124e 100644
--- a/internal/gitaly/service/hook/pack_objects.go
+++ b/internal/gitaly/service/hook/pack_objects.go
@@ -15,10 +15,9 @@ import (
 	"strings"
 	"syscall"
 
-	"github.com/grpc-ecosystem/go-grpc-middleware/logging/logrus/ctxlogrus"
 	"github.com/prometheus/client_golang/prometheus"
 	"github.com/prometheus/client_golang/prometheus/promauto"
-	"github.com/sirupsen/logrus"
+	"gitlab.com/gitlab-org/gitaly/v15/internal/command"
 	"gitlab.com/gitlab-org/gitaly/v15/internal/git"
 	"gitlab.com/gitlab-org/gitaly/v15/internal/git/pktline"
 	gitalyhook "gitlab.com/gitlab-org/gitaly/v15/internal/gitaly/hook"
@@ -129,10 +128,16 @@ func (s *server) packObjectsHook(ctx context.Context, req *gitalypb.PackObjectsH
 		packObjectsCacheLookups.WithLabelValues("hit").Inc()
 	}
 
-	ctxlogrus.Extract(ctx).WithFields(logrus.Fields{
-		"cache_key": cacheKey,
-		"bytes":     servedBytes,
-	}).Info("served bytes")
+	stats := command.StatsFromContext(ctx)
+	if stats != nil {
+		stats.RecordMetadata("pack_objects_cache.key", cacheKey)
+		stats.RecordSum("pack_objects_cache.served_bytes", int(servedBytes))
+		if created {
+			stats.RecordMetadata("pack_objects_cache.hit", "false")
+		} else {
+			stats.RecordMetadata("pack_objects_cache.hit", "true")
+		}
+	}
 	packObjectsServedBytes.Add(float64(servedBytes))
 
 	return nil
@@ -269,14 +274,13 @@ func runPackObjects(
 
 	defer func() {
 		packObjectsGeneratedBytes.Add(float64(counter.N))
-		logger := ctxlogrus.Extract(ctx)
-		logger.WithFields(logrus.Fields{
-			"cache_key": key,
-			"bytes":     counter.N,
-		}).Info("generated bytes")
-
-		if total := totalMessage(stderrBuf.Bytes()); total != "" {
-			logger.WithField("pack.stat", total).Info("pack file compression statistic")
+		stats := command.StatsFromContext(ctx)
+		if stats != nil {
+			stats.RecordMetadata("pack_objects_cache.key", key)
+			stats.RecordSum("pack_objects_cache.generated_bytes", int(counter.N))
+			if total := totalMessage(stderrBuf.Bytes()); total != "" {
+				stats.RecordMetadata("pack_objects.compression_statistics", total)
+			}
 		}
 	}()
 
diff --git a/internal/gitaly/service/hook/pack_objects_test.go b/internal/gitaly/service/hook/pack_objects_test.go
index 0545d50f7..4c0a5342d 100644
--- a/internal/gitaly/service/hook/pack_objects_test.go
+++ b/internal/gitaly/service/hook/pack_objects_test.go
@@ -15,7 +15,6 @@ import (
 
 	"github.com/prometheus/client_golang/prometheus"
 	"github.com/prometheus/client_golang/prometheus/testutil"
-	"github.com/sirupsen/logrus"
 	"github.com/sirupsen/logrus/hooks/test"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
@@ -546,34 +545,18 @@ func testServerPackObjectsHookWithSidechannelWithRuntimeDir(t *testing.T, ctx co
 				"-C", repoPath, "index-pack", "--stdin", "--fix-thin",
 			)
 
-			for _, msg := range []string{"served bytes", "generated bytes"} {
-				t.Run(msg, func(t *testing.T) {
-					var entry *logrus.Entry
-					for _, e := range hook.AllEntries() {
-						if e.Message == msg {
-							entry = e
-						}
-					}
+			entry := hook.LastEntry()
+			require.NotNil(t, entry)
 
-					require.NotNil(t, entry)
-					require.NotEmpty(t, entry.Data["cache_key"])
-					require.Greater(t, entry.Data["bytes"], int64(0))
-				})
-			}
+			fields := entry.Data
+			require.Equal(t, fields["pack_objects_cache.hit"], "false")
+			require.Contains(t, fields, "pack_objects_cache.key")
+			require.Greater(t, fields["pack_objects_cache.served_bytes"], 0)
+			require.Greater(t, fields["pack_objects_cache.generated_bytes"], 0)
 
-			t.Run("pack file compression statistic", func(t *testing.T) {
-				var entry *logrus.Entry
-				for _, e := range hook.AllEntries() {
-					if e.Message == "pack file compression statistic" {
-						entry = e
-					}
-				}
-
-				require.NotNil(t, entry)
-				total := entry.Data["pack.stat"].(string)
-				require.True(t, strings.HasPrefix(total, "Total "))
-				require.False(t, strings.Contains(total, "\n"))
-			})
+			total := fields["pack_objects.compression_statistics"].(string)
+			require.True(t, strings.HasPrefix(total, "Total "))
+			require.False(t, strings.Contains(total, "\n"))
 
 			expectedMetrics := `# HELP gitaly_pack_objects_concurrent_processes Number of concurrent processes
 # TYPE gitaly_pack_objects_concurrent_processes histogram