From 3debed69c8e99bf1f3f7f2f231070f706f8aae0d Mon Sep 17 00:00:00 2001 From: Tanvir Ahmed Date: Mon, 12 Oct 2026 11:36:48 +0000 Subject: [PATCH 1/2] feat: Implemented otel plugin --- README.md | 1 + go.mod | 30 +- go.sum | 68 +++-- internal/bootstrap/plugin_factory.go | 2 + models/plugin.go | 1 + plugins/otel/README.md | 125 ++++++++ plugins/otel/constants/constants.go | 11 + plugins/otel/exporter.go | 165 ++++++++++ plugins/otel/hooks.go | 282 +++++++++++++++++ plugins/otel/hooks_test.go | 441 +++++++++++++++++++++++++++ plugins/otel/plugin.go | 208 +++++++++++++ plugins/otel/plugin_test.go | 224 ++++++++++++++ plugins/otel/types/config.go | 123 ++++++++ plugins/otel/types/config_test.go | 218 +++++++++++++ 14 files changed, 1874 insertions(+), 25 deletions(-) create mode 100644 plugins/otel/README.md create mode 100644 plugins/otel/constants/constants.go create mode 100644 plugins/otel/exporter.go create mode 100644 plugins/otel/hooks.go create mode 100644 plugins/otel/hooks_test.go create mode 100644 plugins/otel/plugin.go create mode 100644 plugins/otel/plugin_test.go create mode 100644 plugins/otel/types/config.go create mode 100644 plugins/otel/types/config_test.go diff --git a/README.md b/README.md index f3e7ca60..b141e39c 100644 --- a/README.md +++ b/README.md @@ -57,6 +57,7 @@ Authula comes with a variety of plugins that provide essential authentication fe - Secondary storage (In-memory, DB, Redis) - Rate limiting - CSRF protection +- OpenTelemetry (distributed tracing & metrics) - Hooks system - Event bus - Custom routes and logic diff --git a/go.mod b/go.mod index d02e6dad..d0c7ab04 100644 --- a/go.mod +++ b/go.mod @@ -37,6 +37,18 @@ require ( github.com/uptrace/bun/dialect/sqlitedialect v1.2.18 github.com/uptrace/bun/extra/bundebug v1.2.18 github.com/wneessen/go-mail v0.8.1 + go.opentelemetry.io/contrib/instrumentation/runtime v0.72.0 + go.opentelemetry.io/otel v1.47.0 + go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetricgrpc v1.47.0 + go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetrichttp v1.47.0 + go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc v1.47.0 + go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp v1.47.0 + go.opentelemetry.io/otel/exporters/stdout/stdoutmetric v1.47.0 + go.opentelemetry.io/otel/exporters/stdout/stdouttrace v1.47.0 + go.opentelemetry.io/otel/metric v1.47.0 + go.opentelemetry.io/otel/sdk v1.47.0 + go.opentelemetry.io/otel/sdk/metric v1.47.0 + go.opentelemetry.io/otel/trace v1.47.0 golang.org/x/crypto v0.57.0 golang.org/x/oauth2 v0.37.0 modernc.org/sqlite v1.58.0 @@ -72,7 +84,7 @@ require ( github.com/fatih/color v1.19.0 // indirect github.com/felixge/httpsnoop v1.1.0 // indirect github.com/gabriel-vasile/mimetype v1.4.15 // indirect - github.com/go-logr/logr v1.4.3 // indirect + github.com/go-logr/logr v1.4.4 // indirect github.com/go-logr/stdr v1.2.2 // indirect github.com/go-ole/go-ole v1.3.0 // indirect github.com/go-playground/locales v0.14.1 // indirect @@ -81,6 +93,7 @@ require ( github.com/gofiber/schema v1.8.3 // indirect github.com/gofiber/utils/v2 v2.4.1 // indirect github.com/golang/protobuf v1.5.4 // indirect + github.com/grpc-ecosystem/grpc-gateway/v2 v2.30.0 // indirect github.com/hashicorp/errwrap v1.1.0 // indirect github.com/hashicorp/go-multierror v1.1.1 // indirect github.com/hashicorp/go-uuid v1.0.3 // indirect @@ -147,18 +160,21 @@ require ( github.com/vmihailenco/tagparser/v2 v2.0.0 // indirect github.com/yusufpapurcu/wmi v1.2.4 // indirect go.opentelemetry.io/auto/sdk v1.2.1 // indirect - go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.69.0 // indirect - go.opentelemetry.io/otel v1.44.0 // indirect - go.opentelemetry.io/otel/metric v1.44.0 // indirect - go.opentelemetry.io/otel/trace v1.44.0 // indirect + go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.70.0 // indirect + go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.47.0 // indirect + go.opentelemetry.io/otel/log v1.47.0 // indirect + go.opentelemetry.io/proto/otlp v1.11.0 // indirect go.uber.org/atomic v1.11.0 // indirect go.yaml.in/yaml/v3 v3.0.5 // indirect golang.org/x/mod v0.41.0 // indirect - golang.org/x/net v0.58.0 // indirect + golang.org/x/net v0.59.0 // indirect golang.org/x/sys v0.48.0 // indirect golang.org/x/text v0.42.0 // indirect google.golang.org/appengine v1.6.8 // indirect - google.golang.org/protobuf v1.36.11 // indirect + google.golang.org/genproto/googleapis/api v0.0.0-20260928230214-8a89bd6388cc // indirect + google.golang.org/genproto/googleapis/rpc v0.0.0-20260928230214-8a89bd6388cc // indirect + google.golang.org/grpc v1.83.2 // indirect + google.golang.org/protobuf v1.36.12 // indirect gopkg.in/yaml.v2 v2.4.0 // indirect modernc.org/libc v1.75.6 // indirect modernc.org/mathutil v1.7.1 // indirect diff --git a/go.sum b/go.sum index a90aad1c..cf1412cd 100644 --- a/go.sum +++ b/go.sum @@ -93,8 +93,8 @@ github.com/gabriel-vasile/mimetype v1.4.15/go.mod h1:azpTcoLcDZRNgFou5j+APrqQx9H github.com/go-chi/chi/v5 v5.3.2 h1:5YQkICvTCSZ25hoRsyJazN0scjzKGiu4VAUc7H1o1nY= github.com/go-chi/chi/v5 v5.3.2/go.mod h1:R+tYY2hNuVUUjxoPtqUdgBqevM9s9njzkTLutVsOCto= github.com/go-logr/logr v1.2.2/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A= -github.com/go-logr/logr v1.4.3 h1:CjnDlHq8ikf6E492q6eKboGOC0T8CDaOvkHCIg8idEI= -github.com/go-logr/logr v1.4.3/go.mod h1:9T104GzyrTigFIr8wt5mBrctHMim0Nb2HLGrmQ40KvY= +github.com/go-logr/logr v1.4.4 h1:tG4xh9yMsRCAiodLVTxyrkzSZ9+o0L1Kg/+cPVcbP/8= +github.com/go-logr/logr v1.4.4/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-ole/go-ole v1.2.6/go.mod h1:pprOEPIfldk/42T2oK7lQ4v4JSDwmV0As9GaiUsvbm0= @@ -134,6 +134,8 @@ github.com/google/uuid v1.6.0 h1:NIvaJDMOsjHA8n1jAhLSgzrAzy1Hgr+hNrb57e+94F0= github.com/google/uuid v1.6.0/go.mod h1:TIyPZe4MgqvfeYDBFedMoGGpEw/LqOeaOT+nhxU+yHo= github.com/gorilla/securecookie v1.1.1/go.mod h1:ra0sb63/xPlUeL+yeDciTfxMRAA+MP+HVt/4epWDjd4= github.com/gorilla/sessions v1.2.1/go.mod h1:dk2InVEVJ0sfLlnXv9EAgkf6ecYs/i80K/zI+bUmuGM= +github.com/grpc-ecosystem/grpc-gateway/v2 v2.30.0 h1:/Tnpcb2E0Pz/tN9s3bfEY2Q8ePCEX9iuS+cneUwncnw= +github.com/grpc-ecosystem/grpc-gateway/v2 v2.30.0/go.mod h1:zOBXOsUaBSjKgmH4OGzV1esUpR3oUSCPYVd2cUBjKYY= github.com/hashicorp/errwrap v1.0.0/go.mod h1:YH+1FKiLXxHSkmPseP+kNlulaMuP3n2brvKWEqk/Jc4= github.com/hashicorp/errwrap v1.1.0 h1:OxrOeh75EUXMY8TBjag2fzXGZ40LB6IKw45YeGUDY2I= github.com/hashicorp/errwrap v1.1.0/go.mod h1:YH+1FKiLXxHSkmPseP+kNlulaMuP3n2brvKWEqk/Jc4= @@ -370,18 +372,40 @@ github.com/zeebo/xxh3 v1.1.0 h1:s7DLGDK45Dyfg7++yxI0khrfwq9661w9EN78eP/UZVs= github.com/zeebo/xxh3 v1.1.0/go.mod h1:IisAie1LELR4xhVinxWS5+zf1lA4p0MW4T+w+W07F5s= go.opentelemetry.io/auto/sdk v1.2.1 h1:jXsnJ4Lmnqd11kwkBV2LgLoFMZKizbCi5fNZ/ipaZ64= go.opentelemetry.io/auto/sdk v1.2.1/go.mod h1:KRTj+aOaElaLi+wW1kO/DZRXwkF4C5xPbEe3ZiIhN7Y= -go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.69.0 h1:8tvICD4vSTOOsNrsI4Ljf6C+6UKvpTEH5XY3JMoyPoo= -go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.69.0/go.mod h1:z9+yiacE0IHRqM4qFfkbt/JYlmYXgss8GY/jXoNuPJI= -go.opentelemetry.io/otel v1.44.0 h1:JjwHmHpA4iZ3wBxluu2fbbE7j4kqlE8jXyAyPXH7HqU= -go.opentelemetry.io/otel v1.44.0/go.mod h1:BMgjTHL9WPRlRjL2oZCBTL4whCGtXch2H4BhOPIAyYc= -go.opentelemetry.io/otel/metric v1.44.0 h1:1w0gILTcHdr3YI+ixLyjemwrVnsMURbTZFrSYCdDdmc= -go.opentelemetry.io/otel/metric v1.44.0/go.mod h1:8O7hanEPBNgEMmybD3s2VBKcgWOCsA6tzHBPODAiquo= -go.opentelemetry.io/otel/sdk v1.44.0 h1:nHYwb9lK+fJPU/dnT6s7W7Z8itMWyqrnVfbheVYrZ58= -go.opentelemetry.io/otel/sdk v1.44.0/go.mod h1:Osuydd3Se74nqjAKxid74N5eC+jfEqfTegHRnq58oK0= -go.opentelemetry.io/otel/sdk/metric v1.44.0 h1:3LlKgI+VjbVsjNRFZJZAJ30WjXC5VkNRks6si09iEfI= -go.opentelemetry.io/otel/sdk/metric v1.44.0/go.mod h1:5B5pMARnXxKhltooO4xUuCBorl65a4EpnTalObqOigA= -go.opentelemetry.io/otel/trace v1.44.0 h1:jxF5CsGYCe74MCRx2X4g7WsY/VBKRqqpNvXlX/6gtIk= -go.opentelemetry.io/otel/trace v1.44.0/go.mod h1:oLl1jrMQAVo6v3GAggN+1VH9VIz9iUSvW53sW1Q8PIE= +go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.70.0 h1:LMuyCAyfalSjDyjdC65nK6N0zoTT63+E/u95X0JovZI= +go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.70.0/go.mod h1:085m8qbm4hgc8rZWGDEa4vmyyo2c3nPxUslYUKUIU04= +go.opentelemetry.io/contrib/instrumentation/runtime v0.72.0 h1:rv8t3kKjyC2/9D99L1MZt4tJSZO4aYUmHus7L//iKKg= +go.opentelemetry.io/contrib/instrumentation/runtime v0.72.0/go.mod h1:ZzG+JmzLLvKzx6tMeLrw2l7F8ik2GeRZJALoPBqnM0c= +go.opentelemetry.io/otel v1.47.0 h1:j7ALJ/zgkS7Z6aeJW09p8VC9804bC+PpeTfCD4XPnOM= +go.opentelemetry.io/otel v1.47.0/go.mod h1:8wS9O2qfXrYrzp6hIF/HOYJJf/wIhFPhR2xLuP+iXQU= +go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetricgrpc v1.47.0 h1:LaLVGJtIzHcvHjVs2OftmKcc+M9mdOqS8vZ1fBD1Yes= +go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetricgrpc v1.47.0/go.mod h1:vF6H5sNDuQBJWgSX00iZgbIqk2MZZoVMH0ar5t5bOpw= +go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetrichttp v1.47.0 h1:7kszRN4Ze5GeAkUnBjBSUIunVBMA+mZIG04auueqguM= +go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetrichttp v1.47.0/go.mod h1:CLzakYy8jOdkBfcveCWYkeKJxujcF4xPhh2Z7IfE98U= +go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.47.0 h1:julhjPeUH/q/7hinbSdDdqt5h7Zw9YWmRlWRhI0jd54= +go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.47.0/go.mod h1:Ao2mz688LH/tFf0yMAenidq6k2YNSx6SIY2q6jDACck= +go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc v1.47.0 h1:UFpxOpYPmMNUtOWhdb+nC1WELIgVf8z9higURrbzYU4= +go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc v1.47.0/go.mod h1:YBGjxe3lt0jtXoEXxGrGhv/jM7oUBUDVK7zhAvNyEjc= +go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp v1.47.0 h1:aXZXsZ012wOgVkqaiQv+Z/d8V0xKjmg70F6m4CE94lc= +go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp v1.47.0/go.mod h1:ziu1gUIJhAaxM3EV1e3Ralk5AAyL1UOYz3lJJ4VSI38= +go.opentelemetry.io/otel/exporters/stdout/stdoutmetric v1.47.0 h1:ww5DYBpMKcqLdxjWrhGUIh6O+ZfvZUaMk4niVyNQPEQ= +go.opentelemetry.io/otel/exporters/stdout/stdoutmetric v1.47.0/go.mod h1:Av5t+Ezx5S/Ks2dsEfWhny+GK+wrZ1K7NZ6aHSWnX3U= +go.opentelemetry.io/otel/exporters/stdout/stdouttrace v1.47.0 h1:N3YQCxjxQ/bMjyc3heladfRm9t9RTksGQH8z4w6yU/0= +go.opentelemetry.io/otel/exporters/stdout/stdouttrace v1.47.0/go.mod h1:Mp8HOFqcaUyypCuGv9IhDdTHnJ56lSudSHMd+pVSCEA= +go.opentelemetry.io/otel/log v1.47.0 h1:cOTS1CcLbSQeZKanGJ+0JpF/+t4PELi3O3bbl2lqCcI= +go.opentelemetry.io/otel/log v1.47.0/go.mod h1:9byitSQ5pLC6PpqwGXjqdMKya6ZTswHRZh2vvXT33nw= +go.opentelemetry.io/otel/metric v1.47.0 h1:4PptaldXx3Eat1XjMZ68pPJEs5wrhlemctZE9a3UdWY= +go.opentelemetry.io/otel/metric v1.47.0/go.mod h1:ADGSXxRrXM6bjbvLo535EstVFlPpPYZm4LBKixjDHwU= +go.opentelemetry.io/otel/metric/x v0.69.0 h1:DjRLr15H83v+hCW7JA9NoJvOkYTtmq5YoDRbe9deYpM= +go.opentelemetry.io/otel/metric/x v0.69.0/go.mod h1:uVvsMPMFFyj/HUQfrUnH3JjnOQ1dwFDorgFLRBasM0k= +go.opentelemetry.io/otel/sdk v1.47.0 h1:zWXEr4j2lFefG87TU6Yg8a7ngfohIKFZHKp0Hf5hC6I= +go.opentelemetry.io/otel/sdk v1.47.0/go.mod h1:VUc24kiOeoGsxG8G9ULx3fWKvB7jMhnGE8Oi607lgR0= +go.opentelemetry.io/otel/sdk/metric v1.47.0 h1:lfISg2j93VT6yqdk9OfUaZmw/GfcZqCCV3jdXtsPnKw= +go.opentelemetry.io/otel/sdk/metric v1.47.0/go.mod h1:ypLp+mW1Nt2x+Szt3b5/i1syodyts49lMOwxpDI3VGw= +go.opentelemetry.io/otel/trace v1.47.0 h1:JOjX/Oci8K94QHddo+bbfya/Ai/nf6/dt9ZfrFNWSrM= +go.opentelemetry.io/otel/trace v1.47.0/go.mod h1:jNaSLa2PZEYFG6fRjJABAu+bw4FS08uDmPg28lTghu0= +go.opentelemetry.io/proto/otlp v1.11.0 h1:5rrYs0Ykyj50sdU/JU0x8etU+LubXWb+gED6TbEdMIk= +go.opentelemetry.io/proto/otlp v1.11.0/go.mod h1:SmVizdCOAm3XBtG1g1NnOdhW6jtddT72hLMhv8VwA8E= go.uber.org/atomic v1.11.0 h1:ZvwS0R+56ePWxUNi+Atn9dWONBPp/AUETXlHW0DxSjE= go.uber.org/atomic v1.11.0/go.mod h1:LUxbIzbOniOlMKjJjyPfpl4v+PKK2cNJn91OQbhoJI0= go.uber.org/goleak v1.3.0 h1:2K3zAYmnTNqV73imy9J1T3WC+gmCePx2hEGkimedGto= @@ -403,8 +427,8 @@ golang.org/x/net v0.0.0-20210226172049-e18ecbb05110/go.mod h1:m0MpNAwzfU5UDzcl9v golang.org/x/net v0.0.0-20220722155237-a158d28d115b/go.mod h1:XRhObCWvk6IyKnWLug+ECip1KBveYUHfp+8e9klMJ9c= golang.org/x/net v0.6.0/go.mod h1:2Tu9+aMcznHK/AK1HMvgo6xiTLG5rD5rZLDS+rp2Bjs= golang.org/x/net v0.7.0/go.mod h1:2Tu9+aMcznHK/AK1HMvgo6xiTLG5rD5rZLDS+rp2Bjs= -golang.org/x/net v0.58.0 h1:ynWG7rqYi4ccpTEuPZ2QGWHktVEM9DMCj9yzDE0Q7To= -golang.org/x/net v0.58.0/go.mod h1:YwCddHnFlT7eLQqVprV19OnhLGtc5xOKgE0RyqgfWAU= +golang.org/x/net v0.59.0 h1:5zfYln+w5XCxwrnMMJPufRgNoXEaGxl0wo5GqPXyues= +golang.org/x/net v0.59.0/go.mod h1:2DA/G1UfVbCpQPeWTmMPGY7Cs2PkBkwu743bVX5PIVg= golang.org/x/oauth2 v0.37.0 h1:JUlcxA8oAtauLfiH8FX2/FkAWHAdi0QtGCGc+hofE98= golang.org/x/oauth2 v0.37.0/go.mod h1:IxwZNxUULJmpBFf9K/9NTMSIfZZuvuTy1gGxhigP/58= golang.org/x/sync v0.0.0-20190423024810-112230192c58/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= @@ -442,12 +466,20 @@ golang.org/x/tools v0.49.0 h1:3NI7VXzL9+1WZD52Dx2ttoPwD5DWrFGpl9mFZDlmisI= golang.org/x/tools v0.49.0/go.mod h1:SJNXV9DBKT0UbdttsQjbfJlAE/q+y36++zo3uL3N0Oo= golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= golang.org/x/xerrors v0.0.0-20191204190536-9bdfabe68543/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= +gonum.org/v1/gonum v0.17.0 h1:VbpOemQlsSMrYmn7T2OUvQ4dqxQXU+ouZFQsZOx50z4= +gonum.org/v1/gonum v0.17.0/go.mod h1:El3tOrEuMpv2UdMrbNlKEh9vd86bmQ6vqIcDwxEOc1E= google.golang.org/appengine v1.6.8 h1:IhEN5q69dyKagZPYMSdIjS2HqprW324FRQZJcGqPAsM= google.golang.org/appengine v1.6.8/go.mod h1:1jJ3jBArFh5pcgW8gCtRJnepW8FzD1V44FJffLiz/Ds= +google.golang.org/genproto/googleapis/api v0.0.0-20260928230214-8a89bd6388cc h1:rZHRz0ogq4Pid1IKtA/ivHi8XONVF5tqUQXA2TtgpkE= +google.golang.org/genproto/googleapis/api v0.0.0-20260928230214-8a89bd6388cc/go.mod h1:K/n0XLazCJHjD73YuMyNJsN38BPPy1kfFnKxUXaThFU= +google.golang.org/genproto/googleapis/rpc v0.0.0-20260928230214-8a89bd6388cc h1:4bNTbnb44EqGVy9HaQxSY2jnafSUdgV3qHtedvNpDKg= +google.golang.org/genproto/googleapis/rpc v0.0.0-20260928230214-8a89bd6388cc/go.mod h1:OaIUM3+LpYcK2GXM4FTmhWoIq371Owdr+Cc7/BsYHHc= +google.golang.org/grpc v1.83.2 h1:EManeRomTObA0BU7I8vXgg/78uE5MJ9M8B39EX2WscU= +google.golang.org/grpc v1.83.2/go.mod h1:YPI1hK3kDked6iHvgX3tR0y+nX/qpMFKhPgFsokw1S8= google.golang.org/protobuf v1.26.0-rc.1/go.mod h1:jlhhOSvTdKEhbULTjvd4ARK9grFBp09yW+WbY/TyQbw= google.golang.org/protobuf v1.26.0/go.mod h1:9q0QmTI4eRPtz6boOQmLYwt+qCgq0jsYwAQnmE0givc= -google.golang.org/protobuf v1.36.11 h1:fV6ZwhNocDyBLK0dj+fg8ektcVegBBuEolpbTQyBNVE= -google.golang.org/protobuf v1.36.11/go.mod h1:HTf+CrKn2C3g5S8VImy6tdcUvCska2kB7j23XfzDpco= +google.golang.org/protobuf v1.36.12 h1:pJOKDDOyeXErUroCihFAd5LQuwXBSpVnKGrj5o/fwxc= +google.golang.org/protobuf v1.36.12/go.mod h1:HTf+CrKn2C3g5S8VImy6tdcUvCska2kB7j23XfzDpco= gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c h1:Hei/4ADfdWqJk1ZMxUNpqntNwaWcugrBjAiHlqqRiVk= gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c/go.mod h1:JHkPIbrfpd72SG/EVd6muEfDQjcINNoR0C8j2r3qZ4Q= diff --git a/internal/bootstrap/plugin_factory.go b/internal/bootstrap/plugin_factory.go index 8d5c4dab..663df7d7 100644 --- a/internal/bootstrap/plugin_factory.go +++ b/internal/bootstrap/plugin_factory.go @@ -15,6 +15,7 @@ import ( magiclinkplugin "github.com/Authula/authula/plugins/magic-link" oauth2plugin "github.com/Authula/authula/plugins/oauth2" organizationsplugin "github.com/Authula/authula/plugins/organizations" + otelplugin "github.com/Authula/authula/plugins/otel" ratelimitplugin "github.com/Authula/authula/plugins/rate-limit" secondarystorageplugin "github.com/Authula/authula/plugins/secondary-storage" sessionplugin "github.com/Authula/authula/plugins/session" @@ -71,6 +72,7 @@ var pluginFactories = []pluginFactory{ newPluginFactory(models.PluginOrganizations.String(), false, organizationsplugin.New), newPluginFactory(models.PluginTOTP.String(), false, totpplugin.New), newPluginFactory(models.PluginApiKey.String(), false, apikeyplugin.New), + newPluginFactory(models.PluginOtel.String(), false, otelplugin.New), } // isPluginEnabled checks if a plugin is enabled in the raw config diff --git a/models/plugin.go b/models/plugin.go index 2328424b..bac28138 100644 --- a/models/plugin.go +++ b/models/plugin.go @@ -27,6 +27,7 @@ const ( PluginTOTP PluginID = "totp" PluginOrganizations PluginID = "organizations" PluginApiKey PluginID = "api_key" + PluginOtel PluginID = "otel" ) func (id PluginID) String() string { diff --git a/plugins/otel/README.md b/plugins/otel/README.md new file mode 100644 index 00000000..456c5d56 --- /dev/null +++ b/plugins/otel/README.md @@ -0,0 +1,125 @@ +# OpenTelemetry plugin + +Opt-in distributed tracing and metrics for Authula, backed by the OpenTelemetry +SDK. The plugin extracts and propagates W3C trace context and records request +and runtime metrics. + +Telemetry is **fail-open**: the hooks never return an error, so a telemetry +problem can never short-circuit a real request. Invalid configuration or a +provider/exporter failure, however, fails `Init` so the server refuses to start +rather than running blind. + +## Enabling + +A present `[plugins.otel]` section enables the plugin. Set `enabled = false` to +turn it back off. When disabled the plugin initializes nothing: no providers, no +exporters, no goroutines, and no hooks. + +```toml +[plugins.otel] +enabled = true +service_name = "authula-service" +exporter = "otlp" +endpoint = "http://localhost:4318" +insecure = true +``` + +## Configuration reference + +| Key | Type | Default | Description | +| --- | --- | --- | --- | +| `enabled` | bool | `true` when the section exists | Master switch. | +| `service_name` | string | `authula` | `service.name` resource attribute. | +| `exporter` | string | `otlp` | `otlp`, `stdout`, or `none`. | +| `protocol` | string | `http` | `http`, `grpc`, or empty (env/default). | +| `endpoint` | string | empty | OTLP endpoint. Empty lets the exporter read `OTEL_EXPORTER_OTLP_ENDPOINT`. | +| `insecure` | bool | `false` | Disable transport security. | +| `headers` | map | empty | Extra OTLP headers. Empty lets `OTEL_EXPORTER_OTLP_HEADERS` apply. | +| `traces_enabled` | bool | `true` | Enable tracing. | +| `metrics_enabled` | bool | `true` | Enable request/runtime metrics. | +| `runtime_metrics` | bool | `true` | Enable Go runtime metrics. | +| `sample_ratio` | float | unset | Trace sample ratio in `[0,1]`. Omit to let the SDK read `OTEL_TRACES_SAMPLER`. | +| `trust_proxy` | bool | `false` | Trust `X-Forwarded-Proto` / `X-Forwarded-For`. | + +### Precedence + +One rule covers every setting: **config field > standard OpenTelemetry +environment variable > SDK default**. + +- `service_name`: config → `OTEL_SERVICE_NAME` → `authula`. +- `endpoint` empty: the exporter reads `OTEL_EXPORTER_OTLP_ENDPOINT`. +- `protocol` empty: `OTEL_EXPORTER_OTLP_PROTOCOL`, otherwise `http`. +- `headers` empty: `OTEL_EXPORTER_OTLP_HEADERS` applies. +- `sample_ratio` unset: `OTEL_TRACES_SAMPLER` applies. When set, the plugin uses + `ParentBased(TraceIDRatioBased(ratio))`; an explicit `0.0` samples nothing. + +Exporter tuning (batch timeout/size, export interval, export timeouts) is left +to the SDK: `OTEL_BSP_*`, `OTEL_METRIC_EXPORT_INTERVAL`, and +`OTEL_EXPORTER_OTLP_*_TIMEOUT`. + +## What is emitted + +### Spans + +- Name: `{method} {route}` for matched routes (e.g. `GET /api/auth/me`), or just + `{method}` when no route matched. The raw URL path is never used as the span + target. +- Kind: server. +- The `traceparent` header is extracted and propagated, so spans join an + existing trace. The span is placed on the request context, so handlers can use + `trace.SpanFromContext(r.Context())` and create child spans. + +Span attributes: `http.request.method`, `http.route` (method-stripped; fixed +`unmatched` when no route matched), `url.path`, `url.scheme`, `client.address`, +`http.response.status_code`, and `authula.actor.type` / `authula.actor.id` when +an actor is present. + +Status semantics follow the stable HTTP semantic conventions: only `>= 500` +responses set the span status to `Error` and add `error.type` (the status code +as a string). A 4xx server span is not an error, so its status stays unset. + +### Metrics + +The only instrument is the semantic-convention histogram +`http.server.request.duration` (unit `s`, with the recommended bucket +boundaries). HTTP semantic conventions define no request-count metric, so none +is emitted; read request counts from the histogram's count aggregation. + +Recorded attributes: `http.request.method`, `http.route`, +`http.response.status_code`, `url.scheme`, plus `error.type` for `>= 500` +responses. OPTIONS preflight requests are not recorded. + +`runtime_metrics = true` additionally starts the OpenTelemetry runtime +instrumentation (Go runtime metrics) on the same meter provider. + +## Bypass paths + +Requests that bypass the normal lifecycle are traced too: OPTIONS preflight, +`isRequestDisabled` 404s, and `DisabledPaths` 404s. The on-request hook opts into +bypass paths with `RunOnBypass: true`; the on-complete hook always runs and sees +the final status. + +## Why hooks instead of `otelhttp` + +Authula's routing and bypass rules live in the hook system, not in a plain +`http.Handler` chain. Using hooks keeps tracing consistent with every other +cross-cutting concern: it runs at a defined stage, respects the final status, +and covers short-circuits and bypass paths that an `otelhttp` middleware would +miss or double-count. + +## Instance-local providers + +The plugin holds its own `Tracer`, `Meter`, and propagator. It never calls +`otel.SetTracerProvider` / `otel.SetMeterProvider` / `otel.SetTextMapPropagator`. +This keeps tests isolated and avoids process-global state. + +The trade-off: third-party code (or future plugins) that uses the *global* +`otel.Tracer(...)` is not captured. Only spans on `req.Context()` are. There is +intentionally no global-registration option. + +## Dependencies + +Adding the plugin links the OpenTelemetry SDK, exporters, and runtime +instrumentation into the binary even when the plugin is disabled (the factory +imports it unconditionally). It is "lightweight when disabled" at runtime, not +in binary size. diff --git a/plugins/otel/constants/constants.go b/plugins/otel/constants/constants.go new file mode 100644 index 00000000..80c23016 --- /dev/null +++ b/plugins/otel/constants/constants.go @@ -0,0 +1,11 @@ +package constants + +const ( + // EnvOTelServiceName is the standard OpenTelemetry environment variable that + // sets the logical service name reported on every signal. + EnvOTelServiceName = "OTEL_SERVICE_NAME" + + // EnvOTelExporterOTLPProtocol is the standard OpenTelemetry environment + // variable that selects the OTLP transport ("grpc" or "http/protobuf"). + EnvOTelExporterOTLPProtocol = "OTEL_EXPORTER_OTLP_PROTOCOL" +) diff --git a/plugins/otel/exporter.go b/plugins/otel/exporter.go new file mode 100644 index 00000000..95eaa726 --- /dev/null +++ b/plugins/otel/exporter.go @@ -0,0 +1,165 @@ +package otel + +import ( + "context" + "fmt" + "os" + "strings" + + "go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetricgrpc" + "go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetrichttp" + "go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc" + "go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp" + "go.opentelemetry.io/otel/exporters/stdout/stdoutmetric" + "go.opentelemetry.io/otel/exporters/stdout/stdouttrace" + sdkmetric "go.opentelemetry.io/otel/sdk/metric" + "go.opentelemetry.io/otel/sdk/resource" + sdktrace "go.opentelemetry.io/otel/sdk/trace" + + "github.com/Authula/authula/plugins/otel/constants" + "github.com/Authula/authula/plugins/otel/types" +) + +// buildTraceExporter constructs the configured span exporter. It returns a nil +// exporter when exporting is disabled ("none"). +func buildTraceExporter(ctx context.Context, cfg types.OTelPluginConfig) (sdktrace.SpanExporter, error) { + switch cfg.Exporter { + case types.ExporterNone: + return nil, nil + case types.ExporterStdout: + return stdouttrace.New() + case types.ExporterOTLP: + if resolveProtocol(cfg) == types.ProtocolGRPC { + return otlptracegrpc.New(ctx, traceGRPCOptions(cfg)...) + } + return otlptracehttp.New(ctx, traceHTTPOptions(cfg)...) + default: + return nil, fmt.Errorf("otel: unsupported trace exporter %q", cfg.Exporter) + } +} + +// buildMetricExporter constructs the configured metric exporter. It returns a +// nil exporter when exporting is disabled ("none"). +func buildMetricExporter(ctx context.Context, cfg types.OTelPluginConfig) (sdkmetric.Exporter, error) { + switch cfg.Exporter { + case types.ExporterNone: + return nil, nil + case types.ExporterStdout: + return stdoutmetric.New() + case types.ExporterOTLP: + if resolveProtocol(cfg) == types.ProtocolGRPC { + return otlpmetricgrpc.New(ctx, metricGRPCOptions(cfg)...) + } + return otlpmetrichttp.New(ctx, metricHTTPOptions(cfg)...) + default: + return nil, fmt.Errorf("otel: unsupported metric exporter %q", cfg.Exporter) + } +} + +// newTracerProvider builds a TracerProvider that batches spans to the supplied +// exporter and only overrides the sampler when a sample ratio is configured. +// Exported so tests can inject their own exporter. +func newTracerProvider(cfg types.OTelPluginConfig, res *resource.Resource, exp sdktrace.SpanExporter) *sdktrace.TracerProvider { + opts := make([]sdktrace.TracerProviderOption, 0, 3) + if res != nil { + opts = append(opts, sdktrace.WithResource(res)) + } + if exp != nil { + opts = append(opts, sdktrace.WithBatcher(exp)) + } + if cfg.SampleRatio != nil { + opts = append(opts, sdktrace.WithSampler(sdktrace.ParentBased(sdktrace.TraceIDRatioBased(*cfg.SampleRatio)))) + } + return sdktrace.NewTracerProvider(opts...) +} + +// newMeterProvider builds a MeterProvider reading through the supplied reader. +func newMeterProvider(_ types.OTelPluginConfig, res *resource.Resource, reader sdkmetric.Reader) *sdkmetric.MeterProvider { + opts := make([]sdkmetric.Option, 0, 2) + if res != nil { + opts = append(opts, sdkmetric.WithResource(res)) + } + if reader != nil { + opts = append(opts, sdkmetric.WithReader(reader)) + } + return sdkmetric.NewMeterProvider(opts...) +} + +// resolveProtocol applies the precedence rule config > OTEL_EXPORTER_OTLP_PROTOCOL > "http". +func resolveProtocol(cfg types.OTelPluginConfig) types.ProtocolType { + if cfg.Protocol != "" { + return cfg.Protocol + } + env := strings.ToLower(strings.TrimSpace(os.Getenv(constants.EnvOTelExporterOTLPProtocol))) + if strings.Contains(env, "grpc") { + return types.ProtocolGRPC + } + return types.ProtocolHTTP +} + +// resolveServiceName applies the precedence rule config > OTEL_SERVICE_NAME > "authula". +func resolveServiceName(cfg types.OTelPluginConfig) string { + if cfg.ServiceName != "" { + return cfg.ServiceName + } + if name := strings.TrimSpace(os.Getenv(constants.EnvOTelServiceName)); name != "" { + return name + } + return types.DefaultServiceName +} + +func traceHTTPOptions(cfg types.OTelPluginConfig) []otlptracehttp.Option { + opts := make([]otlptracehttp.Option, 0, 3) + if cfg.Endpoint != "" { + opts = append(opts, otlptracehttp.WithEndpoint(cfg.Endpoint)) + } + if cfg.Insecure { + opts = append(opts, otlptracehttp.WithInsecure()) + } + if len(cfg.Headers) > 0 { + opts = append(opts, otlptracehttp.WithHeaders(cfg.Headers)) + } + return opts +} + +func traceGRPCOptions(cfg types.OTelPluginConfig) []otlptracegrpc.Option { + opts := make([]otlptracegrpc.Option, 0, 3) + if cfg.Endpoint != "" { + opts = append(opts, otlptracegrpc.WithEndpoint(cfg.Endpoint)) + } + if cfg.Insecure { + opts = append(opts, otlptracegrpc.WithInsecure()) + } + if len(cfg.Headers) > 0 { + opts = append(opts, otlptracegrpc.WithHeaders(cfg.Headers)) + } + return opts +} + +func metricHTTPOptions(cfg types.OTelPluginConfig) []otlpmetrichttp.Option { + opts := make([]otlpmetrichttp.Option, 0, 3) + if cfg.Endpoint != "" { + opts = append(opts, otlpmetrichttp.WithEndpoint(cfg.Endpoint)) + } + if cfg.Insecure { + opts = append(opts, otlpmetrichttp.WithInsecure()) + } + if len(cfg.Headers) > 0 { + opts = append(opts, otlpmetrichttp.WithHeaders(cfg.Headers)) + } + return opts +} + +func metricGRPCOptions(cfg types.OTelPluginConfig) []otlpmetricgrpc.Option { + opts := make([]otlpmetricgrpc.Option, 0, 3) + if cfg.Endpoint != "" { + opts = append(opts, otlpmetricgrpc.WithEndpoint(cfg.Endpoint)) + } + if cfg.Insecure { + opts = append(opts, otlpmetricgrpc.WithInsecure()) + } + if len(cfg.Headers) > 0 { + opts = append(opts, otlpmetricgrpc.WithHeaders(cfg.Headers)) + } + return opts +} diff --git a/plugins/otel/hooks.go b/plugins/otel/hooks.go new file mode 100644 index 00000000..b6fb1649 --- /dev/null +++ b/plugins/otel/hooks.go @@ -0,0 +1,282 @@ +package otel + +import ( + "context" + "net/http" + "strconv" + "strings" + "time" + + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/codes" + "go.opentelemetry.io/otel/metric" + "go.opentelemetry.io/otel/propagation" + semconv "go.opentelemetry.io/otel/semconv/v1.43.0" + "go.opentelemetry.io/otel/trace" + + "github.com/Authula/authula/models" +) + +const ( + // spanStateKey is the key under reqCtx.Values holding the active span state. + spanStateKey = "otel.span.state" + // durationInstrumentName is the semantic-convention HTTP server duration + // histogram name. + durationInstrumentName = "http.server.request.duration" + // routeUnmatched is the fixed, low-cardinality label used when no route was + // matched. + routeUnmatched = "unmatched" + // errorTypeKey is the semantic-convention attribute key for the error class. + errorTypeKey = "error.type" +) + +// durationBuckets are the semantic-convention recommended histogram boundaries +// for HTTP server request duration, in seconds. +var durationBuckets = []float64{0.005, 0.01, 0.025, 0.05, 0.075, 0.1, 0.25, 0.5, 0.75, 1, 2.5, 5, 7.5, 10} + +// spanState carries the per-request span and its start time between the +// on-request and on-complete hooks. +type spanState struct { + span trace.Span + start time.Time +} + +// buildHooks wires the request and completion hooks. When both traces and +// metrics are off the plugin contributes no hooks at all. +func (p *OTelPlugin) buildHooks() []models.Hook { + if !p.pluginConfig.TracesOn() && !p.pluginConfig.MetricsOn() { + return nil + } + + return []models.Hook{ + { + Stage: models.HookOnRequest, + Handler: p.onRequest(), + Order: -100, + RunOnBypass: true, + }, + { + Stage: models.HookOnComplete, + Handler: p.onComplete(), + }, + } +} + +func (p *OTelPlugin) onRequest() models.HookHandler { + return func(reqCtx *models.RequestContext) error { + start := time.Now() + + if reqCtx.Values == nil { + reqCtx.Values = make(map[string]any) + } + + if reqCtx.Request == nil { + reqCtx.Values[spanStateKey] = &spanState{start: start} + return nil + } + + if !p.pluginConfig.TracesOn() { + reqCtx.Values[spanStateKey] = &spanState{start: start} + return nil + } + + ctx := p.propagator.Extract(reqCtx.Request.Context(), propagation.HeaderCarrier(reqCtx.Request.Header)) + + route := routePattern(reqCtx) + spanName := reqCtx.Method + if route != "" { + spanName = reqCtx.Method + " " + route + } + + ctx, span := p.tracer.Start( + ctx, + spanName, + trace.WithSpanKind(trace.SpanKindServer), + trace.WithTimestamp(start), + ) + + reqCtx.Request = reqCtx.Request.WithContext(ctx) + reqCtx.Values[spanStateKey] = &spanState{span: span, start: start} + + return nil + } +} + +func (p *OTelPlugin) onComplete() models.HookHandler { + return func(reqCtx *models.RequestContext) error { + p.finalize(reqCtx) + return nil + } +} + +// finalize ends the span and records the request metric. It is idempotent: a +// missing span state (already finalized, or never started) is a no-op. +func (p *OTelPlugin) finalize(reqCtx *models.RequestContext) { + raw, exists := reqCtx.Values[spanStateKey] + if !exists { + return + } + + state, ok := raw.(*spanState) + if !ok || state == nil { + delete(reqCtx.Values, spanStateKey) + return + } + + status := resolveStatus(reqCtx) + route := routePattern(reqCtx) + scheme, clientAddress := resolveSchemeAndClient(reqCtx, p.pluginConfig.TrustProxy) + ctx := requestContext(reqCtx) + + if p.pluginConfig.TracesOn() && state.span != nil { + p.recordSpan(state.span, reqCtx, status, route, scheme, clientAddress) + } + + if p.pluginConfig.MetricsOn() && p.duration != nil && reqCtx.Method != http.MethodOptions { + attrs := []attribute.KeyValue{ + requestMethodAttr(reqCtx.Method), + semconv.HTTPRoute(routeLabel(route)), + semconv.HTTPResponseStatusCode(status), + semconv.URLScheme(scheme), + } + if status >= http.StatusInternalServerError { + attrs = append(attrs, attribute.String(errorTypeKey, strconv.Itoa(status))) + } + p.duration.Record(ctx, time.Since(state.start).Seconds(), metric.WithAttributes(attrs...)) + } + + if state.span != nil { + state.span.End() + } + delete(reqCtx.Values, spanStateKey) +} + +// recordSpan attaches the HTTP metadata and, for 5xx responses only, the error +// status. Per the stable HTTP semantic conventions a 4xx server span is not an +// error, so its status stays unset. +func (p *OTelPlugin) recordSpan(span trace.Span, reqCtx *models.RequestContext, status int, route, scheme, clientAddress string) { + attrs := []attribute.KeyValue{ + requestMethodAttr(reqCtx.Method), + semconv.HTTPRoute(routeLabel(route)), + semconv.URLPath(reqCtx.Path), + semconv.URLScheme(scheme), + semconv.ClientAddress(clientAddress), + semconv.HTTPResponseStatusCode(status), + } + + if reqCtx.Actor != nil { + attrs = append(attrs, + attribute.String("authula.actor.type", reqCtx.Actor.Type.ToString()), + attribute.String("authula.actor.id", reqCtx.Actor.ID), + ) + } + + span.SetAttributes(attrs...) + + if status >= http.StatusInternalServerError { + span.SetStatus(codes.Error, http.StatusText(status)) + span.SetAttributes(attribute.String(errorTypeKey, strconv.Itoa(status))) + } +} + +// routePattern returns the matched route with its leading "METHOD:" prefix +// stripped, or an empty string when no route was matched. +func routePattern(reqCtx *models.RequestContext) string { + if reqCtx.Route == nil { + return "" + } + pattern := reqCtx.Route.Pattern + if pattern == "" { + return "" + } + if idx := strings.IndexByte(pattern, ':'); idx >= 0 { + return pattern[idx+1:] + } + return pattern +} + +func routeLabel(route string) string { + if route == "" { + return routeUnmatched + } + return route +} + +// resolveStatus resolves the final HTTP status from the captured response, the +// response writer, or defaults to 200. +func resolveStatus(reqCtx *models.RequestContext) int { + if reqCtx.ResponseStatus != 0 { + return reqCtx.ResponseStatus + } + if provider, ok := reqCtx.ResponseWriter.(models.ResponseStatusProvider); ok { + if code := provider.StatusCode(); code != 0 { + return code + } + } + return http.StatusOK +} + +// resolveSchemeAndClient derives the request scheme and client address. With +// trust_proxy enabled the X-Forwarded-Proto/X-Forwarded-For headers take +// precedence; otherwise they are ignored. +func resolveSchemeAndClient(reqCtx *models.RequestContext, trustProxy bool) (string, string) { + scheme := "http" + clientAddress := reqCtx.ClientIP + + if reqCtx.Request == nil { + return scheme, clientAddress + } + + if reqCtx.Request.TLS != nil { + scheme = "https" + } + + if !trustProxy { + return scheme, clientAddress + } + + if proto := strings.TrimSpace(reqCtx.Request.Header.Get("X-Forwarded-Proto")); proto != "" { + scheme = strings.ToLower(proto) + } + if forwardedFor := reqCtx.Request.Header.Get("X-Forwarded-For"); forwardedFor != "" { + if first := strings.TrimSpace(strings.Split(forwardedFor, ",")[0]); first != "" { + clientAddress = first + } + } + + return scheme, clientAddress +} + +func requestContext(reqCtx *models.RequestContext) context.Context { + if reqCtx.Request != nil { + return reqCtx.Request.Context() + } + return context.Background() +} + +// requestMethodAttr maps the HTTP method to its semantic-convention attribute, +// falling back to _OTHER for unknown methods. +func requestMethodAttr(method string) attribute.KeyValue { + switch method { + case http.MethodConnect: + return semconv.HTTPRequestMethodConnect + case http.MethodDelete: + return semconv.HTTPRequestMethodDelete + case http.MethodGet: + return semconv.HTTPRequestMethodGet + case http.MethodHead: + return semconv.HTTPRequestMethodHead + case http.MethodOptions: + return semconv.HTTPRequestMethodOptions + case http.MethodPatch: + return semconv.HTTPRequestMethodPatch + case http.MethodPost: + return semconv.HTTPRequestMethodPost + case http.MethodPut: + return semconv.HTTPRequestMethodPut + case http.MethodTrace: + return semconv.HTTPRequestMethodTrace + default: + return semconv.HTTPRequestMethodOther + } +} diff --git a/plugins/otel/hooks_test.go b/plugins/otel/hooks_test.go new file mode 100644 index 00000000..c63e4ca6 --- /dev/null +++ b/plugins/otel/hooks_test.go @@ -0,0 +1,441 @@ +package otel + +import ( + "context" + "crypto/tls" + "net/http" + "net/http/httptest" + "testing" + + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/codes" + "go.opentelemetry.io/otel/propagation" + sdkmetric "go.opentelemetry.io/otel/sdk/metric" + "go.opentelemetry.io/otel/sdk/metric/metricdata" + sdktrace "go.opentelemetry.io/otel/sdk/trace" + "go.opentelemetry.io/otel/sdk/trace/tracetest" + "go.opentelemetry.io/otel/trace" + + "github.com/Authula/authula/models" + "github.com/Authula/authula/plugins/otel/types" +) + +type fixture struct { + plugin *OTelPlugin + recorder *tracetest.SpanRecorder + reader *sdkmetric.ManualReader +} + +func newFixture(t *testing.T, config types.OTelPluginConfig) *fixture { + t.Helper() + + recorder := tracetest.NewSpanRecorder() + tracerProvider := sdktrace.NewTracerProvider(sdktrace.WithSpanProcessor(recorder)) + + reader := sdkmetric.NewManualReader() + meterProvider := sdkmetric.NewMeterProvider(sdkmetric.WithReader(reader)) + + plugin := &OTelPlugin{ + pluginConfig: config, + propagator: propagation.TraceContext{}, + tracerProvider: tracerProvider, + tracer: tracerProvider.Tracer("test"), + } + if err := plugin.bindMeter(meterProvider.Meter("test")); err != nil { + t.Fatalf("bindMeter() error = %v", err) + } + plugin.meterProvider = meterProvider + + t.Cleanup(func() { + _ = tracerProvider.Shutdown(context.Background()) + _ = meterProvider.Shutdown(context.Background()) + }) + + return &fixture{plugin: plugin, recorder: recorder, reader: reader} +} + +func newRequestContext(method, path, pattern string) *models.RequestContext { + req := httptest.NewRequest(method, path, nil) + return &models.RequestContext{ + Request: req, + Method: method, + Path: path, + Values: make(map[string]any), + Route: &models.Route{Method: method, Path: path, Pattern: pattern}, + } +} + +func findAttribute(span sdktrace.ReadOnlySpan, key attribute.Key) (attribute.Value, bool) { + for _, kv := range span.Attributes() { + if kv.Key == key { + return kv.Value, true + } + } + return attribute.Value{}, false +} + +func TestHookOnRequestPropagatesTraceContext(t *testing.T) { + t.Parallel() + + f := newFixture(t, types.OTelPluginConfig{Enabled: true, TracesEnabled: new(true), MetricsEnabled: new(true)}) + reqCtx := newRequestContext(http.MethodGet, "/api/auth/me", "GET:/api/auth/me") + reqCtx.Request.Header.Set("traceparent", "00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01") + + if err := f.plugin.onRequest()(reqCtx); err != nil { + t.Fatalf("onRequest() error = %v", err) + } + + span := trace.SpanFromContext(reqCtx.Request.Context()) + if !span.SpanContext().IsValid() { + t.Fatal("handler context does not carry a valid span") + } + + want, err := trace.TraceIDFromHex("4bf92f3577b34da6a3ce929d0e0e4736") + if err != nil { + t.Fatalf("bad trace ID: %v", err) + } + if span.SpanContext().TraceID() != want { + t.Fatalf("trace ID = %s, want %s", span.SpanContext().TraceID(), want) + } + + if err := f.plugin.onComplete()(reqCtx); err != nil { + t.Fatalf("onComplete() error = %v", err) + } + + ended := f.recorder.Ended() + if len(ended) != 1 { + t.Fatalf("ended spans = %d, want 1", len(ended)) + } + if ended[0].Name() != "GET /api/auth/me" { + t.Fatalf("span name = %q, want %q", ended[0].Name(), "GET /api/auth/me") + } + if ended[0].SpanKind() != trace.SpanKindServer { + t.Fatalf("span kind = %v, want server", ended[0].SpanKind()) + } +} + +func TestFinalizeSpanAttributes(t *testing.T) { + t.Parallel() + + cases := []struct { + name string + status int + actor *models.Actor + wantStatusAttr int + wantErrorType bool + wantSpanError bool + }{ + {name: "200 success", status: http.StatusOK, wantStatusAttr: 200}, + {name: "404 client error", status: http.StatusNotFound, wantStatusAttr: 404}, + {name: "500 server error", status: http.StatusInternalServerError, wantStatusAttr: 500, wantErrorType: true, wantSpanError: true}, + { + name: "actor identity", + status: http.StatusOK, + actor: &models.Actor{Type: models.ActorUser, ID: "user-123"}, + wantStatusAttr: 200, + }, + } + + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + + f := newFixture(t, types.OTelPluginConfig{Enabled: true, TracesEnabled: new(true), MetricsEnabled: new(true)}) + reqCtx := newRequestContext(http.MethodGet, "/api/auth/me", "GET:/api/auth/me") + reqCtx.ClientIP = "203.0.113.7" + reqCtx.ResponseStatus = tc.status + reqCtx.Actor = tc.actor + + if err := f.plugin.onRequest()(reqCtx); err != nil { + t.Fatalf("onRequest() error = %v", err) + } + if err := f.plugin.onComplete()(reqCtx); err != nil { + t.Fatalf("onComplete() error = %v", err) + } + + ended := f.recorder.Ended() + if len(ended) != 1 { + t.Fatalf("ended spans = %d, want 1", len(ended)) + } + span := ended[0] + + if v, ok := findAttribute(span, attribute.Key("http.request.method")); !ok || v.AsString() != http.MethodGet { + t.Errorf("http.request.method = %v (ok=%v), want GET", v.AsString(), ok) + } + if v, ok := findAttribute(span, attribute.Key("http.route")); !ok || v.AsString() != "/api/auth/me" { + t.Errorf("http.route = %q (ok=%v), want /api/auth/me", v.AsString(), ok) + } + if v, ok := findAttribute(span, attribute.Key("url.path")); !ok || v.AsString() != "/api/auth/me" { + t.Errorf("url.path = %q (ok=%v), want /api/auth/me", v.AsString(), ok) + } + if v, ok := findAttribute(span, attribute.Key("url.scheme")); !ok || v.AsString() != "http" { + t.Errorf("url.scheme = %q (ok=%v), want http", v.AsString(), ok) + } + if v, ok := findAttribute(span, attribute.Key("client.address")); !ok || v.AsString() != "203.0.113.7" { + t.Errorf("client.address = %q (ok=%v), want 203.0.113.7", v.AsString(), ok) + } + if v, ok := findAttribute(span, attribute.Key("http.response.status_code")); !ok || v.AsInt64() != int64(tc.wantStatusAttr) { + t.Errorf("http.response.status_code = %d (ok=%v), want %d", v.AsInt64(), ok, tc.wantStatusAttr) + } + + _, hasErrorType := findAttribute(span, attribute.Key(errorTypeKey)) + if hasErrorType != tc.wantErrorType { + t.Errorf("error.type present = %v, want %v", hasErrorType, tc.wantErrorType) + } + + wantCode := codes.Unset + if tc.wantSpanError { + wantCode = codes.Error + } + if span.Status().Code != wantCode { + t.Errorf("span status = %v, want %v", span.Status().Code, wantCode) + } + + if tc.actor != nil { + if v, ok := findAttribute(span, attribute.Key("authula.actor.type")); !ok || v.AsString() != string(tc.actor.Type) { + t.Errorf("authula.actor.type = %q (ok=%v), want %q", v.AsString(), ok, tc.actor.Type) + } + if v, ok := findAttribute(span, attribute.Key("authula.actor.id")); !ok || v.AsString() != tc.actor.ID { + t.Errorf("authula.actor.id = %q (ok=%v), want %q", v.AsString(), ok, tc.actor.ID) + } + } + }) + } +} + +func TestFinalizeUnmatchedRoute(t *testing.T) { + t.Parallel() + + f := newFixture(t, types.OTelPluginConfig{Enabled: true, TracesEnabled: new(true), MetricsEnabled: new(true)}) + reqCtx := newRequestContext(http.MethodPost, "/api/auth/unknown", "") + reqCtx.ResponseStatus = http.StatusNotFound + + if err := f.plugin.onRequest()(reqCtx); err != nil { + t.Fatalf("onRequest() error = %v", err) + } + if err := f.plugin.onComplete()(reqCtx); err != nil { + t.Fatalf("onComplete() error = %v", err) + } + + span := f.recorder.Ended()[0] + if span.Name() != "POST" { + t.Errorf("span name = %q, want %q", span.Name(), "POST") + } + if v, ok := findAttribute(span, attribute.Key("http.route")); !ok || v.AsString() != routeUnmatched { + t.Errorf("http.route = %q (ok=%v), want %q", v.AsString(), ok, routeUnmatched) + } + if v, ok := findAttribute(span, attribute.Key("url.path")); !ok || v.AsString() != "/api/auth/unknown" { + t.Errorf("url.path = %q, want /api/auth/unknown", v.AsString()) + } +} + +func TestFinalizeUnknownMethodMappedToOther(t *testing.T) { + t.Parallel() + + f := newFixture(t, types.OTelPluginConfig{Enabled: true, TracesEnabled: new(true), MetricsEnabled: new(true)}) + reqCtx := newRequestContext("BREW", "/api/auth/coffee", "") + + if err := f.plugin.onRequest()(reqCtx); err != nil { + t.Fatalf("onRequest() error = %v", err) + } + if err := f.plugin.onComplete()(reqCtx); err != nil { + t.Fatalf("onComplete() error = %v", err) + } + + span := f.recorder.Ended()[0] + if v, ok := findAttribute(span, attribute.Key("http.request.method")); !ok || v.AsString() != "_OTHER" { + t.Errorf("http.request.method = %q (ok=%v), want _OTHER", v.AsString(), ok) + } +} + +func TestResolveSchemeAndClient(t *testing.T) { + t.Parallel() + + cases := []struct { + name string + trustProxy bool + tls bool + forwardedProto string + forwardedFor string + wantScheme string + wantClient string + }{ + {name: "plain http", wantScheme: "http", wantClient: "198.51.100.9"}, + {name: "tls is https", tls: true, wantScheme: "https", wantClient: "198.51.100.9"}, + { + name: "spoofed headers ignored without trust", + forwardedProto: "https", + forwardedFor: "1.2.3.4", + wantScheme: "http", + wantClient: "198.51.100.9", + }, + { + name: "headers honored with trust", + trustProxy: true, + forwardedProto: "https", + forwardedFor: "1.2.3.4, 5.6.7.8", + wantScheme: "https", + wantClient: "1.2.3.4", + }, + } + + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + + reqCtx := newRequestContext(http.MethodGet, "/", "") + reqCtx.ClientIP = "198.51.100.9" + if tc.tls { + reqCtx.Request.TLS = &tls.ConnectionState{} + } + if tc.forwardedProto != "" { + reqCtx.Request.Header.Set("X-Forwarded-Proto", tc.forwardedProto) + } + if tc.forwardedFor != "" { + reqCtx.Request.Header.Set("X-Forwarded-For", tc.forwardedFor) + } + + scheme, client := resolveSchemeAndClient(reqCtx, tc.trustProxy) + if scheme != tc.wantScheme { + t.Errorf("scheme = %q, want %q", scheme, tc.wantScheme) + } + if client != tc.wantClient { + t.Errorf("client = %q, want %q", client, tc.wantClient) + } + }) + } +} + +func TestFinalizeRecordsDurationMetric(t *testing.T) { + t.Parallel() + + cases := []struct { + name string + method string + status int + wantMetric bool + wantErrorType bool + }{ + {name: "request recorded", method: http.MethodGet, status: http.StatusOK, wantMetric: true}, + {name: "5xx records error.type", method: http.MethodPost, status: http.StatusInternalServerError, wantMetric: true, wantErrorType: true}, + {name: "preflight not recorded", method: http.MethodOptions, status: http.StatusOK, wantMetric: false}, + } + + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + + f := newFixture(t, types.OTelPluginConfig{Enabled: true, TracesEnabled: new(true), MetricsEnabled: new(true)}) + reqCtx := newRequestContext(tc.method, "/api/auth/me", "GET:/api/auth/me") + reqCtx.ResponseStatus = tc.status + + if err := f.plugin.onRequest()(reqCtx); err != nil { + t.Fatalf("onRequest() error = %v", err) + } + if err := f.plugin.onComplete()(reqCtx); err != nil { + t.Fatalf("onComplete() error = %v", err) + } + + metric, found := collectMetric(t, f.reader) + if found != tc.wantMetric { + t.Fatalf("metric found = %v, want %v", found, tc.wantMetric) + } + if !tc.wantMetric { + return + } + + if metric.Name != durationInstrumentName { + t.Errorf("metric name = %q, want %q", metric.Name, durationInstrumentName) + } + if metric.Unit != "s" { + t.Errorf("metric unit = %q, want s", metric.Unit) + } + + histogram, ok := metric.Data.(metricdata.Histogram[float64]) + if !ok { + t.Fatalf("metric data type = %T, want histogram", metric.Data) + } + if len(histogram.DataPoints) != 1 { + t.Fatalf("data points = %d, want 1", len(histogram.DataPoints)) + } + + point := histogram.DataPoints[0] + if point.Count != 1 { + t.Errorf("count = %d, want 1", point.Count) + } + if point.Sum <= 0 { + t.Errorf("sum = %v, want > 0", point.Sum) + } + + if v, ok := point.Attributes.Value(attribute.Key("http.response.status_code")); !ok || v.AsInt64() != int64(tc.status) { + t.Errorf("http.response.status_code = %d (ok=%v), want %d", v.AsInt64(), ok, tc.status) + } + if v, ok := point.Attributes.Value(attribute.Key("url.scheme")); !ok || v.AsString() != "http" { + t.Errorf("url.scheme = %q (ok=%v), want http", v.AsString(), ok) + } + _, hasErrorType := point.Attributes.Value(attribute.Key(errorTypeKey)) + if hasErrorType != tc.wantErrorType { + t.Errorf("error.type present = %v, want %v", hasErrorType, tc.wantErrorType) + } + }) + } +} + +func TestFinalizeIdempotentAndShortCircuit(t *testing.T) { + t.Parallel() + + f := newFixture(t, types.OTelPluginConfig{Enabled: true, TracesEnabled: new(true), MetricsEnabled: new(true)}) + reqCtx := newRequestContext(http.MethodGet, "/api/auth/me", "GET:/api/auth/me") + reqCtx.ResponseWriter = httptest.NewRecorder() + reqCtx.ResponseStatus = http.StatusTooManyRequests + + if err := f.plugin.onRequest()(reqCtx); err != nil { + t.Fatalf("onRequest() error = %v", err) + } + // Simulate a short-circuit: no handler ran, completion still finalizes. + if err := f.plugin.onComplete()(reqCtx); err != nil { + t.Fatalf("onComplete() error = %v", err) + } + // A second completion must not end the span again. + if err := f.plugin.onComplete()(reqCtx); err != nil { + t.Fatalf("second onComplete() error = %v", err) + } + + if got := len(f.recorder.Ended()); got != 1 { + t.Fatalf("ended spans = %d, want 1", got) + } +} + +func TestHooksNeverReturnError(t *testing.T) { + t.Parallel() + + f := newFixture(t, types.OTelPluginConfig{Enabled: true, TracesEnabled: new(true), MetricsEnabled: new(true)}) + + // Empty request context: no route, no values. + empty := &models.RequestContext{Method: http.MethodGet, Request: httptest.NewRequest(http.MethodGet, "/", nil)} + if err := f.plugin.onRequest()(empty); err != nil { + t.Fatalf("onRequest() on empty context error = %v", err) + } + if err := f.plugin.onComplete()(empty); err != nil { + t.Fatalf("onComplete() on empty context error = %v", err) + } +} + +func collectMetric(t *testing.T, reader sdkmetric.Reader) (metricdata.Metrics, bool) { + t.Helper() + + var resourceMetrics metricdata.ResourceMetrics + if err := reader.Collect(context.Background(), &resourceMetrics); err != nil { + t.Fatalf("Collect() error = %v", err) + } + + for _, scopeMetrics := range resourceMetrics.ScopeMetrics { + for _, metric := range scopeMetrics.Metrics { + if metric.Name == durationInstrumentName { + return metric, true + } + } + } + + return metricdata.Metrics{}, false +} diff --git a/plugins/otel/plugin.go b/plugins/otel/plugin.go new file mode 100644 index 00000000..b601a1ac --- /dev/null +++ b/plugins/otel/plugin.go @@ -0,0 +1,208 @@ +package otel + +import ( + "context" + "errors" + "fmt" + "sync" + "time" + + "go.opentelemetry.io/contrib/instrumentation/runtime" + "go.opentelemetry.io/otel/metric" + metricnoop "go.opentelemetry.io/otel/metric/noop" + "go.opentelemetry.io/otel/propagation" + sdkmetric "go.opentelemetry.io/otel/sdk/metric" + "go.opentelemetry.io/otel/sdk/resource" + sdktrace "go.opentelemetry.io/otel/sdk/trace" + semconv "go.opentelemetry.io/otel/semconv/v1.43.0" + "go.opentelemetry.io/otel/trace" + tracenoop "go.opentelemetry.io/otel/trace/noop" + + "github.com/Authula/authula/models" + "github.com/Authula/authula/plugins/otel/types" + "github.com/Authula/authula/util" +) + +// scopeName identifies the instrumentation scope attached to every span and +// metric produced by the plugin. +const scopeName = "github.com/Authula/authula/plugins/otel" + +// OTelPlugin provides distributed tracing and request/runtime metrics backed by +// the OpenTelemetry SDK. All providers are instance-local: the plugin never +// touches the process-global otel providers. +type OTelPlugin struct { + pluginConfig types.OTelPluginConfig + pluginCtx *models.PluginContext + logger models.Logger + + tracer trace.Tracer + meter metric.Meter + propagator propagation.TextMapPropagator + + tracerProvider *sdktrace.TracerProvider // nil when traces disabled/none + meterProvider *sdkmetric.MeterProvider // nil when metrics disabled/none + duration metric.Float64Histogram + + closeOnce sync.Once + closeErr error +} + +func New(config types.OTelPluginConfig) *OTelPlugin { + config.ApplyDefaults() + return &OTelPlugin{pluginConfig: config} +} + +func (p *OTelPlugin) Metadata() models.PluginMetadata { + return models.PluginMetadata{ + ID: models.PluginOtel.String(), + Version: "1.0.0", + Description: "Provides OpenTelemetry distributed tracing and request/runtime metrics", + } +} + +func (p *OTelPlugin) Config() any { + return p.pluginConfig +} + +// Init builds the tracer, meter and propagator. Invalid configuration and +// provider construction failures are returned so the server refuses to start +// rather than running blind. A disabled plugin is a no-op. +func (p *OTelPlugin) Init(pluginCtx *models.PluginContext) error { + p.pluginCtx = pluginCtx + p.logger = pluginCtx.Logger + + if err := util.LoadPluginConfig(pluginCtx.GetConfig(), p.Metadata().ID, &p.pluginConfig); err != nil { + return fmt.Errorf("otel: failed to load plugin config: %w", err) + } + + p.pluginConfig.ApplyDefaults() + + if !p.pluginConfig.Enabled { + return nil + } + + if !p.pluginConfig.Valid() { + return fmt.Errorf( + "otel: invalid configuration: exporter=%q protocol=%q sample_ratio=%v", + p.pluginConfig.Exporter, + p.pluginConfig.Protocol, + p.pluginConfig.SampleRatio, + ) + } + + p.propagator = propagation.TraceContext{} + + res, err := resource.Merge( + resource.Default(), + resource.NewWithAttributes( + semconv.SchemaURL, + semconv.ServiceName(resolveServiceName(p.pluginConfig)), + semconv.ServiceVersion(p.Metadata().Version), + ), + ) + if err != nil { + return fmt.Errorf("otel: failed to build resource: %w", err) + } + + if err := p.initTracer(res); err != nil { + return err + } + + if err := p.initMeter(res); err != nil { + return err + } + + if p.pluginConfig.RuntimeOn() && p.pluginConfig.MetricsActive() { + if err := runtime.Start(runtime.WithMeterProvider(p.meterProvider)); err != nil { + p.warn("otel: failed to start runtime metrics", "error", err) + } + } + + return nil +} + +func (p *OTelPlugin) initTracer(res *resource.Resource) error { + if !p.pluginConfig.TracesActive() { + p.tracer = tracenoop.NewTracerProvider().Tracer(scopeName) + return nil + } + + exp, err := buildTraceExporter(context.Background(), p.pluginConfig) + if err != nil { + return err + } + + p.tracerProvider = newTracerProvider(p.pluginConfig, res, exp) + p.tracer = p.tracerProvider.Tracer(scopeName, trace.WithInstrumentationVersion(p.Metadata().Version)) + + return nil +} + +func (p *OTelPlugin) initMeter(res *resource.Resource) error { + if !p.pluginConfig.MetricsActive() { + return p.bindMeter(metricnoop.NewMeterProvider().Meter(scopeName)) + } + + exp, err := buildMetricExporter(context.Background(), p.pluginConfig) + if err != nil { + return err + } + + var reader sdkmetric.Reader + if exp != nil { + reader = sdkmetric.NewPeriodicReader(exp) + } + p.meterProvider = newMeterProvider(p.pluginConfig, res, reader) + + return p.bindMeter(p.meterProvider.Meter(scopeName, metric.WithInstrumentationVersion(p.Metadata().Version))) +} + +// bindMeter stores the meter and creates the sole instrument used by the +// plugin. It is split out so tests can inject an in-memory meter. +func (p *OTelPlugin) bindMeter(meter metric.Meter) error { + p.meter = meter + + duration, err := meter.Float64Histogram( + durationInstrumentName, + metric.WithUnit("s"), + metric.WithExplicitBucketBoundaries(durationBuckets...), + ) + if err != nil { + return fmt.Errorf("otel: failed to create %s instrument: %w", durationInstrumentName, err) + } + p.duration = duration + + return nil +} + +func (p *OTelPlugin) Hooks() []models.Hook { + return p.buildHooks() +} + +func (p *OTelPlugin) Close() error { + p.closeOnce.Do(func() { + ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) + defer cancel() + + var errs []error + if p.meterProvider != nil { + if err := p.meterProvider.Shutdown(ctx); err != nil { + errs = append(errs, err) + } + } + if p.tracerProvider != nil { + if err := p.tracerProvider.Shutdown(ctx); err != nil { + errs = append(errs, err) + } + } + p.closeErr = errors.Join(errs...) + }) + + return p.closeErr +} + +func (p *OTelPlugin) warn(msg string, args ...any) { + if p.logger != nil { + p.logger.Warn(msg, args...) + } +} diff --git a/plugins/otel/plugin_test.go b/plugins/otel/plugin_test.go new file mode 100644 index 00000000..e4baa838 --- /dev/null +++ b/plugins/otel/plugin_test.go @@ -0,0 +1,224 @@ +package otel + +import ( + "testing" + + "github.com/Authula/authula/models" + "github.com/Authula/authula/plugins/otel/constants" + "github.com/Authula/authula/plugins/otel/types" +) + +func nilConfig() *models.Config { + return nil +} + +func TestOTelPluginMetadata(t *testing.T) { + t.Parallel() + + plugin := New(types.OTelPluginConfig{Enabled: true}) + + metadata := plugin.Metadata() + if metadata.ID != models.PluginOtel.String() { + t.Fatalf("Metadata().ID = %q, want %q", metadata.ID, models.PluginOtel.String()) + } + if metadata.Version != "1.0.0" { + t.Fatalf("Metadata().Version = %q, want %q", metadata.Version, "1.0.0") + } + if plugin.Config() == nil { + t.Fatal("Config() should not be nil") + } +} + +func TestOTelPluginHooks(t *testing.T) { + t.Parallel() + + cases := []struct { + name string + traces bool + metrics bool + wantOnReq bool + wantOnDone bool + }{ + {name: "both enabled", traces: true, metrics: true, wantOnReq: true, wantOnDone: true}, + {name: "only traces", traces: true, metrics: false, wantOnReq: true, wantOnDone: true}, + {name: "only metrics", traces: false, metrics: true, wantOnReq: true, wantOnDone: true}, + {name: "both disabled", traces: false, metrics: false, wantOnReq: false, wantOnDone: false}, + } + + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + + plugin := &OTelPlugin{} + plugin.pluginConfig.TracesEnabled = new(tc.traces) + plugin.pluginConfig.MetricsEnabled = new(tc.metrics) + + hooks := plugin.Hooks() + if !tc.wantOnReq && !tc.wantOnDone { + if hooks != nil { + t.Fatalf("Hooks() = %v, want nil", hooks) + } + return + } + + var onReq, onDone int + for _, hook := range hooks { + switch hook.Stage { + case models.HookOnRequest: + onReq++ + if !hook.RunOnBypass { + t.Error("HookOnRequest should opt into bypass paths") + } + if hook.Order != -100 { + t.Errorf("HookOnRequest Order = %d, want -100", hook.Order) + } + case models.HookOnComplete: + onDone++ + } + } + + if (onReq > 0) != tc.wantOnReq { + t.Errorf("HookOnRequest count = %d, want present = %v", onReq, tc.wantOnReq) + } + if (onDone > 0) != tc.wantOnDone { + t.Errorf("HookOnComplete count = %d, want present = %v", onDone, tc.wantOnDone) + } + }) + } +} + +func TestOTelPluginInitDisabledIsNoOp(t *testing.T) { + t.Parallel() + + plugin := New(types.OTelPluginConfig{Enabled: false}) + + err := plugin.Init(&models.PluginContext{GetConfig: nilConfig}) + if err != nil { + t.Fatalf("Init() error = %v, want nil", err) + } + if plugin.tracerProvider != nil { + t.Error("tracerProvider should be nil when disabled") + } + if plugin.meterProvider != nil { + t.Error("meterProvider should be nil when disabled") + } +} + +func TestOTelPluginInitInvalidConfig(t *testing.T) { + t.Parallel() + + cases := []struct { + name string + config types.OTelPluginConfig + }{ + {name: "unknown exporter", config: types.OTelPluginConfig{Exporter: "unknown"}}, + {name: "unknown protocol", config: types.OTelPluginConfig{Exporter: types.ExporterOTLP, Protocol: "quic"}}, + {name: "sample ratio below zero", config: types.OTelPluginConfig{Exporter: types.ExporterOTLP, SampleRatio: new(-0.5)}}, + {name: "sample ratio above one", config: types.OTelPluginConfig{Exporter: types.ExporterOTLP, SampleRatio: new(2.0)}}, + } + + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + + config := tc.config + config.Enabled = true + plugin := New(config) + + if err := plugin.Init(&models.PluginContext{GetConfig: nilConfig}); err == nil { + t.Fatal("Init() error = nil, want non-nil") + } + }) + } +} + +func TestOTelPluginInitAndClose(t *testing.T) { + t.Parallel() + + plugin := New(types.OTelPluginConfig{ + Enabled: true, + Exporter: types.ExporterStdout, + ServiceName: "test-service", + MetricsEnabled: new(false), + RuntimeMetrics: new(false), + }) + if err := plugin.Init(&models.PluginContext{GetConfig: nilConfig}); err != nil { + t.Fatalf("Init() error = %v", err) + } + if plugin.tracerProvider == nil { + t.Error("tracerProvider should not be nil") + } + if plugin.tracer == nil { + t.Error("tracer should not be nil") + } + if plugin.duration == nil { + t.Error("duration instrument should not be nil") + } + + if err := plugin.Close(); err != nil { + t.Fatalf("Close() error = %v", err) + } + // Close is idempotent. + if err := plugin.Close(); err != nil { + t.Fatalf("second Close() error = %v", err) + } +} + +func TestOTelPluginCloseNeverInitialized(t *testing.T) { + t.Parallel() + + if err := (&OTelPlugin{}).Close(); err != nil { + t.Fatalf("Close() on zero plugin error = %v", err) + } +} + +func TestResolveServiceName(t *testing.T) { + cases := []struct { + name string + config types.OTelPluginConfig + env string + expected string + }{ + {name: "config wins", config: types.OTelPluginConfig{ServiceName: "from-config"}, env: "from-env", expected: "from-config"}, + {name: "env used when config empty", config: types.OTelPluginConfig{}, env: "from-env", expected: "from-env"}, + {name: "default when both empty", config: types.OTelPluginConfig{}, env: "", expected: types.DefaultServiceName}, + } + + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + if tc.env == "" { + t.Setenv(constants.EnvOTelServiceName, "") + } else { + t.Setenv(constants.EnvOTelServiceName, tc.env) + } + + if got := resolveServiceName(tc.config); got != tc.expected { + t.Fatalf("resolveServiceName() = %q, want %q", got, tc.expected) + } + }) + } +} + +func TestResolveProtocol(t *testing.T) { + cases := []struct { + name string + config types.OTelPluginConfig + env string + expected types.ProtocolType + }{ + {name: "config wins", config: types.OTelPluginConfig{Protocol: types.ProtocolGRPC}, env: "http/protobuf", expected: types.ProtocolGRPC}, + {name: "env grpc", config: types.OTelPluginConfig{}, env: "grpc", expected: types.ProtocolGRPC}, + {name: "env http", config: types.OTelPluginConfig{}, env: "http/protobuf", expected: types.ProtocolHTTP}, + {name: "default http", config: types.OTelPluginConfig{}, env: "", expected: types.ProtocolHTTP}, + } + + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + t.Setenv(constants.EnvOTelExporterOTLPProtocol, tc.env) + + if got := resolveProtocol(tc.config); got != tc.expected { + t.Fatalf("resolveProtocol() = %q, want %q", got, tc.expected) + } + }) + } +} diff --git a/plugins/otel/types/config.go b/plugins/otel/types/config.go new file mode 100644 index 00000000..07fb8250 --- /dev/null +++ b/plugins/otel/types/config.go @@ -0,0 +1,123 @@ +package types + +// DefaultServiceName is used when neither the plugin config nor the +// OTEL_SERVICE_NAME environment variable provides a service name. +const DefaultServiceName = "authula" + +// ExporterType selects where telemetry is exported. +type ExporterType string + +const ( + // ExporterOTLP exports over the OpenTelemetry Protocol. + ExporterOTLP ExporterType = "otlp" + // ExporterStdout writes telemetry to standard output (useful for debugging). + ExporterStdout ExporterType = "stdout" + // ExporterNone disables exporting entirely. + ExporterNone ExporterType = "none" +) + +// ProtocolType selects the OTLP transport. +type ProtocolType string + +const ( + // ProtocolHTTP uses OTLP over HTTP/protobuf. + ProtocolHTTP ProtocolType = "http" + // ProtocolGRPC uses OTLP over gRPC. + ProtocolGRPC ProtocolType = "grpc" +) + +// OTelPluginConfig is the OpenTelemetry plugin configuration. +// +// It carries both json tags (used by util.LoadPluginConfig/mapstructure) and +// matching toml tags for consistency with the other plugin configs. +// +// TracesEnabled, MetricsEnabled and RuntimeMetrics are pointers so an explicit +// `false` is distinguishable from "unset" (which defaults to true). +type OTelPluginConfig struct { + Enabled bool `json:"enabled" toml:"enabled"` + ServiceName string `json:"service_name,omitempty" toml:"service_name"` + Exporter ExporterType `json:"exporter,omitempty" toml:"exporter"` + Protocol ProtocolType `json:"protocol,omitempty" toml:"protocol"` + Endpoint string `json:"endpoint,omitempty" toml:"endpoint"` + Insecure bool `json:"insecure,omitempty" toml:"insecure"` + Headers map[string]string `json:"headers,omitempty" toml:"headers"` + TracesEnabled *bool `json:"traces_enabled,omitempty" toml:"traces_enabled"` + MetricsEnabled *bool `json:"metrics_enabled,omitempty" toml:"metrics_enabled"` + RuntimeMetrics *bool `json:"runtime_metrics,omitempty" toml:"runtime_metrics"` + SampleRatio *float64 `json:"sample_ratio,omitempty" toml:"sample_ratio"` + TrustProxy bool `json:"trust_proxy,omitempty" toml:"trust_proxy"` +} + +// ApplyDefaults fills unset fields with their default values. It does not touch +// Enabled, which is resolved by the plugin factory and the Init guard. +func (c *OTelPluginConfig) ApplyDefaults() { + if c.Exporter == "" { + c.Exporter = ExporterOTLP + } + if c.TracesEnabled == nil { + c.TracesEnabled = new(true) + } + if c.MetricsEnabled == nil { + c.MetricsEnabled = new(true) + } + if c.RuntimeMetrics == nil { + c.RuntimeMetrics = new(true) + } +} + +// TracesOn reports whether tracing is enabled, defaulting to true when unset. +func (c OTelPluginConfig) TracesOn() bool { + return boolValue(c.TracesEnabled, true) +} + +// MetricsOn reports whether metrics are enabled, defaulting to true when unset. +func (c OTelPluginConfig) MetricsOn() bool { + return boolValue(c.MetricsEnabled, true) +} + +// RuntimeOn reports whether runtime metrics are enabled, defaulting to true +// when unset. +func (c OTelPluginConfig) RuntimeOn() bool { + return boolValue(c.RuntimeMetrics, true) +} + +// TracesActive reports whether tracing should be initialized. It additionally +// treats the "none" exporter as a full disable. +func (c OTelPluginConfig) TracesActive() bool { + return c.TracesOn() && c.Exporter != ExporterNone +} + +// MetricsActive reports whether metrics should be initialized. It additionally +// treats the "none" exporter as a full disable. +func (c OTelPluginConfig) MetricsActive() bool { + return c.MetricsOn() && c.Exporter != ExporterNone +} + +// Valid reports whether the configuration values are within their supported +// ranges. +func (c OTelPluginConfig) Valid() bool { + switch c.Exporter { + case ExporterOTLP, ExporterStdout, ExporterNone: + default: + return false + } + + switch c.Protocol { + case "", ProtocolHTTP, ProtocolGRPC: + default: + return false + } + + if c.SampleRatio != nil && (*c.SampleRatio < 0 || *c.SampleRatio > 1) { + return false + } + + return true +} + +func boolValue(value *bool, fallback bool) bool { + if value != nil { + return *value + } + return fallback +} diff --git a/plugins/otel/types/config_test.go b/plugins/otel/types/config_test.go new file mode 100644 index 00000000..b92a899f --- /dev/null +++ b/plugins/otel/types/config_test.go @@ -0,0 +1,218 @@ +package types_test + +import ( + "testing" + + "github.com/Authula/authula/plugins/otel/types" +) + +func TestOTelPluginConfigApplyDefaults(t *testing.T) { + t.Parallel() + + cases := []struct { + name string + config types.OTelPluginConfig + expected types.OTelPluginConfig + }{ + { + name: "empty config gets all defaults", + config: types.OTelPluginConfig{}, + expected: types.OTelPluginConfig{ + Exporter: types.ExporterOTLP, + TracesEnabled: new(true), + MetricsEnabled: new(true), + RuntimeMetrics: new(true), + }, + }, + { + name: "explicit exporter is preserved", + config: types.OTelPluginConfig{ + Exporter: types.ExporterStdout, + }, + expected: types.OTelPluginConfig{ + Exporter: types.ExporterStdout, + TracesEnabled: new(true), + MetricsEnabled: new(true), + RuntimeMetrics: new(true), + }, + }, + { + name: "explicit toggles are preserved", + config: types.OTelPluginConfig{ + TracesEnabled: new(false), + MetricsEnabled: new(true), + RuntimeMetrics: new(false), + }, + expected: types.OTelPluginConfig{ + Exporter: types.ExporterOTLP, + TracesEnabled: new(false), + MetricsEnabled: new(true), + RuntimeMetrics: new(false), + }, + }, + { + name: "all other fields are preserved", + config: types.OTelPluginConfig{ + Enabled: true, + ServiceName: "billing", + Exporter: types.ExporterOTLP, + Protocol: types.ProtocolGRPC, + Endpoint: "collector:4317", + Insecure: true, + Headers: map[string]string{"x-token": "abc"}, + SampleRatio: new(0.25), + TrustProxy: true, + }, + expected: types.OTelPluginConfig{ + Enabled: true, + ServiceName: "billing", + Exporter: types.ExporterOTLP, + Protocol: types.ProtocolGRPC, + Endpoint: "collector:4317", + Insecure: true, + Headers: map[string]string{"x-token": "abc"}, + TracesEnabled: new(true), + MetricsEnabled: new(true), + RuntimeMetrics: new(true), + SampleRatio: new(0.25), + TrustProxy: true, + }, + }, + } + + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + + config := tc.config + config.ApplyDefaults() + + if config.Exporter != tc.expected.Exporter { + t.Errorf("Exporter = %q, want %q", config.Exporter, tc.expected.Exporter) + } + if *config.TracesEnabled != *tc.expected.TracesEnabled { + t.Errorf("TracesEnabled = %v, want %v", *config.TracesEnabled, *tc.expected.TracesEnabled) + } + if *config.MetricsEnabled != *tc.expected.MetricsEnabled { + t.Errorf("MetricsEnabled = %v, want %v", *config.MetricsEnabled, *tc.expected.MetricsEnabled) + } + if *config.RuntimeMetrics != *tc.expected.RuntimeMetrics { + t.Errorf("RuntimeMetrics = %v, want %v", *config.RuntimeMetrics, *tc.expected.RuntimeMetrics) + } + if config.ServiceName != tc.expected.ServiceName { + t.Errorf("ServiceName = %q, want %q", config.ServiceName, tc.expected.ServiceName) + } + if config.Protocol != tc.expected.Protocol { + t.Errorf("Protocol = %q, want %q", config.Protocol, tc.expected.Protocol) + } + if config.Endpoint != tc.expected.Endpoint { + t.Errorf("Endpoint = %q, want %q", config.Endpoint, tc.expected.Endpoint) + } + if config.Insecure != tc.expected.Insecure { + t.Errorf("Insecure = %v, want %v", config.Insecure, tc.expected.Insecure) + } + if config.TrustProxy != tc.expected.TrustProxy { + t.Errorf("TrustProxy = %v, want %v", config.TrustProxy, tc.expected.TrustProxy) + } + }) + } +} + +func TestOTelPluginConfigSampleRatio(t *testing.T) { + t.Parallel() + + cases := []struct { + name string + ratio *float64 + expect bool + }{ + {name: "nil is valid", ratio: nil, expect: true}, + {name: "zero is valid", ratio: new(0.0), expect: true}, + {name: "one is valid", ratio: new(1.0), expect: true}, + {name: "fraction is valid", ratio: new(0.5), expect: true}, + {name: "below zero is invalid", ratio: new(-0.1), expect: false}, + {name: "above one is invalid", ratio: new(1.1), expect: false}, + } + + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + + config := types.OTelPluginConfig{Exporter: types.ExporterOTLP, SampleRatio: tc.ratio} + if got := config.Valid(); got != tc.expect { + t.Fatalf("Valid() = %v, want %v", got, tc.expect) + } + }) + } +} + +func TestOTelPluginConfigValid(t *testing.T) { + t.Parallel() + + cases := []struct { + name string + config types.OTelPluginConfig + valid bool + }{ + {name: "otlp http", config: types.OTelPluginConfig{Exporter: types.ExporterOTLP, Protocol: types.ProtocolHTTP}, valid: true}, + {name: "otlp grpc", config: types.OTelPluginConfig{Exporter: types.ExporterOTLP, Protocol: types.ProtocolGRPC}, valid: true}, + {name: "empty protocol", config: types.OTelPluginConfig{Exporter: types.ExporterOTLP}, valid: true}, + {name: "stdout", config: types.OTelPluginConfig{Exporter: types.ExporterStdout}, valid: true}, + {name: "none", config: types.OTelPluginConfig{Exporter: types.ExporterNone}, valid: true}, + {name: "unknown exporter", config: types.OTelPluginConfig{Exporter: "carrier-pigeon"}, valid: false}, + {name: "unknown protocol", config: types.OTelPluginConfig{Exporter: types.ExporterOTLP, Protocol: "quic"}, valid: false}, + } + + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + + if got := tc.config.Valid(); got != tc.valid { + t.Fatalf("Valid() = %v, want %v", got, tc.valid) + } + }) + } +} + +func TestOTelPluginConfigActive(t *testing.T) { + t.Parallel() + + cases := []struct { + name string + config types.OTelPluginConfig + tracesOn bool + metricsOn bool + }{ + { + name: "exporter none disables both", + config: types.OTelPluginConfig{Exporter: types.ExporterNone, TracesEnabled: new(true), MetricsEnabled: new(true)}, + tracesOn: false, + metricsOn: false, + }, + { + name: "otlp enables both", + config: types.OTelPluginConfig{Exporter: types.ExporterOTLP, TracesEnabled: new(true), MetricsEnabled: new(true)}, + tracesOn: true, + metricsOn: true, + }, + { + name: "individual toggles respected", + config: types.OTelPluginConfig{Exporter: types.ExporterStdout, TracesEnabled: new(false), MetricsEnabled: new(true)}, + tracesOn: false, + metricsOn: true, + }, + } + + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + + if got := tc.config.TracesActive(); got != tc.tracesOn { + t.Errorf("TracesActive() = %v, want %v", got, tc.tracesOn) + } + if got := tc.config.MetricsActive(); got != tc.metricsOn { + t.Errorf("MetricsActive() = %v, want %v", got, tc.metricsOn) + } + }) + } +} From 9543a978eeb9dfb066e47515f233388fa6a808a2 Mon Sep 17 00:00:00 2001 From: Tanvir Ahmed Date: Sat, 24 Oct 2026 02:19:32 +0000 Subject: [PATCH 2/2] feat(plugins): bridge models.Logger records to OTLP Add a models.Logger fan-out seam, wrap user-supplied loggers in it, and attach an otelslog-backed sink in the OTel plugin when logs_enabled is set. Route core and plugin logging through models.Logger, document the logs bridge, and enforce the log/slog boundary in CI. --- auth.go | 7 + cmd/main.go | 20 +-- cmd/migrate/main.go | 15 +- go.mod | 7 +- go.sum | 12 ++ internal/bootstrap/fanout.go | 162 +++++++++++++++++ internal/bootstrap/fanout_test.go | 165 ++++++++++++++++++ internal/bootstrap/logger.go | 65 ++++--- internal/bootstrap/logger_test.go | 90 ++++++++-- internal/tests/mock_objects.go | 56 ++++++ models/logger.go | 20 ++- plugins/otel/README.md | 58 +++++- plugins/otel/export_test.go | 19 ++ plugins/otel/exporter.go | 63 +++++++ plugins/otel/logbridge.go | 76 ++++++++ plugins/otel/logbridge_test.go | 142 +++++++++++++++ plugins/otel/logger.go | 59 +++++++ plugins/otel/logger_test.go | 123 +++++++++++++ plugins/otel/plugin.go | 21 ++- plugins/otel/tests/exporter.go | 40 +++++ plugins/otel/types/config.go | 8 + .../database_secondary_storage.go | 40 ++++- .../database_secondary_storage_test.go | 23 +++ plugins/secondary-storage/plugin.go | 2 +- 24 files changed, 1218 insertions(+), 75 deletions(-) create mode 100644 internal/bootstrap/fanout.go create mode 100644 internal/bootstrap/fanout_test.go create mode 100644 plugins/otel/export_test.go create mode 100644 plugins/otel/logbridge.go create mode 100644 plugins/otel/logbridge_test.go create mode 100644 plugins/otel/logger.go create mode 100644 plugins/otel/logger_test.go create mode 100644 plugins/otel/tests/exporter.go diff --git a/auth.go b/auth.go index 1b98f636..d535c34d 100644 --- a/auth.go +++ b/auth.go @@ -40,6 +40,13 @@ type Auth struct { Api core.CoreAPI } +// Logger returns the instance's logger. Callers that need to log before or +// after the Auth lifecycle (for example the standalone command) use it instead +// of constructing their own logger. +func (auth *Auth) Logger() models.Logger { + return auth.logger +} + // New creates a new Auth instance using the provided config and plugins. // Handles plugin registration, migrations, and initialization in unified way. // Works identically whether plugins are manually instantiated or built from config. diff --git a/cmd/main.go b/cmd/main.go index 59d4d46f..8f13a4ea 100644 --- a/cmd/main.go +++ b/cmd/main.go @@ -3,7 +3,6 @@ package main import ( "context" "fmt" - "log/slog" "net/http" "os" "os/signal" @@ -23,12 +22,7 @@ import ( func main() { env.LoadEnvConfig() - logger := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{ - Level: slog.LevelDebug, - })) - slog.SetDefault(logger) - - config := loadConfig() + config, configExists := loadConfig() pluginsList := bootstrap.BuildPluginsFromConfig(config) @@ -37,6 +31,11 @@ func main() { Plugins: pluginsList, }) + logger := auth.Logger() + if !configExists { + logger.Debug("No config file found, continuing", "path", env.GetEnv(env.EnvConfigPath, "config.toml")) + } + // Channel to signal restart restartChan := make(chan struct{}) // Channel to signal shutdown @@ -107,16 +106,13 @@ func runServer(logger models.Logger, auth *authula.Auth, restartChan chan struct } // loadConfig loads configuration with proper precedence: -func loadConfig() *models.Config { +func loadConfig() (*models.Config, bool) { configPath := env.GetEnv(env.EnvConfigPath, "config.toml") config, exists, err := configloader.Load(configPath) if err != nil { panic(err) } - if !exists { - slog.Debug("No config file found, continuing", "path", configPath) - } - return config + return config, exists } diff --git a/cmd/migrate/main.go b/cmd/migrate/main.go index 435569db..d17b037a 100644 --- a/cmd/migrate/main.go +++ b/cmd/migrate/main.go @@ -3,7 +3,6 @@ package main import ( "context" "fmt" - "log/slog" "os" "strings" "time" @@ -46,7 +45,7 @@ func init() { func main() { if err := rootCmd.Execute(); err != nil { - slog.Error("migrate command failed", "error", err) + authula.InitLogger(&models.Config{}).Error("migrate command failed", "error", err) os.Exit(1) } } @@ -129,7 +128,7 @@ func runPlugins(action, only, except string, includeDisabled bool) error { } defer runtime.Close() - selector := buildPluginSelector(runtime.config, only, except, includeDisabled, action == "down") + selector := buildPluginSelector(runtime.config, runtime.logger, only, except, includeDisabled, action == "down") ctx, cancel := context.WithTimeout(context.Background(), time.Duration(timeout)*time.Second) defer cancel() @@ -228,11 +227,11 @@ func bootstrapRuntime(configPath string) (*runtimeEnv, error) { if err != nil { return nil, err } - if !exists { - slog.Debug("No config file found, using defaults", "path", configPath) - } logger := authula.InitLogger(config) + if !exists { + logger.Debug("No config file found, using defaults", "path", configPath) + } db, err := authula.InitDatabase(config, logger, config.Logger.Level) if err != nil { return nil, fmt.Errorf("init database: %w", err) @@ -255,14 +254,14 @@ func bootstrapRuntime(configPath string) (*runtimeEnv, error) { }, nil } -func buildPluginSelector(config *models.Config, only, except string, includeDisabled bool, isDown bool) migrationmanager.PluginSelector { +func buildPluginSelector(config *models.Config, logger models.Logger, only, except string, includeDisabled bool, isDown bool) migrationmanager.PluginSelector { selectors := make([]migrationmanager.PluginSelector, 0, 3) if !includeDisabled && !isDown { selectors = append(selectors, func(plugin models.Plugin) bool { enabled := util.IsPluginEnabled(config, plugin.Metadata().ID) if !enabled { - slog.Debug("plugin disabled, skipping", "plugin", plugin.Metadata().ID) + logger.Debug("plugin disabled, skipping", "plugin", plugin.Metadata().ID) } return enabled }) diff --git a/go.mod b/go.mod index d0c7ab04..3b173279 100644 --- a/go.mod +++ b/go.mod @@ -37,16 +37,22 @@ require ( github.com/uptrace/bun/dialect/sqlitedialect v1.2.18 github.com/uptrace/bun/extra/bundebug v1.2.18 github.com/wneessen/go-mail v0.8.1 + go.opentelemetry.io/contrib/bridges/otelslog v0.21.0 go.opentelemetry.io/contrib/instrumentation/runtime v0.72.0 go.opentelemetry.io/otel v1.47.0 + go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploggrpc v0.23.0 + go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploghttp v0.23.0 go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetricgrpc v1.47.0 go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetrichttp v1.47.0 go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc v1.47.0 go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp v1.47.0 + go.opentelemetry.io/otel/exporters/stdout/stdoutlog v0.23.0 go.opentelemetry.io/otel/exporters/stdout/stdoutmetric v1.47.0 go.opentelemetry.io/otel/exporters/stdout/stdouttrace v1.47.0 + go.opentelemetry.io/otel/log v1.47.0 go.opentelemetry.io/otel/metric v1.47.0 go.opentelemetry.io/otel/sdk v1.47.0 + go.opentelemetry.io/otel/sdk/log v1.47.0 go.opentelemetry.io/otel/sdk/metric v1.47.0 go.opentelemetry.io/otel/trace v1.47.0 golang.org/x/crypto v0.57.0 @@ -162,7 +168,6 @@ require ( go.opentelemetry.io/auto/sdk v1.2.1 // indirect go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.70.0 // indirect go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.47.0 // indirect - go.opentelemetry.io/otel/log v1.47.0 // indirect go.opentelemetry.io/proto/otlp v1.11.0 // indirect go.uber.org/atomic v1.11.0 // indirect go.yaml.in/yaml/v3 v3.0.5 // indirect diff --git a/go.sum b/go.sum index cf1412cd..f91251b9 100644 --- a/go.sum +++ b/go.sum @@ -372,12 +372,18 @@ github.com/zeebo/xxh3 v1.1.0 h1:s7DLGDK45Dyfg7++yxI0khrfwq9661w9EN78eP/UZVs= github.com/zeebo/xxh3 v1.1.0/go.mod h1:IisAie1LELR4xhVinxWS5+zf1lA4p0MW4T+w+W07F5s= go.opentelemetry.io/auto/sdk v1.2.1 h1:jXsnJ4Lmnqd11kwkBV2LgLoFMZKizbCi5fNZ/ipaZ64= go.opentelemetry.io/auto/sdk v1.2.1/go.mod h1:KRTj+aOaElaLi+wW1kO/DZRXwkF4C5xPbEe3ZiIhN7Y= +go.opentelemetry.io/contrib/bridges/otelslog v0.21.0 h1:/CdgE52i1OEPHhsGUqrggYNRaZy4v4YgVenGd52dRBI= +go.opentelemetry.io/contrib/bridges/otelslog v0.21.0/go.mod h1:9pBdbVbuehIDzxN4accnzzxEUPT8Nq7grbZMo+J1VN4= go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.70.0 h1:LMuyCAyfalSjDyjdC65nK6N0zoTT63+E/u95X0JovZI= go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.70.0/go.mod h1:085m8qbm4hgc8rZWGDEa4vmyyo2c3nPxUslYUKUIU04= go.opentelemetry.io/contrib/instrumentation/runtime v0.72.0 h1:rv8t3kKjyC2/9D99L1MZt4tJSZO4aYUmHus7L//iKKg= go.opentelemetry.io/contrib/instrumentation/runtime v0.72.0/go.mod h1:ZzG+JmzLLvKzx6tMeLrw2l7F8ik2GeRZJALoPBqnM0c= go.opentelemetry.io/otel v1.47.0 h1:j7ALJ/zgkS7Z6aeJW09p8VC9804bC+PpeTfCD4XPnOM= go.opentelemetry.io/otel v1.47.0/go.mod h1:8wS9O2qfXrYrzp6hIF/HOYJJf/wIhFPhR2xLuP+iXQU= +go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploggrpc v0.23.0 h1:5Ek4qQ5XX0PSQfY7lMW3CvcR36yy8YFDfGnYnaku8zE= +go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploggrpc v0.23.0/go.mod h1:NUKIMOKSexQdTmS1pSxOQBDiVes3DHRier2ePsGW/gQ= +go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploghttp v0.23.0 h1:5WVp40k2fJHuc5BtNTgKk+EugKFT8Eg3lywFfCPI/nE= +go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploghttp v0.23.0/go.mod h1:59nH0RYCGHRlwt15WyioeSYINBbuObeBpTowPhEKWHY= go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetricgrpc v1.47.0 h1:LaLVGJtIzHcvHjVs2OftmKcc+M9mdOqS8vZ1fBD1Yes= go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetricgrpc v1.47.0/go.mod h1:vF6H5sNDuQBJWgSX00iZgbIqk2MZZoVMH0ar5t5bOpw= go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetrichttp v1.47.0 h1:7kszRN4Ze5GeAkUnBjBSUIunVBMA+mZIG04auueqguM= @@ -388,6 +394,8 @@ go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc v1.47.0 h1:UFpxO go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc v1.47.0/go.mod h1:YBGjxe3lt0jtXoEXxGrGhv/jM7oUBUDVK7zhAvNyEjc= go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp v1.47.0 h1:aXZXsZ012wOgVkqaiQv+Z/d8V0xKjmg70F6m4CE94lc= go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp v1.47.0/go.mod h1:ziu1gUIJhAaxM3EV1e3Ralk5AAyL1UOYz3lJJ4VSI38= +go.opentelemetry.io/otel/exporters/stdout/stdoutlog v0.23.0 h1:PW/E9Tw6ZykC88pey0MZY8hKOUeEw+hX6PU+oXA4A9o= +go.opentelemetry.io/otel/exporters/stdout/stdoutlog v0.23.0/go.mod h1:hUw4VNfiOnQ/yzGgy6ZdWVnudXw7iRfImhd6FjXOnvI= go.opentelemetry.io/otel/exporters/stdout/stdoutmetric v1.47.0 h1:ww5DYBpMKcqLdxjWrhGUIh6O+ZfvZUaMk4niVyNQPEQ= go.opentelemetry.io/otel/exporters/stdout/stdoutmetric v1.47.0/go.mod h1:Av5t+Ezx5S/Ks2dsEfWhny+GK+wrZ1K7NZ6aHSWnX3U= go.opentelemetry.io/otel/exporters/stdout/stdouttrace v1.47.0 h1:N3YQCxjxQ/bMjyc3heladfRm9t9RTksGQH8z4w6yU/0= @@ -400,6 +408,10 @@ go.opentelemetry.io/otel/metric/x v0.69.0 h1:DjRLr15H83v+hCW7JA9NoJvOkYTtmq5YoDR go.opentelemetry.io/otel/metric/x v0.69.0/go.mod h1:uVvsMPMFFyj/HUQfrUnH3JjnOQ1dwFDorgFLRBasM0k= go.opentelemetry.io/otel/sdk v1.47.0 h1:zWXEr4j2lFefG87TU6Yg8a7ngfohIKFZHKp0Hf5hC6I= go.opentelemetry.io/otel/sdk v1.47.0/go.mod h1:VUc24kiOeoGsxG8G9ULx3fWKvB7jMhnGE8Oi607lgR0= +go.opentelemetry.io/otel/sdk/log v1.47.0 h1:W4N/ZfgpkRRnmARnqYoQ6BrWA0mrj8IzVDNLlpmUJZY= +go.opentelemetry.io/otel/sdk/log v1.47.0/go.mod h1:Wu74Z2EmOKXi2FleSNAb0Hyau2G+r5kubSEMJw5aAMs= +go.opentelemetry.io/otel/sdk/log/logtest v0.23.0 h1:j3pm42QCrKYYLLkI6OrV1QHFkUfDA6/4EP+Y1PzggLg= +go.opentelemetry.io/otel/sdk/log/logtest v0.23.0/go.mod h1:zt0gEnuTZgDvqvczHwYswz93eqMaIr6upTTsdV/HUlU= go.opentelemetry.io/otel/sdk/metric v1.47.0 h1:lfISg2j93VT6yqdk9OfUaZmw/GfcZqCCV3jdXtsPnKw= go.opentelemetry.io/otel/sdk/metric v1.47.0/go.mod h1:ypLp+mW1Nt2x+Szt3b5/i1syodyts49lMOwxpDI3VGw= go.opentelemetry.io/otel/trace v1.47.0 h1:JOjX/Oci8K94QHddo+bbfya/Ai/nf6/dt9ZfrFNWSrM= diff --git a/internal/bootstrap/fanout.go b/internal/bootstrap/fanout.go new file mode 100644 index 00000000..823b8c3e --- /dev/null +++ b/internal/bootstrap/fanout.go @@ -0,0 +1,162 @@ +package bootstrap + +import ( + "sync" + + "github.com/Authula/authula/models" +) + +// logLevel identifies one of the four severity methods exposed by +// models.Logger. It exists so the fan-out never has to depend on slog. +type logLevel int + +const ( + levelDebug logLevel = iota + levelInfo + levelWarn + levelError +) + +// emit calls the matching method on the supplied logger. +func (l logLevel) emit(logger models.Logger, msg string, args ...any) { + switch l { + case levelDebug: + logger.Debug(msg, args...) + case levelInfo: + logger.Info(msg, args...) + case levelWarn: + logger.Warn(msg, args...) + case levelError: + logger.Error(msg, args...) + } +} + +// fanoutLogger forwards every log call to a base logger plus any sinks attached +// at runtime. Sinks let plugins (for example the OTel log bridge) receive the +// same records without core knowing about them. +type fanoutLogger struct { + mu sync.RWMutex + base models.Logger + sinks []*logSink +} + +type logSink struct { + logger models.Logger +} + +func newFanoutLogger(base models.Logger) *fanoutLogger { + return &fanoutLogger{base: base} +} + +// AddLogger attaches sink and returns an idempotent detach function. A nil sink +// is ignored and detach becomes a no-op. +func (f *fanoutLogger) AddLogger(sink models.Logger) (detach func()) { + if sink == nil { + return func() {} + } + + attached := &logSink{logger: sink} + + f.mu.Lock() + f.sinks = append(f.sinks, attached) + f.mu.Unlock() + + var once sync.Once + return func() { + once.Do(func() { + f.mu.Lock() + defer f.mu.Unlock() + + for i, candidate := range f.sinks { + if candidate == attached { + f.sinks = append(f.sinks[:i], f.sinks[i+1:]...) + return + } + } + }) + } +} + +func (f *fanoutLogger) Debug(msg string, args ...any) { + f.dispatch(levelDebug, msg, args...) +} + +func (f *fanoutLogger) Info(msg string, args ...any) { + f.dispatch(levelInfo, msg, args...) +} + +func (f *fanoutLogger) Warn(msg string, args ...any) { + f.dispatch(levelWarn, msg, args...) +} + +func (f *fanoutLogger) Error(msg string, args ...any) { + f.dispatch(levelError, msg, args...) +} + +// dispatch snapshots the sinks under a read lock, then calls the base followed +// by every sink. Holding no lock while calling out keeps a slow or blocking +// logger from stalling attach/detach. +func (f *fanoutLogger) dispatch(level logLevel, msg string, args ...any) { + sinks := f.snapshot() + + safeEmit(f.base, level, msg, args...) + + for _, sink := range sinks { + if !safeEmit(sink.logger, level, msg, args...) { + f.reportSinkFailure(level, msg) + } + } +} + +func (f *fanoutLogger) snapshot() []*logSink { + f.mu.RLock() + defer f.mu.RUnlock() + + sinks := make([]*logSink, len(f.sinks)) + copy(sinks, f.sinks) + return sinks +} + +// reportSinkFailure tells the base logger that a sink panicked. It is +// best-effort: the report itself is guarded so a broken base cannot panic the +// caller either. +func (f *fanoutLogger) reportSinkFailure(level logLevel, msg string) { + if f.base == nil { + return + } + safeEmit(f.base, levelError, "logger sink panicked", "level", level.String(), "message", msg) +} + +// safeEmit calls logger and reports whether it returned normally. A panicking +// logger can never take down the request that was being logged. +func safeEmit(logger models.Logger, level logLevel, msg string, args ...any) (ok bool) { + if logger == nil { + return true + } + + ok = true + defer func() { + if recover() != nil { + ok = false + } + }() + + level.emit(logger, msg, args...) + return ok +} + +// String returns the human-readable name of the level. +func (l logLevel) String() string { + switch l { + case levelDebug: + return "debug" + case levelInfo: + return "info" + case levelWarn: + return "warn" + case levelError: + return "error" + default: + return "unknown" + } +} diff --git a/internal/bootstrap/fanout_test.go b/internal/bootstrap/fanout_test.go new file mode 100644 index 00000000..47da28c6 --- /dev/null +++ b/internal/bootstrap/fanout_test.go @@ -0,0 +1,165 @@ +package bootstrap + +import ( + "sync" + "testing" + + internaltests "github.com/Authula/authula/internal/tests" +) + +func TestFanoutLoggerForwardsToBaseAndSinks(t *testing.T) { + t.Parallel() + + tests := []struct { + name string + level string + emit func(*fanoutLogger, string, ...any) + }{ + {name: "debug", level: "debug", emit: func(f *fanoutLogger, msg string, args ...any) { f.Debug(msg, args...) }}, + {name: "info", level: "info", emit: func(f *fanoutLogger, msg string, args ...any) { f.Info(msg, args...) }}, + {name: "warn", level: "warn", emit: func(f *fanoutLogger, msg string, args ...any) { f.Warn(msg, args...) }}, + {name: "error", level: "error", emit: func(f *fanoutLogger, msg string, args ...any) { f.Error(msg, args...) }}, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + + base := new(internaltests.LevelRecordingLogger) + sink := new(internaltests.LevelRecordingLogger) + fanout := newFanoutLogger(base) + fanout.AddLogger(sink) + + tc.emit(fanout, "hello", "key", "value") + + for name, logger := range map[string]*internaltests.LevelRecordingLogger{ + "base": base, + "sink": sink, + } { + records := logger.Records() + if len(records) != 1 { + t.Fatalf("%s received %d records, want 1", name, len(records)) + } + if records[0].Level != tc.level { + t.Fatalf("%s level = %q, want %q", name, records[0].Level, tc.level) + } + if records[0].Message != "hello" { + t.Fatalf("%s message = %q, want %q", name, records[0].Message, "hello") + } + } + }) + } +} + +func TestFanoutLoggerAddsSinkAfterConstruction(t *testing.T) { + t.Parallel() + + base := new(internaltests.LevelRecordingLogger) + sink := new(internaltests.LevelRecordingLogger) + fanout := newFanoutLogger(base) + + fanout.Info("before") + fanout.AddLogger(sink) + fanout.Info("after") + + if got := sink.Messages(); len(got) != 1 || got[0] != "after" { + t.Fatalf("sink messages = %v, want [after]", got) + } + if got := base.Messages(); len(got) != 2 { + t.Fatalf("base received %d messages, want 2", len(got)) + } +} + +func TestFanoutLoggerDetachStopsDeliveryAndIsIdempotent(t *testing.T) { + t.Parallel() + + base := new(internaltests.LevelRecordingLogger) + sink := new(internaltests.LevelRecordingLogger) + fanout := newFanoutLogger(base) + + detach := fanout.AddLogger(sink) + fanout.Info("first") + detach() + detach() + fanout.Info("second") + + if got := sink.Messages(); len(got) != 1 || got[0] != "first" { + t.Fatalf("sink messages = %v, want [first]", got) + } + if len(fanout.snapshot()) != 0 { + t.Fatalf("sinks remaining = %d, want 0", len(fanout.snapshot())) + } +} + +func TestFanoutLoggerIgnoresNilSink(t *testing.T) { + t.Parallel() + + base := new(internaltests.LevelRecordingLogger) + fanout := newFanoutLogger(base) + + detach := fanout.AddLogger(nil) + detach() + detach() + fanout.Info("hello") + + if len(fanout.snapshot()) != 0 { + t.Fatalf("sinks remaining = %d, want 0", len(fanout.snapshot())) + } + if got := base.Messages(); len(got) != 1 { + t.Fatalf("base received %d messages, want 1", len(got)) + } +} + +func TestFanoutLoggerRecoversPanickingSink(t *testing.T) { + t.Parallel() + + base := new(internaltests.LevelRecordingLogger) + healthy := new(internaltests.LevelRecordingLogger) + fanout := newFanoutLogger(base) + + fanout.AddLogger(new(internaltests.PanicLogger)) + fanout.AddLogger(healthy) + + fanout.Info("still delivered") + + if got := healthy.Messages(); len(got) != 1 || got[0] != "still delivered" { + t.Fatalf("healthy sink messages = %v, want [still delivered]", got) + } + + records := base.Records() + if len(records) != 2 { + t.Fatalf("base received %d records, want 2 (original + panic report)", len(records)) + } + if records[1].Level != "error" || records[1].Message != "logger sink panicked" { + t.Fatalf("panic report = %+v, want error record", records[1]) + } +} + +func TestFanoutLoggerConcurrentAttachAndLog(t *testing.T) { + t.Parallel() + + fanout := newFanoutLogger(new(internaltests.LevelRecordingLogger)) + + var wg sync.WaitGroup + for range 8 { + wg.Add(2) + go func() { + defer wg.Done() + for range 100 { + fanout.Info("message") + } + }() + go func() { + defer wg.Done() + sink := new(internaltests.LevelRecordingLogger) + detach := fanout.AddLogger(sink) + fanout.Info("message") + detach() + }() + } + wg.Wait() + + if got := len(fanout.snapshot()); got != 0 { + t.Fatalf("sinks remaining = %d, want 0", got) + } +} diff --git a/internal/bootstrap/logger.go b/internal/bootstrap/logger.go index d5ab2934..032c2b79 100644 --- a/internal/bootstrap/logger.go +++ b/internal/bootstrap/logger.go @@ -16,39 +16,52 @@ type LoggerOptions struct { Logger models.Logger } -// InitLogger creates a configured logger instance +// InitLogger creates a configured logger instance. It always returns a +// fan-out: a user-supplied logger is wrapped rather than replaced, so plugins +// can attach sinks in either case. func InitLogger(opts LoggerOptions) models.Logger { - if opts.Logger != nil { - return opts.Logger + base := opts.Logger + var slogBase *slog.Logger + + if base == nil { + level := parseSlogLevel(opts.Level) + + if os.Getenv(env.EnvGoEnvironment) != "production" { + slogBase = slog.New(tint.NewTextHandler(os.Stderr, &tint.Options{ + Level: slog.LevelDebug, + TimeFormat: time.Kitchen, + })) + } else { + slogBase = slog.New(slog.NewJSONHandler(os.Stderr, &slog.HandlerOptions{ + Level: level, + })) + } + base = slogBase } - environment := os.Getenv(env.EnvGoEnvironment) - var logger *slog.Logger + fanout := newFanoutLogger(base) + if slogBase != nil { + // Compatibility only: third-party libraries calling slog.* directly reach + // stderr, but bypass the fan-out and therefore any attached sinks. + slog.SetDefault(slogBase) + } + + return fanout +} - level := slog.LevelInfo - switch opts.Level { +// parseSlogLevel maps a configured level name to a slog level. Unknown or empty +// values fall back to info. +func parseSlogLevel(name string) slog.Level { + switch name { case "debug": - level = slog.LevelDebug + return slog.LevelDebug case "info": - level = slog.LevelInfo + return slog.LevelInfo case "warn": - level = slog.LevelWarn + return slog.LevelWarn case "error": - level = slog.LevelError + return slog.LevelError + default: + return slog.LevelInfo } - - if environment != "production" { - logger = slog.New(tint.NewTextHandler(os.Stderr, &tint.Options{ - Level: slog.LevelDebug, - TimeFormat: time.Kitchen, - })) - } else { - logger = slog.New(slog.NewJSONHandler(os.Stderr, &slog.HandlerOptions{ - Level: level, - })) - } - - slog.SetDefault(logger) - - return logger } diff --git a/internal/bootstrap/logger_test.go b/internal/bootstrap/logger_test.go index 2ff804a1..836268ea 100644 --- a/internal/bootstrap/logger_test.go +++ b/internal/bootstrap/logger_test.go @@ -1,18 +1,88 @@ package bootstrap -import "testing" +import ( + "log/slog" + "testing" -type customLogger struct{} + internaltests "github.com/Authula/authula/internal/tests" + "github.com/Authula/authula/models" +) -func (l *customLogger) Debug(msg string, args ...any) {} -func (l *customLogger) Info(msg string, args ...any) {} -func (l *customLogger) Warn(msg string, args ...any) {} -func (l *customLogger) Error(msg string, args ...any) {} +func TestInitLoggerWrapsConfiguredLogger(t *testing.T) { + // This test inspects the process-global slog default, so it must not run in + // parallel with other tests that mutate it. + original := slog.Default() + t.Cleanup(func() { slog.SetDefault(original) }) -func TestInitLoggerUsesConfiguredLogger(t *testing.T) { - logger := &customLogger{} + base := new(internaltests.LevelRecordingLogger) + sink := new(internaltests.LevelRecordingLogger) - if got := InitLogger(LoggerOptions{Level: "debug", Logger: logger}); got != logger { - t.Fatal("expected configured logger to be used") + logger := InitLogger(LoggerOptions{Level: "debug", Logger: base}) + if logger == base { + t.Fatal("expected InitLogger to return a fan-out wrapper, not the supplied logger") + } + if slog.Default() != original { + t.Fatal("InitLogger must not call slog.SetDefault for a custom logger") + } + + fanout, ok := logger.(models.LoggerFanout) + if !ok { + t.Fatalf("InitLogger returned %T, want models.LoggerFanout", logger) + } + + fanout.AddLogger(sink) + logger.Info("hello", "key", "value") + + if got := base.Messages(); len(got) != 1 || got[0] != "hello" { + t.Fatalf("base messages = %v, want [hello]", got) + } + if got := sink.Messages(); len(got) != 1 || got[0] != "hello" { + t.Fatalf("sink messages = %v, want [hello]", got) + } +} + +func TestInitLoggerDefaultReturnsFanout(t *testing.T) { + original := slog.Default() + t.Cleanup(func() { slog.SetDefault(original) }) + + logger := InitLogger(LoggerOptions{Level: "debug"}) + + fanout, ok := logger.(models.LoggerFanout) + if !ok { + t.Fatalf("InitLogger returned %T, want models.LoggerFanout", logger) + } + + sink := new(internaltests.LevelRecordingLogger) + fanout.AddLogger(sink) + logger.Debug("to sink") + + if got := sink.Messages(); len(got) != 1 || got[0] != "to sink" { + t.Fatalf("sink messages = %v, want [to sink]", got) + } +} + +func TestParseSlogLevel(t *testing.T) { + t.Parallel() + + tests := []struct { + name string + want slog.Level + }{ + {name: "debug", want: slog.LevelDebug}, + {name: "info", want: slog.LevelInfo}, + {name: "warn", want: slog.LevelWarn}, + {name: "error", want: slog.LevelError}, + {name: "", want: slog.LevelInfo}, + {name: "trace", want: slog.LevelInfo}, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + + if got := parseSlogLevel(tc.name); got != tc.want { + t.Fatalf("parseSlogLevel(%q) = %v, want %v", tc.name, got, tc.want) + } + }) } } diff --git a/internal/tests/mock_objects.go b/internal/tests/mock_objects.go index 450a62d6..a26ba2b9 100644 --- a/internal/tests/mock_objects.go +++ b/internal/tests/mock_objects.go @@ -2,6 +2,7 @@ package tests import ( "context" + "sync" "github.com/stretchr/testify/mock" @@ -28,6 +29,61 @@ func (l *RecordingLogger) Error(msg string, args ...any) { l.ErrorCalls = append(l.ErrorCalls, msg) } +// LogRecord is one captured call made to a LevelRecordingLogger. +type LogRecord struct { + Level string + Message string + Args []any +} + +// LevelRecordingLogger records every call with its severity. It is safe for +// concurrent use, which makes it suitable for fan-out tests. +type LevelRecordingLogger struct { + mu sync.Mutex + records []LogRecord +} + +func (l *LevelRecordingLogger) Debug(msg string, args ...any) { l.record("debug", msg, args) } +func (l *LevelRecordingLogger) Info(msg string, args ...any) { l.record("info", msg, args) } +func (l *LevelRecordingLogger) Warn(msg string, args ...any) { l.record("warn", msg, args) } +func (l *LevelRecordingLogger) Error(msg string, args ...any) { l.record("error", msg, args) } + +func (l *LevelRecordingLogger) record(level, msg string, args []any) { + l.mu.Lock() + defer l.mu.Unlock() + + l.records = append(l.records, LogRecord{Level: level, Message: msg, Args: args}) +} + +// Records returns a copy of every captured call, in order. +func (l *LevelRecordingLogger) Records() []LogRecord { + l.mu.Lock() + defer l.mu.Unlock() + + records := make([]LogRecord, len(l.records)) + copy(records, l.records) + return records +} + +// Messages returns the message of every captured call, in order. +func (l *LevelRecordingLogger) Messages() []string { + records := l.Records() + messages := make([]string, len(records)) + for i, record := range records { + messages[i] = record.Message + } + return messages +} + +// PanicLogger panics on every call. It is used to prove that a broken sink +// cannot propagate into the caller. +type PanicLogger struct{} + +func (l *PanicLogger) Debug(msg string, args ...any) { panic("panic logger: debug") } +func (l *PanicLogger) Info(msg string, args ...any) { panic("panic logger: info") } +func (l *PanicLogger) Warn(msg string, args ...any) { panic("panic logger: warn") } +func (l *PanicLogger) Error(msg string, args ...any) { panic("panic logger: error") } + type MockEventBus struct { mock.Mock } diff --git a/models/logger.go b/models/logger.go index 69ee0929..a1d7d0eb 100644 --- a/models/logger.go +++ b/models/logger.go @@ -1,7 +1,7 @@ package models -// Logger defines an interface for logging operations, allowing users to plug in -// different logging implementations such as slog, zerolog, or others. +// Logger is the only logging contract used by core and plugins. Implementations +// are interchangeable; slog is merely the default one. type Logger interface { // Debug logs a message at debug level with optional key-value pairs. Debug(msg string, args ...any) @@ -12,3 +12,19 @@ type Logger interface { // Error logs a message at error level with optional key-value pairs. Error(msg string, args ...any) } + +// LoggerFanout is an optional capability of a Logger that allows plugins to +// attach additional destinations. Detect it with a type assertion: +// +// if fanout, ok := logger.(models.LoggerFanout); ok { +// detach := fanout.AddLogger(sink) +// defer detach() +// } +// +// InitLogger always returns a fan-out, including around a user-supplied Logger, +// so plugins can rely on the capability in normal operation. +type LoggerFanout interface { + // AddLogger attaches sink and returns a function that detaches it. The + // detach function is safe to call more than once. Nil sinks are ignored. + AddLogger(sink Logger) (detach func()) +} diff --git a/plugins/otel/README.md b/plugins/otel/README.md index 456c5d56..8687f004 100644 --- a/plugins/otel/README.md +++ b/plugins/otel/README.md @@ -1,8 +1,8 @@ # OpenTelemetry plugin -Opt-in distributed tracing and metrics for Authula, backed by the OpenTelemetry -SDK. The plugin extracts and propagates W3C trace context and records request -and runtime metrics. +Opt-in distributed tracing, metrics, and logs for Authula, backed by the +OpenTelemetry SDK. The plugin extracts and propagates W3C trace context, records +request and runtime metrics, and can bridge the core logger to OTLP. Telemetry is **fail-open**: the hooks never return an error, so a telemetry problem can never short-circuit a real request. Invalid configuration or a @@ -22,6 +22,7 @@ service_name = "authula-service" exporter = "otlp" endpoint = "http://localhost:4318" insecure = true +logs_enabled = true ``` ## Configuration reference @@ -37,6 +38,7 @@ insecure = true | `headers` | map | empty | Extra OTLP headers. Empty lets `OTEL_EXPORTER_OTLP_HEADERS` apply. | | `traces_enabled` | bool | `true` | Enable tracing. | | `metrics_enabled` | bool | `true` | Enable request/runtime metrics. | +| `logs_enabled` | bool | `false` | Export Authula's `models.Logger` records over OTLP. | | `runtime_metrics` | bool | `true` | Enable Go runtime metrics. | | `sample_ratio` | float | unset | Trace sample ratio in `[0,1]`. Omit to let the SDK read `OTEL_TRACES_SAMPLER`. | | `trust_proxy` | bool | `false` | Trust `X-Forwarded-Proto` / `X-Forwarded-For`. | @@ -47,7 +49,8 @@ One rule covers every setting: **config field > standard OpenTelemetry environment variable > SDK default**. - `service_name`: config → `OTEL_SERVICE_NAME` → `authula`. -- `endpoint` empty: the exporter reads `OTEL_EXPORTER_OTLP_ENDPOINT`. +- `endpoint` empty: the exporter reads `OTEL_EXPORTER_OTLP_ENDPOINT`. For logs, + a non-empty `endpoint` overrides `OTEL_EXPORTER_OTLP_LOGS_ENDPOINT`. - `protocol` empty: `OTEL_EXPORTER_OTLP_PROTOCOL`, otherwise `http`. - `headers` empty: `OTEL_EXPORTER_OTLP_HEADERS` applies. - `sample_ratio` unset: `OTEL_TRACES_SAMPLER` applies. When set, the plugin uses @@ -92,6 +95,45 @@ responses. OPTIONS preflight requests are not recorded. `runtime_metrics = true` additionally starts the OpenTelemetry runtime instrumentation (Go runtime metrics) on the same meter provider. +### Logs + +Logs are opt-in: set `logs_enabled = true`. When enabled, the plugin attaches an +OTLP sink to the core logger fan-out, so every call made through +`models.Logger` (the only logging contract used by core and plugins) is also +exported. A batch processor ships records in the background; `Close` detaches +the sink first, then flushes and shuts the provider down. + +The sink honors the core `logger.level` setting. `config.toml` ships +`level = "debug"`, so by default debug records are exported too. Set +`logger.level = "info"` in production to keep debug noise out of the collector. + +Records are exported to **both** their normal destination (stderr/JSON) and +OTLP. This duplication is intended. Exporter settings (`exporter`, `protocol`, +`endpoint`, `insecure`, `headers`) are shared with traces and metrics. + +#### Custom loggers still work + +`models.Logger` remains a four-method interface and `InitLogger` now always +returns a fan-out around the chosen implementation. Supplying a logger through +`LoggerConfig.Logger` therefore no longer disables log export: the plugin +attaches its sink to the wrapper, and every call is forwarded to the supplied +logger unchanged. A logger that does not implement `models.LoggerFanout` +(only the wrapper does) simply gets no OTLP sink, with one warning. + +Two caveats: + +- `InitLogger` returns a wrapper, not the exact instance you supplied. It + forwards every call, but `logger == yourLogger` comparisons no longer hold. +- `slog.SetDefault` is called only for the default slog-backed logger, as a + compatibility bridge for third-party libraries. Direct `slog.*` calls reach + stderr but bypass the fan-out and therefore do not reach OTLP. + +#### No trace correlation yet + +`models.Logger` has no `context.Context`, so exported records do not carry a +`trace_id` / `span_id`. Correlating logs with spans needs a context-aware logger +and is a separate follow-up. + ## Bypass paths Requests that bypass the normal lifecycle are traced too: OPTIONS preflight, @@ -119,7 +161,7 @@ intentionally no global-registration option. ## Dependencies -Adding the plugin links the OpenTelemetry SDK, exporters, and runtime -instrumentation into the binary even when the plugin is disabled (the factory -imports it unconditionally). It is "lightweight when disabled" at runtime, not -in binary size. +Adding the plugin links the OpenTelemetry SDK, exporters, runtime +instrumentation, and the `otelslog` bridge into the binary even when the plugin +is disabled (the factory imports it unconditionally). It is "lightweight when +disabled" at runtime, not in binary size. diff --git a/plugins/otel/export_test.go b/plugins/otel/export_test.go new file mode 100644 index 00000000..476cfe2e --- /dev/null +++ b/plugins/otel/export_test.go @@ -0,0 +1,19 @@ +package otel + +import ( + sdklog "go.opentelemetry.io/otel/sdk/log" + + "github.com/Authula/authula/models" +) + +// AttachLogsForTest wires the log sink with an in-memory exporter, bypassing +// exporter construction so tests never touch the network. +func AttachLogsForTest(p *OTelPlugin, logger models.Logger, exp sdklog.Exporter) { + p.logger = logger + p.initLoggerWithExporter(nil, exp) +} + +// LogProviderForTest reports the provider created by the log wiring. +func LogProviderForTest(p *OTelPlugin) *sdklog.LoggerProvider { + return p.loggerProvider +} diff --git a/plugins/otel/exporter.go b/plugins/otel/exporter.go index 95eaa726..3395850e 100644 --- a/plugins/otel/exporter.go +++ b/plugins/otel/exporter.go @@ -6,12 +6,16 @@ import ( "os" "strings" + "go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploggrpc" + "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/otlptracegrpc" "go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp" + "go.opentelemetry.io/otel/exporters/stdout/stdoutlog" "go.opentelemetry.io/otel/exporters/stdout/stdoutmetric" "go.opentelemetry.io/otel/exporters/stdout/stdouttrace" + sdklog "go.opentelemetry.io/otel/sdk/log" sdkmetric "go.opentelemetry.io/otel/sdk/metric" "go.opentelemetry.io/otel/sdk/resource" sdktrace "go.opentelemetry.io/otel/sdk/trace" @@ -56,6 +60,37 @@ func buildMetricExporter(ctx context.Context, cfg types.OTelPluginConfig) (sdkme } } +// buildLogExporter constructs the configured log exporter. It returns a nil +// exporter when exporting is disabled ("none"). +func buildLogExporter(ctx context.Context, cfg types.OTelPluginConfig) (sdklog.Exporter, error) { + switch cfg.Exporter { + case types.ExporterNone: + return nil, nil + case types.ExporterStdout: + return stdoutlog.New() + case types.ExporterOTLP: + if resolveProtocol(cfg) == types.ProtocolGRPC { + return otlploggrpc.New(ctx, logGRPCOptions(cfg)...) + } + return otlploghttp.New(ctx, logHTTPOptions(cfg)...) + default: + return nil, fmt.Errorf("otel: unsupported log exporter %q", cfg.Exporter) + } +} + +// newLoggerProvider builds a LoggerProvider that batches records to the +// supplied exporter. +func newLoggerProvider(res *resource.Resource, exp sdklog.Exporter) *sdklog.LoggerProvider { + opts := make([]sdklog.LoggerProviderOption, 0, 2) + if res != nil { + opts = append(opts, sdklog.WithResource(res)) + } + if exp != nil { + opts = append(opts, sdklog.WithProcessor(sdklog.NewBatchProcessor(exp))) + } + return sdklog.NewLoggerProvider(opts...) +} + // newTracerProvider builds a TracerProvider that batches spans to the supplied // exporter and only overrides the sampler when a sample ratio is configured. // Exported so tests can inject their own exporter. @@ -163,3 +198,31 @@ func metricGRPCOptions(cfg types.OTelPluginConfig) []otlpmetricgrpc.Option { } return opts } + +func logHTTPOptions(cfg types.OTelPluginConfig) []otlploghttp.Option { + opts := make([]otlploghttp.Option, 0, 3) + if cfg.Endpoint != "" { + opts = append(opts, otlploghttp.WithEndpoint(cfg.Endpoint)) + } + if cfg.Insecure { + opts = append(opts, otlploghttp.WithInsecure()) + } + if len(cfg.Headers) > 0 { + opts = append(opts, otlploghttp.WithHeaders(cfg.Headers)) + } + return opts +} + +func logGRPCOptions(cfg types.OTelPluginConfig) []otlploggrpc.Option { + opts := make([]otlploggrpc.Option, 0, 3) + if cfg.Endpoint != "" { + opts = append(opts, otlploggrpc.WithEndpoint(cfg.Endpoint)) + } + if cfg.Insecure { + opts = append(opts, otlploggrpc.WithInsecure()) + } + if len(cfg.Headers) > 0 { + opts = append(opts, otlploggrpc.WithHeaders(cfg.Headers)) + } + return opts +} diff --git a/plugins/otel/logbridge.go b/plugins/otel/logbridge.go new file mode 100644 index 00000000..aea12a02 --- /dev/null +++ b/plugins/otel/logbridge.go @@ -0,0 +1,76 @@ +package otel + +import ( + "context" + "log/slog" + + "go.opentelemetry.io/contrib/bridges/otelslog" + sdklog "go.opentelemetry.io/otel/sdk/log" + + "github.com/Authula/authula/models" +) + +// bridgeLogger adapts models.Logger to a slog-backed otelslog handler. It is +// the only place in the plugin where slog types are used. +type bridgeLogger struct { + logger *slog.Logger +} + +// newBridgeLogger builds a models.Logger that emits records to the supplied +// provider. The level filter mirrors the core logger level so the sink never +// exports records the base logger would have dropped. +func newBridgeLogger(provider *sdklog.LoggerProvider, version string, min slog.Level) models.Logger { + handler := otelslog.NewHandler(scopeName, + otelslog.WithLoggerProvider(provider), + otelslog.WithVersion(version), + ) + + return &bridgeLogger{logger: slog.New(levelHandler{ + min: min, + inner: handler, + })} +} + +func (b *bridgeLogger) Debug(msg string, args ...any) { b.logger.Debug(msg, args...) } +func (b *bridgeLogger) Info(msg string, args ...any) { b.logger.Info(msg, args...) } +func (b *bridgeLogger) Warn(msg string, args ...any) { b.logger.Warn(msg, args...) } +func (b *bridgeLogger) Error(msg string, args ...any) { b.logger.Error(msg, args...) } + +// levelHandler enforces the core logger level on the OTel sink. +type levelHandler struct { + min slog.Level + inner slog.Handler +} + +func (h levelHandler) Enabled(ctx context.Context, level slog.Level) bool { + return level >= h.min && h.inner.Enabled(ctx, level) +} + +func (h levelHandler) Handle(ctx context.Context, record slog.Record) error { + return h.inner.Handle(ctx, record) +} + +func (h levelHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + return levelHandler{min: h.min, inner: h.inner.WithAttrs(attrs)} +} + +func (h levelHandler) WithGroup(name string) slog.Handler { + return levelHandler{min: h.min, inner: h.inner.WithGroup(name)} +} + +// parseLevel maps a configured level name to a slog level. Unknown or empty +// values fall back to info. +func parseLevel(name string) slog.Level { + switch name { + case "debug": + return slog.LevelDebug + case "info": + return slog.LevelInfo + case "warn": + return slog.LevelWarn + case "error": + return slog.LevelError + default: + return slog.LevelInfo + } +} diff --git a/plugins/otel/logbridge_test.go b/plugins/otel/logbridge_test.go new file mode 100644 index 00000000..6a5e39d9 --- /dev/null +++ b/plugins/otel/logbridge_test.go @@ -0,0 +1,142 @@ +package otel + +import ( + "context" + "log/slog" + "testing" + + "go.opentelemetry.io/otel/attribute" + otellog "go.opentelemetry.io/otel/log" + sdklog "go.opentelemetry.io/otel/sdk/log" + + "github.com/Authula/authula/models" + oteltests "github.com/Authula/authula/plugins/otel/tests" +) + +func newTestBridge(t *testing.T, min slog.Level) (models.Logger, *oteltests.Exporter) { + t.Helper() + + exporter := new(oteltests.Exporter) + provider := sdklog.NewLoggerProvider( + sdklog.WithProcessor(sdklog.NewSimpleProcessor(exporter)), + ) + t.Cleanup(func() { + if err := provider.Shutdown(context.Background()); err != nil { + t.Fatalf("shutdown provider: %v", err) + } + }) + + return newBridgeLogger(provider, "1.2.3", min), exporter +} + +func TestBridgeLoggerEmitsRecord(t *testing.T) { + t.Parallel() + + logger, exporter := newTestBridge(t, slog.LevelDebug) + logger.Info("hello", "key", "value", "count", 3) + + records := exporter.Records() + if len(records) != 1 { + t.Fatalf("exported %d records, want 1", len(records)) + } + + record := records[0] + if got := record.Body().AsString(); got != "hello" { + t.Fatalf("body = %q, want %q", got, "hello") + } + if got := record.Severity(); got != otellog.SeverityInfo { + t.Fatalf("severity = %v, want %v", got, otellog.SeverityInfo) + } + + scope := record.InstrumentationScope() + if scope.Name != scopeName { + t.Fatalf("scope name = %q, want %q", scope.Name, scopeName) + } + if scope.Version != "1.2.3" { + t.Fatalf("scope version = %q, want %q", scope.Version, "1.2.3") + } + + attributes := map[string]string{} + record.WalkAttributes(func(kv attribute.KeyValue) bool { + attributes[string(kv.Key)] = kv.Value.String() + return true + }) + if attributes["key"] != "value" { + t.Fatalf("key attribute = %q, want %q", attributes["key"], "value") + } + if attributes["count"] != "3" { + t.Fatalf("count attribute = %q, want %q", attributes["count"], "3") + } +} + +func TestBridgeLoggerLevelFilter(t *testing.T) { + t.Parallel() + + tests := []struct { + name string + level slog.Level + want bool + }{ + {name: "debug", level: slog.LevelDebug, want: false}, + {name: "info", level: slog.LevelInfo, want: true}, + {name: "warn", level: slog.LevelWarn, want: true}, + {name: "error", level: slog.LevelError, want: true}, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + + exporter := new(oteltests.Exporter) + provider := sdklog.NewLoggerProvider( + sdklog.WithProcessor(sdklog.NewSimpleProcessor(exporter)), + ) + t.Cleanup(func() { + _ = provider.Shutdown(context.Background()) + }) + + logger := newBridgeLogger(provider, "1.0.0", slog.LevelInfo) + switch tc.level { + case slog.LevelDebug: + logger.Debug("message") + case slog.LevelInfo: + logger.Info("message") + case slog.LevelWarn: + logger.Warn("message") + case slog.LevelError: + logger.Error("message") + } + + got := len(exporter.Records()) == 1 + if got != tc.want { + t.Fatalf("exported = %v, want %v", got, tc.want) + } + }) + } +} + +func TestParseLevel(t *testing.T) { + t.Parallel() + + tests := []struct { + name string + want slog.Level + }{ + {name: "debug", want: slog.LevelDebug}, + {name: "info", want: slog.LevelInfo}, + {name: "warn", want: slog.LevelWarn}, + {name: "error", want: slog.LevelError}, + {name: "", want: slog.LevelInfo}, + {name: "trace", want: slog.LevelInfo}, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + + if got := parseLevel(tc.name); got != tc.want { + t.Fatalf("parseLevel(%q) = %v, want %v", tc.name, got, tc.want) + } + }) + } +} diff --git a/plugins/otel/logger.go b/plugins/otel/logger.go new file mode 100644 index 00000000..35c98a94 --- /dev/null +++ b/plugins/otel/logger.go @@ -0,0 +1,59 @@ +package otel + +import ( + "context" + sdklog "go.opentelemetry.io/otel/sdk/log" + "go.opentelemetry.io/otel/sdk/resource" + + "github.com/Authula/authula/models" +) + +// initLogger builds the log exporter/provider and attaches the OTel sink to the +// core logger fan-out. It is a no-op unless logs_enabled is set. +func (p *OTelPlugin) initLogger(res *resource.Resource) error { + if !p.pluginConfig.LogsActive() { + return nil + } + + exp, err := buildLogExporter(context.Background(), p.pluginConfig) + if err != nil { + return err + } + + p.initLoggerWithExporter(res, exp) + + return nil +} + +// initLoggerWithExporter creates the provider and attaches the sink. Exporters +// are injected so tests can supply an in-memory one. +func (p *OTelPlugin) initLoggerWithExporter(res *resource.Resource, exp sdklog.Exporter) { + p.loggerProvider = newLoggerProvider(res, exp) + + fanout, ok := p.logger.(models.LoggerFanout) + if !ok { + p.warn("otel: log bridge not attached (logger does not support fan-out)") + return + } + + p.detachLogSink = fanout.AddLogger(newBridgeLogger( + p.loggerProvider, + p.Metadata().Version, + parseLevel(p.logLevel()), + )) +} + +// logLevel reads logger.level from the core config. It is nil-safe and returns +// an empty string when unavailable, which parseLevel treats as info. +func (p *OTelPlugin) logLevel() string { + if p.pluginCtx == nil || p.pluginCtx.GetConfig == nil { + return "" + } + + config := p.pluginCtx.GetConfig() + if config == nil { + return "" + } + + return config.Logger.Level +} diff --git a/plugins/otel/logger_test.go b/plugins/otel/logger_test.go new file mode 100644 index 00000000..21a7ef59 --- /dev/null +++ b/plugins/otel/logger_test.go @@ -0,0 +1,123 @@ +package otel_test + +import ( + "log/slog" + "testing" + + "github.com/Authula/authula/internal/bootstrap" + internaltests "github.com/Authula/authula/internal/tests" + "github.com/Authula/authula/models" + otel "github.com/Authula/authula/plugins/otel" + oteltests "github.com/Authula/authula/plugins/otel/tests" + "github.com/Authula/authula/plugins/otel/types" +) + +func newPluginContext(logger models.Logger) *models.PluginContext { + return &models.PluginContext{ + Logger: logger, + GetConfig: func() *models.Config { + return &models.Config{Logger: models.LoggerConfig{Level: "info"}} + }, + } +} + +func newLoggingPlugin() *otel.OTelPlugin { + return otel.New(types.OTelPluginConfig{ + Enabled: true, + Exporter: types.ExporterOTLP, + LogsEnabled: true, + TracesEnabled: new(false), + MetricsEnabled: new(false), + }) +} + +func TestLogsDisabledAttachesNothing(t *testing.T) { + original := slog.Default() + t.Cleanup(func() { slog.SetDefault(original) }) + + logger := bootstrap.InitLogger(bootstrap.LoggerOptions{Level: "info"}) + plugin := otel.New(types.OTelPluginConfig{ + Enabled: true, + Exporter: types.ExporterOTLP, + LogsEnabled: false, + TracesEnabled: new(false), + MetricsEnabled: new(false), + }) + + if err := plugin.Init(newPluginContext(logger)); err != nil { + t.Fatalf("Init() error = %v", err) + } + t.Cleanup(func() { _ = plugin.Close() }) + + if provider := otel.LogProviderForTest(plugin); provider != nil { + t.Fatal("log provider created while logs_enabled=false") + } +} + +func TestLogsBridgeReceivesRecords(t *testing.T) { + tests := []struct { + name string + // build returns the logger to attach and an optional base logger whose + // records prove the wrapper still forwards. + build func(t *testing.T) (models.Logger, *internaltests.LevelRecordingLogger, func()) + }{ + { + name: "default logger", + build: func(t *testing.T) (models.Logger, *internaltests.LevelRecordingLogger, func()) { + original := slog.Default() + return bootstrap.InitLogger(bootstrap.LoggerOptions{Level: "info"}), + nil, + func() { slog.SetDefault(original) } + }, + }, + { + name: "custom logger wrapped by InitLogger", + build: func(t *testing.T) (models.Logger, *internaltests.LevelRecordingLogger, func()) { + original := slog.Default() + base := new(internaltests.LevelRecordingLogger) + return bootstrap.InitLogger(bootstrap.LoggerOptions{Level: "info", Logger: base}), + base, + func() { slog.SetDefault(original) } + }, + }, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + logger, base, cleanup := tc.build(t) + t.Cleanup(cleanup) + + exporter := new(oteltests.Exporter) + plugin := newLoggingPlugin() + otel.AttachLogsForTest(plugin, logger, exporter) + + if provider := otel.LogProviderForTest(plugin); provider == nil { + t.Fatal("log provider was not created") + } + + logger.Info("hello", "key", "value") + + if err := plugin.Close(); err != nil { + t.Fatalf("Close() error = %v", err) + } + + records := exporter.Records() + if len(records) != 1 { + t.Fatalf("exported %d records, want 1", len(records)) + } + if got := records[0].Body().AsString(); got != "hello" { + t.Fatalf("exported body = %q, want %q", got, "hello") + } + + if base != nil { + if got := base.Messages(); len(got) != 1 || got[0] != "hello" { + t.Fatalf("base messages = %v, want [hello]", got) + } + } + + if err := plugin.Close(); err != nil { + t.Fatalf("second Close() error = %v", err) + } + }) + } +} diff --git a/plugins/otel/plugin.go b/plugins/otel/plugin.go index b601a1ac..24b6027b 100644 --- a/plugins/otel/plugin.go +++ b/plugins/otel/plugin.go @@ -11,6 +11,7 @@ import ( "go.opentelemetry.io/otel/metric" metricnoop "go.opentelemetry.io/otel/metric/noop" "go.opentelemetry.io/otel/propagation" + sdklog "go.opentelemetry.io/otel/sdk/log" sdkmetric "go.opentelemetry.io/otel/sdk/metric" "go.opentelemetry.io/otel/sdk/resource" sdktrace "go.opentelemetry.io/otel/sdk/trace" @@ -41,8 +42,12 @@ type OTelPlugin struct { tracerProvider *sdktrace.TracerProvider // nil when traces disabled/none meterProvider *sdkmetric.MeterProvider // nil when metrics disabled/none + loggerProvider *sdklog.LoggerProvider // nil when logs disabled/none duration metric.Float64Histogram + // detachLogSink removes the OTel log sink from the core logger fan-out. + detachLogSink func() + closeOnce sync.Once closeErr error } @@ -56,7 +61,7 @@ func (p *OTelPlugin) Metadata() models.PluginMetadata { return models.PluginMetadata{ ID: models.PluginOtel.String(), Version: "1.0.0", - Description: "Provides OpenTelemetry distributed tracing and request/runtime metrics", + Description: "Provides OpenTelemetry distributed tracing, request/runtime metrics, and log export", } } @@ -112,6 +117,10 @@ func (p *OTelPlugin) Init(pluginCtx *models.PluginContext) error { return err } + if err := p.initLogger(res); err != nil { + return err + } + if p.pluginConfig.RuntimeOn() && p.pluginConfig.MetricsActive() { if err := runtime.Start(runtime.WithMeterProvider(p.meterProvider)); err != nil { p.warn("otel: failed to start runtime metrics", "error", err) @@ -184,7 +193,17 @@ func (p *OTelPlugin) Close() error { ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) defer cancel() + if p.detachLogSink != nil { + p.detachLogSink() + p.detachLogSink = nil + } + var errs []error + if p.loggerProvider != nil { + if err := p.loggerProvider.Shutdown(ctx); err != nil { + errs = append(errs, err) + } + } if p.meterProvider != nil { if err := p.meterProvider.Shutdown(ctx); err != nil { errs = append(errs, err) diff --git a/plugins/otel/tests/exporter.go b/plugins/otel/tests/exporter.go new file mode 100644 index 00000000..26d4640f --- /dev/null +++ b/plugins/otel/tests/exporter.go @@ -0,0 +1,40 @@ +// Package tests holds shared test helpers for the OpenTelemetry plugin. +package tests + +import ( + "context" + "sync" + + sdklog "go.opentelemetry.io/otel/sdk/log" +) + +// Exporter is an in-memory sdklog.Exporter that keeps exported records so +// tests can assert on them without a network endpoint. +type Exporter struct { + mu sync.Mutex + records []sdklog.Record +} + +func (e *Exporter) Export(_ context.Context, records []sdklog.Record) error { + e.mu.Lock() + defer e.mu.Unlock() + + for i := range records { + e.records = append(e.records, records[i].Clone()) + } + return nil +} + +func (e *Exporter) Shutdown(context.Context) error { return nil } + +func (e *Exporter) ForceFlush(context.Context) error { return nil } + +// Records returns a copy of every exported record, in order. +func (e *Exporter) Records() []sdklog.Record { + e.mu.Lock() + defer e.mu.Unlock() + + records := make([]sdklog.Record, len(e.records)) + copy(records, e.records) + return records +} diff --git a/plugins/otel/types/config.go b/plugins/otel/types/config.go index 07fb8250..6567bc9c 100644 --- a/plugins/otel/types/config.go +++ b/plugins/otel/types/config.go @@ -43,6 +43,7 @@ type OTelPluginConfig struct { Headers map[string]string `json:"headers,omitempty" toml:"headers"` TracesEnabled *bool `json:"traces_enabled,omitempty" toml:"traces_enabled"` MetricsEnabled *bool `json:"metrics_enabled,omitempty" toml:"metrics_enabled"` + LogsEnabled bool `json:"logs_enabled,omitempty" toml:"logs_enabled"` RuntimeMetrics *bool `json:"runtime_metrics,omitempty" toml:"runtime_metrics"` SampleRatio *float64 `json:"sample_ratio,omitempty" toml:"sample_ratio"` TrustProxy bool `json:"trust_proxy,omitempty" toml:"trust_proxy"` @@ -93,6 +94,13 @@ func (c OTelPluginConfig) MetricsActive() bool { return c.MetricsOn() && c.Exporter != ExporterNone } +// LogsActive reports whether the logs bridge should be initialized. Logs are +// opt-in, so an unset flag means disabled; the "none" exporter also disables +// them. +func (c OTelPluginConfig) LogsActive() bool { + return c.LogsEnabled && c.Exporter != ExporterNone +} + // Valid reports whether the configuration values are within their supported // ranges. func (c OTelPluginConfig) Valid() bool { diff --git a/plugins/secondary-storage/database_secondary_storage.go b/plugins/secondary-storage/database_secondary_storage.go index efebe875..f5139ac9 100644 --- a/plugins/secondary-storage/database_secondary_storage.go +++ b/plugins/secondary-storage/database_secondary_storage.go @@ -4,17 +4,33 @@ import ( "context" "errors" "fmt" - "log/slog" "strconv" "sync" "time" "github.com/uptrace/bun" + + "github.com/Authula/authula/models" ) +// DatabaseStorageOption customizes a DatabaseSecondaryStorage at construction. +type DatabaseStorageOption func(*DatabaseSecondaryStorage) + +// WithDatabaseStorageLogger injects the logger used for non-fatal cleanup +// errors. A nil logger is ignored. +func WithDatabaseStorageLogger(logger models.Logger) DatabaseStorageOption { + return func(storage *DatabaseSecondaryStorage) { + if logger != nil { + storage.logger = logger + } + } +} + // DatabaseSecondaryStorage implements the SecondaryStorage interface using Bun ORM. type DatabaseSecondaryStorage struct { db bun.IDB + // logger receives non-fatal errors (cleanup, expired-entry deletions). + logger models.Logger // cleanupInterval controls how often expired entries are cleaned up. cleanupInterval time.Duration // stopCleanup is used to signal the cleanup goroutine to stop. @@ -27,7 +43,7 @@ type DatabaseSecondaryStorage struct { closeOnce sync.Once } -func NewDatabaseSecondaryStorage(db bun.IDB, config DatabaseStorageConfig) *DatabaseSecondaryStorage { +func NewDatabaseSecondaryStorage(db bun.IDB, config DatabaseStorageConfig, opts ...DatabaseStorageOption) *DatabaseSecondaryStorage { cleanupInterval := time.Minute if config.CleanupInterval != 0 { cleanupInterval = config.CleanupInterval @@ -41,9 +57,21 @@ func NewDatabaseSecondaryStorage(db bun.IDB, config DatabaseStorageConfig) *Data cleanupStarted: false, } + for _, opt := range opts { + opt(storage) + } + return storage } +// logError reports a non-fatal error through the injected logger. It is a +// no-op when no logger was supplied. +func (storage *DatabaseSecondaryStorage) logError(msg string, args ...any) { + if storage.logger != nil { + storage.logger.Error(msg, args...) + } +} + // StartCleanup starts the background cleanup goroutine that removes expired entries. // This should be called after database migrations have completed. // It is safe to call this multiple times - subsequent calls will be no-ops. @@ -87,7 +115,7 @@ func (storage *DatabaseSecondaryStorage) Get(ctx context.Context, key string) (a if entry.ExpiresAt != nil && time.Now().After(*entry.ExpiresAt) { // Delete the expired entry if _, err := storage.db.NewDelete().Model(&KeyValueStore{}).Where("key = ?", key).Exec(ctx); err != nil { - slog.Error("error deleting expired entry", slog.String("key", key), slog.Any("error", err)) + storage.logError("error deleting expired entry", "key", key, "error", err) } return nil, nil } @@ -168,7 +196,7 @@ func (storage *DatabaseSecondaryStorage) Incr(ctx context.Context, key string, t if entry.ExpiresAt != nil && time.Now().After(*entry.ExpiresAt) { // Delete the expired entry if _, err := storage.db.NewDelete().Model(&KeyValueStore{}).Where("key = ?", key).Exec(ctx); err != nil { - slog.Error("error deleting expired entry during incr", slog.String("key", key), slog.Any("error", err)) + storage.logError("error deleting expired entry during incr", "key", key, "error", err) } } else { // Entry exists and is not expired @@ -186,7 +214,7 @@ func (storage *DatabaseSecondaryStorage) Incr(ctx context.Context, key string, t if entry.ExpiresAt != nil && time.Now().After(*entry.ExpiresAt) { // Delete the expired entry if _, err := storage.db.NewDelete().Model(&KeyValueStore{}).Where("key = ?", key).Exec(ctx); err != nil { - slog.Error("error deleting expired entry during incr", slog.String("key", key), slog.Any("error", err)) + storage.logError("error deleting expired entry during incr", "key", key, "error", err) } } else { // Entry exists and is not expired @@ -245,7 +273,7 @@ func (storage *DatabaseSecondaryStorage) removeExpiredEntries() { Exec(ctx) if err != nil { - slog.Error("error cleaning up expired entries from key_value_store", slog.Any("error", err)) + storage.logError("error cleaning up expired entries from key_value_store", "error", err) } } diff --git a/plugins/secondary-storage/database_secondary_storage_test.go b/plugins/secondary-storage/database_secondary_storage_test.go index b3a3624c..22c80d7f 100644 --- a/plugins/secondary-storage/database_secondary_storage_test.go +++ b/plugins/secondary-storage/database_secondary_storage_test.go @@ -13,6 +13,7 @@ import ( _ "modernc.org/sqlite" "github.com/Authula/authula/internal/sqlitedsn" + internaltests "github.com/Authula/authula/internal/tests" ) // Helper function to create an in-memory SQLite database for testing @@ -744,3 +745,25 @@ func TestDatabaseStorage_PersistenceAcrossInstances(t *testing.T) { } assertStringDB(t, retrieved2, "value2") } + +func TestDatabaseStorageCleanupErrorsUseInjectedLogger(t *testing.T) { + db := newTestDB(t) + logger := new(internaltests.RecordingLogger) + storage := NewDatabaseSecondaryStorage(db, DatabaseStorageConfig{ + CleanupInterval: time.Minute, + }, WithDatabaseStorageLogger(logger)) + + // Removing the table makes the cleanup query fail. + if _, err := db.NewDropTable().Model(&KeyValueStore{}).Exec(context.Background()); err != nil { + t.Fatalf("failed to drop table: %v", err) + } + + storage.removeExpiredEntries() + + if len(logger.ErrorCalls) != 1 { + t.Fatalf("logged %d errors, want 1: %v", len(logger.ErrorCalls), logger.ErrorCalls) + } + if logger.ErrorCalls[0] != "error cleaning up expired entries from key_value_store" { + t.Fatalf("logged %q, want cleanup message", logger.ErrorCalls[0]) + } +} diff --git a/plugins/secondary-storage/plugin.go b/plugins/secondary-storage/plugin.go index 33448800..f5940a2e 100644 --- a/plugins/secondary-storage/plugin.go +++ b/plugins/secondary-storage/plugin.go @@ -122,7 +122,7 @@ func (p *SecondaryStoragePlugin) initDatabaseProvider(ctx *models.PluginContext) return NewDatabaseSecondaryStorage(ctx.DB, DatabaseStorageConfig{ CleanupInterval: cleanupInterval, - }), nil + }, WithDatabaseStorageLogger(ctx.Logger)), nil } // initRedisProvider initializes the Redis storage provider