diff options
author | Justin Tobler <jtobler@gitlab.com> | 2023-06-21 20:09:31 +0300 |
---|---|---|
committer | Justin Tobler <jtobler@gitlab.com> | 2023-06-21 20:09:31 +0300 |
commit | 1b2c003553f04d1d720d35d492475735d3ce06f4 (patch) | |
tree | 50cdd39ca1f4cddb2099b5b6bb5f6ce2752f6ec8 | |
parent | 739c61e1df3f7cd38a1c875a63d84cc6e7153ff2 (diff) | |
parent | 2b87d1b73af6bbe42c03402cf2d3127af80c8d79 (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>
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"}) +} |