Fix external loggers respecting configured format

cmd/cortex/main.go

@@ -20,7 +20,7 @@ import (
 	"github.com/prometheus/client_golang/prometheus/collectors"
 	collectorversion "github.com/prometheus/client_golang/prometheus/collectors/version"
 	"github.com/prometheus/common/version"
-	_ "go.uber.org/automaxprocs"
+	"go.uber.org/automaxprocs/maxprocs"
 	"gopkg.in/yaml.v2"
 
 	"github.com/cortexproject/cortex/pkg/cortex"
@@ -170,6 +170,9 @@ func main() {
 	}
 
 	util_log.InitLogger(&cfg.Server)
+	if _, err := maxprocs.Set(maxprocs.Logger(util_log.AutomaxprocsLogger(util_log.Logger))); err != nil {
+		level.Warn(util_log.Logger).Log("msg", "failed to set GOMAXPROCS from CPU quota", "err", err)
+	}
 	util.InitEvents(eventSampleRate)
 
 	ctx, cancelFn := context.WithCancel(context.Background())

pkg/util/log/external.go

@@ -0,0 +1,159 @@
+package log
+
+import (
+	"fmt"
+	"os"
+	"strconv"
+	"strings"
+
+	kitlog "github.com/go-kit/log"
+	"github.com/go-kit/log/level"
+	"google.golang.org/grpc/grpclog"
+)
+
+// InitExternalLoggers configures package-level loggers from dependencies that
+// do not take Cortex's logger through normal constructors.
+func InitExternalLoggers() {
+	grpclog.SetLoggerV2(NewGRPCLogger(Logger))
+}
+
+// AutomaxprocsLogger adapts the printf-style logger used by automaxprocs to
+// Cortex's configured go-kit logger.
+func AutomaxprocsLogger(logger kitlog.Logger) func(string, ...interface{}) {
+	return func(format string, args ...interface{}) {
+		level.Info(logger).Log("msg", fmt.Sprintf(format, args...))
+	}
+}
+
+// NewGRPCLogger adapts gRPC's package-level logger to Cortex's configured
+// go-kit logger so gRPC transport logs use the selected Cortex log format.
+func NewGRPCLogger(logger kitlog.Logger) grpclog.LoggerV2 {
+	return &grpcLogger{
+		logger:   logger,
+		severity: grpcSeverityFromEnv(),
+		verbose:  grpcVerbosityFromEnv(),
+	}
+}
+
+type grpcSeverity int
+
+const (
+	grpcSeverityInfo grpcSeverity = iota
+	grpcSeverityWarning
+	grpcSeverityError
+)
+
+type grpcLogger struct {
+	logger   kitlog.Logger
+	severity grpcSeverity
+	verbose  int
+}
+
+func (l *grpcLogger) Info(args ...any) {
+	l.log(grpcSeverityInfo, fmt.Sprint(args...))
+}
+
+func (l *grpcLogger) Infoln(args ...any) {
+	l.log(grpcSeverityInfo, trimPrintln(fmt.Sprintln(args...)))
+}
+
+func (l *grpcLogger) Infof(format string, args ...any) {
+	l.log(grpcSeverityInfo, fmt.Sprintf(format, args...))
+}
+
+func (l *grpcLogger) Warning(args ...any) {
+	l.log(grpcSeverityWarning, fmt.Sprint(args...))
+}
+
+func (l *grpcLogger) Warningln(args ...any) {
+	l.log(grpcSeverityWarning, trimPrintln(fmt.Sprintln(args...)))
+}
+
+func (l *grpcLogger) Warningf(format string, args ...any) {
+	l.log(grpcSeverityWarning, fmt.Sprintf(format, args...))
+}
+
+func (l *grpcLogger) Error(args ...any) {
+	l.log(grpcSeverityError, fmt.Sprint(args...))
+}
+
+func (l *grpcLogger) Errorln(args ...any) {
+	l.log(grpcSeverityError, trimPrintln(fmt.Sprintln(args...)))
+}
+
+func (l *grpcLogger) Errorf(format string, args ...any) {
+	l.log(grpcSeverityError, fmt.Sprintf(format, args...))
+}
+
+func (l *grpcLogger) Fatal(args ...any) {
+	l.log(grpcSeverityError, fmt.Sprint(args...))
+	os.Exit(1)
+}
+
+func (l *grpcLogger) Fatalln(args ...any) {
+	l.log(grpcSeverityError, trimPrintln(fmt.Sprintln(args...)))
+	os.Exit(1)
+}
+
+func (l *grpcLogger) Fatalf(format string, args ...any) {
+	l.log(grpcSeverityError, fmt.Sprintf(format, args...))
+	os.Exit(1)
+}
+
+func (l *grpcLogger) V(level int) bool {
+	return level <= l.verbose
+}
+
+func (l *grpcLogger) InfoDepth(_ int, args ...any) {
+	l.Infoln(args...)
+}
+
+func (l *grpcLogger) WarningDepth(_ int, args ...any) {
+	l.Warningln(args...)
+}
+
+func (l *grpcLogger) ErrorDepth(_ int, args ...any) {
+	l.Errorln(args...)
+}
+
+func (l *grpcLogger) FatalDepth(_ int, args ...any) {
+	l.Fatalln(args...)
+}
+
+func (l *grpcLogger) log(severity grpcSeverity, msg string) {
+	if severity < l.severity {
+		return
+	}
+
+	switch severity {
+	case grpcSeverityInfo:
+		level.Info(l.logger).Log("msg", msg)
+	case grpcSeverityWarning:
+		level.Warn(l.logger).Log("msg", msg)
+	default:
+		level.Error(l.logger).Log("msg", msg)
+	}
+}
+
+func grpcSeverityFromEnv() grpcSeverity {
+	switch strings.ToLower(os.Getenv("GRPC_GO_LOG_SEVERITY_LEVEL")) {
+	case "info":
+		return grpcSeverityInfo
+	case "warning":
+		return grpcSeverityWarning
+	default:
+		return grpcSeverityError
+	}
+}
+
+func grpcVerbosityFromEnv() int {
+	verbosity, err := strconv.Atoi(os.Getenv("GRPC_GO_LOG_VERBOSITY_LEVEL"))
+	if err != nil {
+		return 0
+	}
+	return verbosity
+}
+
+func trimPrintln(msg string) string {
+	return strings.TrimSuffix(msg, "\n")
+}

pkg/util/log/external_test.go

@@ -0,0 +1,58 @@
+package log
+
+import (
+	"bytes"
+	"encoding/json"
+	"testing"
+
+	kitlog "github.com/go-kit/log"
+	"github.com/stretchr/testify/require"
+	"github.com/weaveworks/common/logging"
+)
+
+func TestGRPCLoggerUsesConfiguredLogger(t *testing.T) {
+	t.Setenv("GRPC_GO_LOG_SEVERITY_LEVEL", "")
+	t.Setenv("GRPC_GO_LOG_VERBOSITY_LEVEL", "")
+
+	logger, logs := testJSONLogger(t)
+	grpcLogger := NewGRPCLogger(logger)
+
+	grpcLogger.Info("not logged by default")
+	grpcLogger.Error("transport failure")
+
+	entry := readSingleJSONLogEntry(t, logs)
+	require.Equal(t, "error", entry["level"])
+	require.Equal(t, "transport failure", entry["msg"])
+	require.NotContains(t, logs.String(), "not logged by default")
+}
+
+func TestAutomaxprocsLoggerUsesConfiguredLogger(t *testing.T) {
+	logger, logs := testJSONLogger(t)
+
+	AutomaxprocsLogger(logger)("maxprocs: Leaving GOMAXPROCS=%v: CPU quota undefined", 4)
+
+	entry := readSingleJSONLogEntry(t, logs)
+	require.Equal(t, "info", entry["level"])
+	require.Equal(t, "maxprocs: Leaving GOMAXPROCS=4: CPU quota undefined", entry["msg"])
+}
+
+func testJSONLogger(t *testing.T) (kitlog.Logger, *bytes.Buffer) {
+	t.Helper()
+
+	var logLevel logging.Level
+	require.NoError(t, logLevel.Set("debug"))
+
+	logs := &bytes.Buffer{}
+	return newPrometheusLoggerFrom(kitlog.NewJSONLogger(logs), logLevel), logs
+}
+
+func readSingleJSONLogEntry(t *testing.T, logs *bytes.Buffer) map[string]interface{} {
+	t.Helper()
+
+	lines := bytes.Split(bytes.TrimSpace(logs.Bytes()), []byte("\n"))
+	require.Len(t, lines, 1)
+
+	var entry map[string]interface{}
+	require.NoError(t, json.Unmarshal(lines[0], &entry))
+	return entry
+}

pkg/util/log/log.go

@@ -44,6 +44,7 @@ func InitLogger(cfg *server.Config) {
 	// when use util_log.Logger, skip 6 stack frames.
 	Logger = newPrometheusLoggerFrom(l, cfg.LogLevel, "caller", log.Caller(6))
 	SLogger = GoKitLogToSlog(Logger)
+	InitExternalLoggers()
 
 	// cfg.Log wraps log function, skip 7 stack frames to get caller information.
 	// this works in go 1.12, but doesn't work in versions earlier.