Merge pull request jamestelfer#50 from cultureamp/otel-log-config

fix: allow Open Telemetry SDK logging configuration

.envrc

@@ -48,6 +48,11 @@ source_env_if_exists .envrc.private
 # may be "grpc" or "stdout"
 # export OBSERVE_TYPE="grpc"
 
+# Configure internal Open Telemetry SDK logging. Levels are "debug", "info",
+# "warn" or "" (disabled). Defaults to disabled; any incorrect value will also
+# be interpreted as disabled.
+# export OBSERVE_OTEL_LOG_LEVEL=""
+
 # the service name reported in traces and metrics
 # export OBSERVE_SERVICE_NAME="chinmina-bridge"
 

go.mod

@@ -7,6 +7,8 @@ require (
 	github.com/bradleyfalzon/ghinstallation/v2 v2.10.0
 	github.com/buildkite/go-buildkite/v3 v3.11.0
 	github.com/go-jose/go-jose/v4 v4.0.1
+	github.com/go-logr/logr v1.4.2
+	github.com/go-logr/zerologr v1.2.3
 	github.com/google/go-github/v61 v61.0.0
 	github.com/justinas/alice v1.2.0
 	github.com/maypok86/otter v1.2.0
@@ -25,7 +27,6 @@ require (
 	github.com/dolthub/maphash v0.1.0 // indirect
 	github.com/felixge/httpsnoop v1.0.4 // indirect
 	github.com/gammazero/deque v0.2.1 // indirect
-	github.com/go-logr/logr v1.4.1 // indirect
 	github.com/go-logr/stdr v1.2.2 // indirect
 	github.com/golang-jwt/jwt/v4 v4.5.0 // indirect
 	github.com/google/go-github/v60 v60.0.0 // indirect

go.sum

@@ -20,10 +20,12 @@ github.com/gammazero/deque v0.2.1/go.mod h1:LFroj8x4cMYCukHJDbxFCkT+r9AndaJnFMuZ
 github.com/go-jose/go-jose/v4 v4.0.1 h1:QVEPDE3OluqXBQZDcnNvQrInro2h0e4eqNbnZSWqS6U=
 github.com/go-jose/go-jose/v4 v4.0.1/go.mod h1:WVf9LFMHh/QVrmqrOfqun0C45tMe3RoiKJMPvgWwLfY=
 github.com/go-logr/logr v1.2.2/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A=
-github.com/go-logr/logr v1.4.1 h1:pKouT5E8xu9zeFC39JXRDukb6JFQPXM5p5I91188VAQ=
-github.com/go-logr/logr v1.4.1/go.mod h1:9T104GzyrTigFIr8wt5mBrctHMim0Nb2HLGrmQ40KvY=
+github.com/go-logr/logr v1.4.2 h1:6pFjapn8bFcIbiKo3XT4j/BhANplGihG6tvd+8rYgrY=
+github.com/go-logr/logr v1.4.2/go.mod h1:9T104GzyrTigFIr8wt5mBrctHMim0Nb2HLGrmQ40KvY=
 github.com/go-logr/stdr v1.2.2 h1:hSWxHoqTgW2S2qGc0LTAI563KZ5YKYRhT3MFKZMbjag=
 github.com/go-logr/stdr v1.2.2/go.mod h1:mMo/vtBO5dYbehREoey6XUKy/eSumjCCveDpRre4VKE=
+github.com/go-logr/zerologr v1.2.3 h1:up5N9vcH9Xck3jJkXzgyOxozT14R47IyDODz8LM1KSs=
+github.com/go-logr/zerologr v1.2.3/go.mod h1:BxwGo7y5zgSHYR1BjbnHPyF/5ZjVKfKxAZANVu6E8Ho=
 github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA=
 github.com/golang-jwt/jwt/v4 v4.5.0 h1:7cYmW1XlMY7h7ii7UhUyChSgS5wUJEnm9uZVTGqOWzg=
 github.com/golang-jwt/jwt/v4 v4.5.0/go.mod h1:m21LjoU+eqJr34lmDMbreY2eSTRJ1cv77w39/MY0Ch0=

integration/docker-compose.yaml

@@ -42,6 +42,7 @@ services:
       # Jaeger standalone doesn't support metrics
       - OBSERVE_METRICS_ENABLED=false
       - OBSERVE_TYPE=grpc
+      - OBSERVE_OTEL_LOG_LEVEL=debug
     volumes:
       - "..:/src"
 

internal/config/config.go

@@ -42,6 +42,7 @@ type GithubConfig struct {
 }
 
 type ObserveConfig struct {
+	SDKLogLevel                string `env:"OBSERVE_OTEL_LOG_LEVEL, default=info"`
 	Enabled                    bool   `env:"OBSERVE_ENABLED, default=false"`
 	MetricsEnabled             bool   `env:"OBSERVE_METRICS_ENABLED, default=true"`
 	Type                       string `env:"OBSERVE_TYPE, default=grpc"`

internal/observe/telemetry.go

@@ -7,8 +7,11 @@ import (
 	"net/http/httptrace"
 	"time"
 
+	"github.com/go-logr/logr"
+	"github.com/go-logr/zerologr"
 	"github.com/jamestelfer/chinmina-bridge/internal/config"
 	"github.com/rs/zerolog"
+	"github.com/rs/zerolog/log"
 	"go.opentelemetry.io/contrib/instrumentation/net/http/httptrace/otelhttptrace"
 	"go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp"
 	"go.opentelemetry.io/otel"
@@ -34,6 +37,8 @@ func Configure(ctx context.Context, cfg config.ObserveConfig) (shutdown func(con
 		return func(context.Context) error { return nil }, nil
 	}
 
+	configureLogging(cfg)
+
 	var shutdownFuncs []func(context.Context) error
 
 	// Allow clean up functions to be executed for the various subsystems that
@@ -163,6 +168,56 @@ func newMeterProvider(ctx context.Context, cfg config.ObserveConfig, e exporters
 	return meterProvider, nil
 }
 
+func configureLogging(cfg config.ObserveConfig) {
+	// configure console logger to handle the otel tracing levels
+	otelInfLvl := zerolog.Level(-3)
+	otelDbgLvl := zerolog.Level(-7)
+
+	level := zerolog.Disabled
+
+	// convert the configured string value to one appropriate for zerolog
+	switch cfg.SDKLogLevel {
+	case "debug":
+		level = otelDbgLvl
+	case "info":
+		level = otelInfLvl
+	case "warn":
+		level = zerolog.DebugLevel
+	case "":
+		// disabled
+	default:
+		log.Warn().
+			Str("configured", cfg.SDKLogLevel).
+			Msg("invalid configuration for OBSERVE_OTEL_LOG_LEVEL, internal OTel logging disabled.")
+	}
+
+	// don't bother to configure when disabled
+	if level == zerolog.Disabled {
+		return
+	}
+
+	// The otel internal logger (logr) uses V levels of 1, 4 and 8 respectively,
+	// which corresponds to zerolog levels of 0 (Debug), -3 and -7. Since these
+	// levels are non-standard for zerolog, configuration for the ConsoleLogger is
+	// added.
+	zerolog.FormattedLevels[otelInfLvl] = "OINF"
+	zerolog.LevelColors[otelInfLvl] = 90 // grey
+	zerolog.FormattedLevels[otelDbgLvl] = "ODBG"
+	zerolog.LevelColors[otelDbgLvl] = 90 // grey
+
+	// The zerolog logger that otel will write to, using its own level, and
+	// marking all events with the "otel" source.
+	otelLogger := log.Logger.
+		Level(level).
+		With().
+		Str("source", "otel").
+		Logger()
+
+	// bridge the logger to the logr library used by otel
+	l := logr.New(zerologr.NewLogSink(&otelLogger))
+	otel.SetLogger(l)
+}
+
 type exporters interface {
 	Trace(ctx context.Context) (trace.SpanExporter, error)
 	Metric(ctx context.Context) (metric.Exporter, error)

main.go

@@ -127,10 +127,18 @@ func launchServer() error {
 }
 
 func configureLogging() {
-	zerolog.SetGlobalLevel(zerolog.InfoLevel)
+	// Set global level to the minimum: allows the Open Telemetry logging to be
+	// configured separately. However, it means that any logger that sets its
+	// level will log as this effectively disables the global level.
+	zerolog.SetGlobalLevel(zerolog.Level(-128))
+
+	// default level is Info
+	log.Logger = log.Level(zerolog.InfoLevel)
+
 	if os.Getenv("ENV") == "development" {
-		log.Logger = log.Output(zerolog.ConsoleWriter{Out: os.Stdout})
-		zerolog.SetGlobalLevel(zerolog.DebugLevel)
+		log.Logger = log.
+			Output(zerolog.ConsoleWriter{Out: os.Stdout}).
+			Level(zerolog.DebugLevel)
 	}
 }