log: Disable gRPC HealthCheck message logging

gRPC HealthCheck messages are quite noisy, dominate the log volume in
Gitaly, and usually are not that useful. We now disable them by
default and add documentation on how to enable them.

Closes https://gitlab.com/gitlab-org/gitaly/-/issues/3428

Changelog: changed

6 files changed, 81 insertions, 2 deletions

diff --git a/doc/configuration/README.md b/doc/configuration/README.md
index 70cf84498..0f7658bf1 100644
--- a/doc/configuration/README.md
+++ b/doc/configuration/README.md
@@ -164,3 +164,18 @@ level = "warn"
 |sentry_dsn|string|no|Sentry DSN for exception monitoring|
 |sentry_environment|string|no|Sentry Environment for exception monitoring|
 |ruby_sentry_dsn|string|no|Sentry DSN for gitaly-ruby exception monitoring|
+
+#### Environment variables
+
+|name|default|notes|
+|----|-------|-----|
+|GITALY_LOG_REQUEST_METHOD_ALLOW_PATTERN||Regular expression that controls which gRPC methods should be logged|
+|GITALY_LOG_REQUEST_METHOD_DENY_PATTERN|`^/grpc.health.v1.Health/Check$`|Regular expression that controls which gRPC methods should be filtered out|
+
+Note that `GITALY_LOG_REQUEST_METHOD_ALLOW_PATTERN` takes precedence
+over `GITALY_LOG_REQUEST_METHOD_DENY_PATTERN`. If a pattern matches in
+allow pattern, then it will be logged, even if it also matches the deny
+pattern. All error messages are logged unconditionally.
+
+By default, health check gRPC messages are not logged. To enable them,
+set `GITALY_LOG_REQUEST_METHOD_ALLOW_PATTERN` to `.`.
diff --git a/internal/gitaly/server/server_factory_test.go b/internal/gitaly/server/server_factory_test.go
index 661835098..c2afcd7c6 100644
--- a/internal/gitaly/server/server_factory_test.go
+++ b/internal/gitaly/server/server_factory_test.go
@@ -147,6 +147,8 @@ func TestGitalyServerFactory(t *testing.T) {
 	})
 
 	t.Run("logging check", func(t *testing.T) {
+		testhelper.ModifyEnvironment(t, "GITALY_LOG_REQUEST_METHOD_ALLOW_PATTERN", ".")
+
 		cfg := testcfg.Build(t)
 		logger, hook := test.NewNullLogger()
 		sf := NewGitalyServerFactory(
diff --git a/internal/helper/env/env.go b/internal/helper/env/env.go
index a988b3abf..e8fb5c70b 100644
--- a/internal/helper/env/env.go
+++ b/internal/helper/env/env.go
@@ -4,6 +4,7 @@ import (
 	"fmt"
 	"os"
 	"strconv"
+	"strings"
 	"time"
 )
 
@@ -51,3 +52,16 @@ func GetDuration(name string, fallback time.Duration) (time.Duration, error) {
 	}
 	return v, nil
 }
+
+// GetString fetches a given name from the environment and falls back to a
+// default value if the name is not available. The value is stripped of
+// leading and trailing whitespace.
+func GetString(name string, fallback string) string {
+	value := os.Getenv(name)
+
+	if value == "" {
+		return fallback
+	}
+
+	return strings.TrimSpace(value)
+}
diff --git a/internal/helper/env/env_test.go b/internal/helper/env/env_test.go
index 89a43f02e..10e68c143 100644
--- a/internal/helper/env/env_test.go
+++ b/internal/helper/env/env_test.go
@@ -171,3 +171,37 @@ func TestGetDuration(t *testing.T) {
 		})
 	}
 }
+
+func TestGetString(t *testing.T) {
+	for _, tc := range []struct {
+		value    string
+		fallback string
+		expected string
+	}{
+		{
+			value:    "Hello",
+			expected: "Hello",
+		},
+		{
+			value:    "hello ",
+			expected: "hello",
+		},
+		{
+			fallback: "fallback value",
+			expected: "fallback value",
+		},
+		{
+			value:    " ",
+			fallback: "fallback value",
+			expected: "",
+		},
+	} {
+		t.Run(fmt.Sprintf("value=%s,fallback=%s", tc.value, tc.fallback), func(t *testing.T) {
+			testhelper.ModifyEnvironment(t, "TEST_STRING", tc.value)
+
+			result := env.GetString("TEST_STRING", tc.fallback)
+
+			assert.Equal(t, tc.expected, result)
+		})
+	}
+}
diff --git a/internal/log/log.go b/internal/log/log.go
index b987283b2..42cb2bd94 100644
--- a/internal/log/log.go
+++ b/internal/log/log.go
@@ -9,6 +9,7 @@ import (
 	grpcmwlogrus "github.com/grpc-ecosystem/go-grpc-middleware/logging/logrus"
 	"github.com/grpc-ecosystem/go-grpc-middleware/logging/logrus/ctxlogrus"
 	"github.com/sirupsen/logrus"
+	"gitlab.com/gitlab-org/gitaly/v14/internal/helper/env"
 	"google.golang.org/grpc"
 	"google.golang.org/grpc/codes"
 	"google.golang.org/grpc/stats"
@@ -21,6 +22,9 @@ const (
 	LogTimestampFormat = "2006-01-02T15:04:05.000"
 	// LogTimestampFormatUTC defines the utc timestamp format in log files
 	LogTimestampFormatUTC = "2006-01-02T15:04:05.000Z"
+
+	defaultLogRequestMethodAllowPattern = ""
+	defaultLogRequestMethodDenyPattern  = "^/grpc.health.v1.Health/Check$"
 )
 
 type utcFormatter struct {
@@ -116,7 +120,9 @@ func DeciderOption() grpcmwlogrus.Option {
 }
 
 func methodNameMatcherFromEnv() func(string) bool {
-	if pattern := os.Getenv("GITALY_LOG_REQUEST_METHOD_ALLOW_PATTERN"); pattern != "" {
+	if pattern :=
+		env.GetString("GITALY_LOG_REQUEST_METHOD_ALLOW_PATTERN",
+			defaultLogRequestMethodAllowPattern); pattern != "" {
 		methodRegex := regexp.MustCompile(pattern)
 
 		return func(fullMethodName string) bool {
@@ -124,7 +130,9 @@ func methodNameMatcherFromEnv() func(string) bool {
 		}
 	}
 
-	if pattern := os.Getenv("GITALY_LOG_REQUEST_METHOD_DENY_PATTERN"); pattern != "" {
+	if pattern :=
+		env.GetString("GITALY_LOG_REQUEST_METHOD_DENY_PATTERN",
+			defaultLogRequestMethodDenyPattern); pattern != "" {
 		methodRegex := regexp.MustCompile(pattern)
 
 		return func(fullMethodName string) bool {
diff --git a/internal/log/log_test.go b/internal/log/log_test.go
index a6b32b93b..224ea8389 100644
--- a/internal/log/log_test.go
+++ b/internal/log/log_test.go
@@ -462,6 +462,12 @@ func TestLogDeciderOption_logByRegexpMatch(t *testing.T) {
 			desc:             "default setting",
 			skip:             "",
 			only:             "",
+			shouldLogMethods: []string{"InfoRefsUploadPack", "PostUploadPackWithSidechannel"},
+		},
+		{
+			desc:             "allow all",
+			skip:             "",
+			only:             ".",
 			shouldLogMethods: []string{"Check", "InfoRefsUploadPack", "PostUploadPackWithSidechannel"},
 		},
 		{