From b6ee471196742a8be3a9583ef2971a383c7531f8 Mon Sep 17 00:00:00 2001 From: Quang-Minh Nguyen Date: Wed, 8 Nov 2023 17:13:06 +0700 Subject: [PATCH 1/2] Fix chatty loopWriter logs when log level config is empty For https://gitlab.com/gitlab-org/gitaly/-/issues/5658 Recently, we noticed that Gitaly sometimes outputs verbose transportation logs with `info` severity: "[transport] [server-transport 0xc005cdf520] loopyWriter exiting with error: transport closed by client" The loopy writer stuff is gRPC-internal logic and likely doesn't indicate anything important. In fact, those logs are always output when the server/client closes the transportation regardless of the errors. The log printing statement can be found here: https://github.com/grpc/grpc-go/blob/8edfa1a17b3ff88cdb8cc9ec39fce22b812cf842/internal/transport/http2_server.go#L1232 We implemented a mechanism to replace grpc's default logger to make it less chatty. The replacement uplifts the minimum grpc logger level to "warning" when the configured Gitaly log level is "info". Unfortunately, it doesn't handle the case where Gitaly does not configure log level. As a result, grpc falls back to its "info". This commit handles that edge case. --- internal/log/configure.go | 2 +- internal/log/configure_test.go | 5 +++++ 2 files changed, 6 insertions(+), 1 deletion(-) diff --git a/internal/log/configure.go b/internal/log/configure.go index 691ffa7b3a..da3eda3aa0 100644 --- a/internal/log/configure.go +++ b/internal/log/configure.go @@ -127,7 +127,7 @@ func mapGRPCLogLevel(level string) string { // grpc-go is too verbose at level 'info'. So when config.toml requests // level info, we tell grpc-go to log at 'warn' instead. - if level == "info" { + if level == "info" || level == "" { return "warning" } diff --git a/internal/log/configure_test.go b/internal/log/configure_test.go index db2f0fe2e7..01853d39f3 100644 --- a/internal/log/configure_test.go +++ b/internal/log/configure_test.go @@ -160,6 +160,11 @@ func TestMapGRPCLogLevel(t *testing.T) { level: "info", expectedLevel: "warning", }, + { + desc: "empty level gets mapped", + level: "", + expectedLevel: "warning", + }, { desc: "environment overrides value", environmentLevel: "ERROR", -- GitLab From 136473dde55da6ca9781f90ae105dc4830a9a2c4 Mon Sep 17 00:00:00 2001 From: Quang-Minh Nguyen Date: Wed, 8 Nov 2023 17:27:15 +0700 Subject: [PATCH 2/2] Set logging level config to "info" explicitly In multiple places, we state that the default log level is "info" by default. The "info" severity is set when the underlying logging library parses the log level unsuccessfully. We don't have set the default config to "info". In a prior commit, we fixed a grpc logger issue due to the missing of configured log level. To prevent that from happening again at another place, this commit sets a default logging level. --- internal/gitaly/config/config.go | 9 +++++++++ internal/gitaly/config/config_test.go | 6 ++++++ 2 files changed, 15 insertions(+) diff --git a/internal/gitaly/config/config.go b/internal/gitaly/config/config.go index 735fa2d659..2ff633bd39 100644 --- a/internal/gitaly/config/config.go +++ b/internal/gitaly/config/config.go @@ -584,6 +584,14 @@ func (scc StreamCacheConfig) Validate() error { AsError() } +func defaultLoggingConfig() Logging { + return Logging{ + Config: log.Config{ + Level: "info", + }, + } +} + func defaultPackObjectsCacheConfig() StreamCacheConfig { return StreamCacheConfig{ // The Pack-Objects cache is effective at deduplicating concurrent @@ -616,6 +624,7 @@ func defaultPackObjectsLimiting() PackObjectsLimiting { func Load(file io.Reader) (Cfg, error) { cfg := Cfg{ Prometheus: prometheus.DefaultConfig(), + Logging: defaultLoggingConfig(), PackObjectsCache: defaultPackObjectsCacheConfig(), PackObjectsLimiting: defaultPackObjectsLimiting(), } diff --git a/internal/gitaly/config/config_test.go b/internal/gitaly/config/config_test.go index 41c12c8008..37d8f4cb0e 100644 --- a/internal/gitaly/config/config_test.go +++ b/internal/gitaly/config/config_test.go @@ -20,6 +20,7 @@ import ( "gitlab.com/gitlab-org/gitaly/v16/internal/gitaly/config/sentry" "gitlab.com/gitlab-org/gitaly/v16/internal/helper/duration" "gitlab.com/gitlab-org/gitaly/v16/internal/helper/perm" + "gitlab.com/gitlab-org/gitaly/v16/internal/log" "gitlab.com/gitlab-org/gitaly/v16/internal/testhelper" ) @@ -55,6 +56,7 @@ func TestLoadEmptyConfig(t *testing.T) { require.NoError(t, err) expectedCfg := Cfg{ + Logging: defaultLoggingConfig(), Prometheus: prometheus.DefaultConfig(), PackObjectsCache: defaultPackObjectsCacheConfig(), PackObjectsLimiting: defaultPackObjectsLimiting(), @@ -212,6 +214,9 @@ sentry_dsn = "abc123"`) require.NoError(t, err) require.Equal(t, Logging{ + Config: log.Config{ + Level: "info", + }, Sentry: Sentry(sentry.Config{ Environment: "production", DSN: "abc123", @@ -259,6 +264,7 @@ func TestLoadConfigCommand(t *testing.T) { modifyDefaultConfig := func(modify func(cfg *Cfg)) Cfg { cfg := &Cfg{ + Logging: defaultLoggingConfig(), Prometheus: prometheus.DefaultConfig(), PackObjectsCache: defaultPackObjectsCacheConfig(), PackObjectsLimiting: defaultPackObjectsLimiting(), -- GitLab