From 4b1ca50b9558bd77ddee50d06d71c889247f6982 Mon Sep 17 00:00:00 2001 From: James Telfer <792299+jamestelfer@users.noreply.github.com> Date: Sat, 1 Jun 2024 23:04:43 +1000 Subject: [PATCH] fix: allow OTel SDK logging to be enabled Allows for some easier diagnosis of issues with telemetry. --- .envrc | 5 +++ go.mod | 3 +- go.sum | 6 ++-- integration/docker-compose.yaml | 1 + internal/config/config.go | 1 + internal/observe/telemetry.go | 55 +++++++++++++++++++++++++++++++++ main.go | 14 +++++++-- 7 files changed, 79 insertions(+), 6 deletions(-) diff --git a/.envrc b/.envrc index e89860f..f7298d6 100644 --- a/.envrc +++ b/.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" diff --git a/go.mod b/go.mod index 6063734..a4694f7 100644 --- a/go.mod +++ b/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 diff --git a/go.sum b/go.sum index a1c155a..46fc6d5 100644 --- a/go.sum +++ b/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= diff --git a/integration/docker-compose.yaml b/integration/docker-compose.yaml index 7d410a0..b8ead9e 100644 --- a/integration/docker-compose.yaml +++ b/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" diff --git a/internal/config/config.go b/internal/config/config.go index d4c81f6..f83e68a 100644 --- a/internal/config/config.go +++ b/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"` diff --git a/internal/observe/telemetry.go b/internal/observe/telemetry.go index 4bdf48f..f49adf2 100644 --- a/internal/observe/telemetry.go +++ b/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) diff --git a/main.go b/main.go index b1fec88..d5bec1b 100644 --- a/main.go +++ b/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) } }