Welcome to mirror list, hosted at ThFree Co, Russian Federation.

gitlab.com/gitlab-org/gitaly.git - Unnamed repository; edit this file 'description' to name the repository.
summaryrefslogtreecommitdiff
diff options
context:
space:
mode:
authorJustin Tobler <jtobler@gitlab.com>2023-06-21 20:09:31 +0300
committerJustin Tobler <jtobler@gitlab.com>2023-06-21 20:09:31 +0300
commit1b2c003553f04d1d720d35d492475735d3ce06f4 (patch)
tree50cdd39ca1f4cddb2099b5b6bb5f6ce2752f6ec8
parent739c61e1df3f7cd38a1c875a63d84cc6e7153ff2 (diff)
parent2b87d1b73af6bbe42c03402cf2d3127af80c8d79 (diff)
Merge branch 'qmnguyen0711/convert-stats-log-fields-to-general-purpose' into 'master'
Convert command.Stats to a general-purpose field logger See merge request https://gitlab.com/gitlab-org/gitaly/-/merge_requests/5948 Merged-by: Justin Tobler <jtobler@gitlab.com> Approved-by: John Cai <jcai@gitlab.com> Approved-by: Justin Tobler <jtobler@gitlab.com> Co-authored-by: Quang-Minh Nguyen <qmnguyen@gitlab.com>
-rw-r--r--cmd/gitaly/check_test.go3
-rw-r--r--cmd/gitaly/main_test.go2
-rw-r--r--internal/command/command.go25
-rw-r--r--internal/command/spawntoken.go7
-rw-r--r--internal/command/spawntoken_test.go21
-rw-r--r--internal/command/stats.go80
-rw-r--r--internal/command/stats_test.go88
-rw-r--r--internal/git/catfile/request_queue.go10
-rw-r--r--internal/git/catfile/request_queue_test.go8
-rw-r--r--internal/git/command_factory.go10
-rw-r--r--internal/git/command_factory_test.go66
-rw-r--r--internal/git/trace2hooks/packobjects_metrics.go10
-rw-r--r--internal/git/trace2hooks/packobjects_metrics_ext_test.go22
-rw-r--r--internal/git/trace2hooks/packobjects_metrics_test.go20
-rw-r--r--internal/gitaly/server/server.go8
-rw-r--r--internal/gitaly/service/hook/pack_objects.go24
-rw-r--r--internal/grpc/middleware/customfieldshandler/customfields_handler.go (renamed from internal/grpc/middleware/commandstatshandler/commandstatshandler.go)18
-rw-r--r--internal/grpc/middleware/customfieldshandler/customfields_handler_test.go (renamed from internal/grpc/middleware/commandstatshandler/commandstatshandler_test.go)9
-rw-r--r--internal/log/customfields.go82
-rw-r--r--internal/log/customfields_test.go89
20 files changed, 304 insertions, 298 deletions
diff --git a/cmd/gitaly/check_test.go b/cmd/gitaly/check_test.go
index d951f4637..6f7349910 100644
--- a/cmd/gitaly/check_test.go
+++ b/cmd/gitaly/check_test.go
@@ -97,6 +97,7 @@ func TestCheckBadCreds(t *testing.T) {
cmd.Stdout = &stdout
require.Error(t, cmd.Run())
+ require.Contains(t, stdout.String(), `Checking GitLab API access: FAILED`)
require.Contains(t, stderr.String(), "HTTP GET to GitLab endpoint /check failed: authorization failed")
- require.Regexp(t, `Checking GitLab API access: .* level=error msg="Internal API error" .* error="authorization failed" method=GET status=401 url="http://127.0.0.1:[0-9]+/api/v4/internal/check"\nFAIL`, stdout.String())
+ require.Regexp(t, `.* level=error msg="Internal API error" .* error="authorization failed" method=GET status=401 url="http://127.0.0.1:[0-9]+/api/v4/internal/check"`, stderr.String())
}
diff --git a/cmd/gitaly/main_test.go b/cmd/gitaly/main_test.go
index a6c2a1937..3c70d9ed9 100644
--- a/cmd/gitaly/main_test.go
+++ b/cmd/gitaly/main_test.go
@@ -36,7 +36,7 @@ func TestGitalyCLI(t *testing.T) {
desc: "with non-existent config",
args: []string{"non-existent-file"},
exitCode: 1,
- stdout: `msg="load config: config_path \"non-existent-file\"`,
+ stderr: `msg="load config: config_path \"non-existent-file\"`,
},
{
desc: "check without config",
diff --git a/internal/command/command.go b/internal/command/command.go
index ea688a156..bbea588c8 100644
--- a/internal/command/command.go
+++ b/internal/command/command.go
@@ -21,6 +21,7 @@ import (
"github.com/sirupsen/logrus"
"gitlab.com/gitlab-org/gitaly/v16/internal/command/commandcounter"
"gitlab.com/gitlab-org/gitaly/v16/internal/featureflag"
+ "gitlab.com/gitlab-org/gitaly/v16/internal/log"
"gitlab.com/gitlab-org/gitaly/v16/internal/tracing"
labkittracing "gitlab.com/gitlab-org/labkit/tracing"
)
@@ -460,23 +461,23 @@ func (c *Command) logProcessComplete() {
entry.Error(c.stderrBuffer.String())
}
- if stats := StatsFromContext(ctx); stats != nil {
- stats.RecordSum("command.count", 1)
- stats.RecordSum("command.system_time_ms", int(systemTime.Milliseconds()))
- stats.RecordSum("command.user_time_ms", int(userTime.Milliseconds()))
- stats.RecordSum("command.cpu_time_ms", int(systemTime.Milliseconds()+userTime.Milliseconds()))
- stats.RecordSum("command.real_time_ms", int(realTime.Milliseconds()))
+ if customFields := log.CustomFieldsFromContext(ctx); customFields != nil {
+ customFields.RecordSum("command.count", 1)
+ customFields.RecordSum("command.system_time_ms", int(systemTime.Milliseconds()))
+ customFields.RecordSum("command.user_time_ms", int(userTime.Milliseconds()))
+ customFields.RecordSum("command.cpu_time_ms", int(systemTime.Milliseconds()+userTime.Milliseconds()))
+ customFields.RecordSum("command.real_time_ms", int(realTime.Milliseconds()))
if ok {
- stats.RecordMax("command.maxrss", int(rusage.Maxrss))
- stats.RecordSum("command.inblock", int(rusage.Inblock))
- stats.RecordSum("command.oublock", int(rusage.Oublock))
- stats.RecordSum("command.minflt", int(rusage.Minflt))
- stats.RecordSum("command.majflt", int(rusage.Majflt))
+ customFields.RecordMax("command.maxrss", int(rusage.Maxrss))
+ customFields.RecordSum("command.inblock", int(rusage.Inblock))
+ customFields.RecordSum("command.oublock", int(rusage.Oublock))
+ customFields.RecordSum("command.minflt", int(rusage.Minflt))
+ customFields.RecordSum("command.majflt", int(rusage.Majflt))
}
if c.cgroupPath != "" {
- stats.RecordMetadata("command.cgroup_path", c.cgroupPath)
+ customFields.RecordMetadata("command.cgroup_path", c.cgroupPath)
}
}
diff --git a/internal/command/spawntoken.go b/internal/command/spawntoken.go
index 2b0065bf5..ff7ef7f5e 100644
--- a/internal/command/spawntoken.go
+++ b/internal/command/spawntoken.go
@@ -8,6 +8,7 @@ import (
"github.com/kelseyhightower/envconfig"
"github.com/prometheus/client_golang/prometheus"
"github.com/prometheus/client_golang/prometheus/promauto"
+ "gitlab.com/gitlab-org/gitaly/v16/internal/log"
"gitlab.com/gitlab-org/gitaly/v16/internal/structerr"
"gitlab.com/gitlab-org/gitaly/v16/internal/tracing"
"gitlab.com/gitlab-org/gitaly/v16/proto/go/gitalypb"
@@ -85,10 +86,10 @@ func getSpawnToken(ctx context.Context) (putToken func(), err error) {
func recordTime(ctx context.Context, start time.Time, msg string) {
delta := time.Since(start)
- if stats := StatsFromContext(ctx); stats != nil {
- stats.RecordSum("command.spawn_token_wait_ms", int(delta.Milliseconds()))
+ if customFields := log.CustomFieldsFromContext(ctx); customFields != nil {
+ customFields.RecordSum("command.spawn_token_wait_ms", int(delta.Milliseconds()))
if len(msg) != 0 {
- stats.RecordMetadata("command.spawn_token_error", msg)
+ customFields.RecordMetadata("command.spawn_token_error", msg)
}
}
}
diff --git a/internal/command/spawntoken_test.go b/internal/command/spawntoken_test.go
index 62f534b7f..dc025b2ea 100644
--- a/internal/command/spawntoken_test.go
+++ b/internal/command/spawntoken_test.go
@@ -5,6 +5,7 @@ import (
"time"
"github.com/stretchr/testify/require"
+ "gitlab.com/gitlab-org/gitaly/v16/internal/log"
"gitlab.com/gitlab-org/gitaly/v16/internal/structerr"
"gitlab.com/gitlab-org/gitaly/v16/internal/testhelper"
"gitlab.com/gitlab-org/gitaly/v16/proto/go/gitalypb"
@@ -16,15 +17,15 @@ func TestGetSpawnToken_CommandStats(t *testing.T) {
t.Parallel()
ctx := testhelper.Context(t)
- ctx = InitContextStats(ctx)
+ ctx = log.InitContextCustomFields(ctx)
putToken, err := getSpawnToken(ctx)
require.Nil(t, err)
putToken()
- stats := StatsFromContext(ctx)
- require.NotNil(t, stats)
- require.Contains(t, stats.Fields(), "command.spawn_token_wait_ms")
+ customFields := log.CustomFieldsFromContext(ctx)
+ require.NotNil(t, customFields)
+ require.Contains(t, customFields.Fields(), "command.spawn_token_wait_ms")
}
// This test modifies a global config, hence should never run in parallel
@@ -41,7 +42,7 @@ func TestGetSpawnToken_CommandStats_timeout(t *testing.T) {
}()
ctx := testhelper.Context(t)
- ctx = InitContextStats(ctx)
+ ctx = log.InitContextCustomFields(ctx)
_, err := getSpawnToken(ctx)
@@ -57,10 +58,10 @@ func TestGetSpawnToken_CommandStats_timeout(t *testing.T) {
require.Equal(t, "process spawn timed out after 1ms", limitErr.ErrorMessage)
require.Equal(t, durationpb.New(0), limitErr.RetryAfter)
- stats := StatsFromContext(ctx)
- require.NotNil(t, stats)
- fields := stats.Fields()
+ customFields := log.CustomFieldsFromContext(ctx)
+ require.NotNil(t, customFields)
+ logrusFields := customFields.Fields()
- require.GreaterOrEqual(t, fields["command.spawn_token_wait_ms"], 0)
- require.Equal(t, fields["command.spawn_token_error"], "spawn token timeout")
+ require.GreaterOrEqual(t, logrusFields["command.spawn_token_wait_ms"], 0)
+ require.Equal(t, logrusFields["command.spawn_token_error"], "spawn token timeout")
}
diff --git a/internal/command/stats.go b/internal/command/stats.go
deleted file mode 100644
index 03b8f6025..000000000
--- a/internal/command/stats.go
+++ /dev/null
@@ -1,80 +0,0 @@
-package command
-
-import (
- "context"
- "sync"
-
- "github.com/sirupsen/logrus"
-)
-
-type requestStatsKey struct{}
-
-// Stats records statistics about a command that was spawned.
-type Stats struct {
- resource map[string]int
- metadata map[string]string
- sync.Mutex
-}
-
-// RecordSum sums up all the values for a given key.
-func (stats *Stats) RecordSum(key string, value int) {
- stats.Lock()
- defer stats.Unlock()
-
- if prevValue, ok := stats.resource[key]; ok {
- value += prevValue
- }
-
- stats.resource[key] = value
-}
-
-// RecordMax will store the max value for a given key.
-func (stats *Stats) RecordMax(key string, value int) {
- stats.Lock()
- defer stats.Unlock()
-
- if prevValue, ok := stats.resource[key]; ok {
- if prevValue > value {
- return
- }
- }
-
- stats.resource[key] = value
-}
-
-// RecordMetadata records metadata for the given key.
-func (stats *Stats) RecordMetadata(key string, value string) {
- stats.Lock()
- defer stats.Unlock()
-
- stats.metadata[key] = value
-}
-
-// Fields returns all the stats as logrus.Fields
-func (stats *Stats) Fields() logrus.Fields {
- stats.Lock()
- defer stats.Unlock()
-
- f := logrus.Fields{}
- for k, v := range stats.resource {
- f[k] = v
- }
- for k, v := range stats.metadata {
- f[k] = v
- }
- return f
-}
-
-// StatsFromContext gets the `Stats` from the given context.
-func StatsFromContext(ctx context.Context) *Stats {
- stats, _ := ctx.Value(requestStatsKey{}).(*Stats)
- return stats
-}
-
-// InitContextStats returns a new context with `Stats` added to the given context.
-func InitContextStats(ctx context.Context) context.Context {
- return context.WithValue(ctx, requestStatsKey{}, &Stats{
- resource: make(map[string]int),
- metadata: make(map[string]string),
- })
-}
diff --git a/internal/command/stats_test.go b/internal/command/stats_test.go
deleted file mode 100644
index bf33cb10d..000000000
--- a/internal/command/stats_test.go
+++ /dev/null
@@ -1,88 +0,0 @@
-package command
-
-import (
- "testing"
-
- "github.com/sirupsen/logrus"
- "github.com/stretchr/testify/require"
- "gitlab.com/gitlab-org/gitaly/v16/internal/testhelper"
-)
-
-func TestStatsFromContext_BackgroundContext(t *testing.T) {
- ctx := testhelper.Context(t)
-
- stats := StatsFromContext(ctx)
- require.Nil(t, stats)
-}
-
-func TestStatsFromContext_InitContext(t *testing.T) {
- ctx := testhelper.Context(t)
-
- ctx = InitContextStats(ctx)
-
- stats := StatsFromContext(ctx)
-
- require.NotNil(t, stats)
- require.Equal(t, stats.Fields(), logrus.Fields{})
-}
-
-func TestStatsFromContext_RecordSum(t *testing.T) {
- ctx := testhelper.Context(t)
-
- ctx = InitContextStats(ctx)
-
- stats := StatsFromContext(ctx)
-
- stats.RecordSum("foo", 1)
- stats.RecordSum("foo", 1)
-
- require.NotNil(t, stats)
- require.Equal(t, stats.Fields(), logrus.Fields{"foo": 2})
-}
-
-func TestStatsFromContext_RecordSumByRef(t *testing.T) {
- ctx := testhelper.Context(t)
-
- ctx = InitContextStats(ctx)
-
- stats := StatsFromContext(ctx)
-
- stats.RecordSum("foo", 1)
- stats.RecordSum("foo", 1)
-
- stats2 := StatsFromContext(ctx)
-
- require.NotNil(t, stats2)
- require.Equal(t, stats2.Fields(), logrus.Fields{"foo": 2})
-}
-
-func TestStatsFromContext_RecordMax(t *testing.T) {
- ctx := testhelper.Context(t)
-
- ctx = InitContextStats(ctx)
-
- stats := StatsFromContext(ctx)
-
- stats.RecordMax("foo", 1024)
- stats.RecordMax("foo", 256)
- stats.RecordMax("foo", 512)
-
- require.NotNil(t, stats)
- require.Equal(t, stats.Fields(), logrus.Fields{"foo": 1024})
-}
-
-func TestStatsFromContext_RecordMetadata(t *testing.T) {
- ctx := testhelper.Context(t)
-
- ctx = InitContextStats(ctx)
-
- stats := StatsFromContext(ctx)
-
- stats.RecordMetadata("foo", "bar")
- require.NotNil(t, stats)
- require.Equal(t, stats.Fields(), logrus.Fields{"foo": "bar"})
-
- stats.RecordMetadata("foo", "baz") // override the existing value
- require.NotNil(t, stats)
- require.Equal(t, stats.Fields(), logrus.Fields{"foo": "baz"})
-}
diff --git a/internal/git/catfile/request_queue.go b/internal/git/catfile/request_queue.go
index d90a8a738..9e7c99549 100644
--- a/internal/git/catfile/request_queue.go
+++ b/internal/git/catfile/request_queue.go
@@ -9,8 +9,8 @@ import (
"sync/atomic"
"time"
- "gitlab.com/gitlab-org/gitaly/v16/internal/command"
"gitlab.com/gitlab-org/gitaly/v16/internal/git"
+ "gitlab.com/gitlab-org/gitaly/v16/internal/log"
)
const (
@@ -261,10 +261,10 @@ func logDuration(ctx context.Context, logFieldName string) func() {
start := time.Now()
return func() {
delta := time.Since(start)
- if stats := command.StatsFromContext(ctx); stats != nil {
- stats.RecordSum(fmt.Sprintf("catfile.%s_count", logFieldName), 1)
- stats.RecordSum(fmt.Sprintf("catfile.%s_ms", logFieldName), int(delta.Milliseconds()))
- stats.RecordSum("catfile.duration_ms", int(delta.Milliseconds()))
+ if customFields := log.CustomFieldsFromContext(ctx); customFields != nil {
+ customFields.RecordSum(fmt.Sprintf("catfile.%s_count", logFieldName), 1)
+ customFields.RecordSum(fmt.Sprintf("catfile.%s_ms", logFieldName), int(delta.Milliseconds()))
+ customFields.RecordSum("catfile.duration_ms", int(delta.Milliseconds()))
}
}
}
diff --git a/internal/git/catfile/request_queue_test.go b/internal/git/catfile/request_queue_test.go
index 0cd99adfe..81c2f873f 100644
--- a/internal/git/catfile/request_queue_test.go
+++ b/internal/git/catfile/request_queue_test.go
@@ -10,9 +10,9 @@ import (
"unsafe"
"github.com/stretchr/testify/require"
- "gitlab.com/gitlab-org/gitaly/v16/internal/command"
"gitlab.com/gitlab-org/gitaly/v16/internal/git"
"gitlab.com/gitlab-org/gitaly/v16/internal/git/gittest"
+ "gitlab.com/gitlab-org/gitaly/v16/internal/log"
"gitlab.com/gitlab-org/gitaly/v16/internal/testhelper"
"gitlab.com/gitlab-org/gitaly/v16/internal/testhelper/testcfg"
)
@@ -414,7 +414,7 @@ func TestRequestQueue_CommandStats(t *testing.T) {
t.Parallel()
ctx := testhelper.Context(t)
- ctx = command.InitContextStats(ctx)
+ ctx = log.InitContextCustomFields(ctx)
oid := git.ObjectID(strings.Repeat("1", gittest.DefaultObjectHash.EncodedLen()))
@@ -429,8 +429,8 @@ func TestRequestQueue_CommandStats(t *testing.T) {
_, err := queue.ReadObject(ctx)
require.NoError(t, err)
- stats := command.StatsFromContext(ctx)
- fields := stats.Fields()
+ customFields := log.CustomFieldsFromContext(ctx)
+ fields := customFields.Fields()
require.Contains(t, fields, "catfile.request_object_count")
require.Contains(t, fields, "catfile.request_object_ms")
require.Contains(t, fields, "catfile.flush_count")
diff --git a/internal/git/command_factory.go b/internal/git/command_factory.go
index 729cea715..09979243f 100644
--- a/internal/git/command_factory.go
+++ b/internal/git/command_factory.go
@@ -617,12 +617,12 @@ func (cf *ExecCommandFactory) GlobalConfiguration(ctx context.Context) ([]Config
func (cf *ExecCommandFactory) trace2Finalizer(manager *trace2.Manager) func(context.Context, *command.Command) {
return func(ctx context.Context, cmd *command.Command) {
manager.Finish(ctx)
- stats := command.StatsFromContext(ctx)
- if stats != nil {
- stats.RecordMetadata("trace2.activated", "true")
- stats.RecordMetadata("trace2.hooks", strings.Join(manager.HookNames(), ","))
+ customFields := log.CustomFieldsFromContext(ctx)
+ if customFields != nil {
+ customFields.RecordMetadata("trace2.activated", "true")
+ customFields.RecordMetadata("trace2.hooks", strings.Join(manager.HookNames(), ","))
if manager.Error() != nil {
- stats.RecordMetadata("trace2.error", manager.Error().Error())
+ customFields.RecordMetadata("trace2.error", manager.Error().Error())
}
}
}
diff --git a/internal/git/command_factory_test.go b/internal/git/command_factory_test.go
index d361f4626..6e733afc2 100644
--- a/internal/git/command_factory_test.go
+++ b/internal/git/command_factory_test.go
@@ -18,13 +18,13 @@ import (
"github.com/sirupsen/logrus"
"github.com/stretchr/testify/require"
- "gitlab.com/gitlab-org/gitaly/v16/internal/command"
"gitlab.com/gitlab-org/gitaly/v16/internal/git"
"gitlab.com/gitlab-org/gitaly/v16/internal/git/gittest"
"gitlab.com/gitlab-org/gitaly/v16/internal/git/trace2"
"gitlab.com/gitlab-org/gitaly/v16/internal/git/trace2hooks"
"gitlab.com/gitlab-org/gitaly/v16/internal/gitaly/config"
"gitlab.com/gitlab-org/gitaly/v16/internal/helper/text"
+ "gitlab.com/gitlab-org/gitaly/v16/internal/log"
"gitlab.com/gitlab-org/gitaly/v16/internal/testhelper"
"gitlab.com/gitlab-org/gitaly/v16/internal/testhelper/testcfg"
"gitlab.com/gitlab-org/gitaly/v16/internal/tracing"
@@ -737,10 +737,10 @@ func TestWithTrace2Hooks(t *testing.T) {
}
for _, tc := range []struct {
- desc string
- setup func(t *testing.T) []trace2.Hook
- expectedStats map[string]any
- withStats bool
+ desc string
+ setup func(t *testing.T) []trace2.Hook
+ expectedFields map[string]any
+ withFields bool
}{
{
desc: "trace2 hook runs successfully",
@@ -755,8 +755,8 @@ func TestWithTrace2Hooks(t *testing.T) {
},
}
},
- withStats: true,
- expectedStats: map[string]any{
+ withFields: true,
+ expectedFields: map[string]any{
"trace2.activated": "true",
"trace2.hooks": "dummy",
},
@@ -781,8 +781,8 @@ func TestWithTrace2Hooks(t *testing.T) {
},
}
},
- withStats: true,
- expectedStats: map[string]any{
+ withFields: true,
+ expectedFields: map[string]any{
"trace2.activated": "true",
"trace2.hooks": "dummy,dummy2",
},
@@ -792,8 +792,8 @@ func TestWithTrace2Hooks(t *testing.T) {
setup: func(t *testing.T) []trace2.Hook {
return []trace2.Hook{}
},
- withStats: true,
- expectedStats: map[string]any{
+ withFields: true,
+ expectedFields: map[string]any{
"trace2.activated": nil,
"trace2.hooks": nil,
},
@@ -817,15 +817,15 @@ func TestWithTrace2Hooks(t *testing.T) {
},
}
},
- withStats: true,
- expectedStats: map[string]any{
+ withFields: true,
+ expectedFields: map[string]any{
"trace2.activated": "true",
"trace2.hooks": "dummy,dummy2",
"trace2.error": `trace2: executing "dummy" handler: something goes wrong`,
},
},
{
- desc: "stats is not initialized",
+ desc: "context does not initialize custom fields",
setup: func(t *testing.T) []trace2.Hook {
return []trace2.Hook{
&dummyHook{
@@ -837,28 +837,28 @@ func TestWithTrace2Hooks(t *testing.T) {
},
}
},
- withStats: false,
+ withFields: false,
},
} {
t.Run(tc.desc, func(t *testing.T) {
hooks := tc.setup(t)
ctx := testhelper.Context(t)
- if tc.withStats {
- ctx = command.InitContextStats(ctx)
+ if tc.withFields {
+ ctx = log.InitContextCustomFields(ctx)
}
performPackObjectGit(t, ctx, git.WithTrace2Hooks(hooks))
- if tc.withStats {
- stats := command.StatsFromContext(ctx)
- require.NotNil(t, stats)
+ if tc.withFields {
+ customFields := log.CustomFieldsFromContext(ctx)
+ require.NotNil(t, customFields)
- fields := stats.Fields()
- for key, value := range tc.expectedStats {
- require.Equal(t, value, fields[key])
+ logrusFields := customFields.Fields()
+ for key, value := range tc.expectedFields {
+ require.Equal(t, value, logrusFields[key])
}
} else {
- require.Nil(t, command.StatsFromContext(ctx))
+ require.Nil(t, log.CustomFieldsFromContext(ctx))
}
})
}
@@ -922,12 +922,12 @@ func TestTrace2TracingExporter(t *testing.T) {
reporter, cleanup := testhelper.StubTracingReporter(t, tc.tracerOptions...)
defer cleanup()
- ctx := tc.setup(t, command.InitContextStats(testhelper.Context(t)))
+ ctx := tc.setup(t, log.InitContextCustomFields(testhelper.Context(t)))
performRevList(t, ctx)
- stats := command.StatsFromContext(ctx)
- require.NotNil(t, stats)
- statFields := stats.Fields()
+ customFields := log.CustomFieldsFromContext(ctx)
+ require.NotNil(t, customFields)
+ statFields := customFields.Fields()
var spans []string
for _, span := range testhelper.ReportedSpans(t, reporter) {
@@ -992,14 +992,14 @@ func TestTrace2PackObjectsMetrics(t *testing.T) {
t.Run(tc.desc, func(t *testing.T) {
t.Parallel()
- ctx := command.InitContextStats(testhelper.Context(t))
+ ctx := log.InitContextCustomFields(testhelper.Context(t))
tc.performGitCommand(t, ctx)
- stats := command.StatsFromContext(ctx)
- require.NotNil(t, stats)
+ customFields := log.CustomFieldsFromContext(ctx)
+ require.NotNil(t, customFields)
- statFields := stats.Fields()
- tc.assert(t, ctx, statFields)
+ logrusFields := customFields.Fields()
+ tc.assert(t, ctx, logrusFields)
})
}
}
diff --git a/internal/git/trace2hooks/packobjects_metrics.go b/internal/git/trace2hooks/packobjects_metrics.go
index 171b3c581..f9fd5515e 100644
--- a/internal/git/trace2hooks/packobjects_metrics.go
+++ b/internal/git/trace2hooks/packobjects_metrics.go
@@ -5,8 +5,8 @@ import (
"strconv"
"github.com/prometheus/client_golang/prometheus"
- "gitlab.com/gitlab-org/gitaly/v16/internal/command"
"gitlab.com/gitlab-org/gitaly/v16/internal/git/trace2"
+ "gitlab.com/gitlab-org/gitaly/v16/internal/log"
)
var statsIntData = map[string]string{
@@ -56,18 +56,18 @@ func (p *PackObjectsMetrics) Name() string {
// When it finds one, it updates Prometheus objects and log fields accordingly.
func (p *PackObjectsMetrics) Handle(rootCtx context.Context, trace *trace2.Trace) error {
trace.Walk(rootCtx, func(ctx context.Context, trace *trace2.Trace) context.Context {
- stats := command.StatsFromContext(ctx)
- if stats != nil {
+ customFields := log.CustomFieldsFromContext(ctx)
+ if customFields != nil {
if field, ok := statsIntData[trace.Name]; ok {
data, err := strconv.Atoi(trace.Metadata["data"])
if err == nil {
- stats.RecordSum(field, data)
+ customFields.RecordSum(field, data)
}
}
if field, ok := statsElapsedTimes[trace.Name]; ok {
elapsedTime := trace.FinishTime.Sub(trace.StartTime).Milliseconds()
- stats.RecordSum(field, int(elapsedTime))
+ customFields.RecordSum(field, int(elapsedTime))
}
if stage, ok := histogramStageNames[trace.Name]; ok {
diff --git a/internal/git/trace2hooks/packobjects_metrics_ext_test.go b/internal/git/trace2hooks/packobjects_metrics_ext_test.go
index 7583aea83..edf432788 100644
--- a/internal/git/trace2hooks/packobjects_metrics_ext_test.go
+++ b/internal/git/trace2hooks/packobjects_metrics_ext_test.go
@@ -8,12 +8,12 @@ import (
"github.com/sirupsen/logrus"
"github.com/stretchr/testify/require"
- "gitlab.com/gitlab-org/gitaly/v16/internal/command"
"gitlab.com/gitlab-org/gitaly/v16/internal/git"
"gitlab.com/gitlab-org/gitaly/v16/internal/git/gittest"
"gitlab.com/gitlab-org/gitaly/v16/internal/git/trace2"
"gitlab.com/gitlab-org/gitaly/v16/internal/git/trace2hooks"
"gitlab.com/gitlab-org/gitaly/v16/internal/gitaly/config"
+ "gitlab.com/gitlab-org/gitaly/v16/internal/log"
"gitlab.com/gitlab-org/gitaly/v16/internal/testhelper"
"gitlab.com/gitlab-org/gitaly/v16/internal/testhelper/testcfg"
"gitlab.com/gitlab-org/gitaly/v16/proto/go/gitalypb"
@@ -175,7 +175,7 @@ func TestPackObjectsMetrics(t *testing.T) {
t.Run(tc.desc, func(t *testing.T) {
t.Parallel()
- ctx := command.InitContextStats(testhelper.Context(t))
+ ctx := log.InitContextCustomFields(testhelper.Context(t))
repoProto, cfg, input := tc.setupRepo(ctx)
gitCmdFactory, cleanup, err := git.NewExecCommandFactory(cfg, git.WithTrace2Hooks([]trace2.Hook{
trace2hooks.NewPackObjectsMetrics(),
@@ -197,17 +197,17 @@ func TestPackObjectsMetrics(t *testing.T) {
err = cmd.Wait()
require.NoError(t, err)
- stats := command.StatsFromContext(ctx)
- require.NotNil(t, stats)
+ customFields := log.CustomFieldsFromContext(ctx)
+ require.NotNil(t, customFields)
- statFields := stats.Fields()
- require.Equal(t, "true", statFields["trace2.activated"])
- require.Equal(t, "pack_objects_metrics", statFields["trace2.hooks"])
- require.Contains(t, statFields, "pack_objects.enumerate_objects_ms")
- require.Contains(t, statFields, "pack_objects.prepare_pack_ms")
- require.Contains(t, statFields, "pack_objects.write_pack_file_ms")
+ logrusFields := customFields.Fields()
+ require.Equal(t, "true", logrusFields["trace2.activated"])
+ require.Equal(t, "pack_objects_metrics", logrusFields["trace2.hooks"])
+ require.Contains(t, logrusFields, "pack_objects.enumerate_objects_ms")
+ require.Contains(t, logrusFields, "pack_objects.prepare_pack_ms")
+ require.Contains(t, logrusFields, "pack_objects.write_pack_file_ms")
- tc.assert(t, statFields)
+ tc.assert(t, logrusFields)
})
}
}
diff --git a/internal/git/trace2hooks/packobjects_metrics_test.go b/internal/git/trace2hooks/packobjects_metrics_test.go
index 9d32dcfd6..c4645acd5 100644
--- a/internal/git/trace2hooks/packobjects_metrics_test.go
+++ b/internal/git/trace2hooks/packobjects_metrics_test.go
@@ -8,8 +8,8 @@ import (
"github.com/prometheus/client_golang/prometheus/testutil"
"github.com/sirupsen/logrus"
"github.com/stretchr/testify/require"
- "gitlab.com/gitlab-org/gitaly/v16/internal/command"
"gitlab.com/gitlab-org/gitaly/v16/internal/git/trace2"
+ "gitlab.com/gitlab-org/gitaly/v16/internal/log"
"gitlab.com/gitlab-org/gitaly/v16/internal/testhelper"
)
@@ -25,12 +25,12 @@ func TestPackObjectsMetrics_Handle(t *testing.T) {
desc string
inputTrace *trace2.Trace
expectedMetrics string
- expectedStats logrus.Fields
+ expectedFields logrus.Fields
}{
{
desc: "empty trace",
inputTrace: nil,
- expectedStats: logrus.Fields{},
+ expectedFields: logrus.Fields{},
expectedMetrics: ``,
},
{
@@ -41,7 +41,7 @@ func TestPackObjectsMetrics_Handle(t *testing.T) {
StartTime: current,
FinishTime: time.Time{},
},
- expectedStats: logrus.Fields{},
+ expectedFields: logrus.Fields{},
expectedMetrics: ``,
},
{
@@ -153,7 +153,7 @@ func TestPackObjectsMetrics_Handle(t *testing.T) {
),
},
}),
- expectedStats: logrus.Fields{
+ expectedFields: logrus.Fields{
"pack_objects.written_object_count": 99,
"pack_objects.loosened_unused_packed_objects": 1234,
"pack_objects.stdin_packs_hints": 999,
@@ -314,7 +314,7 @@ gitaly_pack_objects_stages_seconds_count{stage="write-pack-file"} 1
),
},
}),
- expectedStats: logrus.Fields{
+ expectedFields: logrus.Fields{
"pack_objects.written_object_count": 101,
"pack_objects.loosened_unused_packed_objects": 4690,
"pack_objects.stdin_packs_hints": 999,
@@ -375,7 +375,7 @@ gitaly_pack_objects_stages_seconds_count{stage="write-pack-file"} 2
t.Run(tc.desc, func(t *testing.T) {
t.Parallel()
- ctx := command.InitContextStats(testhelper.Context(t))
+ ctx := log.InitContextCustomFields(testhelper.Context(t))
exporter := NewPackObjectsMetrics()
@@ -390,9 +390,9 @@ gitaly_pack_objects_stages_seconds_count{stage="write-pack-file"} 2
),
)
- stats := command.StatsFromContext(ctx)
- require.NotNil(t, stats)
- require.Equal(t, tc.expectedStats, stats.Fields())
+ customFields := log.CustomFieldsFromContext(ctx)
+ require.NotNil(t, customFields)
+ require.Equal(t, tc.expectedFields, customFields.Fields())
})
}
}
diff --git a/internal/gitaly/server/server.go b/internal/gitaly/server/server.go
index fbe73feaf..f9caf4e08 100644
--- a/internal/gitaly/server/server.go
+++ b/internal/gitaly/server/server.go
@@ -14,7 +14,7 @@ import (
"gitlab.com/gitlab-org/gitaly/v16/internal/grpc/grpcstats"
"gitlab.com/gitlab-org/gitaly/v16/internal/grpc/listenmux"
"gitlab.com/gitlab-org/gitaly/v16/internal/grpc/middleware/cache"
- "gitlab.com/gitlab-org/gitaly/v16/internal/grpc/middleware/commandstatshandler"
+ "gitlab.com/gitlab-org/gitaly/v16/internal/grpc/middleware/customfieldshandler"
"gitlab.com/gitlab-org/gitaly/v16/internal/grpc/middleware/featureflag"
"gitlab.com/gitlab-org/gitaly/v16/internal/grpc/middleware/limithandler"
"gitlab.com/gitlab-org/gitaly/v16/internal/grpc/middleware/metadatahandler"
@@ -107,7 +107,7 @@ func (s *GitalyServerFactory) New(secure bool, opts ...Option) (*grpc.Server, er
logMsgProducer := grpcmwlogrus.WithMessageProducer(
gitalylog.MessageProducer(
gitalylog.PropagationMessageProducer(grpcmwlogrus.DefaultMessageProducer),
- commandstatshandler.FieldsProducer,
+ customfieldshandler.FieldsProducer,
grpcstats.FieldsProducer,
featureflag.FieldsProducer,
structerr.FieldsProducer,
@@ -120,7 +120,7 @@ func (s *GitalyServerFactory) New(secure bool, opts ...Option) (*grpc.Server, er
grpccorrelation.StreamServerCorrelationInterceptor(), // Must be above the metadata handler
metadatahandler.StreamInterceptor,
grpcprometheus.StreamServerInterceptor,
- commandstatshandler.StreamInterceptor,
+ customfieldshandler.StreamInterceptor,
limithandler.StatsStreamInterceptor,
grpcmwlogrus.StreamServerInterceptor(s.logger,
grpcmwlogrus.WithTimestampFormat(gitalylog.LogTimestampFormat),
@@ -137,7 +137,7 @@ func (s *GitalyServerFactory) New(secure bool, opts ...Option) (*grpc.Server, er
grpccorrelation.UnaryServerCorrelationInterceptor(), // Must be above the metadata handler
metadatahandler.UnaryInterceptor,
grpcprometheus.UnaryServerInterceptor,
- commandstatshandler.UnaryInterceptor,
+ customfieldshandler.UnaryInterceptor,
limithandler.StatsUnaryInterceptor,
grpcmwlogrus.UnaryServerInterceptor(s.logger,
grpcmwlogrus.WithTimestampFormat(gitalylog.LogTimestampFormat),
diff --git a/internal/gitaly/service/hook/pack_objects.go b/internal/gitaly/service/hook/pack_objects.go
index 58f6d12ec..925416e81 100644
--- a/internal/gitaly/service/hook/pack_objects.go
+++ b/internal/gitaly/service/hook/pack_objects.go
@@ -17,11 +17,11 @@ import (
"github.com/prometheus/client_golang/prometheus"
"github.com/prometheus/client_golang/prometheus/promauto"
- "gitlab.com/gitlab-org/gitaly/v16/internal/command"
"gitlab.com/gitlab-org/gitaly/v16/internal/git"
"gitlab.com/gitlab-org/gitaly/v16/internal/git/pktline"
gitalyhook "gitlab.com/gitlab-org/gitaly/v16/internal/gitaly/hook"
"gitlab.com/gitlab-org/gitaly/v16/internal/helper"
+ "gitlab.com/gitlab-org/gitaly/v16/internal/log"
"gitlab.com/gitlab-org/gitaly/v16/internal/stream"
"gitlab.com/gitlab-org/gitaly/v16/internal/structerr"
"gitlab.com/gitlab-org/gitaly/v16/proto/go/gitalypb"
@@ -95,14 +95,14 @@ func (s *server) packObjectsHook(ctx context.Context, req *gitalypb.PackObjectsH
packObjectsCacheLookups.WithLabelValues("hit").Inc()
}
- stats := command.StatsFromContext(ctx)
- if stats != nil {
- stats.RecordMetadata("pack_objects_cache.key", cacheKey)
- stats.RecordSum("pack_objects_cache.served_bytes", int(servedBytes))
+ customFields := log.CustomFieldsFromContext(ctx)
+ if customFields != nil {
+ customFields.RecordMetadata("pack_objects_cache.key", cacheKey)
+ customFields.RecordSum("pack_objects_cache.served_bytes", int(servedBytes))
if created {
- stats.RecordMetadata("pack_objects_cache.hit", "false")
+ customFields.RecordMetadata("pack_objects_cache.hit", "false")
} else {
- stats.RecordMetadata("pack_objects_cache.hit", "true")
+ customFields.RecordMetadata("pack_objects_cache.hit", "true")
}
}
packObjectsServedBytes.Add(float64(servedBytes))
@@ -241,12 +241,12 @@ func runPackObjects(
defer func() {
packObjectsGeneratedBytes.Add(float64(counter.N))
- stats := command.StatsFromContext(ctx)
- if stats != nil {
- stats.RecordMetadata("pack_objects_cache.key", key)
- stats.RecordSum("pack_objects_cache.generated_bytes", int(counter.N))
+ customFields := log.CustomFieldsFromContext(ctx)
+ if customFields != nil {
+ customFields.RecordMetadata("pack_objects_cache.key", key)
+ customFields.RecordSum("pack_objects_cache.generated_bytes", int(counter.N))
if total := totalMessage(stderrBuf.Bytes()); total != "" {
- stats.RecordMetadata("pack_objects.compression_statistics", total)
+ customFields.RecordMetadata("pack_objects.compression_statistics", total)
}
}
}()
diff --git a/internal/grpc/middleware/commandstatshandler/commandstatshandler.go b/internal/grpc/middleware/customfieldshandler/customfields_handler.go
index c1029e1d8..bf4054053 100644
--- a/internal/grpc/middleware/commandstatshandler/commandstatshandler.go
+++ b/internal/grpc/middleware/customfieldshandler/customfields_handler.go
@@ -1,27 +1,27 @@
-package commandstatshandler
+package customfieldshandler
import (
"context"
grpcmw "github.com/grpc-ecosystem/go-grpc-middleware"
"github.com/sirupsen/logrus"
- "gitlab.com/gitlab-org/gitaly/v16/internal/command"
+ "gitlab.com/gitlab-org/gitaly/v16/internal/log"
"google.golang.org/grpc"
)
-// UnaryInterceptor returns a Unary Interceptor
+// UnaryInterceptor returns a Unary Interceptor that initializes and injects a log.CustomFields object into the context
func UnaryInterceptor(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (interface{}, error) {
- ctx = command.InitContextStats(ctx)
+ ctx = log.InitContextCustomFields(ctx)
res, err := handler(ctx, req)
return res, err
}
-// StreamInterceptor returns a Stream Interceptor
+// StreamInterceptor returns a Stream Interceptor that initializes and injects a log.CustomFields object into the context
func StreamInterceptor(srv interface{}, stream grpc.ServerStream, info *grpc.StreamServerInfo, handler grpc.StreamHandler) error {
ctx := stream.Context()
- ctx = command.InitContextStats(ctx)
+ ctx = log.InitContextCustomFields(ctx)
wrapped := grpcmw.WrapServerStream(stream)
wrapped.WrappedContext = ctx
@@ -31,10 +31,10 @@ func StreamInterceptor(srv interface{}, stream grpc.ServerStream, info *grpc.Str
return err
}
-// FieldsProducer extracts stats info from the context and returns it as a logging fields.
+// FieldsProducer extracts custom fields info from the context and returns it as a logging fields.
func FieldsProducer(ctx context.Context, _ error) logrus.Fields {
- if stats := command.StatsFromContext(ctx); stats != nil {
- return stats.Fields()
+ if fields := log.CustomFieldsFromContext(ctx); fields != nil {
+ return fields.Fields()
}
return nil
}
diff --git a/internal/grpc/middleware/commandstatshandler/commandstatshandler_test.go b/internal/grpc/middleware/customfieldshandler/customfields_handler_test.go
index 483a2cc3d..67568378b 100644
--- a/internal/grpc/middleware/commandstatshandler/commandstatshandler_test.go
+++ b/internal/grpc/middleware/customfieldshandler/customfields_handler_test.go
@@ -1,4 +1,4 @@
-package commandstatshandler
+package customfieldshandler
import (
"context"
@@ -10,7 +10,6 @@ import (
"github.com/sirupsen/logrus"
"github.com/sirupsen/logrus/hooks/test"
"github.com/stretchr/testify/require"
- "gitlab.com/gitlab-org/gitaly/v16/internal/command"
"gitlab.com/gitlab-org/gitaly/v16/internal/git/catfile"
"gitlab.com/gitlab-org/gitaly/v16/internal/git/gittest"
"gitlab.com/gitlab-org/gitaly/v16/internal/gitaly/config"
@@ -163,9 +162,9 @@ func TestInterceptor(t *testing.T) {
func TestFieldsProducer(t *testing.T) {
ctx := testhelper.Context(t)
- ctx = command.InitContextStats(ctx)
- stats := command.StatsFromContext(ctx)
- stats.RecordMax("stub", 42)
+ ctx = log.InitContextCustomFields(ctx)
+ fields := log.CustomFieldsFromContext(ctx)
+ fields.RecordMax("stub", 42)
require.Equal(t, logrus.Fields{"stub": 42}, FieldsProducer(ctx, nil))
}
diff --git a/internal/log/customfields.go b/internal/log/customfields.go
new file mode 100644
index 000000000..1622810f2
--- /dev/null
+++ b/internal/log/customfields.go
@@ -0,0 +1,82 @@
+package log
+
+import (
+ "context"
+ "sync"
+
+ "github.com/sirupsen/logrus"
+)
+
+type requestCustomFieldsKey struct{}
+
+// CustomFields stores custom fields, which will be logged as a part of gRPC logs. The gRPC server is expected to add
+// corresponding interceptors. They initialize a CustomFields object and inject it into the context. Callers can pull
+// the object out with CustomFieldsFromContext.
+type CustomFields struct {
+ numericFields map[string]int
+ stringFields map[string]string
+ sync.Mutex
+}
+
+// RecordSum sums up all the values for a given key.
+func (fields *CustomFields) RecordSum(key string, value int) {
+ fields.Lock()
+ defer fields.Unlock()
+
+ if prevValue, ok := fields.numericFields[key]; ok {
+ value += prevValue
+ }
+
+ fields.numericFields[key] = value
+}
+
+// RecordMax will store the max value for a given key.
+func (fields *CustomFields) RecordMax(key string, value int) {
+ fields.Lock()
+ defer fields.Unlock()
+
+ if prevValue, ok := fields.numericFields[key]; ok {
+ if prevValue > value {
+ return
+ }
+ }
+
+ fields.numericFields[key] = value
+}
+
+// RecordMetadata records a string metadata for the given key.
+func (fields *CustomFields) RecordMetadata(key string, value string) {
+ fields.Lock()
+ defer fields.Unlock()
+
+ fields.stringFields[key] = value
+}
+
+// Fields returns all the fields as logrus.Fields
+func (fields *CustomFields) Fields() logrus.Fields {
+ fields.Lock()
+ defer fields.Unlock()
+
+ f := logrus.Fields{}
+ for k, v := range fields.numericFields {
+ f[k] = v
+ }
+ for k, v := range fields.stringFields {
+ f[k] = v
+ }
+ return f
+}
+
+// CustomFieldsFromContext gets the `CustomFields` from the given context.
+func CustomFieldsFromContext(ctx context.Context) *CustomFields {
+ fields, _ := ctx.Value(requestCustomFieldsKey{}).(*CustomFields)
+ return fields
+}
+
+// InitContextCustomFields returns a new context with `CustomFields` added to the given context.
+func InitContextCustomFields(ctx context.Context) context.Context {
+ return context.WithValue(ctx, requestCustomFieldsKey{}, &CustomFields{
+ numericFields: make(map[string]int),
+ stringFields: make(map[string]string),
+ })
+}
diff --git a/internal/log/customfields_test.go b/internal/log/customfields_test.go
new file mode 100644
index 000000000..07577b17c
--- /dev/null
+++ b/internal/log/customfields_test.go
@@ -0,0 +1,89 @@
+package log_test
+
+import (
+ "testing"
+
+ "github.com/sirupsen/logrus"
+ "github.com/stretchr/testify/require"
+ "gitlab.com/gitlab-org/gitaly/v16/internal/log"
+ "gitlab.com/gitlab-org/gitaly/v16/internal/testhelper"
+)
+
+func TestStatsFromContext_BackgroundContext(t *testing.T) {
+ ctx := testhelper.Context(t)
+
+ customFields := log.CustomFieldsFromContext(ctx)
+ require.Nil(t, customFields)
+}
+
+func TestStatsFromContext_InitContext(t *testing.T) {
+ ctx := testhelper.Context(t)
+
+ ctx = log.InitContextCustomFields(ctx)
+
+ customFields := log.CustomFieldsFromContext(ctx)
+
+ require.NotNil(t, customFields)
+ require.Equal(t, customFields.Fields(), logrus.Fields{})
+}
+
+func TestStatsFromContext_RecordSum(t *testing.T) {
+ ctx := testhelper.Context(t)
+
+ ctx = log.InitContextCustomFields(ctx)
+
+ customFields := log.CustomFieldsFromContext(ctx)
+
+ customFields.RecordSum("foo", 1)
+ customFields.RecordSum("foo", 1)
+
+ require.NotNil(t, customFields)
+ require.Equal(t, customFields.Fields(), logrus.Fields{"foo": 2})
+}
+
+func TestStatsFromContext_RecordSumByRef(t *testing.T) {
+ ctx := testhelper.Context(t)
+
+ ctx = log.InitContextCustomFields(ctx)
+
+ customFields := log.CustomFieldsFromContext(ctx)
+
+ customFields.RecordSum("foo", 1)
+ customFields.RecordSum("foo", 1)
+
+ stats2 := log.CustomFieldsFromContext(ctx)
+
+ require.NotNil(t, stats2)
+ require.Equal(t, stats2.Fields(), logrus.Fields{"foo": 2})
+}
+
+func TestStatsFromContext_RecordMax(t *testing.T) {
+ ctx := testhelper.Context(t)
+
+ ctx = log.InitContextCustomFields(ctx)
+
+ customFields := log.CustomFieldsFromContext(ctx)
+
+ customFields.RecordMax("foo", 1024)
+ customFields.RecordMax("foo", 256)
+ customFields.RecordMax("foo", 512)
+
+ require.NotNil(t, customFields)
+ require.Equal(t, customFields.Fields(), logrus.Fields{"foo": 1024})
+}
+
+func TestStatsFromContext_RecordMetadata(t *testing.T) {
+ ctx := testhelper.Context(t)
+
+ ctx = log.InitContextCustomFields(ctx)
+
+ customFields := log.CustomFieldsFromContext(ctx)
+
+ customFields.RecordMetadata("foo", "bar")
+ require.NotNil(t, customFields)
+ require.Equal(t, customFields.Fields(), logrus.Fields{"foo": "bar"})
+
+ customFields.RecordMetadata("foo", "baz") // override the existing value
+ require.NotNil(t, customFields)
+ require.Equal(t, customFields.Fields(), logrus.Fields{"foo": "baz"})
+}