Merge branch 'grpc-go-log-level' into 'master'

Use custom log levels for grpc-go

Closes #1206

See merge request gitlab-org/gitaly!765

6 files changed, 99 insertions, 61 deletions

diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md
index 27cf472ec..5387417da 100644
--- a/CONTRIBUTING.md
+++ b/CONTRIBUTING.md
@@ -161,11 +161,7 @@ See the [beginner's guide](doc/beginners_guide.md).
 
 ## Debug Logging
 
-Debug logging can be enabled in Gitaly through the `GITALY_DEBUG` environment variable:
-
-```
-$ GITALY_DEBUG=1 ./gitaly config.toml
-```
+Debug logging can be enabled in Gitaly using `level = "debug"` under `[logging]` in config.toml.
 
 ## Git Tracing
 
@@ -173,10 +169,10 @@ Gitaly will reexport `GIT_TRACE*` [environment variables](https://git-scm.com/bo
 
 This can be an aid to debugging some sets of problems. For example, if you would like to know what git is going internally, you can set `GIT_TRACE=true`:
 
-Note that since git stderr stream will be logged at debug level, you need to enable debug logging too.
+Note that since git stderr stream will be logged at debug level, you need to enable debug logging in `config.toml`.
 
 ```shell
-$ GITALY_DEBUG=1 GIT_TRACE=true ./gitaly config.toml
+$ GIT_TRACE=true ./gitaly config.toml
 ...
 DEBU[0015] 13:04:08.646399 git.c:322               trace: built-in: git 'gc'  grpc.method=GarbageCollect grpc.request.repoPath="gitlab/gitlab-design.git" grpc.request.repoStorage=default grpc.request.topLevelGroup=gitlab grpc.service=gitaly.RepositoryService peer.address= span.kind=server system=grpc
 DEBU[0015] 13:04:08.649346 run-command.c:626       trace: run_command: 'pack-refs' '--all' '--prune'  grpc.method=GarbageCollect grpc.request.repoPath="gitlab/gitlab-design.git" grpc.request.repoStorage=default grpc.request.topLevelGroup=gitlab grpc.service=gitaly.RepositoryService peer.address= span.kind=server system=grpc
diff --git a/changelogs/unreleased/grpc-go-log-level.yml b/changelogs/unreleased/grpc-go-log-level.yml
new file mode 100644
index 000000000..8d15f1436
--- /dev/null
+++ b/changelogs/unreleased/grpc-go-log-level.yml
@@ -0,0 +1,5 @@
+---
+title: Use custom log levels for grpc-go
+merge_request: 765
+author:
+type: other
diff --git a/doc/configuration/README.md b/doc/configuration/README.md
index 337e11f87..91755e4f5 100644
--- a/doc/configuration/README.md
+++ b/doc/configuration/README.md
@@ -115,6 +115,13 @@ max\_rss limit.
 
 ### Logging
 
+Example:
+
+```
+[logging]
+level = "warn"
+```
+
 |name|type|required|notes|
 |----|----|--------|-----|
 |format|string|no|Log format: "text" or "json". Default: "text"|
@@ -124,10 +131,6 @@ max\_rss limit.
 
 ## Environment variables
 
-### GITALY_DEBUG
-
-When set to `1`, Gitaly will print debug log messages.
-
 ### GITALY_SOCKET_PATH
 
 Required unless GITALY_LISTEN_ADDR is set. Overrides `socket_path` in
diff --git a/internal/config/logger.go b/internal/config/logger.go
index e66a28845..66e9f4748 100644
--- a/internal/config/logger.go
+++ b/internal/config/logger.go
@@ -1,47 +1,10 @@
 package config
 
 import (
-	"os"
-
-	log "github.com/sirupsen/logrus"
-)
-
-var (
-	debugLoggingEnabled = os.Getenv("GITALY_DEBUG") == "1"
+	gitalylog "gitlab.com/gitlab-org/gitaly/internal/log"
 )
 
-func init() {
-	// This ensures that any log statements that occur before
-	// the configuration has been loaded will be written to
-	// stdout instead of stderr
-	log.SetOutput(os.Stdout)
-}
-
-func configureLoggingFormat() {
-	switch Config.Logging.Format {
-	case "json":
-		log.SetFormatter(&log.JSONFormatter{})
-		return
-	case "":
-		// Just stick with the default
-		return
-	default:
-		log.WithField("format", Config.Logging.Format).Fatal("invalid logger format")
-	}
-}
-
-// ConfigureLogging uses the global conf and environmental vars to configure the logged
+// ConfigureLogging uses the global conf and environmental vars to configure log levels and format
 func ConfigureLogging() {
-	if level, err := log.ParseLevel(Config.Logging.Level); err != nil {
-		log.SetLevel(log.InfoLevel)
-	} else {
-		log.SetLevel(level)
-	}
-
-	// Allow override based on environment variable
-	if debugLoggingEnabled {
-		log.SetLevel(log.DebugLevel)
-	}
-
-	configureLoggingFormat()
+	gitalylog.Configure(Config.Logging.Format, Config.Logging.Level)
 }
diff --git a/internal/log/log.go b/internal/log/log.go
new file mode 100644
index 000000000..dec2579e1
--- /dev/null
+++ b/internal/log/log.go
@@ -0,0 +1,67 @@
+package log
+
+import (
+	"os"
+
+	"github.com/sirupsen/logrus"
+)
+
+var (
+	// Default is the default logrus logger
+	Default = logrus.StandardLogger()
+
+	// GrpcGo is a dedicated logrus logger for the grpc-go library. We use it
+	// to control the library's chattiness.
+	GrpcGo = logrus.New()
+
+	// Loggers is convenient when you want to apply configuration to all
+	// loggers
+	Loggers = []*logrus.Logger{Default, GrpcGo}
+)
+
+func init() {
+	// This ensures that any log statements that occur before
+	// the configuration has been loaded will be written to
+	// stdout instead of stderr
+	for _, l := range Loggers {
+		l.Out = os.Stdout
+	}
+}
+
+// Configure sets the format and level on all loggers. It applies level
+// mapping to the GrpcGo logger.
+func Configure(format string, level string) {
+	switch format {
+	case "json":
+		for _, l := range Loggers {
+			l.Formatter = &logrus.JSONFormatter{}
+		}
+	case "":
+		// Just stick with the default
+	default:
+		logrus.WithField("format", format).Fatal("invalid logger format")
+	}
+
+	logrusLevel, err := logrus.ParseLevel(level)
+	if err != nil {
+		logrusLevel = logrus.InfoLevel
+	}
+
+	for _, l := range Loggers {
+		if l == GrpcGo {
+			l.SetLevel(mapGrpcLogLevel(logrusLevel))
+		} else {
+			l.SetLevel(logrusLevel)
+		}
+	}
+}
+
+func mapGrpcLogLevel(level logrus.Level) logrus.Level {
+	// 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 == logrus.InfoLevel {
+		return logrus.WarnLevel
+	}
+
+	return level
+}
diff --git a/internal/server/server.go b/internal/server/server.go
index 41eb602a7..cdc954a3d 100644
--- a/internal/server/server.go
+++ b/internal/server/server.go
@@ -6,6 +6,7 @@ import (
 	log "github.com/sirupsen/logrus"
 
 	"gitlab.com/gitlab-org/gitaly/internal/helper/fieldextractors"
+	gitalylog "gitlab.com/gitlab-org/gitaly/internal/log"
 	"gitlab.com/gitlab-org/gitaly/internal/logsanitizer"
 	"gitlab.com/gitlab-org/gitaly/internal/middleware/cancelhandler"
 	"gitlab.com/gitlab-org/gitaly/internal/middleware/limithandler"
@@ -43,18 +44,21 @@ func concurrencyKeyFn(ctx context.Context) string {
 var logrusEntry *log.Entry
 
 func init() {
-	logger := log.StandardLogger()
+	for _, l := range gitalylog.Loggers {
+		urlSanitizer := logsanitizer.NewURLSanitizerHook()
+		urlSanitizer.AddPossibleGrpcMethod(
+			"CreateRepositoryFromURL",
+			"FetchRemote",
+			"UpdateRemoteMirror",
+		)
+		l.Hooks.Add(urlSanitizer)
+	}
 
-	urlSanitizer := logsanitizer.NewURLSanitizerHook()
-	urlSanitizer.AddPossibleGrpcMethod(
-		"CreateRepositoryFromURL",
-		"FetchRemote",
-		"UpdateRemoteMirror",
-	)
-	logger.Hooks.Add(urlSanitizer)
+	// logrusEntry is used by middlewares below
+	logrusEntry = log.NewEntry(gitalylog.Default)
 
-	logrusEntry = log.NewEntry(logger)
-	grpc_logrus.ReplaceGrpcLogger(logrusEntry)
+	// grpc-go gets a custom logger; it is too chatty
+	grpc_logrus.ReplaceGrpcLogger(log.NewEntry(gitalylog.GrpcGo))
 }
 
 // New returns a GRPC server with all Gitaly services and interceptors set up.