diff --git a/auth/go.mod b/auth/go.mod index 3d710293..df7190e8 100644 --- a/auth/go.mod +++ b/auth/go.mod @@ -41,6 +41,7 @@ require ( github.com/lestrrat-go/option/v2 v2.0.0 // indirect github.com/segmentio/asm v1.2.1 // indirect go.opentelemetry.io/auto/sdk v1.1.0 // indirect + go.opentelemetry.io/contrib/bridges/otelslog v0.13.0 // indirect go.opentelemetry.io/otel/metric v1.38.0 // indirect go.opentelemetry.io/otel/trace v1.38.0 // indirect go.opentelemetry.io/proto/otlp v1.7.1 // indirect diff --git a/auth/go.sum b/auth/go.sum index 18acb692..44d40eed 100644 --- a/auth/go.sum +++ b/auth/go.sum @@ -161,6 +161,8 @@ github.com/valyala/fasttemplate v1.2.2/go.mod h1:KHLXt3tVN2HBp8eijSv/kGJopbvo7S+ github.com/yuin/goldmark v1.4.13/go.mod h1:6yULJ656Px+3vBD8DxQVa3kxgyrAnzto9xy5taEt/CY= go.opentelemetry.io/auto/sdk v1.1.0 h1:cH53jehLUN6UFLY71z+NDOiNJqDdPRaXzTel0sJySYA= go.opentelemetry.io/auto/sdk v1.1.0/go.mod h1:3wSPjt5PWp2RhlCcmmOial7AvC4DQqZb7a7wCow3W8A= +go.opentelemetry.io/contrib/bridges/otelslog v0.13.0 h1:bwnLpizECbPr1RrQ27waeY2SPIPeccCx/xLuoYADZ9s= +go.opentelemetry.io/contrib/bridges/otelslog v0.13.0/go.mod h1:3nWlOiiqA9UtUnrcNk82mYasNxD8ehOspL0gOfEo6Y4= go.opentelemetry.io/contrib/instrumentation/github.com/labstack/echo/otelecho v0.63.0 h1:6YeICKmGrvgJ5th4+OMNpcuoB6q/Xs8gt0YCO7MUv1k= go.opentelemetry.io/contrib/instrumentation/github.com/labstack/echo/otelecho v0.63.0/go.mod h1:ZEA7j2B35siNV0T00aapacNzjz4tvOlNoHp0ncCfwNQ= go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.61.0 h1:F7Jx+6hwnZ41NSFTO5q4LYDtJRXBf2PD0rNBkeB/lus= diff --git a/auth/main.go b/auth/main.go index 4827096c..9d4b9bc1 100644 --- a/auth/main.go +++ b/auth/main.go @@ -5,9 +5,12 @@ import ( "encoding/base64" "errors" "fmt" + "log/slog" "net/http" "os" "os/user" + "slices" + "sort" "strings" "github.com/zoriya/kyoo/keibi/dbc" @@ -140,7 +143,7 @@ func OpenDatabase() (*pgxpool.Pool, error) { return nil, err } - fmt.Println("Migrating database") + slog.Info("Database migration state", "state", "starting") dbi := stdlib.OpenDBFromPool(db) defer dbi.Close() @@ -156,7 +159,7 @@ func OpenDatabase() (*pgxpool.Pool, error) { return nil, err } m.Up() - fmt.Println("Migrating finished") + slog.Info("Database migration state", "state", "completed") return db, nil } @@ -227,17 +230,72 @@ func (h *Handler) TokenToJwt(next echo.HandlerFunc) echo.HandlerFunc { // @in header // @name Authorization func main() { - e := echo.New() - e.Use(middleware.Logger()) - e.Validator = &Validator{validator: validator.New(validator.WithRequiredStructEnabled())} - e.HTTPErrorHandler = ErrorHandler + ctx := context.Background() - cleanup, err := setupOtel(e) + logger, _, err := SetupLogger(ctx) if err != nil { - e.Logger.Fatal("Failed to setup otel: ", err) + slog.Error("logger init", "err", err) + } + + cleanup, err := setupOtel(ctx) + if err != nil { + slog.Error("Failed to setup otel: ", "err", err) return } - defer cleanup() + defer cleanup(ctx) + + e := echo.New() + e.HideBanner = true + e.Logger.SetOutput(logger) + instrument(e) + + ignorepath := []string{ + "/.well-known/jwks.json", + "/auth/health", + "/auth/ready", + } + slog.Info("Skipping request logging for these paths", "paths", func() string { sort.Strings(ignorepath); return strings.Join(ignorepath, ",") }()) + + // using example from https://echo.labstack.com/docs/middleware/logger#examples + // full configs https://github.com/labstack/echo/blob/master/middleware/request_logger.go + e.Use(middleware.RequestLoggerWithConfig(middleware.RequestLoggerConfig{ + // declare a small set of paths to ignore + Skipper: func(c echo.Context) bool { + p := c.Request().URL.Path + return slices.Contains(ignorepath, p) + }, + LogStatus: true, + LogURI: true, + LogError: true, + LogHost: true, + LogMethod: true, + LogUserAgent: true, + HandleError: true, // forwards error to the global error handler, so it can decide appropriate status code + LogValuesFunc: func(c echo.Context, v middleware.RequestLoggerValues) error { + if v.Error == nil { + logger.LogAttrs(ctx, slog.LevelInfo, "web_request", + slog.String("method", v.Method), + slog.Int("status", v.Status), + slog.String("host", v.Host), + slog.String("uri", v.URI), + slog.String("agent", v.UserAgent), + ) + } else { + logger.LogAttrs(ctx, slog.LevelError, "web_request_error", + slog.String("method", v.Method), + slog.Int("status", v.Status), + slog.String("host", v.Host), + slog.String("uri", v.URI), + slog.String("agent", v.UserAgent), + slog.String("err", v.Error.Error()), + ) + } + return nil + }, + })) + + e.Validator = &Validator{validator: validator.New(validator.WithRequiredStructEnabled())} + e.HTTPErrorHandler = ErrorHandler db, err := OpenDatabase() if err != nil { diff --git a/auth/otel.go b/auth/otel.go index 0eae1a99..f1b02c61 100644 --- a/auth/otel.go +++ b/auth/otel.go @@ -2,6 +2,9 @@ package main import ( "context" + "errors" + "log/slog" + "os" "strings" "github.com/labstack/echo/v4" @@ -11,21 +14,23 @@ import ( "go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploghttp" "go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetricgrpc" "go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetrichttp" - "go.opentelemetry.io/otel/exporters/otlp/otlptrace" "go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc" "go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp" - "go.opentelemetry.io/otel/log/global" - "go.opentelemetry.io/otel/sdk/log" - "go.opentelemetry.io/otel/sdk/metric" + logotel "go.opentelemetry.io/otel/log" + logotelglobal "go.opentelemetry.io/otel/log/global" + logotelnoop "go.opentelemetry.io/otel/log/noop" + metricotel "go.opentelemetry.io/otel/metric" + metricotelnoop "go.opentelemetry.io/otel/metric/noop" + logsdk "go.opentelemetry.io/otel/sdk/log" + metricsdk "go.opentelemetry.io/otel/sdk/metric" "go.opentelemetry.io/otel/sdk/resource" - "go.opentelemetry.io/otel/sdk/trace" + tracesdk "go.opentelemetry.io/otel/sdk/trace" semconv "go.opentelemetry.io/otel/semconv/v1.26.0" + traceotel "go.opentelemetry.io/otel/trace" + traceotelnoop "go.opentelemetry.io/otel/trace/noop" ) -func setupOtel(e *echo.Echo) (func(), error) { - ctx := context.Background() - proto := GetenvOr("OTEL_EXPORTER_OTLP_PROTOCOL", "http/protobuf") - +func setupOtel(ctx context.Context) (func(context.Context) error, error) { res, err := resource.New( ctx, resource.WithAttributes(semconv.ServiceNameKey.String("kyoo.auth")), @@ -40,64 +45,141 @@ func setupOtel(e *echo.Echo) (func(), error) { return nil, err } - var le log.Exporter - if proto == "http/protobuf" { - le, err = otlploghttp.New(ctx) - } else { + slog.Info("Configuring OTEL") + + var le logsdk.Exporter + var me metricsdk.Exporter + var te tracesdk.SpanExporter + switch { + case strings.TrimSpace(os.Getenv("OTEL_EXPORTER_OTLP_ENDPOINT")) == "": + slog.Info("Using OLTP type", "type", "noop") + le = nil + me = nil + te = nil + case strings.ToLower(strings.TrimSpace(os.Getenv("OTEL_EXPORTER_OTLP_PROTOCOL"))) == "grpc": + slog.Info("Using OLTP type", "type", "grpc") le, err = otlploggrpc.New(ctx) + if err != nil { + slog.Error("Failed setting up OLTP: ", err) + return nil, err + } + me, err = otlpmetricgrpc.New(ctx) + if err != nil { + slog.Error("Failed setting up OLTP: ", err) + return nil, err + } + te, err = otlptracegrpc.New(ctx) + if err != nil { + slog.Error("Failed setting up OLTP: ", err) + return nil, err + } + default: + slog.Info("Using OLTP type", "type", "http") + le, err = otlploghttp.New(ctx) + if err != nil { + slog.Error("Failed setting up OLTP: ", err) + return nil, err + } + me, err = otlpmetrichttp.New(ctx) + if err != nil { + slog.Error("Failed setting up OLTP: ", err) + return nil, err + } + te, err = otlptracehttp.New(ctx) + if err != nil { + slog.Error("Failed setting up OLTP: ", err) + return nil, err + } } if err != nil { return nil, err } - lp := log.NewLoggerProvider( - log.WithProcessor(log.NewBatchProcessor(le)), - log.WithResource(res), - ) - global.SetLoggerProvider(lp) - var me metric.Exporter - if proto == "http/protobuf" { - me, err = otlpmetrichttp.New(ctx) - } else { - me, err = otlpmetricgrpc.New(ctx) + // default to noop providers + var lp logotel.LoggerProvider = logotelnoop.NewLoggerProvider() + var mp metricotel.MeterProvider = metricotelnoop.NewMeterProvider() + var tp traceotel.TracerProvider = traceotelnoop.NewTracerProvider() + + // use exporter if configured + if le != nil { + lp = logsdk.NewLoggerProvider( + logsdk.WithProcessor(logsdk.NewBatchProcessor(le)), + logsdk.WithResource(res), + ) } - if err != nil { - return func() {}, err + + if me != nil { + mp = metricsdk.NewMeterProvider( + metricsdk.WithReader( + metricsdk.NewPeriodicReader(me), + ), + metricsdk.WithResource(res), + ) } - mp := metric.NewMeterProvider( - metric.WithReader( - metric.NewPeriodicReader(me), - ), - metric.WithResource(res), - ) + + if te != nil { + tp = tracesdk.NewTracerProvider( + tracesdk.WithBatcher(te), + tracesdk.WithResource(res), + ) + } + + // set providers + logotelglobal.SetLoggerProvider(lp) otel.SetMeterProvider(mp) - - var te *otlptrace.Exporter - if proto == "http/protobuf" { - te, err = otlptracehttp.New(ctx) - } else { - te, err = otlptracegrpc.New(ctx) - } - if err != nil { - return func() {}, err - } - tp := trace.NewTracerProvider( - trace.WithBatcher(te), - trace.WithResource(res), - ) otel.SetTracerProvider(tp) + // configure shutting down + // noop providers do not have a Shudown method + log_shutdown := func(ctx context.Context) error { + if otelprovider, ok := lp.(*logsdk.LoggerProvider); ok && otelprovider != nil { + return otelprovider.Shutdown(ctx) + } + return nil + } + + metric_shutdown := func(ctx context.Context) error { + if otelprovider, ok := mp.(*metricsdk.MeterProvider); ok && otelprovider != nil { + return otelprovider.Shutdown(ctx) + } + return nil + } + + trace_shutdown := func(ctx context.Context) error { + if otelprovider, ok := tp.(*tracesdk.TracerProvider); ok && otelprovider != nil { + return otelprovider.Shutdown(ctx) + } + return nil + } + + return func(ctx context.Context) error { + slog.Info("Shutting down OTEL") + + // run shutdowns and collect errors + var errs []error + if err := trace_shutdown(ctx); err != nil { + errs = append(errs, err) + } + if err := metric_shutdown(ctx); err != nil { + errs = append(errs, err) + } + if err := log_shutdown(ctx); err != nil { + errs = append(errs, err) + } + + if len(errs) == 0 { + return nil + } + return errors.Join(errs...) + }, nil +} + +func instrument(e *echo.Echo) { e.Use(otelecho.Middleware("kyoo.auth", otelecho.WithSkipper(func(c echo.Context) bool { return (c.Path() == "/auth/health" || c.Path() == "/auth/ready" || strings.HasPrefix(c.Path(), "/.well-known/")) }))) - - return func() { - lp.Shutdown(ctx) - mp.Shutdown(ctx) - tp.Shutdown(ctx) - }, nil } // stolen from https://github.com/exaring/otelpgx/issues/47 diff --git a/auth/slog.go b/auth/slog.go new file mode 100644 index 00000000..7e57b33e --- /dev/null +++ b/auth/slog.go @@ -0,0 +1,111 @@ +package main + +import ( + "context" + "log/slog" + "os" + "strings" + + logotelbridge "go.opentelemetry.io/contrib/bridges/otelslog" + logotelglobal "go.opentelemetry.io/otel/log/global" +) + +type SlogAdapter struct { + *slog.Logger +} + +// add Write so SlogAdapter satisfies io.Writer (Echo's logger output) +func (a *SlogAdapter) Write(p []byte) (int, error) { + msg := strings.TrimSpace(string(p)) + // Echo middleware writes request lines at INFO; use Info here. + a.Info(msg) + return len(p), nil +} + +type tee struct { + a, b slog.Handler + minA slog.Level + minB slog.Level +} + +// a = stdout +// b = otel +// minA = minimum level for stdout +// minB = minimum level for otel (from OTEL_LOG_LEVEL) +func NewTee(a, b slog.Handler, minA, minB slog.Level) slog.Handler { + return &tee{a: a, b: b, minA: minA, minB: minB} +} + +func (t *tee) Enabled(ctx context.Context, level slog.Level) bool { + if (t.minA == 0 || level >= t.minA) && t.a.Enabled(ctx, level) { + return true + } + if (t.minB == 0 || level >= t.minB) && t.b.Enabled(ctx, level) { + return true + } + return false +} + +func (t *tee) Handle(ctx context.Context, r slog.Record) error { + if t.minA == 0 || r.Level >= t.minA { + if err := t.a.Handle(ctx, r); err != nil { + return err + } + } + if t.minB == 0 || r.Level >= t.minB { + return t.b.Handle(ctx, r) + } + return nil +} + +func (t *tee) WithAttrs(attrs []slog.Attr) slog.Handler { + return NewTee(t.a.WithAttrs(attrs), t.b.WithAttrs(attrs), t.minA, t.minB) +} + +func (t *tee) WithGroup(name string) slog.Handler { + return NewTee(t.a.WithGroup(name), t.b.WithGroup(name), t.minA, t.minB) +} + +func SetupLogger(ctx context.Context) (*SlogAdapter, func(context.Context) error, error) { + stdout := slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{ + ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr { + // drop the default time attribute so text output has no timestamp + if a.Key == "time" { + return slog.Attr{} + } + return a + }, + }) + otelHandler := logotelbridge.NewHandler("slog", logotelbridge.WithLoggerProvider(logotelglobal.GetLoggerProvider())) + + minStdout := parseLogLevel(os.Getenv("STDOUT_LOG_LEVEL")) + minOtel := parseLogLevel(os.Getenv("OTEL_LOG_LEVEL")) + + handler := NewTee(stdout, otelHandler, minStdout, minOtel) + + logger := slog.New(handler) + adapter := &SlogAdapter{logger} + shutdown := func(ctx context.Context) error { return nil } + + slog.SetDefault(adapter.Logger) + return adapter, shutdown, nil +} + +func parseLogLevel(v string) slog.Level { + v = strings.ToUpper(strings.TrimSpace(v)) + if v == "" { + return slog.LevelInfo + } + m := map[string]slog.Level{ + "TRACE": slog.LevelDebug, + "DEBUG": slog.LevelDebug, + "INFO": slog.LevelInfo, + "WARN": slog.LevelWarn, + "WARNING": slog.LevelWarn, + "ERROR": slog.LevelError, + } + if lv, ok := m[v]; ok { + return lv + } + return slog.LevelInfo +}