From 6f2aba8626fee7bf8f12b432e3b596762bcb0081 Mon Sep 17 00:00:00 2001 From: Rex Raphael Date: Sat, 17 Oct 2026 22:57:32 -0500 Subject: [PATCH 01/18] build: re-pin forge v1.12.9, grove v1.8.0 and the tier-2 releases Moves the root module to forge v1.12.9 (and forge/extensions/auth), grove v1.8.0 with every driver and kv module we use, chronicle v1.9.0, relay v1.8.0 and warden v1.8.0. go-utils lands on v1.4.1 through forge. You get grove's db.client spans and query duration metric for every store call, and the chronicle and relay calls the hooks and the outbox make are now traced and measured by those libraries. trove stays on v1.7.0, and the qualification modules keep their deliberate pins. --- go.mod | 33 ++++++++++++++++------------- go.sum | 66 ++++++++++++++++++++++++++++++++-------------------------- 2 files changed, 54 insertions(+), 45 deletions(-) diff --git a/go.mod b/go.mod index 31d9e3e..a4f4512 100644 --- a/go.mod +++ b/go.mod @@ -13,19 +13,19 @@ require ( github.com/testcontainers/testcontainers-go/modules/postgres v0.44.0 github.com/testcontainers/testcontainers-go/modules/redis v0.44.0 github.com/vmihailenco/msgpack/v5 v5.4.1 - github.com/xraph/chronicle v1.8.0 - github.com/xraph/forge v1.12.7 - github.com/xraph/forge/extensions/auth v1.12.7 - github.com/xraph/grove v1.7.3 - github.com/xraph/grove/drivers/mongodriver v1.7.3 - github.com/xraph/grove/drivers/pgdriver v1.7.3 - github.com/xraph/grove/drivers/sqlitedriver v1.7.3 - github.com/xraph/grove/kv v1.7.3 - github.com/xraph/grove/kv/drivers/redisdriver v1.7.3 - github.com/xraph/relay v1.7.2 + github.com/xraph/chronicle v1.9.0 + github.com/xraph/forge v1.12.9 + github.com/xraph/forge/extensions/auth v1.12.9 + github.com/xraph/grove v1.8.0 + github.com/xraph/grove/drivers/mongodriver v1.8.0 + github.com/xraph/grove/drivers/pgdriver v1.8.0 + github.com/xraph/grove/drivers/sqlitedriver v1.8.0 + github.com/xraph/grove/kv v1.8.0 + github.com/xraph/grove/kv/drivers/redisdriver v1.8.0 + github.com/xraph/relay v1.8.0 github.com/xraph/trove v1.7.0 github.com/xraph/vessel v1.0.4 - github.com/xraph/warden v1.7.1 + github.com/xraph/warden v1.8.0 github.com/zeebo/blake3 v0.2.4 go.jetify.com/typeid/v2 v2.0.0-alpha.3 go.mongodb.org/mongo-driver/v2 v2.9.1 @@ -120,11 +120,11 @@ require ( github.com/tklauser/numcpus v0.12.0 // indirect github.com/uptrace/bunrouter v1.0.23 // indirect github.com/x448/float16 v0.8.4 // indirect - github.com/xraph/confy v1.0.3 // indirect - github.com/xraph/go-utils v1.3.0 + github.com/xraph/confy v1.1.0 // indirect + github.com/xraph/go-utils v1.4.1 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/contrib/instrumentation/net/http/otelhttp v0.70.0 // indirect go.yaml.in/yaml/v2 v2.4.4 // indirect go.yaml.in/yaml/v3 v3.0.5 // indirect golang.org/x/crypto v0.57.0 // indirect @@ -166,6 +166,8 @@ require ( github.com/go-openapi/swag/typeutils v0.28.0 // indirect github.com/go-openapi/swag/yamlutils v0.28.0 // indirect github.com/gofrs/uuid/v5 v5.5.1 // indirect + github.com/grafana/pyroscope-go v1.4.3 // indirect + github.com/grafana/pyroscope-go/godeltaprof v0.1.11 // indirect github.com/grpc-ecosystem/grpc-gateway/v2 v2.29.0 // indirect github.com/hashicorp/go-metrics v0.6.1 // indirect github.com/klauspost/cpuid/v2 v2.4.0 // indirect @@ -184,11 +186,12 @@ require ( github.com/xdg-go/scram v1.2.0 // indirect github.com/xdg-go/stringprep v1.0.4 // indirect github.com/youmark/pkcs8 v0.0.0-20240726163527-a2c0da244d78 // indirect - go.opentelemetry.io/otel/exporters/jaeger v1.17.0 // indirect + go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetrichttp v1.45.0 // indirect go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.45.0 // indirect go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp v1.45.0 // indirect go.opentelemetry.io/otel/log v1.47.0 // indirect go.opentelemetry.io/otel/metric v1.47.0 // indirect + go.opentelemetry.io/otel/sdk/metric v1.45.0 // indirect go.opentelemetry.io/proto/otlp v1.11.0 // indirect go.uber.org/atomic v1.11.0 // indirect google.golang.org/genproto/googleapis/api v0.0.0-20260803160001-6ac0973c030d // indirect diff --git a/go.sum b/go.sum index 4dd2a55..6359e67 100644 --- a/go.sum +++ b/go.sum @@ -159,6 +159,10 @@ github.com/google/pprof v0.0.0-20250317173921-a4b03ec1a45e h1:ijClszYn+mADRFY17k github.com/google/pprof v0.0.0-20250317173921-a4b03ec1a45e/go.mod h1:boTsfXsheKC2y+lKOCMpSfarhxDeIzfZG1jqGcPl3cA= 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/grafana/pyroscope-go v1.4.3 h1:XAfYZe5ie8eRTsKAMHQG60ESJjHBV5XUijk8vDvqalw= +github.com/grafana/pyroscope-go v1.4.3/go.mod h1:enNhwzbML7+hMzJHTvKAIqTGqIaOOF1rgF+2au+NOwg= +github.com/grafana/pyroscope-go/godeltaprof v0.1.11 h1:el5LYpXissAiCKZ5/6yjlr6mhYVV6Cp5lahTocxraXM= +github.com/grafana/pyroscope-go/godeltaprof v0.1.11/go.mod h1:jl1V8M4cWsXciROCPIDDG7CtjSjT/ECbp6eLVuMxYRI= github.com/grpc-ecosystem/grpc-gateway/v2 v2.29.0 h1:5VipnvEpbqr2gA2VbM+nYVbkIF28c5ZQfqCBQ5g2xfk= github.com/grpc-ecosystem/grpc-gateway/v2 v2.29.0/go.mod h1:Hyl3n6Twe1hvtd9XUXDec4pTvgMSEixRuQKPTMH2bNs= github.com/hashicorp/consul/api v1.34.4 h1:0U4YZ1Yp7K9WK9ex0gTJraFim26l02wCvsmf2ukalVE= @@ -389,36 +393,36 @@ github.com/xdg-go/scram v1.2.0 h1:bYKF2AEwG5rqd1BumT4gAnvwU/M9nBp2pTSxeZw7Wvs= github.com/xdg-go/scram v1.2.0/go.mod h1:3dlrS0iBaWKYVt2ZfA4cj48umJZ+cAEbR6/SjLA88I8= github.com/xdg-go/stringprep v1.0.4 h1:XLI/Ng3O1Atzq0oBs3TWm+5ZVgkq2aqdlvP9JtoZ6c8= github.com/xdg-go/stringprep v1.0.4/go.mod h1:mPGuuIYwz7CmR2bT9j4GbQqutWS1zV24gijq1dTyGkM= -github.com/xraph/chronicle v1.8.0 h1:N4e+pRCZxXSwKeGD9RpBL/kmavLFEp6NYWwBomPN7kc= -github.com/xraph/chronicle v1.8.0/go.mod h1:VutAlbZ0EVAiSAWgP0XlDQcNm4S6RgzR0vB/nfMqs3U= -github.com/xraph/confy v1.0.3 h1:mY0kIo9+dU+XcGGN7cm4IfOhvk4SDj5TrnccpGi21fs= -github.com/xraph/confy v1.0.3/go.mod h1:DcYB+N0yKpr3t1yhhkdIIiCfch30Kh5wW6GRntUMOGk= -github.com/xraph/forge v1.12.7 h1:hsmw7bm1u82bW0I1sBenk1vEUYF2xV3dujeFt9iJkos= -github.com/xraph/forge v1.12.7/go.mod h1:O1JOH9fxDhKRyvBbIl2UpZ+aFCjv7vO/IbNfAwnYSEI= -github.com/xraph/forge/extensions/auth v1.12.7 h1:qmrPJD9q7B/q+w7jwZ8gNIx63nEeO1+g/HP6PL5+HVU= -github.com/xraph/forge/extensions/auth v1.12.7/go.mod h1:r9LFtMkQF7OV/XWa4C9WGjL33fphALJ9t6d05KXRzQ8= -github.com/xraph/go-utils v1.3.0 h1:bMZxwH9Xi/6UqhHSotKHB3a+/FnqnlUnEKf+aHZaw5c= -github.com/xraph/go-utils v1.3.0/go.mod h1:NfSn00r74ZjcIhVujIDPdKV25Ktghy2yz0DQmIKEARk= -github.com/xraph/grove v1.7.3 h1:zGwoXhxPYfxyZMpp3MYyXyEo8QqIJeJvnDKJZMpFj3Q= -github.com/xraph/grove v1.7.3/go.mod h1:PFMxsJ2mFagV3ghdbufuBXn2ImdXSC27MZDpUsePKHM= -github.com/xraph/grove/drivers/mongodriver v1.7.3 h1:qo7aQEKPDFjkjSZJbmdbLUgeRE8bjQCGLQcBwgSTGjA= -github.com/xraph/grove/drivers/mongodriver v1.7.3/go.mod h1:p+HhIx2Ii8dTfCCX/OaqEcIfPxSQxMWHorjXDqDWYlU= -github.com/xraph/grove/drivers/pgdriver v1.7.3 h1:QlyfKTDsijG4Rpcr21y09eEVXtoBipk2521O9VmKWrg= -github.com/xraph/grove/drivers/pgdriver v1.7.3/go.mod h1:KdmMNyhsATlkIr7CEZjSXpVFveSJt1eYO2lgPFaWTrE= -github.com/xraph/grove/drivers/sqlitedriver v1.7.3 h1:nnw6yafmdGf5091jiQxAkljBsSA7qpGUGo5VSCvn66I= -github.com/xraph/grove/drivers/sqlitedriver v1.7.3/go.mod h1:6tokGLpt5pI3ZvXDYlSkqwT+h2k/ky8qDvaUnbTmzeI= -github.com/xraph/grove/kv v1.7.3 h1:5A+fkV01d14qfFK53+Yz9H1MvC4AjuJKwalkPDk4B3A= -github.com/xraph/grove/kv v1.7.3/go.mod h1:Po/f07wtXHU54APbZldEF1BkRSUCyBgnKQ7rxNS6S68= -github.com/xraph/grove/kv/drivers/redisdriver v1.7.3 h1:IUVmk3dM843LKKgN0HsmEkZH8emLK6Lsh+zOb7Sz4+4= -github.com/xraph/grove/kv/drivers/redisdriver v1.7.3/go.mod h1:svwrBXvdJZckBZpDV1RDfhMDE8/41NoyqGST0h0X7i0= -github.com/xraph/relay v1.7.2 h1:AVMpP9P8tGUchLNywCwZjRlR8nJUEK0tYSu/PgmEoVE= -github.com/xraph/relay v1.7.2/go.mod h1:5hwMX3KFZxl14BkPA5O96kYc6wLQntojXegODe544Y4= +github.com/xraph/chronicle v1.9.0 h1:npLeZDrOb6XOVee5OD7fHkxcYbH1j/atJ0p9FA7botY= +github.com/xraph/chronicle v1.9.0/go.mod h1:x2k4cIlGDyE8ZNBYCVN7EFrOCSQ0LSo45yEnsSrkkSs= +github.com/xraph/confy v1.1.0 h1:xkWaujezyxi+8AcSgmkWarB6MacGlrhozJi+QcOD5P0= +github.com/xraph/confy v1.1.0/go.mod h1:HZwQ/RixbBNtBMT7IcULVYbAkyFjeXcJDNJDYj6m5oI= +github.com/xraph/forge v1.12.9 h1:hZ/qqPpXzTQm17aFdMsc7oINDuFrJAwIyidkphQT/yw= +github.com/xraph/forge v1.12.9/go.mod h1:atngBzJc3w2wDz/PYOZroYE7K5Xm5BpCDLIh5wLm9Oc= +github.com/xraph/forge/extensions/auth v1.12.9 h1:ZzvVev+KMAclQYuNg/28hS1bO2Vhaa+7QvKE2SPD8i0= +github.com/xraph/forge/extensions/auth v1.12.9/go.mod h1:+RriGL+jRZ5zO4GiSLm8eHb8Ypmnp8braypoj8s4YjA= +github.com/xraph/go-utils v1.4.1 h1:uP4CD+AaCKThbfR8kdQUh0kKHCFFaGb300fKMEJoSJY= +github.com/xraph/go-utils v1.4.1/go.mod h1:fMahP6kPUjJP5UmzVje2GSL7OGT9+xpYkukK2dLjSMM= +github.com/xraph/grove v1.8.0 h1:j1QsA/sqnc3WlVRSqvkRXrksC1ckv17hPvEEMjinwAc= +github.com/xraph/grove v1.8.0/go.mod h1:pZsulQT7WO3Owv9f2bxjW/qZxaz8y75SwdtVTPWKod8= +github.com/xraph/grove/drivers/mongodriver v1.8.0 h1:DzT2vRThDm02CkP9P37x5ECHXF3koqm9Rlcs9TYYc0k= +github.com/xraph/grove/drivers/mongodriver v1.8.0/go.mod h1:vp9jfR08GBmh3a42CGAdC87Z2vy8JurEO2VT4c0X17k= +github.com/xraph/grove/drivers/pgdriver v1.8.0 h1:UxYJKdObN9Qd0kQD8JrD9AX4AeDRAV8M5WlOKdQBdJE= +github.com/xraph/grove/drivers/pgdriver v1.8.0/go.mod h1:V9vYMFGIWdtkTOrOEB+rR5kXlhkuQeWjjCKRa0btTdg= +github.com/xraph/grove/drivers/sqlitedriver v1.8.0 h1:CKTCDEN7t/DQbTuZEuvcZx5JYe+rvxLw0oRXaBeyAOo= +github.com/xraph/grove/drivers/sqlitedriver v1.8.0/go.mod h1:ZC2rVcW+ZfWDIiTl1BZ2F9jeIlhl5LayBMyENJoXZSk= +github.com/xraph/grove/kv v1.8.0 h1:YZFeZYWK7omUaloWlVpMwFobl1dI2NCBHH2/iTs6yxo= +github.com/xraph/grove/kv v1.8.0/go.mod h1:dRzQTDR3/btTAxaBr/gXLv5KtSgkdQKWxzE7jaQAoDI= +github.com/xraph/grove/kv/drivers/redisdriver v1.8.0 h1:cyIWJffqtQbhPzSDCvTdZ8xHD12Qs0oclKRxd5h3+L0= +github.com/xraph/grove/kv/drivers/redisdriver v1.8.0/go.mod h1:iW0FOUNFeFi6VBw8OQpV8wUr2U/D/Xyv006NKc1ae9Y= +github.com/xraph/relay v1.8.0 h1:Pfa76U4S1p0NUS87ZZLw5mzqzXz50gp/0wmUE/xSRvQ= +github.com/xraph/relay v1.8.0/go.mod h1:ymuGmz2y2PLfHE7Thynf4L4lgRH3ruv5vbazfjMo1X4= github.com/xraph/trove v1.7.0 h1:SgvTEINhDaFR1pTf240X6og3xPuX0XbZtM2GK1ilAXU= github.com/xraph/trove v1.7.0/go.mod h1:bLs3RZEd6OlBY4xjmLaaacNKR7M5RdM75GQvEIAPVCo= github.com/xraph/vessel v1.0.4 h1:YVG80hm7bAKTwogwLXZMlp46tMHHJThUcvCUOWao9Yk= github.com/xraph/vessel v1.0.4/go.mod h1:5hgrMbuczxu2kRIM3iVJ3wPSb6HOvbMhV4nkRFaPNqs= -github.com/xraph/warden v1.7.1 h1:/Nl1br4Gstca28MFLMzWc5ysjtyAnoNsxk+6cwt91kI= -github.com/xraph/warden v1.7.1/go.mod h1:VQyjSHdqd9X0EZWm8OBn/ZdSN86BiQMcDSPEbQQXHQw= +github.com/xraph/warden v1.8.0 h1:U4ErO2KRr7XPwa/NZllU9YBc0pLlfabp00LIIH3FBn0= +github.com/xraph/warden v1.8.0/go.mod h1:LfjpZAVXPQFev8rG2Kp5Qj0UQVP8eLLvzr3yfBvf9dM= github.com/youmark/pkcs8 v0.0.0-20240726163527-a2c0da244d78 h1:ilQV1hzziu+LLM3zUTJ0trRztfwgjqKnBWNtSRkbmwM= github.com/youmark/pkcs8 v0.0.0-20240726163527-a2c0da244d78/go.mod h1:aL8wCCfTfSfmXjznFBSZNN13rSJjlIOI1fUNAtF7rmI= github.com/yuin/goldmark v1.4.13/go.mod h1:6yULJ656Px+3vBD8DxQVa3kxgyrAnzto9xy5taEt/CY= @@ -438,12 +442,12 @@ go.mongodb.org/mongo-driver/v2 v2.9.1 h1:jewiFs2m1/VOQp8qhFshX6hWZ+EAXDhZHXExAUM go.mongodb.org/mongo-driver/v2 v2.9.1/go.mod h1:SHKN0IWkKmEVGHLjXnni6s4wPKX4v86FTgOeJJFuXcA= 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/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/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/jaeger v1.17.0 h1:D7UpUy2Xc2wsi1Ras6V40q806WM07rqoCWzXu7Sqy+4= -go.opentelemetry.io/otel/exporters/jaeger v1.17.0/go.mod h1:nPCqOnEH9rNLKqH/+rrUjiMzHJdV1BlpKcTwRTyKkKI= +go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetrichttp v1.45.0 h1:pnxy6c/kvNBWdNNFzqpjuJLm9Hjhgk/Q0nY221rwuk0= +go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetrichttp v1.45.0/go.mod h1:qw6YsFapotRwoDhXRZvljzaOvCQB7UfnafEJagpN2TA= go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.45.0 h1:QRefszxJmfPdjXUUm3j6iDzY03mTPXMjqErFqQ67vUg= go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.45.0/go.mod h1:Tiz03lTBVBrm7eWZBOidzEaYaJa8tjwGUGv6d8mlTyk= go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp v1.45.0 h1:QBajQ2SrwQijzHyZbQlPsuIzpl/ll8DY6wPWsajeGcI= @@ -452,6 +456,8 @@ go.opentelemetry.io/otel/log v1.47.0 h1:cOTS1CcLbSQeZKanGJ+0JpF/+t4PELi3O3bbl2lq 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.67.0 h1:PcicCNZFkZ4bXfSooXdo3WN7RBOVOtjVdo1wD358Uns= +go.opentelemetry.io/otel/metric/x v0.67.0/go.mod h1:FBjCWZe6wgcqxcMtjdGiClDKXb2YxxXii0CXftE4QtI= go.opentelemetry.io/otel/sdk v1.45.0 h1:4VVSMgQ83dUgW2aoX5f6JgLvHwIvzcuLnF9lUdCSpCw= go.opentelemetry.io/otel/sdk v1.45.0/go.mod h1:Sr40LgXV7DsKMMJMKOhUWOgMWTfAaqvm2kF0g7ilwuA= go.opentelemetry.io/otel/sdk/metric v1.45.0 h1:oVFszMfyj1Am6s24Vtc7wBb8BKLcwepJjNEYILuiE3o= From 5b9ff0e9e0c015fc4098081b92ddc247df4f9e23 Mon Sep 17 00:00:00 2001 From: Rex Raphael Date: Sat, 17 Oct 2026 23:28:02 -0500 Subject: [PATCH 02/18] feat(telemetry): add a leaf package for Dispatch's spans and metrics Adds github.com/xraph/dispatch/telemetry, the one place the subsystems get their tracer and metric instruments from. It imports only the standard library, OpenTelemetry and go-utils metrics, so the worker, cron, workflow, durable and artifact packages can all import it, and exec stays a leaf. A Telemetry carries a tracer provider (nil means the global one, looked up per span) and a go-utils metric factory (nil means metrics are off). Every label has a fixed set of values and a vector drops anything outside it, so no series can grow per job, tenant or error message. Queue names become a label only when you configured them; anything else is recorded as "other". It also holds the helpers the reviews kept asking for: Detach strips the inherited span and baggage from a long-lived loop's context, Fail sets a short status class plus an exception.type event and never the error text, and a small bounded cache lets an attempt link to the span that enqueued its job when this process did the enqueue. --- internal/metricstest/metricstest.go | 168 ++++++++ internal/oteltest/oteltest.go | 152 ++++++++ telemetry/doc.go | 18 + telemetry/metrics.go | 577 ++++++++++++++++++++++++++++ telemetry/telemetry.go | 250 ++++++++++++ telemetry/telemetry_test.go | 186 +++++++++ 6 files changed, 1351 insertions(+) create mode 100644 internal/metricstest/metricstest.go create mode 100644 internal/oteltest/oteltest.go create mode 100644 telemetry/doc.go create mode 100644 telemetry/metrics.go create mode 100644 telemetry/telemetry.go create mode 100644 telemetry/telemetry_test.go diff --git a/internal/metricstest/metricstest.go b/internal/metricstest/metricstest.go new file mode 100644 index 0000000..f46e837 --- /dev/null +++ b/internal/metricstest/metricstest.go @@ -0,0 +1,168 @@ +// Package metricstest is a go-utils metric factory for Dispatch's tests. It +// keys series by name and labels, as Forge's registry does. go-utils' own +// collector keys them by name alone, which folds every labelled series into +// the first one created. +package metricstest + +import ( + "maps" + "slices" + "strings" + "sync" + + gu "github.com/xraph/go-utils/metrics" +) + +// Factory records every series created through it. +type Factory struct { + mu sync.Mutex + labels map[string][]map[string]string + counters map[string]gu.Counter + gauges map[string]gu.Gauge + histograms map[string]gu.Histogram +} + +var _ gu.MetricFactory = (*Factory)(nil) + +// New returns an empty Factory. +func New() *Factory { + return &Factory{ + labels: map[string][]map[string]string{}, + counters: map[string]gu.Counter{}, + gauges: map[string]gu.Gauge{}, + histograms: map[string]gu.Histogram{}, + } +} + +// Key names one series: its name, then its labels sorted by key. +func Key(name string, labels map[string]string) string { + var b strings.Builder + b.WriteString(name) + for _, k := range slices.Sorted(maps.Keys(labels)) { + b.WriteString("|" + k + "=" + labels[k]) + } + return b.String() +} + +func (f *Factory) register(name string, opts []gu.MetricOption) string { + o := &gu.MetricOptions{} + for _, opt := range opts { + opt(o) + } + labels := maps.Clone(o.Labels) + if labels == nil { + labels = map[string]string{} + } + key := Key(name, labels) + if !slices.ContainsFunc(f.labels[name], func(l map[string]string) bool { return Key(name, l) == key }) { + f.labels[name] = append(f.labels[name], labels) + } + return key +} + +// Counter implements gu.MetricFactory. +func (f *Factory) Counter(name string, opts ...gu.MetricOption) gu.Counter { + f.mu.Lock() + defer f.mu.Unlock() + key := f.register(name, opts) + if c, ok := f.counters[key]; ok { + return c + } + c := gu.NewCounter(name, opts...) + f.counters[key] = c + return c +} + +// Gauge implements gu.MetricFactory. +func (f *Factory) Gauge(name string, opts ...gu.MetricOption) gu.Gauge { + f.mu.Lock() + defer f.mu.Unlock() + key := f.register(name, opts) + if g, ok := f.gauges[key]; ok { + return g + } + g := gu.NewGauge(name, opts...) + f.gauges[key] = g + return g +} + +// Histogram implements gu.MetricFactory. +func (f *Factory) Histogram(name string, opts ...gu.MetricOption) gu.Histogram { + f.mu.Lock() + defer f.mu.Unlock() + key := f.register(name, opts) + if h, ok := f.histograms[key]; ok { + return h + } + h := gu.NewHistogram(name, opts...) + f.histograms[key] = h + return h +} + +// Summary implements gu.MetricFactory. Dispatch records no summaries. +func (f *Factory) Summary(name string, opts ...gu.MetricOption) gu.Summary { + return gu.NewSummary(name, opts...) +} + +// Timer implements gu.MetricFactory. Dispatch records no timers. +func (f *Factory) Timer(name string, opts ...gu.MetricOption) gu.Timer { + return gu.NewTimer(name, opts...) +} + +// Names returns every metric name created through f, sorted. +func (f *Factory) Names() []string { + f.mu.Lock() + defer f.mu.Unlock() + return slices.Sorted(maps.Keys(f.labels)) +} + +// Series returns the label sets created under name, in creation order. +func (f *Factory) Series(name string) []map[string]string { + f.mu.Lock() + defer f.mu.Unlock() + return slices.Clone(f.labels[name]) +} + +// CounterValue returns the value of the counter series name{labels}, and +// whether it exists. Pass labels as key, value pairs. +func (f *Factory) CounterValue(name string, labels ...string) (float64, bool) { + f.mu.Lock() + defer f.mu.Unlock() + c, ok := f.counters[Key(name, pairs(labels))] + if !ok { + return 0, false + } + return c.Value(), true +} + +// GaugeValue returns the value of the gauge series name{labels}, and whether +// it exists. +func (f *Factory) GaugeValue(name string, labels ...string) (float64, bool) { + f.mu.Lock() + defer f.mu.Unlock() + g, ok := f.gauges[Key(name, pairs(labels))] + if !ok { + return 0, false + } + return g.Value(), true +} + +// HistogramCount returns the observation count of the histogram series +// name{labels}, and whether it exists. +func (f *Factory) HistogramCount(name string, labels ...string) (uint64, bool) { + f.mu.Lock() + defer f.mu.Unlock() + h, ok := f.histograms[Key(name, pairs(labels))] + if !ok { + return 0, false + } + return h.Count(), true +} + +func pairs(kv []string) map[string]string { + out := make(map[string]string, len(kv)/2) + for i := 0; i+1 < len(kv); i += 2 { + out[kv[i]] = kv[i+1] + } + return out +} diff --git a/internal/oteltest/oteltest.go b/internal/oteltest/oteltest.go new file mode 100644 index 0000000..6c4b4d7 --- /dev/null +++ b/internal/oteltest/oteltest.go @@ -0,0 +1,152 @@ +// Package oteltest installs a span recorder for Dispatch's tests and checks +// what the recorded spans may and may not carry. +package oteltest + +import ( + "context" + "strings" + "testing" + "time" + + "go.opentelemetry.io/otel" + sdktrace "go.opentelemetry.io/otel/sdk/trace" + "go.opentelemetry.io/otel/sdk/trace/tracetest" + "go.opentelemetry.io/otel/trace" +) + +// Recorder is a span recorder that also signals each span's end, so a test +// can wait for a span without sleeping. +type Recorder struct { + *tracetest.SpanRecorder + ended chan struct{} +} + +// OnEnd implements sdktrace.SpanProcessor. +func (r *Recorder) OnEnd(s sdktrace.ReadOnlySpan) { + r.SpanRecorder.OnEnd(s) + select { + case r.ended <- struct{}{}: + default: + } +} + +// WaitFor blocks until n spans called name have ended, or fails the test +// after timeout, and returns them. +func (r *Recorder) WaitFor(t *testing.T, name string, n int, timeout time.Duration) []sdktrace.ReadOnlySpan { + t.Helper() + deadline := time.NewTimer(timeout) + defer deadline.Stop() + for { + if got := Named(r.Ended(), name); len(got) >= n { + return got + } + select { + case <-r.ended: + case <-deadline.C: + t.Fatalf("timed out waiting for %d %q spans; have %d", n, name, len(Named(r.Ended(), name))) + return nil + } + } +} + +// NewRecorder returns a Recorder that is not installed anywhere. Register it +// with forge.RegisterSpanProcessor to record a Forge app's spans. +func NewRecorder() *Recorder { + return &Recorder{SpanRecorder: tracetest.NewSpanRecorder(), ended: make(chan struct{}, 1)} +} + +// Record installs a recording tracer provider as the global provider and +// restores the previous one when the test ends. Tests that call it must not +// run in parallel with other tests that read the global provider. +func Record(t *testing.T) *Recorder { + t.Helper() + r := NewRecorder() + tp := sdktrace.NewTracerProvider(sdktrace.WithSpanProcessor(r)) + prev := otel.GetTracerProvider() + otel.SetTracerProvider(tp) + t.Cleanup(func() { + otel.SetTracerProvider(prev) + _ = tp.Shutdown(context.Background()) //nolint:errcheck // test cleanup + }) + return r +} + +// SpanContext returns a context carrying a started span from a throwaway +// provider, standing in for the boot or request span a long-lived loop must +// not keep. End is called for you when the test ends. +func SpanContext(t *testing.T) context.Context { + t.Helper() + tp := sdktrace.NewTracerProvider() + ctx, span := tp.Tracer("oteltest").Start(context.Background(), "start dispatch") + t.Cleanup(func() { + span.End() + _ = tp.Shutdown(context.Background()) //nolint:errcheck // test cleanup + }) + return ctx +} + +// Named returns the ended spans called name. +func Named(spans []sdktrace.ReadOnlySpan, name string) []sdktrace.ReadOnlySpan { + var out []sdktrace.ReadOnlySpan + for _, s := range spans { + if s.Name() == name { + out = append(out, s) + } + } + return out +} + +// Attr returns the value of key on s as a string, and whether it is set. +func Attr(s sdktrace.ReadOnlySpan, key string) (string, bool) { + for _, a := range s.Attributes() { + if string(a.Key) == key { + return a.Value.String(), true + } + } + return "", false +} + +// IsRoot reports whether s has no parent. +func IsRoot(s sdktrace.ReadOnlySpan) bool { + return !s.Parent().IsValid() +} + +// ChildOf reports whether child's parent is parent. +func ChildOf(child, parent sdktrace.ReadOnlySpan) bool { + return child.Parent().SpanID() == parent.SpanContext().SpanID() && + child.Parent().TraceID() == parent.SpanContext().TraceID() +} + +// LinksTo reports whether s links to sc. +func LinksTo(s sdktrace.ReadOnlySpan, sc trace.SpanContext) bool { + for _, l := range s.Links() { + if l.SpanContext.SpanID() == sc.SpanID() && l.SpanContext.TraceID() == sc.TraceID() { + return true + } + } + return false +} + +// AssertNoValue fails when any span quotes needle in its name, status, +// attributes or event attributes. Feed a personal value (an email address) +// through a payload or an error and check it never reaches a span. +func AssertNoValue(t *testing.T, spans []sdktrace.ReadOnlySpan, needle string) { + t.Helper() + for _, s := range spans { + if strings.Contains(s.Name(), needle) || strings.Contains(s.Status().Description, needle) { + t.Errorf("span %q quotes %q in its name or status", s.Name(), needle) + } + for _, a := range s.Attributes() { + if strings.Contains(a.Value.String(), needle) { + t.Errorf("span %q attribute %s quotes %q", s.Name(), a.Key, needle) + } + } + for _, ev := range s.Events() { + for _, a := range ev.Attributes { + if strings.Contains(a.Value.String(), needle) { + t.Errorf("span %q event %q attribute %s quotes %q", s.Name(), ev.Name, a.Key, needle) + } + } + } + } +} diff --git a/telemetry/doc.go b/telemetry/doc.go new file mode 100644 index 0000000..b2a92ed --- /dev/null +++ b/telemetry/doc.go @@ -0,0 +1,18 @@ +// Package telemetry holds the OpenTelemetry spans and metric instruments +// Dispatch records for the work it does itself: the job pool and runner, +// cron, checkpoint workflows, the durable runtime, the outbox publisher and +// the artifact sweeper. +// +// It is a leaf package. It imports the standard library, OpenTelemetry and +// go-utils metrics, and nothing else from Dispatch, so every subsystem can +// import it without a cycle. exec deliberately does not import it. +// +// You rarely build a Telemetry yourself. engine.Build builds one from +// engine.WithMetricFactory and engine.WithTracerProvider and hands it to every +// subsystem it constructs, and the Forge extension passes the app's metrics. +// Build one with New only when you assemble a subsystem (a worker.Pool, a +// durable runtime Worker, a delivery Publisher) outside the engine. +// +// A nil *Telemetry is valid everywhere: spans go to the global tracer +// provider and no metrics are recorded. +package telemetry diff --git a/telemetry/metrics.go b/telemetry/metrics.go new file mode 100644 index 0000000..04b9edc --- /dev/null +++ b/telemetry/metrics.go @@ -0,0 +1,577 @@ +package telemetry + +import ( + "strings" + "sync" + "time" + + gu "github.com/xraph/go-utils/metrics" +) + +// Metric names, as Dispatch registers them. A Forge app scrapes each one +// with its namespace in front: dispatch_jobs_enqueued_total is +// forge_dispatch_jobs_enqueued_total on /_/metrics. +const ( + MetricJobsEnqueued = "dispatch_jobs_enqueued_total" + MetricJobAttemptDuration = "dispatch_job_attempt_duration_seconds" + MetricJobsDeadLettered = "dispatch_jobs_dead_lettered_total" + MetricJobQueueWait = "dispatch_job_queue_wait_seconds" + MetricJobPolls = "dispatch_job_polls_total" + MetricJobsRequeued = "dispatch_jobs_requeued_total" + MetricJobLeaseRenewals = "dispatch_job_lease_renewals_total" + MetricJobsReclaimed = "dispatch_jobs_reclaimed_total" + MetricJobsActive = "dispatch_jobs_active" + + MetricCronFires = "dispatch_cron_fires_total" + MetricCronFireLag = "dispatch_cron_fire_lag_seconds" + MetricCronLeader = "dispatch_cron_leader" + MetricWorkflowRuns = "dispatch_workflow_run_duration_seconds" + MetricWorkflowStep = "dispatch_workflow_step_duration_seconds" + + MetricDurableTaskDuration = "dispatch_durable_task_duration_seconds" + MetricDurablePolls = "dispatch_durable_polls_total" + MetricDurableReplayDuration = "dispatch_durable_replay_duration_seconds" + + MetricOutboxDeliveryDuration = "dispatch_outbox_delivery_duration_seconds" + MetricOutboxDeliveryLag = "dispatch_outbox_delivery_lag_seconds" + + MetricArtifactsSwept = "dispatch_artifacts_swept_total" + MetricArtifactsPurged = "dispatch_artifacts_purged_total" + MetricArtifactBytesReclaimed = "dispatch_artifact_bytes_reclaimed_total" +) + +// Job attempt outcomes, the outcome label on +// dispatch_job_attempt_duration_seconds and the dispatch.job.outcome span +// attribute. +const ( + OutcomeCompleted = "completed" + OutcomeRetry = "retry" + OutcomeDeadLettered = "dead_lettered" + OutcomeRequeued = "requeued" + OutcomeLeaseLost = "lease_lost" + OutcomeCancelled = "cancelled" + OutcomeStoreError = "store_error" +) + +// Dead letter reasons, the reason label on dispatch_jobs_dead_lettered_total. +const ( + DeadLetterRetriesExhausted = "retries_exhausted" + DeadLetterPermanent = "permanent" + DeadLetterLaunchFailures = "launch_failures" +) + +// Requeue reasons, the reason label on dispatch_jobs_requeued_total: a job +// this worker claimed and handed back without running it. +const ( + RequeueRateLimited = "rate_limited" + RequeueNoCapacity = "no_capacity" + RequeueShutdown = "shutdown" +) + +// Shared result values. +const ( + ResultOK = "ok" + ResultError = "error" +) + +// Poll results, the result label on dispatch_job_polls_total and +// dispatch_durable_polls_total. +const ( + PollWork = "work" + PollEmpty = "empty" + PollError = "error" +) + +// Lease renewal results, the result label on +// dispatch_job_lease_renewals_total. +const ( + RenewalOK = "ok" + RenewalLost = "lost" + RenewalError = "error" +) + +// Cron fire results, the result label on dispatch_cron_fires_total. +const ( + CronFired = "fired" + CronLocked = "locked" + CronSkipped = "skipped" + CronError = "error" +) + +// Durable task results, the result label on +// dispatch_durable_task_duration_seconds. +const ( + DurableOK = "ok" + DurableContention = "contention" + DurableLeaseLost = "lease_lost" + DurableNoHandler = "no_handler" + DurableCancelled = "cancelled" + DurableError = "error" +) + +// Outbox delivery results, the result label on +// dispatch_outbox_delivery_duration_seconds. All but acknowledged are the +// failure categories the publisher already persists on a retry. +const ( + OutboxAcknowledged = "acknowledged" + OutboxRejected = "rejected" + OutboxTimeout = "timeout" + OutboxConflict = "conflict" + OutboxUnavailable = "unavailable" + OutboxInvalidReceipt = "invalid_receipt" +) + +// Artifact purge results, the result label on dispatch_artifacts_purged_total. +const ( + PurgeOK = "ok" + PurgeSkipped = "skipped" +) + +var ( + jobOutcomes = []string{OutcomeCompleted, OutcomeRetry, OutcomeDeadLettered, OutcomeRequeued, OutcomeLeaseLost, OutcomeCancelled, OutcomeStoreError} + dlqReasons = []string{DeadLetterRetriesExhausted, DeadLetterPermanent, DeadLetterLaunchFailures} + requeues = []string{RequeueRateLimited, RequeueNoCapacity, RequeueShutdown} + pollResults = []string{PollWork, PollEmpty, PollError} + renewals = []string{RenewalOK, RenewalLost, RenewalError} + cronResults = []string{CronFired, CronLocked, CronSkipped, CronError} + okError = []string{ResultOK, ResultError} + runResults = []string{"completed", "failed"} + stepKinds = []string{"step", "parallel", "fan_out", "child", "spawn", "wait_event", "wait_all", "wait_any", "wait_match", "sleep", "compensate"} + taskKinds = []string{"workflow", "activity", "timer", "timeout", "child_delivery", "execution_timeout"} + taskResults = []string{DurableOK, DurableContention, DurableLeaseLost, DurableNoHandler, DurableCancelled, DurableError} + destinations = []string{"chronicle", "relay"} + outboxResult = []string{OutboxAcknowledged, OutboxRejected, OutboxTimeout, OutboxConflict, OutboxUnavailable, OutboxInvalidReceipt} + sweepReasons = []string{"retention", "orphan"} + purgeResults = []string{PurgeOK, PurgeSkipped} + + // attemptBuckets cover a job attempt or a workflow step, from a fast + // in-process handler to an hour-long batch job. + attemptBuckets = []float64{0.005, 0.01, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10, 30, 60, 300, 900, 3600} + // waitBuckets cover how long due work waits: queue wait, cron lag and + // outbox lag. + waitBuckets = []float64{0.01, 0.05, 0.1, 0.5, 1, 2, 5, 10, 30, 60, 300, 900, 3600} + // taskBuckets cover one durable task or one outbox delivery call. + taskBuckets = []float64{0.001, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10, 30, 60} +) + +// JobMetrics are the job pool, runner and enqueue instruments. +type JobMetrics struct { + enqueued *vec[gu.Counter] + attempts *vec[gu.Histogram] + deadLettered *vec[gu.Counter] + queueWait *vec[gu.Histogram] + polls *vec[gu.Counter] + requeued *vec[gu.Counter] + renewals *vec[gu.Counter] + reclaimed gu.Counter + active gu.Gauge +} + +// Jobs returns the job instruments, building them on the first call. It +// returns nil, which records nothing, when metrics are off. +func (t *Telemetry) Jobs() *JobMetrics { + if t == nil || t.factory == nil { + return nil + } + t.jobsOnce.Do(func() { + f, queues := t.factory, t.queueValues() + t.jobs = &JobMetrics{ + enqueued: counterVec(f, MetricJobsEnqueued, "Jobs written to the store, by queue", + label{"queue", queues}), + attempts: histogramVec(f, MetricJobAttemptDuration, "Job attempts from start to their terminal write, by queue and outcome", attemptBuckets, + label{"queue", queues}, label{"outcome", jobOutcomes}), + deadLettered: counterVec(f, MetricJobsDeadLettered, "Jobs moved to the dead letter queue, by queue and reason", + label{"queue", queues}, label{"reason", dlqReasons}), + queueWait: histogramVec(f, MetricJobQueueWait, "Time from a job becoming due to a worker starting it, by queue", waitBuckets, + label{"queue", queues}), + polls: counterVec(f, MetricJobPolls, "Job pool dequeue polls, by result", + label{"result", pollResults}), + requeued: counterVec(f, MetricJobsRequeued, "Claimed jobs handed back without running, by queue and reason", + label{"queue", queues}, label{"reason", requeues}), + renewals: counterVec(f, MetricJobLeaseRenewals, "Job lease renewals and heartbeats, by result", + label{"result", renewals}), + reclaimed: f.Counter(MetricJobsReclaimed, gu.WithDescription("Jobs whose lease expired, returned to pending by the reaper")), + active: f.Gauge(MetricJobsActive, gu.WithDescription("Job attempts running on this worker")), + } + }) + + return t.jobs +} + +// Enqueued counts one job written to the store. +func (m *JobMetrics) Enqueued(queue string) { + if m != nil { + m.enqueued.counter(queue) + } +} + +// Attempt records one finished job attempt. +func (m *JobMetrics) Attempt(queue, outcome string, d time.Duration) { + if m != nil { + m.attempts.observe(d.Seconds(), queue, outcome) + } +} + +// DeadLettered counts one job moved to the dead letter queue. +func (m *JobMetrics) DeadLettered(queue, reason string) { + if m != nil { + m.deadLettered.counter(queue, reason) + } +} + +// QueueWait records how long a claimed job waited past its due time. +func (m *JobMetrics) QueueWait(queue string, d time.Duration) { + if m != nil { + m.queueWait.observe(max(d, 0).Seconds(), queue) + } +} + +// Poll counts one dequeue poll. +func (m *JobMetrics) Poll(result string) { + if m != nil { + m.polls.counter(result) + } +} + +// Requeued counts one claimed job handed back without running. +func (m *JobMetrics) Requeued(queue, reason string) { + if m != nil { + m.requeued.counter(queue, reason) + } +} + +// Renewal counts one lease renewal or heartbeat. +func (m *JobMetrics) Renewal(result string) { + if m != nil { + m.renewals.counter(result) + } +} + +// Reclaimed counts jobs the reaper returned to pending. +func (m *JobMetrics) Reclaimed(n int) { + if m != nil && n > 0 { + m.reclaimed.Add(float64(n)) + } +} + +// Active sets the number of attempts running on this worker. +func (m *JobMetrics) Active(n int) { + if m != nil { + m.active.Set(float64(n)) + } +} + +// CronMetrics are the cron scheduler instruments. +type CronMetrics struct { + fires *vec[gu.Counter] + lag gu.Histogram + leader gu.Gauge +} + +// Cron returns the cron instruments, or nil when metrics are off. +func (t *Telemetry) Cron() *CronMetrics { + if t == nil || t.factory == nil { + return nil + } + t.cronOnce.Do(func() { + f := t.factory + t.cron = &CronMetrics{ + fires: counterVec(f, MetricCronFires, "Due cron entries this scheduler handled, by result", + label{"result", cronResults}), + lag: f.Histogram(MetricCronFireLag, gu.WithBuckets(waitBuckets...), gu.WithUnit("s"), + gu.WithDescription("Time from a cron entry's due time to its job being enqueued")), + leader: f.Gauge(MetricCronLeader, gu.WithDescription("1 while this scheduler holds cron leadership, 0 otherwise")), + } + }) + + return t.cron +} + +// Fire counts one due cron entry handled. +func (m *CronMetrics) Fire(result string) { + if m != nil { + m.fires.counter(result) + } +} + +// Lag records how late a cron entry fired. +func (m *CronMetrics) Lag(d time.Duration) { + if m != nil { + m.lag.Observe(max(d, 0).Seconds()) + } +} + +// Leader records whether this scheduler leads. +func (m *CronMetrics) Leader(leading bool) { + if m == nil { + return + } + if leading { + m.leader.Set(1) + return + } + m.leader.Set(0) +} + +// WorkflowMetrics are the checkpoint workflow instruments. +type WorkflowMetrics struct { + runs *vec[gu.Histogram] + steps *vec[gu.Histogram] +} + +// Workflows returns the checkpoint workflow instruments, or nil when +// metrics are off. +func (t *Telemetry) Workflows() *WorkflowMetrics { + if t == nil || t.factory == nil { + return nil + } + t.workflowOnce.Do(func() { + f := t.factory + t.workflow = &WorkflowMetrics{ + runs: histogramVec(f, MetricWorkflowRuns, "Checkpoint workflow runs, by result", attemptBuckets, + label{"result", runResults}), + steps: histogramVec(f, MetricWorkflowStep, "Checkpoint workflow steps that ran (not replayed), by kind and result", attemptBuckets, + label{"kind", stepKinds}, label{"result", okError}), + } + }) + + return t.workflow +} + +// Run records one finished workflow run. result is completed or failed. +func (m *WorkflowMetrics) Run(result string, d time.Duration) { + if m != nil { + m.runs.observe(d.Seconds(), result) + } +} + +// Step records one workflow step that ran. +func (m *WorkflowMetrics) Step(kind, result string, d time.Duration) { + if m != nil { + m.steps.observe(d.Seconds(), kind, result) + } +} + +// DurableMetrics are the durable runtime instruments. +type DurableMetrics struct { + tasks *vec[gu.Histogram] + polls *vec[gu.Counter] + replay gu.Histogram +} + +// Durable returns the durable runtime instruments, or nil when metrics are +// off. +func (t *Telemetry) Durable() *DurableMetrics { + if t == nil || t.factory == nil { + return nil + } + t.durableOnce.Do(func() { + f := t.factory + t.durable = &DurableMetrics{ + tasks: histogramVec(f, MetricDurableTaskDuration, "Durable tasks from claim to finish, by kind and result", taskBuckets, + label{"kind", taskKinds}, label{"result", taskResults}), + polls: counterVec(f, MetricDurablePolls, "Durable task claim polls, by kind and result", + label{"kind", taskKinds}, label{"result", pollResults}), + replay: f.Histogram(MetricDurableReplayDuration, gu.WithBuckets(taskBuckets...), gu.WithUnit("s"), + gu.WithDescription("Time to replay a workflow's history and evaluate its next decision")), + } + }) + + return t.durable +} + +// Task records one claimed durable task. +func (m *DurableMetrics) Task(kind, result string, d time.Duration) { + if m != nil { + m.tasks.observe(d.Seconds(), kind, result) + } +} + +// Poll counts one durable claim poll. +func (m *DurableMetrics) Poll(kind, result string) { + if m != nil { + m.polls.counter(kind, result) + } +} + +// Replay records one history replay. +func (m *DurableMetrics) Replay(d time.Duration) { + if m != nil { + m.replay.Observe(d.Seconds()) + } +} + +// OutboxMetrics are the outbox publisher instruments. +type OutboxMetrics struct { + deliveries *vec[gu.Histogram] + lag *vec[gu.Histogram] +} + +// Outbox returns the outbox publisher instruments, or nil when metrics are +// off. +func (t *Telemetry) Outbox() *OutboxMetrics { + if t == nil || t.factory == nil { + return nil + } + t.outboxOnce.Do(func() { + f := t.factory + t.outbox = &OutboxMetrics{ + deliveries: histogramVec(f, MetricOutboxDeliveryDuration, "Outbox delivery attempts, by destination and result", taskBuckets, + label{"destination", destinations}, label{"result", outboxResult}), + lag: histogramVec(f, MetricOutboxDeliveryLag, "Time from an outbox intent being accepted to its sink acknowledging it, by destination", waitBuckets, + label{"destination", destinations}), + } + }) + + return t.outbox +} + +// Delivery records one delivery attempt. +func (m *OutboxMetrics) Delivery(destination, result string, d time.Duration) { + if m != nil { + m.deliveries.observe(d.Seconds(), destination, result) + } +} + +// Lag records how long an acknowledged delivery waited since acceptance. +func (m *OutboxMetrics) Lag(destination string, d time.Duration) { + if m != nil { + m.lag.observe(max(d, 0).Seconds(), destination) + } +} + +// ArtifactMetrics are the artifact sweeper instruments. +type ArtifactMetrics struct { + swept *vec[gu.Counter] + purged *vec[gu.Counter] + bytes gu.Counter +} + +// Artifacts returns the artifact sweeper instruments, or nil when metrics +// are off. +func (t *Telemetry) Artifacts() *ArtifactMetrics { + if t == nil || t.factory == nil { + return nil + } + t.artifactsOnce.Do(func() { + f := t.factory + t.artifacts = &ArtifactMetrics{ + swept: counterVec(f, MetricArtifactsSwept, "Ephemeral artifacts marked for purge, by reason", + label{"reason", sweepReasons}), + purged: counterVec(f, MetricArtifactsPurged, "Artifacts the purge pass handled, by result", + label{"result", purgeResults}), + bytes: f.Counter(MetricArtifactBytesReclaimed, gu.WithDescription("Bytes of artifact storage the purge pass deleted")), + } + }) + + return t.artifacts +} + +// Swept counts artifacts marked for purge. +func (m *ArtifactMetrics) Swept(reason string, n int) { + if m != nil && n > 0 { + m.swept.add(float64(n), reason) + } +} + +// Purged counts artifacts the purge pass handled. +func (m *ArtifactMetrics) Purged(result string, n int) { + if m != nil && n > 0 { + m.purged.add(float64(n), result) + } +} + +// BytesReclaimed counts bytes the purge pass deleted. +func (m *ArtifactMetrics) BytesReclaimed(n int64) { + if m != nil && n > 0 { + m.bytes.Add(float64(n)) + } +} + +// label is one label key and the only values it may take. A value outside +// the set is never recorded, so no metric can grow a series per job, tenant +// or free-text string. +type label struct { + key string + values []string +} + +// vec is a metric family with fixed label keys. Children are created on +// first use, through the factory, and cached. +type vec[T any] struct { + labels []label + allowed []map[string]struct{} + build func(map[string]string) T + mu sync.Mutex + children map[string]T +} + +func newVec[T any](mk func(map[string]string) T, labels ...label) *vec[T] { + v := &vec[T]{labels: labels, build: mk, children: map[string]T{}} + for _, l := range labels { + set := make(map[string]struct{}, len(l.values)) + for _, value := range l.values { + set[value] = struct{}{} + } + v.allowed = append(v.allowed, set) + } + + return v +} + +func (v *vec[T]) with(values ...string) (T, bool) { + var zero T + if len(values) != len(v.labels) { + return zero, false + } + for i, value := range values { + if _, ok := v.allowed[i][value]; !ok { + return zero, false + } + } + key := strings.Join(values, "\xff") + + v.mu.Lock() + defer v.mu.Unlock() + if child, ok := v.children[key]; ok { + return child, true + } + lm := make(map[string]string, len(values)) + for i, value := range values { + lm[v.labels[i].key] = value + } + child := v.build(lm) + v.children[key] = child + + return child, true +} + +func counterVec(f gu.MetricFactory, name, help string, labels ...label) *vec[gu.Counter] { + return newVec(func(l map[string]string) gu.Counter { + return f.Counter(name, gu.WithLabels(l), gu.WithDescription(help)) + }, labels...) +} + +func histogramVec(f gu.MetricFactory, name, help string, buckets []float64, labels ...label) *vec[gu.Histogram] { + return newVec(func(l map[string]string) gu.Histogram { + return f.Histogram(name, gu.WithLabels(l), gu.WithBuckets(buckets...), gu.WithUnit("s"), gu.WithDescription(help)) + }, labels...) +} + +func (v *vec[T]) counter(values ...string) { v.add(1, values...) } + +func (v *vec[T]) add(delta float64, values ...string) { + if child, ok := v.with(values...); ok { + if c, isCounter := any(child).(gu.Counter); isCounter { + c.Add(delta) + } + } +} + +func (v *vec[T]) observe(value float64, values ...string) { + if child, ok := v.with(values...); ok { + if h, isHistogram := any(child).(gu.Histogram); isHistogram { + h.Observe(value) + } + } +} diff --git a/telemetry/telemetry.go b/telemetry/telemetry.go new file mode 100644 index 0000000..6b51877 --- /dev/null +++ b/telemetry/telemetry.go @@ -0,0 +1,250 @@ +package telemetry + +import ( + "context" + "errors" + "fmt" + "sync" + + gu "github.com/xraph/go-utils/metrics" + "go.opentelemetry.io/otel" + "go.opentelemetry.io/otel/baggage" + "go.opentelemetry.io/otel/codes" + semconv "go.opentelemetry.io/otel/semconv/v1.43.0" + "go.opentelemetry.io/otel/trace" +) + +// ScopeName is the instrumentation scope on every span Dispatch starts. +const ScopeName = "github.com/xraph/dispatch" + +// OtherQueue is the queue label for any queue outside the configured set. +// Queue names are chosen by whoever enqueues, so only the names you +// configured (WithQueues) become label values. Everything else collapses +// into this one. +const OtherQueue = "other" + +// Telemetry carries the tracer provider and metric factory Dispatch records +// through. Build it once with New and share it; it is safe for concurrent +// use. A nil *Telemetry records no metrics and starts spans on the global +// tracer provider. +type Telemetry struct { + tp trace.TracerProvider + factory gu.MetricFactory + queues map[string]struct{} + links *linkCache + + jobsOnce sync.Once + jobs *JobMetrics + cronOnce sync.Once + cron *CronMetrics + workflowOnce sync.Once + workflow *WorkflowMetrics + durableOnce sync.Once + durable *DurableMetrics + outboxOnce sync.Once + outbox *OutboxMetrics + artifactsOnce sync.Once + artifacts *ArtifactMetrics +} + +// Option configures a Telemetry. +type Option func(*Telemetry) + +// WithMetrics records Dispatch's metrics through f. In a Forge app that is +// app.Metrics(). The factory has to key series by name and labels, as +// Forge's does. A nil factory leaves metrics off. +func WithMetrics(f gu.MetricFactory) Option { + return func(t *Telemetry) { t.factory = f } +} + +// WithTracerProvider starts Dispatch's spans on tp. A nil tp, the default, +// means the global provider, looked up on every span so a provider installed +// later (forge.New, a test recorder) still receives them. +func WithTracerProvider(tp trace.TracerProvider) Option { + return func(t *Telemetry) { t.tp = tp } +} + +// WithQueues names the queues that may appear as a metric label. Pass the +// queues your workers poll and the ones you configured limits for. Any other +// queue name is recorded as OtherQueue. +func WithQueues(names ...string) Option { + return func(t *Telemetry) { + for _, n := range names { + if n != "" && n != OtherQueue { + t.queues[n] = struct{}{} + } + } + } +} + +// New builds a Telemetry. +func New(opts ...Option) *Telemetry { + t := &Telemetry{queues: map[string]struct{}{}, links: newLinkCache(defaultLinkCapacity)} + for _, opt := range opts { + opt(t) + } + + return t +} + +// Tracer returns the tracer Dispatch's spans start on. +func (t *Telemetry) Tracer() trace.Tracer { + if t == nil || t.tp == nil { + return otel.Tracer(ScopeName) + } + + return t.tp.Tracer(ScopeName) +} + +// Start starts a span under Dispatch's instrumentation scope. The caller +// ends it. +func (t *Telemetry) Start(ctx context.Context, name string, opts ...trace.SpanStartOption) (context.Context, trace.Span) { + return t.Tracer().Start(ctx, name, opts...) //nolint:spancheck // the caller ends the span +} + +// StartChild starts a span only when ctx already carries a local Dispatch +// span, using that span's own tracer provider. Code that has no Telemetry of +// its own (the staging middleware) uses it to nest under the job attempt it +// runs in without a span of its own outside one. The caller ends it. +func StartChild(ctx context.Context, name string, opts ...trace.SpanStartOption) (context.Context, trace.Span) { + parent := trace.SpanFromContext(ctx) + + return parent.TracerProvider().Tracer(ScopeName).Start(ctx, name, opts...) //nolint:spancheck // the caller ends the span +} + +// QueueLabel maps a queue name to its metric label: the name itself when it +// is one of the configured queues, OtherQueue otherwise. +func (t *Telemetry) QueueLabel(queue string) string { + if t == nil { + return OtherQueue + } + if _, ok := t.queues[queue]; ok { + return queue + } + + return OtherQueue +} + +func (t *Telemetry) queueValues() []string { + out := make([]string, 0, len(t.queues)+1) + for q := range t.queues { + out = append(out, q) + } + + return append(out, OtherQueue) +} + +// Detach returns ctx without its span or baggage, keeping its values, +// deadline and cancellation. A long-lived loop calls it once on the context +// it was started with. forge v1.12.9 hands an extension's Start a context +// that carries the "start " boot span, and a request context carries +// the request's server span; without this, every query an idle poll makes +// would land in that long-finished trace. +func Detach(ctx context.Context) context.Context { + ctx = trace.ContextWithSpanContext(ctx, trace.SpanContext{}) + + return baggage.ContextWithoutBaggage(ctx) +} + +// Fail marks span as failed. class is a short, bounded description (a +// failure class such as "handler error", never err.Error()), and the +// exception event carries only exception.type: the error's Go type or a +// sentinel's name. Driver and handler messages quote values (payload +// fragments, keys, addresses), and none of that belongs on a span. +func Fail(span trace.Span, class, errType string) { + span.SetStatus(codes.Error, class) + if errType != "" { + span.AddEvent("exception", trace.WithAttributes(semconv.ExceptionType(errType))) + } +} + +// ErrorType names err for an exception event: "context.Canceled" or +// "context.DeadlineExceeded" when the chain holds one, otherwise the Go type +// of the innermost error, such as "*net.OpError". It returns "" for nil. +func ErrorType(err error) string { + switch { + case err == nil: + return "" + case errors.Is(err, context.Canceled): + return "context.Canceled" + case errors.Is(err, context.DeadlineExceeded): + return "context.DeadlineExceeded" + } + for { + next := errors.Unwrap(err) + if next == nil { + return fmt.Sprintf("%T", err) + } + err = next + } +} + +// RememberEnqueue records the span context that enqueued a job, so an +// attempt this process runs can link back to it. Nothing about it is stored +// with the job: the cache is in memory, bounded, and an attempt on another +// worker simply starts without a link. +func (t *Telemetry) RememberEnqueue(jobID string, sc trace.SpanContext) { + if t == nil || !sc.IsValid() { + return + } + t.links.put(jobID, sc) +} + +// EnqueueLinks returns a link to the span that enqueued jobID, when this +// process enqueued it recently enough to remember. +func (t *Telemetry) EnqueueLinks(jobID string) []trace.Link { + if t == nil { + return nil + } + sc, ok := t.links.get(jobID) + if !ok { + return nil + } + + return []trace.Link{{SpanContext: sc}} +} + +// defaultLinkCapacity bounds the enqueue link cache. An entry is a job ID +// and a span context, so this is well under a megabyte. +const defaultLinkCapacity = 4096 + +// linkCache is a bounded FIFO map from job ID to the span context that +// enqueued it. Entries are kept after a read so retries link too, and the +// oldest entry goes when the cache is full. +type linkCache struct { + mu sync.Mutex + size int + order []string + next int + items map[string]trace.SpanContext +} + +func newLinkCache(capacity int) *linkCache { + return &linkCache{size: capacity, order: make([]string, 0, capacity), items: make(map[string]trace.SpanContext, capacity)} +} + +func (c *linkCache) put(key string, sc trace.SpanContext) { + c.mu.Lock() + defer c.mu.Unlock() + + if _, ok := c.items[key]; ok { + c.items[key] = sc + return + } + if len(c.order) < c.size { + c.order = append(c.order, key) + } else { + delete(c.items, c.order[c.next]) + c.order[c.next] = key + c.next = (c.next + 1) % c.size + } + c.items[key] = sc +} + +func (c *linkCache) get(key string) (trace.SpanContext, bool) { + c.mu.Lock() + defer c.mu.Unlock() + sc, ok := c.items[key] + + return sc, ok +} diff --git a/telemetry/telemetry_test.go b/telemetry/telemetry_test.go new file mode 100644 index 0000000..9975491 --- /dev/null +++ b/telemetry/telemetry_test.go @@ -0,0 +1,186 @@ +package telemetry_test + +import ( + "context" + "errors" + "fmt" + "testing" + "time" + + "go.opentelemetry.io/otel/baggage" + "go.opentelemetry.io/otel/codes" + "go.opentelemetry.io/otel/trace" + + "github.com/xraph/dispatch/internal/metricstest" + "github.com/xraph/dispatch/internal/oteltest" + "github.com/xraph/dispatch/telemetry" +) + +func TestQueueLabelCollapsesUnconfiguredQueues(t *testing.T) { + tel := telemetry.New(telemetry.WithQueues("default", "emails", "")) + + for queue, want := range map[string]string{ + "default": "default", + "emails": "emails", + "tenant-42": telemetry.OtherQueue, + "alice@example.com": telemetry.OtherQueue, + "": telemetry.OtherQueue, + } { + if got := tel.QueueLabel(queue); got != want { + t.Errorf("QueueLabel(%q) = %q, want %q", queue, got, want) + } + } + + var nilTel *telemetry.Telemetry + if got := nilTel.QueueLabel("default"); got != telemetry.OtherQueue { + t.Errorf("nil Telemetry QueueLabel = %q", got) + } +} + +func TestMetricsRecordOnlyDocumentedLabelValues(t *testing.T) { + f := metricstest.New() + tel := telemetry.New(telemetry.WithMetrics(f), telemetry.WithQueues("default")) + jobs := tel.Jobs() + + jobs.Attempt("default", telemetry.OutcomeCompleted, time.Second) + jobs.Attempt(tel.QueueLabel("customer-queue"), telemetry.OutcomeRetry, time.Second) + // Neither value is in its label's set, so neither creates a series. + jobs.Attempt("customer-queue", telemetry.OutcomeCompleted, time.Second) + jobs.Attempt("default", "boom: alice@example.com", time.Second) + + if n, ok := f.HistogramCount(telemetry.MetricJobAttemptDuration, "queue", "default", "outcome", "completed"); !ok || n != 1 { + t.Fatalf("completed attempt count = %d, %v", n, ok) + } + if n, ok := f.HistogramCount(telemetry.MetricJobAttemptDuration, "queue", "other", "outcome", "retry"); !ok || n != 1 { + t.Fatalf("collapsed queue count = %d, %v", n, ok) + } + if got := len(f.Series(telemetry.MetricJobAttemptDuration)); got != 2 { + t.Fatalf("attempt series = %d, want 2: %v", got, f.Series(telemetry.MetricJobAttemptDuration)) + } + for _, labels := range f.Series(telemetry.MetricJobAttemptDuration) { + if len(labels) != 2 || labels["queue"] == "" || labels["outcome"] == "" { + t.Errorf("series labels = %v, want exactly queue and outcome", labels) + } + } +} + +func TestNilTelemetryIsSafe(t *testing.T) { + var tel *telemetry.Telemetry + tel.Jobs().Attempt("default", telemetry.OutcomeCompleted, time.Second) + tel.Cron().Leader(true) + tel.Workflows().Step("step", "ok", time.Second) + tel.Durable().Task("workflow", "ok", time.Second) + tel.Outbox().Delivery("relay", telemetry.OutboxAcknowledged, time.Second) + tel.Artifacts().BytesReclaimed(10) + tel.RememberEnqueue("job", trace.SpanContext{}) + if links := tel.EnqueueLinks("job"); links != nil { + t.Fatalf("nil Telemetry links = %v", links) + } + _, span := tel.Start(context.Background(), "noop") + span.End() + + // A Telemetry without a factory records nothing either. + if telemetry.New().Jobs() != nil { + t.Fatal("Jobs() without a factory should be nil") + } +} + +func TestDetachDropsSpanAndBaggage(t *testing.T) { + ctx := oteltest.SpanContext(t) + member, err := baggage.NewMember("user", "alice") + if err != nil { + t.Fatal(err) + } + bag, err := baggage.New(member) + if err != nil { + t.Fatal(err) + } + ctx = baggage.ContextWithBaggage(ctx, bag) + ctx, cancel := context.WithCancel(ctx) + + detached := telemetry.Detach(ctx) + if trace.SpanContextFromContext(detached).IsValid() { + t.Fatal("Detach kept the span") + } + if baggage.FromContext(detached).Len() != 0 { + t.Fatal("Detach kept the baggage") + } + cancel() + if detached.Err() == nil { + t.Fatal("Detach dropped cancellation") + } +} + +func TestEnqueueLinksAreBounded(t *testing.T) { + tel := telemetry.New() + sc := func(i int) trace.SpanContext { + var tid trace.TraceID + var sid trace.SpanID + tid[0], sid[0] = byte(i%250+1), byte(i%250+1) + tid[1], sid[1] = byte(i/250+1), byte(i/250+1) + return trace.NewSpanContext(trace.SpanContextConfig{TraceID: tid, SpanID: sid, TraceFlags: trace.FlagsSampled}) + } + + tel.RememberEnqueue("first", sc(0)) + if links := tel.EnqueueLinks("first"); len(links) != 1 || links[0].SpanContext.SpanID() != sc(0).SpanID() { + t.Fatalf("links = %v", links) + } + // A retry reads it again. + if links := tel.EnqueueLinks("first"); len(links) != 1 { + t.Fatalf("second read lost the link: %v", links) + } + // An invalid span context is never remembered. + tel.RememberEnqueue("untraced", trace.SpanContext{}) + if links := tel.EnqueueLinks("untraced"); links != nil { + t.Fatalf("untraced links = %v", links) + } + + for i := 1; i <= 5000; i++ { + tel.RememberEnqueue(fmt.Sprintf("job-%d", i), sc(i)) + } + if links := tel.EnqueueLinks("first"); links != nil { + t.Fatal("the oldest entry outlived the cache bound") + } + if links := tel.EnqueueLinks("job-5000"); len(links) != 1 { + t.Fatal("the newest entry is missing") + } +} + +func TestFailRecordsClassAndTypeOnly(t *testing.T) { + sr := oteltest.Record(t) + _, span := telemetry.New().Start(context.Background(), "work") + err := fmt.Errorf("deliver to alice@example.com: %w", context.DeadlineExceeded) + telemetry.Fail(span, "delivery failed", telemetry.ErrorType(err)) + span.End() + + spans := sr.Ended() + if len(spans) != 1 { + t.Fatalf("spans = %d", len(spans)) + } + if spans[0].Status().Code != codes.Error || spans[0].Status().Description != "delivery failed" { + t.Fatalf("status = %+v", spans[0].Status()) + } + if got := spans[0].Events()[0].Attributes[0].Value.AsString(); got != "context.DeadlineExceeded" { + t.Fatalf("exception.type = %q", got) + } + oteltest.AssertNoValue(t, spans, "alice@example.com") +} + +type innerError struct{ msg string } + +func (e *innerError) Error() string { return e.msg } + +func TestErrorTypeNamesInnermostError(t *testing.T) { + inner := &innerError{msg: "alice@example.com"} + for err, want := range map[error]string{ + nil: "", + fmt.Errorf("outer: %w", inner): "*telemetry_test.innerError", + fmt.Errorf("stop: %w", context.Canceled): "context.Canceled", + errors.New("dial tcp 10.0.0.1: refused"): "*errors.errorString", + fmt.Errorf("a: %w", fmt.Errorf("b: %w", inner)): "*telemetry_test.innerError", + } { + if got := telemetry.ErrorType(err); got != want { + t.Errorf("ErrorType(%v) = %q, want %q", err, got, want) + } + } +} From 873fc292cdc8b6155336a59c612f2a4523499d76 Mon Sep 17 00:00:00 2001 From: Rex Raphael Date: Sat, 17 Oct 2026 23:28:20 -0500 Subject: [PATCH 03/18] feat(worker): trace each job attempt and its terminal path The pool now starts one root "process job" span per attempt in runJob, so the terminal write, the dead letter push and every lifecycle hook, JobStarted included, run inside it. The middleware span used to end before any of that happened. The attempt is its own trace; when this process enqueued the job it links back to the enqueue span instead of parenting off it, and nothing about the trace is stored with the job. Each terminal path gets a child span (complete job, schedule job retry, dead-letter job, requeue job, abandon job), and the attempt's outcome, exec status, executor and dead letter reason land on the process span. A lost lease adds a "lease lost" event to the attempt the heartbeat cancels. The tracing middleware's span is renamed from dispatch.job.execute to "run job handler" and nests under the attempt. It no longer copies err.Error() into the status or records the error with its message: a handler error can quote its payload. Success leaves the status unset. You also get the pool and runner metrics: attempts by queue and outcome, dead letters by reason, queue wait, polls, requeues, lease renewals, reclaimed jobs and the active attempt gauge. A reaper pass that reclaims anything leaves one root span; an empty pass, like an empty poll, records only a counter. --- artifact/staging/middleware.go | 13 +- middleware/tracing.go | 26 +-- middleware/tracing_test.go | 56 +++-- worker/admission.go | 9 +- worker/export_test.go | 2 +- worker/pool.go | 91 +++++++- worker/runner.go | 104 ++++++++- worker/telemetry.go | 161 ++++++++++++++ worker/telemetry_test.go | 383 +++++++++++++++++++++++++++++++++ 9 files changed, 805 insertions(+), 40 deletions(-) create mode 100644 worker/telemetry.go create mode 100644 worker/telemetry_test.go diff --git a/artifact/staging/middleware.go b/artifact/staging/middleware.go index e6c3591..53a9ab0 100644 --- a/artifact/staging/middleware.go +++ b/artifact/staging/middleware.go @@ -6,12 +6,15 @@ import ( "fmt" log "github.com/xraph/go-utils/log" + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/trace" "github.com/xraph/dispatch" "github.com/xraph/dispatch/artifact" "github.com/xraph/dispatch/artifact/cache" "github.com/xraph/dispatch/job" "github.com/xraph/dispatch/middleware" + "github.com/xraph/dispatch/telemetry" ) // SpecLookup resolves a job name to its declared inputs. The engine @@ -72,7 +75,15 @@ func Middleware( return verr } - staged, release, serr := stageInputs(ctx, svc, c, specs, bindings, cfg.Logger) + // Nested under the attempt's span when there is one, and absent + // when there is not: staging has no Telemetry of its own. + stageCtx, span := telemetry.StartChild(ctx, "stage job inputs", + trace.WithAttributes(attribute.Int("dispatch.job.inputs", len(bindings)))) + staged, release, serr := stageInputs(stageCtx, svc, c, specs, bindings, cfg.Logger) + if serr != nil { + telemetry.Fail(span, "staging failed", telemetry.ErrorType(serr)) + } + span.End() // Release before returning whatever happens — including a panic // unwinding through here — or a failed job would pin cache entries diff --git a/middleware/tracing.go b/middleware/tracing.go index 5d8455a..f73dec6 100644 --- a/middleware/tracing.go +++ b/middleware/tracing.go @@ -5,22 +5,27 @@ import ( "go.opentelemetry.io/otel" "go.opentelemetry.io/otel/attribute" - "go.opentelemetry.io/otel/codes" "go.opentelemetry.io/otel/trace" "github.com/xraph/dispatch/job" + "github.com/xraph/dispatch/telemetry" ) // tracerName is the instrumentation scope name for dispatch tracing. const tracerName = "github.com/xraph/dispatch" -// Tracing returns middleware that wraps job execution in an OpenTelemetry span. -// If no TracerProvider is configured globally, the default noop tracer is used -// and this middleware becomes a pass-through with zero overhead. +// Tracing returns middleware that wraps the rest of the chain, and the +// handler, in an OpenTelemetry span named "run job handler". If no +// TracerProvider is configured globally, the default noop tracer is used and +// this middleware becomes a pass-through with zero overhead. // -// Span attributes include: dispatch.job.id, dispatch.job.name, dispatch.queue, -// dispatch.retry_count, dispatch.scope.app_id, dispatch.scope.org_id. -// On error, the span status is set to codes.Error with the error message. +// Inside an engine the worker pool already gives every attempt a root +// "process job" span, and this span is its child. Span attributes include: +// dispatch.job.id, dispatch.job.name, dispatch.queue, dispatch.retry_count, +// dispatch.scope.app_id, dispatch.scope.org_id. When the handler fails the +// span gets an Error status with a fixed description and an exception event +// carrying only exception.type. The error's message is never recorded: a +// handler error can quote its payload. func Tracing() Middleware { tracer := otel.Tracer(tracerName) return TracingWithTracer(tracer) @@ -31,7 +36,7 @@ func Tracing() Middleware { // when multiple providers are in use. func TracingWithTracer(tracer trace.Tracer) Middleware { return func(ctx context.Context, j *job.Job, next Handler) error { - ctx, span := tracer.Start(ctx, "dispatch.job.execute", + ctx, span := tracer.Start(ctx, "run job handler", trace.WithAttributes( attribute.String("dispatch.job.id", j.ID.String()), attribute.String("dispatch.job.name", j.Name), @@ -46,10 +51,7 @@ func TracingWithTracer(tracer trace.Tracer) Middleware { err := next(ctx) if err != nil { - span.RecordError(err) - span.SetStatus(codes.Error, err.Error()) - } else { - span.SetStatus(codes.Ok, "") + telemetry.Fail(span, "handler error", telemetry.ErrorType(err)) } return err diff --git a/middleware/tracing_test.go b/middleware/tracing_test.go index 1618aa2..00eecc2 100644 --- a/middleware/tracing_test.go +++ b/middleware/tracing_test.go @@ -3,6 +3,7 @@ package middleware_test import ( "context" "errors" + "strings" "testing" "go.opentelemetry.io/otel/attribute" @@ -51,8 +52,8 @@ func TestTracing_CreatesSpan(t *testing.T) { t.Fatalf("expected 1 span, got %d", len(spans)) } - if spans[0].Name() != "dispatch.job.execute" { - t.Errorf("expected span name %q, got %q", "dispatch.job.execute", spans[0].Name()) + if spans[0].Name() != "run job handler" { + t.Errorf("expected span name %q, got %q", "run job handler", spans[0].Name()) } } @@ -102,7 +103,7 @@ func TestTracing_SpanAttributes(t *testing.T) { } } -func TestTracing_Success_SetsOkStatus(t *testing.T) { +func TestTracing_Success_LeavesStatusUnset(t *testing.T) { sr, tracer := setupTestTracer() m := mw.TracingWithTracer(tracer) j := newTestJob() @@ -116,8 +117,8 @@ func TestTracing_Success_SetsOkStatus(t *testing.T) { t.Fatalf("expected 1 span, got %d", len(spans)) } - if spans[0].Status().Code != codes.Ok { - t.Errorf("expected status Ok, got %v", spans[0].Status().Code) + if spans[0].Status().Code != codes.Unset { + t.Errorf("expected status Unset, got %v", spans[0].Status().Code) } } @@ -126,7 +127,7 @@ func TestTracing_Error_SetsErrorStatus(t *testing.T) { m := mw.TracingWithTracer(tracer) j := newTestJob() - handlerErr := errors.New("handler failed") + handlerErr := errors.New("charge alice@example.com failed") err := m(context.Background(), j, func(_ context.Context) error { return handlerErr }) @@ -142,22 +143,32 @@ func TestTracing_Error_SetsErrorStatus(t *testing.T) { if spans[0].Status().Code != codes.Error { t.Errorf("expected status Error, got %v", spans[0].Status().Code) } - if spans[0].Status().Description != "handler failed" { - t.Errorf("expected status description %q, got %q", "handler failed", spans[0].Status().Description) + if spans[0].Status().Description != "handler error" { + t.Errorf("expected status description %q, got %q", "handler error", spans[0].Status().Description) } - // Verify error event was recorded. + // The exception event names the error's type and nothing else: a + // handler error can quote its payload. events := spans[0].Events() found := false for _, ev := range events { - if ev.Name == "exception" { - found = true - break + if ev.Name != "exception" { + continue + } + found = true + for _, a := range ev.Attributes { + if a.Key == "exception.message" || a.Key == "exception.stacktrace" { + t.Errorf("exception event carries %s", a.Key) + } + if a.Key == "exception.type" && a.Value.AsString() != "*errors.errorString" { + t.Errorf("exception.type = %q", a.Value.AsString()) + } } } if !found { t.Error("expected 'exception' event to be recorded on span") } + assertNoValue(t, spans[0], "alice@example.com") } func TestTracing_PropagatesContext(t *testing.T) { @@ -202,3 +213,24 @@ func TestTracing_DefaultNoopSafe(t *testing.T) { t.Error("handler was not called") } } + +// assertNoValue fails when s carries needle in its status, any attribute or +// any event attribute. +func assertNoValue(t *testing.T, s sdktrace.ReadOnlySpan, needle string) { + t.Helper() + if strings.Contains(s.Status().Description, needle) { + t.Errorf("span %q status quotes %q", s.Name(), needle) + } + for _, a := range s.Attributes() { + if strings.Contains(a.Value.String(), needle) { + t.Errorf("span %q attribute %s quotes %q", s.Name(), a.Key, needle) + } + } + for _, ev := range s.Events() { + for _, a := range ev.Attributes { + if strings.Contains(a.Value.String(), needle) { + t.Errorf("span %q event %q attribute %s quotes %q", s.Name(), ev.Name, a.Key, needle) + } + } + } +} diff --git a/worker/admission.go b/worker/admission.go index 6565fa9..bf4a5e1 100644 --- a/worker/admission.go +++ b/worker/admission.go @@ -5,9 +5,11 @@ import ( "time" log "github.com/xraph/go-utils/log" + "go.opentelemetry.io/otel/trace" "github.com/xraph/dispatch/job" "github.com/xraph/dispatch/resource" + "github.com/xraph/dispatch/telemetry" ) // admitted is a claimed job together with the local resource lease held @@ -49,6 +51,11 @@ type inflight struct { // defaults. Held here so the renewal loop does not issue a GetJob per // job per interval purely to recover a duration it already knew. leaseTTL time.Duration + + // span is the attempt's "process job" span, so the heartbeat loop can + // note a lost lease on the attempt it cancels. Nil when the attempt was + // tracked without one. + span trace.Span } // dequeueBudget is the capacity ceiling this worker offers the store, @@ -237,7 +244,7 @@ func (p *Pool) requeueLocalMisfit(j *job.Job, cause error) { log.String("error", cause.Error()), ) - p.requeueRateLimited(j) + p.requeueDelayed(j, telemetry.RequeueNoCapacity) } // releaseQueueSlot returns the queue/tenant token acquired for j, if the diff --git a/worker/export_test.go b/worker/export_test.go index 9c78779..fe282d7 100644 --- a/worker/export_test.go +++ b/worker/export_test.go @@ -32,7 +32,7 @@ func (p *Pool) ReclaimOnce(ctx context.Context) { // without running the pool's goroutines or the executor. func (p *Pool) TrackJob(jobID string, leaseEpoch int, leaseTTL time.Duration) context.Context { ctx, cancel := context.WithCancelCause(context.Background()) - p.trackJob(jobID, cancel, nil, leaseEpoch, leaseTTL) + p.trackJob(jobID, cancel, nil, leaseEpoch, leaseTTL, nil) return ctx } diff --git a/worker/pool.go b/worker/pool.go index b7fdf39..ca43394 100644 --- a/worker/pool.go +++ b/worker/pool.go @@ -9,11 +9,13 @@ import ( "time" log "github.com/xraph/go-utils/log" + "go.opentelemetry.io/otel/trace" "github.com/xraph/dispatch/ext" "github.com/xraph/dispatch/id" "github.com/xraph/dispatch/job" "github.com/xraph/dispatch/resource" + "github.com/xraph/dispatch/telemetry" ) // isTransientStoreErr reports whether err is a transient store failure — @@ -137,6 +139,10 @@ type Pool struct { // overriding the keys derived from the manager's capacity. customKeys []string + // tel is where the pool's spans and metrics go. Nil records no metrics + // and starts spans on the global tracer provider. + tel *telemetry.Telemetry + stopCh chan struct{} wakeCh chan struct{} // nudges the fetcher out of its idle backoff jobCh chan admitted // hand-off from the fetcher to the workers @@ -267,6 +273,14 @@ func WithWorkerCustomKeys(keys []string) PoolOption { return func(p *Pool) { p.customKeys = slices.Clone(keys) } } +// WithTelemetry sets where the pool records its spans and metrics: one +// root "process job" span per attempt, and the poll, requeue, lease and +// reclaim counters. engine.Build passes the engine's own; without it the +// pool records no metrics and starts spans on the global tracer provider. +func WithTelemetry(t *telemetry.Telemetry) PoolOption { + return func(p *Pool) { p.tel = t } +} + // WithStoreCallTimeout caps a single store roundtrip. Pass a positive // duration to override defaultStoreCallTimeout, zero to leave the // default in place, or a negative value to disable the timeout @@ -587,6 +601,7 @@ func (p *Pool) fetchLoop() { if p.cancelCtx.Err() != nil { return // Clean exit during shutdown } + p.tel.Jobs().Poll(telemetry.PollError) p.logger.Error("dequeue error", log.String("error", err.Error())) // Back off on errors too; hot-spinning at pollInterval only // piles onto a struggling store. @@ -601,6 +616,12 @@ func (p *Pool) fetchLoop() { continue } + if len(jobs) == 0 { + p.tel.Jobs().Poll(telemetry.PollEmpty) + } else { + p.tel.Jobs().Poll(telemetry.PollWork) + } + // dispatched counts jobs actually handed to a worker, which is what // paces the loop below — len(jobs) is not, because a refused job // never reaches the blocking hand-off that used to do the pacing. @@ -747,6 +768,13 @@ func clearJobAssignment(j *job.Job) { // requeueRateLimited returns a job the queue manager refused to pending // with a small delay. func (p *Pool) requeueRateLimited(j *job.Job) { + p.requeueDelayed(j, telemetry.RequeueRateLimited) +} + +// requeueDelayed returns a claimed job to pending one poll interval out, +// counting it under reason. +func (p *Pool) requeueDelayed(j *job.Job, reason string) { + p.tel.Jobs().Requeued(p.tel.QueueLabel(j.Queue), reason) j.State = job.StatePending j.RunAt = time.Now().Add(p.pollInterval) clearJobAssignment(j) @@ -765,6 +793,7 @@ func (p *Pool) requeueRateLimited(j *job.Job) { // pending during shutdown so it isn't stranded in the running state with no // heartbeat. Uses a fresh context: the pool's own contexts are already done. func (p *Pool) requeueUndispatched(j *job.Job) { + p.tel.Jobs().Requeued(p.tel.QueueLabel(j.Queue), telemetry.RequeueShutdown) ctx, cancel := context.WithTimeout(context.Background(), 2*time.Second) defer cancel() j.State = job.StatePending @@ -805,10 +834,26 @@ func (p *Pool) runJob(a admitted) { j := a.job - p.extensions.EmitJobStarted(p.cancelCtx, j) + // The attempt's root span. It is started here rather than in the + // middleware chain so the terminal write, the dead letter push and + // every lifecycle hook (including JobStarted below) fall inside it. + // p.cancelCtx descends from context.Background, so nothing inherited + // can parent it. + spanCtx, span := p.startAttemptSpan(j) + defer span.End() + + if !j.RunAt.IsZero() { + p.tel.Jobs().QueueWait(p.tel.QueueLabel(j.Queue), time.Since(j.RunAt)) + } + + rec := &attempt{} + spanCtx = withAttempt(spanCtx, rec) + defer func() { endAttemptSpan(span, rec) }() - ctx, cancel := context.WithCancelCause(p.cancelCtx) - p.trackJob(j.ID.String(), cancel, a.lease, j.LeaseEpoch, p.leaseTTLFor(j)) + p.extensions.EmitJobStarted(spanCtx, j) + + ctx, cancel := context.WithCancelCause(spanCtx) + p.trackJob(j.ID.String(), cancel, a.lease, j.LeaseEpoch, p.leaseTTLFor(j), span) // A fenced terminal write needs the store's lease capability, this // pool's worker ID, and the epoch j.LeaseEpoch carries from the @@ -898,7 +943,10 @@ func (p *Pool) sendHeartbeats() { hbCtx, hbCancel := p.callCtx() err := p.store.HeartbeatJob(hbCtx, parsedID, p.workerID) hbCancel() - if err != nil { + if err == nil { + p.tel.Jobs().Renewal(telemetry.RenewalOK) + } else { + p.tel.Jobs().Renewal(telemetry.RenewalError) p.logger.Warn("heartbeat failed", log.String("job_id", snap.jobID), log.String("error", err.Error()), @@ -913,10 +961,12 @@ func (p *Pool) sendHeartbeats() { ) hbCancel() if renewErr == nil { + p.tel.Jobs().Renewal(telemetry.RenewalOK) continue } if errors.Is(renewErr, job.ErrLeaseLost) { + p.tel.Jobs().Renewal(telemetry.RenewalLost) p.logger.Warn("lease lost, cancelling job", log.String("job_id", snap.jobID), ) @@ -924,6 +974,8 @@ func (p *Pool) sendHeartbeats() { continue } + p.tel.Jobs().Renewal(telemetry.RenewalError) + // A transient store blip must not cancel a healthy job; only a // definitive ErrLeaseLost above does that. p.logger.Warn("lease renewal failed", @@ -972,6 +1024,7 @@ func (p *Pool) reapStaleJobs() { // does the claim and the read in one statement, so unlike the legacy // path two pools cannot both reset the same job. func (p *Pool) reclaimExpiredLeases() { + started := time.Now() reapCtx, reapCancel := p.callCtx() reclaimed, err := p.leaseStore.ReclaimExpiredLeases(reapCtx, DefaultReclaimBatch) reapCancel() @@ -985,6 +1038,8 @@ func (p *Pool) reclaimExpiredLeases() { return } + p.recordReclaim(started, len(reclaimed)) + for _, j := range reclaimed { p.logger.Info("reclaimed expired lease", log.String("job_id", j.ID.String()), @@ -1000,6 +1055,7 @@ func (p *Pool) reclaimExpiredLeases() { } func (p *Pool) reapStaleJobsLegacy() { + started := time.Now() reapCtx, reapCancel := p.callCtx() stale, err := p.store.ReapStaleJobs(reapCtx, p.staleJobThreshold) reapCancel() @@ -1039,6 +1095,8 @@ func (p *Pool) reapStaleJobsLegacy() { ) } + p.recordReclaim(started, reset) + // The reset jobs are pending again; wake the fetcher so they are // retried now rather than after the idle poll backoff. if reset > 0 { @@ -1046,6 +1104,24 @@ func (p *Pool) reapStaleJobsLegacy() { } } +// recordReclaim counts jobs a reaper pass returned to pending and, when there +// were any, leaves a root span for the pass. An empty pass, the usual case, +// records nothing: the reaper ticks every few seconds, and a trace per tick +// would bury the ones that matter. The span starts when the pass did, so +// its duration is the pass's own. +func (p *Pool) recordReclaim(started time.Time, n int) { + if n == 0 { + return + } + p.tel.Jobs().Reclaimed(n) + _, span := p.tel.Start(p.cancelCtx, "reclaim job leases", + trace.WithNewRoot(), + trace.WithTimestamp(started), + trace.WithAttributes(attrReclaimed.Int(n)), + ) + span.End() +} + // trackJob records one job's cancel func, resource lease, and job-lease // bookkeeping so the heartbeat loop and shutdown path can act on it. // @@ -1058,6 +1134,7 @@ func (p *Pool) trackJob( lease resource.Lease, leaseEpoch int, leaseTTL time.Duration, + span trace.Span, ) { p.activeMu.Lock() p.activeJobs[jobID] = &inflight{ @@ -1065,7 +1142,9 @@ func (p *Pool) trackJob( lease: lease, leaseEpoch: leaseEpoch, leaseTTL: leaseTTL, + span: span, } + p.tel.Jobs().Active(len(p.activeJobs)) p.activeMu.Unlock() } @@ -1081,6 +1160,7 @@ func (p *Pool) untrackJob(jobID string) *inflight { } delete(p.activeJobs, jobID) + p.tel.Jobs().Active(len(p.activeJobs)) return rec } @@ -1106,5 +1186,8 @@ func (p *Pool) cancelJob(jobID string, cause error) { return } + if rec.span != nil && errors.Is(cause, job.ErrLeaseLost) { + rec.span.AddEvent("lease lost") + } rec.cancel(cause) } diff --git a/worker/runner.go b/worker/runner.go index 03e6f57..d714b8e 100644 --- a/worker/runner.go +++ b/worker/runner.go @@ -18,6 +18,7 @@ import ( "time" log "github.com/xraph/go-utils/log" + "go.opentelemetry.io/otel/trace" "github.com/xraph/dispatch" "github.com/xraph/dispatch/artifact" @@ -28,6 +29,7 @@ import ( "github.com/xraph/dispatch/id" "github.com/xraph/dispatch/job" "github.com/xraph/dispatch/middleware" + "github.com/xraph/dispatch/telemetry" ) // maxLaunchAttempts bounds how many times one job may fail to launch on this @@ -114,6 +116,9 @@ type Runner struct { // living on the job value. launchMu sync.Mutex launches map[string]launchAttempt + + // tel records attempt and dead letter metrics. Nil records none. + tel *telemetry.Telemetry } // launchAttempt is one job's running launch-failure count on this worker. @@ -167,6 +172,17 @@ func (r *Runner) WithArtifacts(svc *artifact.Service, scratchRoot string) *Runne return r } +// WithTelemetry sets where the runner records attempt and dead letter +// metrics, and returns r so callers can chain it onto NewRunner. Its spans +// (one per terminal path, plus "commit job outputs") nest under whatever +// span the attempt's context carries, the pool's "process job" span in +// practice, and are not started without one. +func (r *Runner) WithTelemetry(t *telemetry.Telemetry) *Runner { + r.tel = t + + return r +} + // Reclaim asks every configured executor to release sandboxes this worker // leaked across a restart, and removes stale scratch output directories // a previous process left behind. The pool calls it once at startup. @@ -247,6 +263,23 @@ func (r *Runner) Close() error { // cancelled it, or JobFailed otherwise, so extensions still observe // the loss. func (r *Runner) Execute(ctx context.Context, j *job.Job) error { + started := time.Now() + rec := attemptFrom(ctx) + if rec == nil { + rec = &attempt{} + ctx = withAttempt(ctx, rec) + } + defer func() { + if rec.outcome != "" { + r.tel.Jobs().Attempt(r.tel.QueueLabel(j.Queue), rec.outcome, time.Since(started)) + } + }() + + return r.execute(ctx, j) +} + +// execute is Execute without the attempt bookkeeping. +func (r *Runner) execute(ctx context.Context, j *job.Job) error { at := &attemptUsage{} terminal, err := r.terminalFor(j, at) @@ -330,6 +363,9 @@ func (r *Runner) terminalFor(j *job.Job, at *attemptUsage) (middleware.Handler, } return func(ctx context.Context) error { + if a := attemptFrom(ctx); a != nil { + a.executor = executor.Name() + } req := r.request(j, policy) // A rung above in-process gets a scratch directory to write its @@ -741,9 +777,18 @@ func (r *Runner) commitOutputs(ctx context.Context, j *job.Job, req *exec.Reques return nil } + ctx, span := telemetry.StartChild(ctx, "commit job outputs", + trace.WithAttributes(attrOutputs.Int(len(entries)))) + defer span.End() + owner := artifact.OwnerRef{Kind: artifact.OwnerJob, ID: j.ID.String()} - return r.commitOutputEntries(ctx, owner, j.RetryCount, fenceToken(ctx), entries) + err = r.commitOutputEntries(ctx, owner, j.RetryCount, fenceToken(ctx), entries) + if err != nil { + telemetry.Fail(span, "commit failed", jobErrorType(err)) + } + + return err } // collectOutputEntries walks dir for the regular files a sandbox left @@ -1029,9 +1074,13 @@ func (r *Runner) updateJob(ctx context.Context, j *job.Job) error { // has just cancelled, and a read through it would fail on every backend // that honours the context. func (r *Runner) abandonLostLease(ctx context.Context, j *job.Job, cause error) error { + ctx, span := telemetry.StartChild(ctx, "abandon job") + defer span.End() + detached := context.WithoutCancel(ctx) if cur := r.cancelledRow(detached, j.ID); cur != nil { + setOutcome(ctx, telemetry.OutcomeCancelled, nil) r.logger.Info("job cancelled while running, discarding terminal write", log.String("job_id", j.ID.String()), log.String("job_name", j.Name), @@ -1042,6 +1091,7 @@ func (r *Runner) abandonLostLease(ctx context.Context, j *job.Job, cause error) return cause } + setOutcome(ctx, telemetry.OutcomeLeaseLost, nil) r.logger.Warn("lease lost, discarding terminal write", log.String("job_id", j.ID.String()), log.String("job_name", j.Name), @@ -1075,6 +1125,9 @@ func (r *Runner) cancelledRow(ctx context.Context, jobID id.JobID) *job.Job { // handleSuccess marks the job as completed and emits the lifecycle event. func (r *Runner) handleSuccess(ctx context.Context, j *job.Job, now time.Time, elapsed time.Duration) error { + ctx, span := telemetry.StartChild(ctx, "complete job") + defer span.End() + r.forgetLaunchFailures(j.ID.String()) j.State = job.StateCompleted @@ -1085,6 +1138,7 @@ func (r *Runner) handleSuccess(ctx context.Context, j *job.Job, now time.Time, e return r.abandonLostLease(ctx, j, updateErr) } + r.storeFailed(ctx, span, updateErr) r.logger.Error("failed to update job after success", log.String("job_id", j.ID.String()), log.String("job_name", j.Name), @@ -1093,10 +1147,18 @@ func (r *Runner) handleSuccess(ctx context.Context, j *job.Job, now time.Time, e return updateErr } + setOutcome(ctx, telemetry.OutcomeCompleted, nil) r.extensions.EmitJobCompleted(ctx, j, elapsed) return nil } +// storeFailed reports a terminal write that failed for a reason other than +// a lost lease. +func (r *Runner) storeFailed(ctx context.Context, span trace.Span, err error) { + setOutcome(ctx, telemetry.OutcomeStoreError, err) + telemetry.Fail(span, "store error", jobErrorType(err)) +} + // handleFailure either requeues the job or increments the retry counter and // retries, depending on whether the failure was the work's fault. // @@ -1124,10 +1186,10 @@ func (r *Runner) handleFailure(ctx context.Context, j *job.Job, handlerErr error dispatch.ErrPermanent, j.Name, n, j.LastError) j.LastError = capped.Error() - return r.sendToDLQ(ctx, j, capped) + return r.sendToDLQ(ctx, j, capped, telemetry.DeadLetterLaunchFailures) } - return r.requeueAfterLaunchFailure(ctx, j, now) + return r.requeueAfterLaunchFailure(ctx, j, now, handlerErr) } j.RetryCount++ @@ -1145,14 +1207,14 @@ func (r *Runner) handleFailure(ctx context.Context, j *job.Job, handlerErr error log.String("error", handlerErr.Error()), ) - return r.sendToDLQ(ctx, j, handlerErr) + return r.sendToDLQ(ctx, j, handlerErr, telemetry.DeadLetterPermanent) } if j.RetryCount <= j.MaxRetries { - return r.scheduleRetry(ctx, j, now) + return r.scheduleRetry(ctx, j, now, handlerErr) } - return r.sendToDLQ(ctx, j, handlerErr) + return r.sendToDLQ(ctx, j, handlerErr, telemetry.DeadLetterRetriesExhausted) } // recordLaunchFailure counts one launch failure for a job and returns the @@ -1190,7 +1252,10 @@ func (r *Runner) forgetLaunchFailures(jobID string) { // requeueAfterLaunchFailure returns the job to pending with a backoff // delay derived from the retry count without advancing it. -func (r *Runner) requeueAfterLaunchFailure(ctx context.Context, j *job.Job, now time.Time) error { +func (r *Runner) requeueAfterLaunchFailure(ctx context.Context, j *job.Job, now time.Time, cause error) error { + ctx, span := telemetry.StartChild(ctx, "requeue job") + defer span.End() + delay := r.backoff.Delay(j.RetryCount + 1) j.RunAt = now.Add(delay) j.State = job.StatePending @@ -1201,6 +1266,7 @@ func (r *Runner) requeueAfterLaunchFailure(ctx context.Context, j *job.Job, now return r.abandonLostLease(ctx, j, updateErr) } + r.storeFailed(ctx, span, updateErr) r.logger.Error("failed to requeue job after launch failure", log.String("job_id", j.ID.String()), log.String("error", updateErr.Error()), @@ -1209,6 +1275,8 @@ func (r *Runner) requeueAfterLaunchFailure(ctx context.Context, j *job.Job, now return updateErr } + setOutcome(ctx, telemetry.OutcomeRequeued, cause) + r.logger.Warn("sandbox launch failed; requeued without consuming a retry", log.String("job_id", j.ID.String()), log.String("job_name", j.Name), @@ -1220,7 +1288,10 @@ func (r *Runner) requeueAfterLaunchFailure(ctx context.Context, j *job.Job, now } // scheduleRetry sets the job to StateRetrying with a backoff delay. -func (r *Runner) scheduleRetry(ctx context.Context, j *job.Job, now time.Time) error { +func (r *Runner) scheduleRetry(ctx context.Context, j *job.Job, now time.Time, cause error) error { + ctx, span := telemetry.StartChild(ctx, "schedule job retry") + defer span.End() + // The attempt reached the handler, so whatever launch trouble this job // had is behind it. r.forgetLaunchFailures(j.ID.String()) @@ -1235,6 +1306,7 @@ func (r *Runner) scheduleRetry(ctx context.Context, j *job.Job, now time.Time) e return r.abandonLostLease(ctx, j, updateErr) } + r.storeFailed(ctx, span, updateErr) r.logger.Error("failed to update job for retry", log.String("job_id", j.ID.String()), log.String("error", updateErr.Error()), @@ -1242,6 +1314,7 @@ func (r *Runner) scheduleRetry(ctx context.Context, j *job.Job, now time.Time) e return updateErr } + setOutcome(ctx, telemetry.OutcomeRetry, cause) r.extensions.EmitJobRetrying(ctx, j, j.RetryCount, nextRunAt) r.logger.Info("job scheduled for retry", @@ -1256,7 +1329,12 @@ func (r *Runner) scheduleRetry(ctx context.Context, j *job.Job, now time.Time) e } // sendToDLQ marks the job as failed, pushes it to the DLQ, and emits events. -func (r *Runner) sendToDLQ(ctx context.Context, j *job.Job, handlerErr error) error { +// reason is why it went there, for the dead letter metric. +func (r *Runner) sendToDLQ(ctx context.Context, j *job.Job, handlerErr error, reason string) error { + ctx, span := telemetry.StartChild(ctx, "dead-letter job", + trace.WithAttributes(attrDLQReason.String(reason))) + defer span.End() + r.forgetLaunchFailures(j.ID.String()) j.State = job.StateFailed @@ -1266,6 +1344,7 @@ func (r *Runner) sendToDLQ(ctx context.Context, j *job.Job, handlerErr error) er return r.abandonLostLease(ctx, j, updateErr) } + r.storeFailed(ctx, span, updateErr) r.logger.Error("failed to update job as failed", log.String("job_id", j.ID.String()), log.String("error", updateErr.Error()), @@ -1273,8 +1352,15 @@ func (r *Runner) sendToDLQ(ctx context.Context, j *job.Job, handlerErr error) er return updateErr } + setOutcome(ctx, telemetry.OutcomeDeadLettered, handlerErr) + if a := attemptFrom(ctx); a != nil { + a.dlqReason = reason + } + r.tel.Jobs().DeadLettered(r.tel.QueueLabel(j.Queue), reason) + if r.dlqService != nil { if dlqErr := r.dlqService.Push(ctx, j, handlerErr); dlqErr != nil { + telemetry.Fail(span, "dead letter push failed", jobErrorType(dlqErr)) r.logger.Error("failed to push job to DLQ", log.String("job_id", j.ID.String()), log.String("error", dlqErr.Error()), diff --git a/worker/telemetry.go b/worker/telemetry.go new file mode 100644 index 0000000..7226165 --- /dev/null +++ b/worker/telemetry.go @@ -0,0 +1,161 @@ +package worker + +import ( + "context" + "errors" + + "go.opentelemetry.io/otel/attribute" + semconv "go.opentelemetry.io/otel/semconv/v1.43.0" + "go.opentelemetry.io/otel/trace" + + "github.com/xraph/dispatch" + "github.com/xraph/dispatch/exec" + "github.com/xraph/dispatch/job" + "github.com/xraph/dispatch/telemetry" +) + +// Span attribute keys the job attempt spans carry. +const ( + attrJobName = attribute.Key("dispatch.job.name") + attrJobAttempt = attribute.Key("dispatch.job.attempt") + attrJobMaxRetries = attribute.Key("dispatch.job.max_retries") + attrLeaseEpoch = attribute.Key("dispatch.job.lease_epoch") + attrOutcome = attribute.Key("dispatch.job.outcome") + attrExecStatus = attribute.Key("dispatch.job.exec_status") + attrExecutor = attribute.Key("dispatch.job.executor") + attrDLQReason = attribute.Key("dispatch.job.dlq_reason") + attrScopeAppID = attribute.Key("dispatch.scope.app_id") + attrScopeOrgID = attribute.Key("dispatch.scope.org_id") + attrReclaimed = attribute.Key("dispatch.lease.reclaimed") + attrOutputs = attribute.Key("dispatch.job.outputs") +) + +// messagingSystem is the messaging.system value on job spans. +var messagingSystem = semconv.MessagingSystemKey.String("dispatch") + +// attempt is what one job attempt reports back to whoever owns its span. +// Runner.Execute fills it in on the way through its terminal paths; the pool +// reads it when the attempt returns. +type attempt struct { + outcome string + errType string + execStatus string + dlqReason string + executor string +} + +type attemptKey struct{} + +func withAttempt(ctx context.Context, a *attempt) context.Context { + return context.WithValue(ctx, attemptKey{}, a) +} + +func attemptFrom(ctx context.Context) *attempt { + a, ok := ctx.Value(attemptKey{}).(*attempt) + if !ok { + return nil + } + + return a +} + +// setOutcome records how the attempt ended. cause is the failure that led +// there, nil for a success or a benign end. +func setOutcome(ctx context.Context, outcome string, cause error) { + a := attemptFrom(ctx) + if a == nil { + return + } + a.outcome = outcome + if cause == nil { + return + } + a.errType = jobErrorType(cause) + var execErr *exec.Error + if errors.As(cause, &execErr) { + a.execStatus = string(execErr.Status) + } +} + +// failureClass is the span status description for an outcome. Benign ends +// (completed, a lost lease, an operator's cancel) are not failures. +func failureClass(outcome string) string { + switch outcome { + case telemetry.OutcomeRetry: + return "handler error, retrying" + case telemetry.OutcomeDeadLettered: + return "handler error, dead-lettered" + case telemetry.OutcomeRequeued: + return "launch failed, requeued" + case telemetry.OutcomeStoreError: + return "store error" + default: + return "" + } +} + +// jobErrorType names a job failure for an exception event without its +// message: a Dispatch sentinel's name where one is in the chain, else the +// innermost error's Go type. +func jobErrorType(err error) string { + var execErr *exec.Error + switch { + case errors.Is(err, job.ErrLeaseLost): + return "job.ErrLeaseLost" + case errors.As(err, &execErr): + return "*exec.Error" + case errors.Is(err, dispatch.ErrPermanent): + return "dispatch.ErrPermanent" + default: + return telemetry.ErrorType(err) + } +} + +// startAttemptSpan starts the root span for one job attempt. The attempt is +// its own trace: the job crossed the store to get here, and the span that +// enqueued it (if this process did) is a link, not a parent. +func (p *Pool) startAttemptSpan(j *job.Job) (context.Context, trace.Span) { + attrs := []attribute.KeyValue{ + messagingSystem, + semconv.MessagingOperationTypeProcess, + semconv.MessagingOperationName("process"), + semconv.MessagingDestinationName(j.Queue), + semconv.MessagingMessageID(j.ID.String()), + attrJobName.String(j.Name), + attrJobAttempt.Int(j.RetryCount + 1), + attrJobMaxRetries.Int(j.MaxRetries), + attrLeaseEpoch.Int(j.LeaseEpoch), + } + if j.ScopeAppID != "" { + attrs = append(attrs, attrScopeAppID.String(j.ScopeAppID)) + } + if j.ScopeOrgID != "" { + attrs = append(attrs, attrScopeOrgID.String(j.ScopeOrgID)) + } + + return p.tel.Start(p.cancelCtx, "process job", + trace.WithNewRoot(), + trace.WithSpanKind(trace.SpanKindConsumer), + trace.WithLinks(p.tel.EnqueueLinks(j.ID.String())...), + trace.WithAttributes(attrs...), + ) +} + +// endAttemptSpan writes what the attempt reported onto its span. +func endAttemptSpan(span trace.Span, a *attempt) { + if a.outcome != "" { + span.SetAttributes(attrOutcome.String(a.outcome)) + } + if a.execStatus != "" { + span.SetAttributes(attrExecStatus.String(a.execStatus)) + } + if a.dlqReason != "" { + span.SetAttributes(attrDLQReason.String(a.dlqReason)) + } + if a.executor != "" { + span.SetAttributes(attrExecutor.String(a.executor)) + } + if class := failureClass(a.outcome); class != "" { + telemetry.Fail(span, class, a.errType) + } +} diff --git a/worker/telemetry_test.go b/worker/telemetry_test.go new file mode 100644 index 0000000..09fbaca --- /dev/null +++ b/worker/telemetry_test.go @@ -0,0 +1,383 @@ +package worker_test + +import ( + "context" + "encoding/json" + "fmt" + "sync" + "testing" + "time" + + log "github.com/xraph/go-utils/log" + "go.opentelemetry.io/otel/codes" + sdktrace "go.opentelemetry.io/otel/sdk/trace" + "go.opentelemetry.io/otel/trace" + + "github.com/xraph/dispatch" + "github.com/xraph/dispatch/backoff" + "github.com/xraph/dispatch/dlq" + "github.com/xraph/dispatch/ext" + "github.com/xraph/dispatch/id" + "github.com/xraph/dispatch/internal/metricstest" + "github.com/xraph/dispatch/internal/oteltest" + "github.com/xraph/dispatch/job" + "github.com/xraph/dispatch/middleware" + "github.com/xraph/dispatch/store/memory" + "github.com/xraph/dispatch/telemetry" + "github.com/xraph/dispatch/worker" +) + +const waitSpan = 5 * time.Second + +// spanCtxExt records the span context every lifecycle hook ran under. +type spanCtxExt struct { + mu sync.Mutex + seen map[string]trace.SpanContext +} + +func (e *spanCtxExt) Name() string { return "span-ctx" } + +func (e *spanCtxExt) record(ctx context.Context, hook string) { + e.mu.Lock() + defer e.mu.Unlock() + if e.seen == nil { + e.seen = map[string]trace.SpanContext{} + } + e.seen[hook] = trace.SpanContextFromContext(ctx) +} + +func (e *spanCtxExt) get(hook string) trace.SpanContext { + e.mu.Lock() + defer e.mu.Unlock() + return e.seen[hook] +} + +func (e *spanCtxExt) OnJobStarted(ctx context.Context, _ *job.Job) error { + e.record(ctx, "started") + return nil +} + +func (e *spanCtxExt) OnJobCompleted(ctx context.Context, _ *job.Job, _ time.Duration) error { + e.record(ctx, "completed") + return nil +} + +func (e *spanCtxExt) OnJobDLQ(ctx context.Context, _ *job.Job, _ error) error { + e.record(ctx, "dlq") + return nil +} + +type telemetryPool struct { + pool *worker.Pool + store *memory.Store + reg *job.Registry + tel *telemetry.Telemetry + metrics *metricstest.Factory + hooks *spanCtxExt +} + +func newTelemetryPool(t *testing.T, s job.Store, mem *memory.Store) *telemetryPool { + t.Helper() + logger := log.NewNoopLogger() + reg := job.NewRegistry() + extensions := ext.NewRegistry(logger) + hooks := &spanCtxExt{} + extensions.Register(hooks) + f := metricstest.New() + tel := telemetry.New(telemetry.WithMetrics(f), telemetry.WithQueues("default")) + + runner := worker.NewExecutor(reg, extensions, mem, dlq.NewService(mem, mem), + backoff.NewConstant(time.Hour), logger, middleware.Recover(logger)).WithTelemetry(tel) + pool := worker.NewPool(s, runner, extensions, logger, + worker.WithPoolConcurrency(1), + worker.WithPollInterval(10*time.Millisecond), + worker.WithPoolQueues([]string{"default"}), + worker.WithTelemetry(tel), + ) + t.Cleanup(func() { + ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) + defer cancel() + _ = pool.Stop(ctx) + }) + return &telemetryPool{pool: pool, store: mem, reg: reg, tel: tel, metrics: f, hooks: hooks} +} + +func (tp *telemetryPool) enqueue(t *testing.T, name string, payload any) *job.Job { + t.Helper() + data, err := json.Marshal(payload) + if err != nil { + t.Fatal(err) + } + now := time.Now().UTC() + j := &job.Job{ID: id.NewJobID(), Name: name, Queue: "default", Payload: data, + State: job.StatePending, MaxRetries: 3, RunAt: now} + j.CreatedAt, j.UpdatedAt = now, now + if err := tp.store.EnqueueJob(context.Background(), j); err != nil { + t.Fatal(err) + } + return j +} + +func childrenOf(spans []sdktrace.ReadOnlySpan, parent sdktrace.ReadOnlySpan, name string) []sdktrace.ReadOnlySpan { + var out []sdktrace.ReadOnlySpan + for _, s := range oteltest.Named(spans, name) { + if oteltest.ChildOf(s, parent) { + out = append(out, s) + } + } + return out +} + +func TestAttemptSpanOwnsTheTerminalPath(t *testing.T) { + sr := oteltest.Record(t) + mem := memory.New() + tp := newTelemetryPool(t, mem, mem) + job.RegisterDefinition(tp.reg, job.NewDefinition("greet", func(context.Context, struct{ Name string }) error { return nil })) + + // The process that enqueued the job remembered its span, so the attempt + // links back to it. + _, enqueueSpan := sdktrace.NewTracerProvider().Tracer("test").Start(context.Background(), "enqueue job") + j := tp.enqueue(t, "greet", struct{ Name string }{"Ada"}) + tp.tel.RememberEnqueue(j.ID.String(), enqueueSpan.SpanContext()) + enqueueSpan.End() + + if err := tp.pool.Start(oteltest.SpanContext(t)); err != nil { + t.Fatal(err) + } + process := sr.WaitFor(t, "process job", 1, waitSpan)[0] + + if !oteltest.IsRoot(process) { + t.Error("process job has a parent; it must start its own trace") + } + if process.SpanKind() != trace.SpanKindConsumer { + t.Errorf("kind = %v, want consumer", process.SpanKind()) + } + if !oteltest.LinksTo(process, enqueueSpan.SpanContext()) { + t.Error("process job does not link to the enqueue span") + } + for key, want := range map[string]string{ + "messaging.system": "dispatch", + "messaging.operation.type": "process", + "messaging.destination.name": "default", + "messaging.message.id": j.ID.String(), + "dispatch.job.name": "greet", + "dispatch.job.attempt": "1", + "dispatch.job.outcome": telemetry.OutcomeCompleted, + } { + if got, _ := oteltest.Attr(process, key); got != want { + t.Errorf("%s = %q, want %q", key, got, want) + } + } + if process.Status().Code != codes.Unset { + t.Errorf("status = %v, want unset", process.Status()) + } + + spans := sr.Ended() + complete := childrenOf(spans, process, "complete job") + if len(complete) != 1 { + t.Fatalf("complete job children = %d, want 1", len(complete)) + } + // Hooks run inside the attempt's trace: JobStarted under the process + // span itself, JobCompleted under the terminal write's span. + if got := tp.hooks.get("started"); got.SpanID() != process.SpanContext().SpanID() { + t.Error("JobStarted did not run under the process job span") + } + if got := tp.hooks.get("completed"); got.SpanID() != complete[0].SpanContext().SpanID() { + t.Error("JobCompleted did not run under the complete job span") + } + + if n, ok := tp.metrics.HistogramCount(telemetry.MetricJobAttemptDuration, "queue", "default", "outcome", "completed"); !ok || n != 1 { + t.Errorf("attempt metric = %d, %v", n, ok) + } + if n, ok := tp.metrics.HistogramCount(telemetry.MetricJobQueueWait, "queue", "default"); !ok || n != 1 { + t.Errorf("queue wait metric = %d, %v", n, ok) + } + if v, ok := tp.metrics.CounterValue(telemetry.MetricJobPolls, "result", telemetry.PollWork); !ok || v < 1 { + t.Errorf("work polls = %v, %v", v, ok) + } + if v, _ := tp.metrics.GaugeValue(telemetry.MetricJobsActive); v != 0 { + t.Errorf("active jobs after the attempt = %v, want 0", v) + } +} + +func TestAttemptSpanOnDeadLetterKeepsPayloadAndErrorOff(t *testing.T) { + sr := oteltest.Record(t) + mem := memory.New() + tp := newTelemetryPool(t, mem, mem) + job.RegisterDefinition(tp.reg, job.NewDefinition("charge", func(_ context.Context, p struct{ Email string }) error { + return fmt.Errorf("%w: card for %s declined", dispatch.ErrPermanent, p.Email) + })) + tp.enqueue(t, "charge", struct{ Email string }{"alice@example.com"}) + + if err := tp.pool.Start(context.Background()); err != nil { + t.Fatal(err) + } + process := sr.WaitFor(t, "process job", 1, waitSpan)[0] + + if got, _ := oteltest.Attr(process, "dispatch.job.outcome"); got != telemetry.OutcomeDeadLettered { + t.Errorf("outcome = %q", got) + } + if got, _ := oteltest.Attr(process, "dispatch.job.dlq_reason"); got != telemetry.DeadLetterPermanent { + t.Errorf("dlq reason = %q", got) + } + if process.Status().Code != codes.Error || process.Status().Description != "handler error, dead-lettered" { + t.Errorf("status = %+v", process.Status()) + } + var excType string + for _, ev := range process.Events() { + if ev.Name == "exception" { + for _, a := range ev.Attributes { + if a.Key == "exception.type" { + excType = a.Value.AsString() + } + } + } + } + if excType != "dispatch.ErrPermanent" { + t.Errorf("exception.type = %q", excType) + } + + spans := sr.Ended() + dead := childrenOf(spans, process, "dead-letter job") + if len(dead) != 1 { + t.Fatalf("dead-letter job children = %d, want 1", len(dead)) + } + if got := tp.hooks.get("dlq"); got.SpanID() != dead[0].SpanContext().SpanID() { + t.Error("JobDLQ did not run under the dead-letter job span") + } + if v, ok := tp.metrics.CounterValue(telemetry.MetricJobsDeadLettered, "queue", "default", "reason", "permanent"); !ok || v != 1 { + t.Errorf("dead lettered metric = %v, %v", v, ok) + } + oteltest.AssertNoValue(t, spans, "alice@example.com") +} + +func TestAttemptSpanOnRetry(t *testing.T) { + sr := oteltest.Record(t) + mem := memory.New() + tp := newTelemetryPool(t, mem, mem) + job.RegisterDefinition(tp.reg, job.NewDefinition("flaky", func(context.Context, struct{}) error { + return fmt.Errorf("upstream returned 503") + })) + tp.enqueue(t, "flaky", struct{}{}) + + if err := tp.pool.Start(context.Background()); err != nil { + t.Fatal(err) + } + process := sr.WaitFor(t, "process job", 1, waitSpan)[0] + + if got, _ := oteltest.Attr(process, "dispatch.job.outcome"); got != telemetry.OutcomeRetry { + t.Errorf("outcome = %q", got) + } + if process.Status().Description != "handler error, retrying" { + t.Errorf("status = %+v", process.Status()) + } + if len(childrenOf(sr.Ended(), process, "schedule job retry")) != 1 { + t.Error("no schedule job retry child") + } + if n, ok := tp.metrics.HistogramCount(telemetry.MetricJobAttemptDuration, "queue", "default", "outcome", "retry"); !ok || n != 1 { + t.Errorf("retry attempt metric = %d, %v", n, ok) + } +} + +// spanCheckingStore records whether any query the pool's background loops +// make carries a valid span. +type spanCheckingStore struct { + *memory.Store + mu sync.Mutex + polls int + traced int + polled chan struct{} + limitAt int +} + +func (s *spanCheckingStore) DequeueJobs(ctx context.Context, opts job.DequeueOpts) ([]*job.Job, error) { + s.mu.Lock() + s.polls++ + if trace.SpanContextFromContext(ctx).IsValid() { + s.traced++ + } + if s.polls == s.limitAt { + close(s.polled) + } + s.mu.Unlock() + return s.Store.DequeueJobs(ctx, opts) +} + +func TestIdlePollsCarryNoSpan(t *testing.T) { + sr := oteltest.Record(t) + mem := memory.New() + s := &spanCheckingStore{Store: mem, polled: make(chan struct{}), limitAt: 3} + tp := newTelemetryPool(t, s, mem) + + // Started under a context that carries a span, as forge's Start does. + if err := tp.pool.Start(oteltest.SpanContext(t)); err != nil { + t.Fatal(err) + } + select { + case <-s.polled: + case <-time.After(waitSpan): + t.Fatal("pool did not poll") + } + + s.mu.Lock() + traced := s.traced + s.mu.Unlock() + if traced != 0 { + t.Errorf("%d idle store calls carried a span", traced) + } + if spans := sr.Ended(); len(spans) != 0 { + t.Errorf("idle pool started %d spans", len(spans)) + } + if v, ok := tp.metrics.CounterValue(telemetry.MetricJobPolls, "result", telemetry.PollEmpty); !ok || v < 1 { + t.Errorf("empty polls = %v, %v", v, ok) + } +} + +func TestReclaimLeavesOneSpanPerPassThatDidWork(t *testing.T) { + sr := oteltest.Record(t) + ctx := context.Background() + mem := memory.New() + tp := newTelemetryPool(t, mem, mem) + j := tp.enqueue(t, "reclaim-me", struct{}{}) + if _, err := mem.DequeueJobs(ctx, job.DequeueOpts{Queues: []string{"default"}, Limit: 1, + WorkerID: id.NewWorkerID(), LeaseUntil: time.Now().UTC().Add(-time.Minute)}); err != nil { + t.Fatal(err) + } + + tp.pool.ReclaimOnce(ctx) + tp.pool.ReclaimOnce(ctx) // nothing left: no span + + spans := oteltest.Named(sr.Ended(), "reclaim job leases") + if len(spans) != 1 { + t.Fatalf("reclaim spans = %d, want 1", len(spans)) + } + if !oteltest.IsRoot(spans[0]) { + t.Error("reclaim span has a parent") + } + if got, _ := oteltest.Attr(spans[0], "dispatch.lease.reclaimed"); got != "1" { + t.Errorf("reclaimed = %q", got) + } + if v, ok := tp.metrics.CounterValue(telemetry.MetricJobsReclaimed); !ok || v != 1 { + t.Errorf("reclaimed metric = %v, %v", v, ok) + } + got, err := mem.GetJob(ctx, j.ID) + if err != nil || got.State != job.StatePending { + t.Fatalf("job = %+v, %v", got, err) + } +} + +func TestRequeueCountsItsReason(t *testing.T) { + mem := memory.New() + tp := newTelemetryPool(t, mem, mem) + j := tp.enqueue(t, "limited", struct{}{}) + + tp.pool.RequeueRateLimitedForTest(context.Background(), j) + tp.pool.RequeueUndispatchedForTest(j) + + if v, ok := tp.metrics.CounterValue(telemetry.MetricJobsRequeued, "queue", "default", "reason", telemetry.RequeueRateLimited); !ok || v != 1 { + t.Errorf("rate limited = %v, %v", v, ok) + } + if v, ok := tp.metrics.CounterValue(telemetry.MetricJobsRequeued, "queue", "default", "reason", telemetry.RequeueShutdown); !ok || v != 1 { + t.Errorf("shutdown = %v, %v", v, ok) + } +} From e0f8b5a090f86d15dd143b0837e1fec6146f0585 Mon Sep 17 00:00:00 2001 From: Rex Raphael Date: Sat, 17 Oct 2026 23:28:40 -0500 Subject: [PATCH 04/18] feat(cron): trace each due entry and record fire metrics Every entry the leader finds due gets one root "fire cron entry" span, covering the lock, the re-read, the enqueue and the bookkeeping writes, so the job it enqueues hangs off the fire and the attempt links back to it. An idle tick (not the leader, or nothing due) starts nothing. You get dispatch_cron_fires_total by result (fired, locked, skipped, error), the lag between an entry's due time and its enqueue, and a 0/1 leadership gauge that drops to 0 when the scheduler stops. --- cron/scheduler.go | 103 +++++++++++++++++++++------ cron/telemetry_test.go | 158 +++++++++++++++++++++++++++++++++++++++++ 2 files changed, 240 insertions(+), 21 deletions(-) create mode 100644 cron/telemetry_test.go diff --git a/cron/scheduler.go b/cron/scheduler.go index 98b2bec..1a33463 100644 --- a/cron/scheduler.go +++ b/cron/scheduler.go @@ -12,11 +12,14 @@ import ( cronlib "github.com/robfig/cron/v3" log "github.com/xraph/go-utils/log" + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/trace" "github.com/xraph/dispatch" "github.com/xraph/dispatch/cluster" "github.com/xraph/dispatch/id" "github.com/xraph/dispatch/job" + "github.com/xraph/dispatch/telemetry" ) // isTransientStoreErr reports whether err is a transient store failure — @@ -93,6 +96,13 @@ func WithSchedulerStoreCallTimeout(d time.Duration) SchedulerOption { return func(s *Scheduler) { s.storeCallTimeout = d } } +// WithTelemetry sets where the scheduler records its spans and metrics: one +// root "fire cron entry" span per due entry, the fire counter and lag +// histogram, and the leadership gauge. engine.Build passes the engine's own. +func WithTelemetry(t *telemetry.Telemetry) SchedulerOption { + return func(s *Scheduler) { s.tel = t } +} + // cronParser supports standard 5-field cron and descriptors like "@every 30s". var cronParser = cronlib.NewParser( cronlib.Minute | cronlib.Hour | cronlib.Dom | cronlib.Month | cronlib.Dow | cronlib.Descriptor, @@ -120,6 +130,8 @@ type Scheduler struct { workerID id.WorkerID logger log.Logger + tel *telemetry.Telemetry + tickInterval time.Duration lockTTL time.Duration leaderTTL time.Duration @@ -222,6 +234,7 @@ func (s *Scheduler) Stop(_ context.Context) error { s.cancelFunc() } s.wg.Wait() + s.tel.Cron().Leader(false) s.logger.Info("cron scheduler stopped") }) return nil @@ -252,14 +265,22 @@ func (s *Scheduler) leaderLoop() { // stalled driver session can't hold a pool connection beyond the // scheduler's own tick budget. Mirrors worker.Pool.callCtx. func (s *Scheduler) callCtx() (context.Context, context.CancelFunc) { + return s.callCtxFrom(s.cancelCtx) +} + +// callCtxFrom is callCtx for a call that belongs to one fire: it bounds +// the call the same way but keeps ctx's span, so the fire's queries and its +// enqueue nest under it. ctx descends from s.cancelCtx, so Stop still +// cancels it. +func (s *Scheduler) callCtxFrom(ctx context.Context) (context.Context, context.CancelFunc) { if s.storeCallTimeout < 0 { - return s.cancelCtx, func() {} + return ctx, func() {} } d := s.storeCallTimeout if d == 0 { d = defaultStoreCallTimeout } - return context.WithTimeout(s.cancelCtx, d) + return context.WithTimeout(ctx, d) } // amLeader reports whether this instance holds a still-valid leadership @@ -278,6 +299,7 @@ func (s *Scheduler) setLeader(leading bool, until time.Time) { s.isLeader = leading s.leaderUntil = until s.leaderMu.Unlock() + s.tel.Cron().Leader(leading) if leading && !wasLeader { // Fresh leadership: re-list entries before the first tick fires. @@ -429,11 +451,38 @@ func (s *Scheduler) tick() { if due == nil || due.After(now) { continue } - s.fireEntry(s.cancelCtx, entry.ID, now) + s.fire(entry, *due, now) + } +} + +// fire handles one entry the cache says is due, under its own root span. +// s.cancelCtx descends from context.Background, so no boot or request span +// can parent it; idle ticks never get this far and start nothing. +func (s *Scheduler) fire(entry *Entry, due, now time.Time) { + ctx, span := s.tel.Start(s.cancelCtx, "fire cron entry", + trace.WithNewRoot(), + trace.WithAttributes( + attribute.String("dispatch.cron.id", entry.ID.String()), + attribute.String("dispatch.cron.name", entry.Name), + attribute.String("dispatch.cron.job_name", entry.JobName), + ), + ) + defer span.End() + + result := s.fireEntry(ctx, entry.ID, now) + span.SetAttributes(attribute.String("dispatch.cron.result", result)) + if result == telemetry.CronError { + telemetry.Fail(span, "cron fire failed", "") + } + if result == telemetry.CronFired { + s.tel.Cron().Lag(time.Since(due)) } + s.tel.Cron().Fire(result) } -// fireEntry fires one entry the cache says is due. +// fireEntry fires one entry the cache says is due and reports what +// happened: fired, locked (another worker holds the entry), skipped (the +// store says it is no longer due) or error. // // The cache can be cronRefreshInterval old, and an operator acting // through another node invalidates only that node's cache, so a cached @@ -443,35 +492,35 @@ func (s *Scheduler) tick() { // lands after the re-read still sees the fire it raced go out, but // nothing here can undo the disable: the post-fire writes are // UpdateCronLastRun and UpdateCronNextRun, and neither touches enabled. -func (s *Scheduler) fireEntry(ctx context.Context, cronID id.CronID, now time.Time) { +func (s *Scheduler) fireEntry(ctx context.Context, cronID id.CronID, now time.Time) string { // Acquire per-entry lock under a bounded subcontext. - acqCtx, acqCancel := s.callCtx() + acqCtx, acqCancel := s.callCtxFrom(ctx) acquired, err := s.cronStore.AcquireCronLock(acqCtx, cronID, s.workerID, s.lockTTL) acqCancel() if err != nil { s.logCronErr("acquire cron lock error", cronID, err) - return + return storeResult(err) } if !acquired { - return // Another worker got it. + return telemetry.CronLocked // Another worker got it. } - getCtx, getCancel := s.callCtx() + getCtx, getCancel := s.callCtxFrom(ctx) entry, err := s.cronStore.GetCron(getCtx, cronID) getCancel() if err != nil { s.logCronErr("re-read cron entry error", cronID, err) if !errors.Is(err, dispatch.ErrCronNotFound) { - s.releaseCronLock(cronID) + s.releaseCronLock(ctx, cronID) } - return + return storeResult(err) } if !entry.Enabled || entry.NextRunAt == nil || entry.NextRunAt.After(now) { // Disabled, or fired or rescheduled since the cache was listed. // Re-list on the next tick so the cache stops offering it. s.cronDirty.Store(true) - s.releaseCronLock(cronID) - return + s.releaseCronLock(ctx, cronID) + return telemetry.CronSkipped } // Enqueue the job with optional queue override. @@ -479,7 +528,7 @@ func (s *Scheduler) fireEntry(ctx context.Context, cronID id.CronID, now time.Ti if entry.Queue != "" { enqOpts = append(enqOpts, job.WithQueue(entry.Queue)) } - enqCtx, enqCancel := s.callCtx() + enqCtx, enqCancel := s.callCtxFrom(ctx) jobID, enqErr := s.enqueue(enqCtx, entry.JobName, entry.Payload, enqOpts...) enqCancel() if enqErr != nil { @@ -488,13 +537,13 @@ func (s *Scheduler) fireEntry(ctx context.Context, cronID id.CronID, now time.Ti log.String("job_name", entry.JobName), log.String("error", enqErr.Error()), ) - s.releaseCronLock(cronID) - return + s.releaseCronLock(ctx, cronID) + return telemetry.CronError } // Record the fire with targeted writes only. A whole-row write here // would put back whatever enabled was when the row was read. - lrCtx, lrCancel := s.callCtx() + lrCtx, lrCancel := s.callCtxFrom(ctx) err = s.cronStore.UpdateCronLastRun(lrCtx, cronID, now) lrCancel() if err != nil { @@ -511,7 +560,7 @@ func (s *Scheduler) fireEntry(ctx context.Context, cronID id.CronID, now time.Ti } else { next := sched.Next(now) s.nextRuns[cronID.String()] = next - nrCtx, nrCancel := s.callCtx() + nrCtx, nrCancel := s.callCtxFrom(ctx) err = s.cronStore.UpdateCronNextRun(nrCtx, cronID, next) nrCancel() if err != nil { @@ -519,7 +568,7 @@ func (s *Scheduler) fireEntry(ctx context.Context, cronID id.CronID, now time.Ti } } - s.releaseCronLock(cronID) + s.releaseCronLock(ctx, cronID) // Emit hook. if s.emitter != nil { @@ -531,11 +580,23 @@ func (s *Scheduler) fireEntry(ctx context.Context, cronID id.CronID, now time.Ti log.String("job_name", entry.JobName), log.String("job_id", jobID.String()), ) + + return telemetry.CronFired +} + +// storeResult classifies a failed store call while firing. An entry deleted +// since the cache listed it is ordinary, so it counts as skipped. +func storeResult(err error) string { + if errors.Is(err, dispatch.ErrCronNotFound) { + return telemetry.CronSkipped + } + + return telemetry.CronError } // releaseCronLock gives up this worker's lock on an entry. -func (s *Scheduler) releaseCronLock(cronID id.CronID) { - relCtx, relCancel := s.callCtx() +func (s *Scheduler) releaseCronLock(ctx context.Context, cronID id.CronID) { + relCtx, relCancel := s.callCtxFrom(ctx) err := s.cronStore.ReleaseCronLock(relCtx, cronID, s.workerID) relCancel() if err != nil { diff --git a/cron/telemetry_test.go b/cron/telemetry_test.go new file mode 100644 index 0000000..9c2083a --- /dev/null +++ b/cron/telemetry_test.go @@ -0,0 +1,158 @@ +package cron_test + +import ( + "context" + "sync" + "testing" + "time" + + "go.opentelemetry.io/otel/trace" + + "github.com/xraph/dispatch/cluster" + "github.com/xraph/dispatch/cron" + "github.com/xraph/dispatch/id" + "github.com/xraph/dispatch/internal/metricstest" + "github.com/xraph/dispatch/internal/oteltest" + "github.com/xraph/dispatch/job" + "github.com/xraph/dispatch/store/memory" + "github.com/xraph/dispatch/telemetry" +) + +// spanEnqueuer records the span context each enqueue ran under. +type spanEnqueuer struct { + mu sync.Mutex + spans []trace.SpanContext +} + +func (e *spanEnqueuer) Fn() cron.EnqueueFunc { + return func(ctx context.Context, _ string, _ []byte, _ ...job.Option) (id.JobID, error) { + e.mu.Lock() + e.spans = append(e.spans, trace.SpanContextFromContext(ctx)) + e.mu.Unlock() + return id.NewJobID(), nil + } +} + +func (e *spanEnqueuer) first() trace.SpanContext { + e.mu.Lock() + defer e.mu.Unlock() + if len(e.spans) == 0 { + return trace.SpanContext{} + } + return e.spans[0] +} + +// spanCheckingCronStore records whether an idle tick's queries carry a span. +type spanCheckingCronStore struct { + *memory.Store + mu sync.Mutex + lists int + traced int + listed chan struct{} +} + +func (s *spanCheckingCronStore) ListCrons(ctx context.Context) ([]*cron.Entry, error) { + s.mu.Lock() + s.lists++ + if trace.SpanContextFromContext(ctx).IsValid() { + s.traced++ + } + if s.lists == 2 { + close(s.listed) + } + s.mu.Unlock() + return s.Store.ListCrons(ctx) +} + +func leadingScheduler(t *testing.T, cs cron.Store, mem *memory.Store, enqueue cron.EnqueueFunc, tel *telemetry.Telemetry) *cron.Scheduler { + t.Helper() + ctx := context.Background() + workerID := id.NewWorkerID() + if err := mem.RegisterWorker(ctx, &cluster.Worker{ID: workerID, Hostname: "test", State: cluster.WorkerActive, + LastSeen: time.Now().UTC(), CreatedAt: time.Now().UTC()}); err != nil { + t.Fatal(err) + } + if ok, err := mem.AcquireLeadership(ctx, workerID, 30*time.Second); err != nil || !ok { + t.Fatalf("AcquireLeadership: %v %v", ok, err) + } + sched := cron.NewScheduler(cs, mem, enqueue, nil, workerID, nil, + cron.WithTickInterval(10*time.Millisecond), + cron.WithLeaderTTL(10*time.Second), + cron.WithCronRefreshInterval(10*time.Millisecond), + cron.WithTelemetry(tel), + ) + t.Cleanup(func() { _ = sched.Stop(context.Background()) }) + return sched +} + +func TestFireCronEntryIsARootSpanAroundTheEnqueue(t *testing.T) { + sr := oteltest.Record(t) + mem := memory.New() + f := metricstest.New() + enq := &spanEnqueuer{} + sched := leadingScheduler(t, mem, mem, enq.Fn(), telemetry.New(telemetry.WithMetrics(f))) + registerDueEntry(t, mem, "nightly-report", "send-report") + + if err := sched.Start(oteltest.SpanContext(t)); err != nil { + t.Fatal(err) + } + fire := sr.WaitFor(t, "fire cron entry", 1, 5*time.Second)[0] + + if !oteltest.IsRoot(fire) { + t.Error("fire cron entry has a parent") + } + for key, want := range map[string]string{ + "dispatch.cron.name": "nightly-report", + "dispatch.cron.job_name": "send-report", + "dispatch.cron.result": telemetry.CronFired, + } { + if got, _ := oteltest.Attr(fire, key); got != want { + t.Errorf("%s = %q, want %q", key, got, want) + } + } + if got := enq.first(); got.SpanID() != fire.SpanContext().SpanID() { + t.Error("the cron enqueue did not run under the fire span") + } + + if v, ok := f.CounterValue(telemetry.MetricCronFires, "result", telemetry.CronFired); !ok || v < 1 { + t.Errorf("fired = %v, %v", v, ok) + } + if len(f.Series(telemetry.MetricCronFireLag)) != 1 { + t.Error("no cron lag series") + } + if v, _ := f.GaugeValue(telemetry.MetricCronLeader); v != 1 { + t.Errorf("leader gauge = %v, want 1", v) + } + if err := sched.Stop(context.Background()); err != nil { + t.Fatal(err) + } + if v, _ := f.GaugeValue(telemetry.MetricCronLeader); v != 0 { + t.Errorf("leader gauge after Stop = %v, want 0", v) + } +} + +func TestIdleCronTicksStartNoSpans(t *testing.T) { + sr := oteltest.Record(t) + mem := memory.New() + cs := &spanCheckingCronStore{Store: mem, listed: make(chan struct{})} + sched := leadingScheduler(t, cs, mem, (&spanEnqueuer{}).Fn(), telemetry.New()) + + if err := sched.Start(oteltest.SpanContext(t)); err != nil { + t.Fatal(err) + } + select { + case <-cs.listed: + case <-time.After(5 * time.Second): + t.Fatal("scheduler never listed its entries") + } + + cs.mu.Lock() + traced := cs.traced + cs.mu.Unlock() + if traced != 0 { + t.Errorf("%d idle ListCrons calls carried a span", traced) + } + if spans := sr.Ended(); len(spans) != 0 { + t.Errorf("idle scheduler started %d spans", len(spans)) + } +} From 156315ed135fa9c301bab1e145888f1640b765cd Mon Sep 17 00:00:00 2001 From: Rex Raphael Date: Sat, 17 Oct 2026 23:28:40 -0500 Subject: [PATCH 05/18] feat(workflow): trace checkpoint runs and the steps that actually run A run gets a "run workflow" span. When the caller waits on it (Start, RunChild, MigrateRun) it is a child of the caller's span; when it outlives the caller (ResumeAll at boot, ReplayFrom, SpawnChild) it starts its own trace with a link back. ReplayFrom and spawned children used to keep the caller's span through WithoutCancel. Each step that runs gets a "run workflow step" span with its kind and name, and the step function receives that span's context. A step replayed from its checkpoint gets no span. Compensations are steps of kind compensate. Run and step durations are recorded by result. --- workflow/context.go | 10 +- workflow/replay.go | 7 +- workflow/runner.go | 36 ++++++- workflow/step.go | 139 +++++++++++++++---------- workflow/telemetry.go | 83 +++++++++++++++ workflow/telemetry_test.go | 207 +++++++++++++++++++++++++++++++++++++ 6 files changed, 421 insertions(+), 61 deletions(-) create mode 100644 workflow/telemetry.go create mode 100644 workflow/telemetry_test.go diff --git a/workflow/context.go b/workflow/context.go index 1743e2c..5dcc081 100644 --- a/workflow/context.go +++ b/workflow/context.go @@ -8,6 +8,7 @@ import ( "github.com/xraph/dispatch/event" "github.com/xraph/dispatch/id" + "github.com/xraph/dispatch/telemetry" ) // StepEmitter is called by the Workflow to emit step lifecycle events. @@ -60,6 +61,10 @@ type Workflow struct { // compensations is a LIFO stack of undo actions. On workflow failure, // these are executed in reverse order. compensations []Compensation + + // tel is the runner's telemetry, for step spans and metrics. Nil starts + // spans on the global provider and records no metrics. + tel *telemetry.Telemetry } // NewWorkflowContext creates a new Workflow execution context. @@ -122,7 +127,10 @@ func (w *Workflow) RunCompensations() error { // Execute compensation. start := time.Now() - if compErr := comp.Compensate(w.ctx); compErr != nil { + cctx, done := w.startStep(stepKindCompensate, stepName) + compErr := comp.Compensate(cctx) + done(compErr) + if compErr != nil { w.emitter.EmitStepFailed(w.ctx, w.run, stepName, compErr) w.logger.Error("compensation failed", log.String("step", comp.StepName), diff --git a/workflow/replay.go b/workflow/replay.go index 07f35db..08f9b27 100644 --- a/workflow/replay.go +++ b/workflow/replay.go @@ -184,13 +184,16 @@ func (r *Runner) replayFrom(ctx context.Context, runID id.RunID, fromStep string r.emitter.EmitWorkflowStarted(ctx, &run) launched = true + // WithoutCancel keeps the caller's span, which ends when ReplayFrom + // returns; the replayed run is its own trace, linked back to it. + detached, spanOpts := detachedRun(context.WithoutCancel(ctx)) go func() { defer r.inflight.Done() - bg, cancel := context.WithCancel(context.WithoutCancel(ctx)) + bg, cancel := context.WithCancel(detached) defer cancel() stop := context.AfterFunc(r.life, cancel) defer stop() - r.executeRun(bg, &run, runner, run.Input) + r.executeRun(bg, &run, runner, run.Input, spanOpts...) }() return plan, nil diff --git a/workflow/runner.go b/workflow/runner.go index 6e25b50..862a4dd 100644 --- a/workflow/runner.go +++ b/workflow/runner.go @@ -8,11 +8,14 @@ import ( "time" log "github.com/xraph/go-utils/log" + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/trace" "github.com/xraph/dispatch" "github.com/xraph/dispatch/event" "github.com/xraph/dispatch/id" "github.com/xraph/dispatch/scope" + "github.com/xraph/dispatch/telemetry" ) // RunEmitter emits workflow-level lifecycle events. @@ -44,6 +47,8 @@ type Runner struct { lifeMu sync.Mutex closed bool inflight sync.WaitGroup + + tel *telemetry.Telemetry } // NewRunner creates a workflow runner. @@ -119,14 +124,21 @@ func (r *Runner) StartRaw(ctx context.Context, name string, input []byte) (*Run, // executeRun runs the workflow handler and handles completion/failure. // It injects the Runner itself as the ChildStarter, and triggers saga // compensations on workflow failure. -func (r *Runner) executeRun(ctx context.Context, run *Run, runner RunnerFunc, input []byte) { +// +// The run gets a "run workflow" span: a child of ctx's span for a run the +// caller waits on, or its own root when opts say so (see detachedRun). +func (r *Runner) executeRun(ctx context.Context, run *Run, runner RunnerFunc, input []byte, opts ...trace.SpanStartOption) { // Restore scope into context. ctx = scope.Restore(ctx, run.ScopeAppID, run.ScopeOrgID) + ctx, span := r.startRun(ctx, run, opts...) + defer span.End() + start := time.Now() wf := NewWorkflowContext(ctx, run, r.store, r.eventStore, r.emitter, r.logger) wf.SetChildStarter(r) // Inject self as child starter. + wf.tel = r.tel err := runner(wf, input) elapsed := time.Since(start) @@ -134,6 +146,8 @@ func (r *Runner) executeRun(ctx context.Context, run *Run, runner RunnerFunc, in now := time.Now().UTC() if err != nil { + telemetry.Fail(span, "workflow failed", telemetry.ErrorType(err)) + r.tel.Workflows().Run("failed", elapsed) // Run saga compensations before marking as failed. if len(wf.Compensations()) > 0 { r.logger.Info("running saga compensations", @@ -161,6 +175,7 @@ func (r *Runner) executeRun(ctx context.Context, run *Run, runner RunnerFunc, in return } + r.tel.Workflows().Run("completed", elapsed) run.State = RunStateCompleted run.CompletedAt = &now if updateErr := r.store.UpdateRun(ctx, run); updateErr != nil { @@ -240,8 +255,10 @@ func (r *Runner) SpawnChildRaw(ctx context.Context, parentRunID id.RunID, name s r.emitter.EmitWorkflowStarted(ctx, run) - // Execute in background goroutine. - go r.executeRun(ctx, run, runner, input) + // Execute in background goroutine. The parent step's span ends before + // the child does, so the child is its own trace, linked back to it. + bg, opts := detachedRun(ctx) + go r.executeRun(bg, run, runner, input, opts...) return run, nil } @@ -250,6 +267,10 @@ func (r *Runner) SpawnChildRaw(ctx context.Context, parentRunID id.RunID, name s // It re-executes the handler; steps with checkpoints are skipped automatically. // The run continues on its stamped version (not necessarily the latest). func (r *Runner) Resume(ctx context.Context, runID id.RunID) error { + return r.resume(ctx, runID) +} + +func (r *Runner) resume(ctx context.Context, runID id.RunID, opts ...trace.SpanStartOption) error { run, err := r.store.GetRun(ctx, runID) if err != nil { return fmt.Errorf("get run %s: %w", runID, err) @@ -264,7 +285,7 @@ func (r *Runner) Resume(ctx context.Context, runID id.RunID) error { return fmt.Errorf("no workflow registered for %q version %d (run %s)", run.Name, run.Version, runID) } - r.executeRun(ctx, run, runner, run.Input) + r.executeRun(ctx, run, runner, run.Input, opts...) return nil } @@ -308,12 +329,17 @@ func (r *Runner) ResumeAll(ctx context.Context) error { return fmt.Errorf("list running workflow runs: %w", err) } + // Each resumed run is its own trace, linked to whatever called this + // (the engine's boot span at startup), rather than a long child of it. + bg, opts := detachedRun(ctx) + opts = append(opts, trace.WithAttributes(attribute.Bool("dispatch.workflow.resumed", true))) + for _, run := range runs { r.logger.Info("resuming workflow run", log.String("run_id", run.ID.String()), log.String("workflow", run.Name), ) - if resumeErr := r.Resume(ctx, run.ID); resumeErr != nil { + if resumeErr := r.resume(bg, run.ID, opts...); resumeErr != nil { r.logger.Error("failed to resume workflow run", log.String("run_id", run.ID.String()), log.String("error", resumeErr.Error()), diff --git a/workflow/step.go b/workflow/step.go index f884f5d..8cf67c5 100644 --- a/workflow/step.go +++ b/workflow/step.go @@ -21,7 +21,7 @@ import ( // this step name, the step is skipped (idempotent replay). Otherwise // the function is executed and a checkpoint is saved on success. // On failure, EmitWorkflowStepFailed is called and the error is returned. -func (w *Workflow) Step(name string, fn func(ctx context.Context) error) error { +func (w *Workflow) Step(name string, fn func(ctx context.Context) error) (err error) { // Check for existing checkpoint (resume case). data, err := w.store.GetCheckpoint(w.ctx, w.run.ID, name) if err != nil { @@ -35,22 +35,25 @@ func (w *Workflow) Step(name string, fn func(ctx context.Context) error) error { return nil } + sctx, done := w.startStep(stepKindStep, name) + defer func() { done(err) }() + // Execute the step. start := time.Now() - stepErr := fn(w.ctx) + stepErr := fn(sctx) elapsed := time.Since(start) if stepErr != nil { - w.emitter.EmitStepFailed(w.ctx, w.run, name, stepErr) + w.emitter.EmitStepFailed(sctx, w.run, name, stepErr) return fmt.Errorf("workflow %s step %q: %w", w.run.Name, name, stepErr) } // Save checkpoint (empty data since Step has no result). - if saveErr := w.store.SaveCheckpoint(w.ctx, w.run.ID, name, []byte{}); saveErr != nil { + if saveErr := w.store.SaveCheckpoint(sctx, w.run.ID, name, []byte{}); saveErr != nil { return fmt.Errorf("workflow %s: save checkpoint %q: %w", w.run.Name, name, saveErr) } - w.emitter.EmitStepCompleted(w.ctx, w.run, name, elapsed) + w.emitter.EmitStepCompleted(sctx, w.run, name, elapsed) return nil } @@ -61,7 +64,7 @@ func (w *Workflow) Step(name string, fn func(ctx context.Context) error) error { // // This is a package-level generic function because Go does not allow // generic methods on non-generic receiver types. -func StepWithResult[T any](w *Workflow, name string, fn func(ctx context.Context) (T, error)) (T, error) { +func StepWithResult[T any](w *Workflow, name string, fn func(ctx context.Context) (T, error)) (_ T, err error) { var zero T // Check for existing checkpoint. @@ -83,13 +86,16 @@ func StepWithResult[T any](w *Workflow, name string, fn func(ctx context.Context return result, nil } + sctx, done := w.startStep(stepKindStep, name) + defer func() { done(err) }() + // Execute the step. start := time.Now() - result, stepErr := fn(w.ctx) + result, stepErr := fn(sctx) elapsed := time.Since(start) if stepErr != nil { - w.emitter.EmitStepFailed(w.ctx, w.run, name, stepErr) + w.emitter.EmitStepFailed(sctx, w.run, name, stepErr) return zero, fmt.Errorf("workflow %s step %q: %w", w.run.Name, name, stepErr) } @@ -101,11 +107,11 @@ func StepWithResult[T any](w *Workflow, name string, fn func(ctx context.Context } // Save checkpoint. - if saveErr := w.store.SaveCheckpoint(w.ctx, w.run.ID, name, buf.Bytes()); saveErr != nil { + if saveErr := w.store.SaveCheckpoint(sctx, w.run.ID, name, buf.Bytes()); saveErr != nil { return zero, fmt.Errorf("workflow %s: save checkpoint %q: %w", w.run.Name, name, saveErr) } - w.emitter.EmitStepCompleted(w.ctx, w.run, name, elapsed) + w.emitter.EmitStepCompleted(sctx, w.run, name, elapsed) return result, nil } @@ -113,7 +119,7 @@ func StepWithResult[T any](w *Workflow, name string, fn func(ctx context.Context // If any step fails, the others are cancelled and the first error is returned. // Each sub-step gets its own checkpoint with the name "parallel::". // A group-level checkpoint marks overall completion for resume. -func (w *Workflow) Parallel(groupName string, steps ...func(ctx context.Context) error) error { +func (w *Workflow) Parallel(groupName string, steps ...func(ctx context.Context) error) (err error) { groupKey := "parallel:" + groupName // Check if entire group already completed. @@ -129,7 +135,10 @@ func (w *Workflow) Parallel(groupName string, steps ...func(ctx context.Context) return nil } - g, gctx := errgroup.WithContext(w.ctx) + sctx, done := w.startStep(stepKindParallel, groupKey) + defer func() { done(err) }() + + g, gctx := errgroup.WithContext(sctx) for i, step := range steps { stepName := fmt.Sprintf("parallel:%s:%d", groupName, i) @@ -146,7 +155,7 @@ func (w *Workflow) Parallel(groupName string, steps ...func(ctx context.Context) start := time.Now() if fnErr := fn(gctx); fnErr != nil { - w.emitter.EmitStepFailed(w.ctx, w.run, stepName, fnErr) + w.emitter.EmitStepFailed(sctx, w.run, stepName, fnErr) return fnErr } @@ -154,7 +163,7 @@ func (w *Workflow) Parallel(groupName string, steps ...func(ctx context.Context) if saveErr := w.store.SaveCheckpoint(gctx, w.run.ID, stepName, []byte{}); saveErr != nil { return saveErr } - w.emitter.EmitStepCompleted(w.ctx, w.run, stepName, elapsed) + w.emitter.EmitStepCompleted(sctx, w.run, stepName, elapsed) return nil }) } @@ -164,14 +173,14 @@ func (w *Workflow) Parallel(groupName string, steps ...func(ctx context.Context) } // Save group-level checkpoint. - return w.store.SaveCheckpoint(w.ctx, w.run.ID, groupKey, []byte{}) + return w.store.SaveCheckpoint(sctx, w.run.ID, groupKey, []byte{}) } // WaitForEvent blocks until an event matching the given name is published // or the timeout expires. On success the event is acknowledged and checkpointed. // On timeout, an empty checkpoint is saved and nil is returned. // On resume from checkpoint, the cached event is returned without re-waiting. -func (w *Workflow) WaitForEvent(name string, timeout time.Duration) (*event.Event, error) { +func (w *Workflow) WaitForEvent(name string, timeout time.Duration) (_ *event.Event, err error) { stepName := "wait:" + name // Check for checkpoint. @@ -193,22 +202,25 @@ func (w *Workflow) WaitForEvent(name string, timeout time.Duration) (*event.Even return &evt, nil } + sctx, done := w.startStep(stepKindWaitEvent, stepName) + defer func() { done(err) }() + // Subscribe for event. - evt, subErr := w.eventStore.SubscribeEvent(w.ctx, name, timeout) + evt, subErr := w.eventStore.SubscribeEvent(sctx, name, timeout) if subErr != nil { return nil, fmt.Errorf("workflow %s wait %q: %w", w.run.Name, name, subErr) } if evt == nil { // Timeout — save empty checkpoint. - if saveErr := w.store.SaveCheckpoint(w.ctx, w.run.ID, stepName, []byte{}); saveErr != nil { + if saveErr := w.store.SaveCheckpoint(sctx, w.run.ID, stepName, []byte{}); saveErr != nil { return nil, saveErr } return nil, nil } // Ack the event. - if ackErr := w.eventStore.AckEvent(w.ctx, evt.ID); ackErr != nil { + if ackErr := w.eventStore.AckEvent(sctx, evt.ID); ackErr != nil { w.logger.Warn("failed to ack event", log.String("event_id", evt.ID.String()), log.String("error", ackErr.Error()), @@ -220,7 +232,7 @@ func (w *Workflow) WaitForEvent(name string, timeout time.Duration) (*event.Even if encErr != nil { return nil, fmt.Errorf("workflow %s: encode wait result %q: %w", w.run.Name, name, encErr) } - if saveErr := w.store.SaveCheckpoint(w.ctx, w.run.ID, stepName, evtData); saveErr != nil { + if saveErr := w.store.SaveCheckpoint(sctx, w.run.ID, stepName, evtData); saveErr != nil { return nil, saveErr } @@ -230,7 +242,7 @@ func (w *Workflow) WaitForEvent(name string, timeout time.Duration) (*event.Even // Sleep pauses the workflow for the specified duration. On crash recovery, // if a checkpoint exists for this sleep step, it is skipped immediately. // The sleep can be interrupted by context cancellation. -func (w *Workflow) Sleep(name string, d time.Duration) error { +func (w *Workflow) Sleep(name string, d time.Duration) (err error) { stepName := "sleep:" + name // Check for checkpoint. @@ -246,15 +258,18 @@ func (w *Workflow) Sleep(name string, d time.Duration) error { return nil } + sctx, done := w.startStep(stepKindSleep, stepName) + defer func() { done(err) }() + // Actually sleep. select { case <-time.After(d): - case <-w.ctx.Done(): - return w.ctx.Err() + case <-sctx.Done(): + return sctx.Err() } // Save checkpoint. - return w.store.SaveCheckpoint(w.ctx, w.run.ID, stepName, []byte{}) + return w.store.SaveCheckpoint(sctx, w.run.ID, stepName, []byte{}) } // ── Saga Compensations ────────────────────────────── @@ -305,7 +320,7 @@ func StepWithResultAndCompensation[T any]( // and the result is checkpointed for crash recovery. // // T is the input type, R is the result type (decoded from the child's JSON output). -func RunChild[T, R any](w *Workflow, name string, input T) (R, error) { +func RunChild[T, R any](w *Workflow, name string, input T) (_ R, err error) { var zero R stepName := "child:" + name @@ -326,6 +341,9 @@ func RunChild[T, R any](w *Workflow, name string, input T) (R, error) { return result, nil } + sctx, done := w.startStep(stepKindChild, stepName) + defer func() { done(err) }() + if w.childStarter == nil { return zero, fmt.Errorf("workflow %s: child starter not configured", w.run.Name) } @@ -338,18 +356,18 @@ func RunChild[T, R any](w *Workflow, name string, input T) (R, error) { // Start child workflow (blocking). start := time.Now() - childRun, startErr := w.childStarter.StartChildRaw(w.ctx, w.run.ID, name, inputData) + childRun, startErr := w.childStarter.StartChildRaw(sctx, w.run.ID, name, inputData) elapsed := time.Since(start) if startErr != nil { - w.emitter.EmitStepFailed(w.ctx, w.run, stepName, startErr) + w.emitter.EmitStepFailed(sctx, w.run, stepName, startErr) return zero, fmt.Errorf("workflow %s child %q: %w", w.run.Name, name, startErr) } // Check child result. if childRun.State == RunStateFailed { childErr := fmt.Errorf("child workflow %q failed: %s", name, childRun.Error) - w.emitter.EmitStepFailed(w.ctx, w.run, stepName, childErr) + w.emitter.EmitStepFailed(sctx, w.run, stepName, childErr) return zero, childErr } @@ -366,11 +384,11 @@ func RunChild[T, R any](w *Workflow, name string, input T) (R, error) { if encErr != nil { return zero, fmt.Errorf("workflow %s: encode child checkpoint %q: %w", w.run.Name, name, encErr) } - if saveErr := w.store.SaveCheckpoint(w.ctx, w.run.ID, stepName, chkData); saveErr != nil { + if saveErr := w.store.SaveCheckpoint(sctx, w.run.ID, stepName, chkData); saveErr != nil { return zero, fmt.Errorf("workflow %s: save child checkpoint %q: %w", w.run.Name, name, saveErr) } - w.emitter.EmitStepCompleted(w.ctx, w.run, stepName, elapsed) + w.emitter.EmitStepCompleted(sctx, w.run, stepName, elapsed) return result, nil } @@ -378,7 +396,7 @@ func RunChild[T, R any](w *Workflow, name string, input T) (R, error) { // and returns the child's run ID. The child run is linked to the parent // via ParentRunID and executes in a background goroutine. Use the Store's // GetRun to check on its status later. -func SpawnChild[T any](w *Workflow, name string, input T) (id.RunID, error) { +func SpawnChild[T any](w *Workflow, name string, input T) (_ id.RunID, err error) { stepName := "spawn:" + name // Check for existing checkpoint (contains the child run ID string). @@ -399,6 +417,9 @@ func SpawnChild[T any](w *Workflow, name string, input T) (id.RunID, error) { return runID, nil } + sctx, done := w.startStep(stepKindSpawn, stepName) + defer func() { done(err) }() + if w.childStarter == nil { return id.Nil, fmt.Errorf("workflow %s: child starter not configured", w.run.Name) } @@ -411,27 +432,27 @@ func SpawnChild[T any](w *Workflow, name string, input T) (id.RunID, error) { // Spawn child workflow (non-blocking). start := time.Now() - childRun, spawnErr := w.childStarter.SpawnChildRaw(w.ctx, w.run.ID, name, inputData) + childRun, spawnErr := w.childStarter.SpawnChildRaw(sctx, w.run.ID, name, inputData) elapsed := time.Since(start) if spawnErr != nil { - w.emitter.EmitStepFailed(w.ctx, w.run, stepName, spawnErr) + w.emitter.EmitStepFailed(sctx, w.run, stepName, spawnErr) return id.Nil, fmt.Errorf("workflow %s spawn %q: %w", w.run.Name, name, spawnErr) } // Checkpoint the child run ID. - if saveErr := w.store.SaveCheckpoint(w.ctx, w.run.ID, stepName, []byte(childRun.ID.String())); saveErr != nil { + if saveErr := w.store.SaveCheckpoint(sctx, w.run.ID, stepName, []byte(childRun.ID.String())); saveErr != nil { return id.Nil, fmt.Errorf("workflow %s: save spawn checkpoint %q: %w", w.run.Name, name, saveErr) } - w.emitter.EmitStepCompleted(w.ctx, w.run, stepName, elapsed) + w.emitter.EmitStepCompleted(sctx, w.run, stepName, elapsed) return childRun.ID, nil } // FanOut starts N child workflows in parallel and collects all results. // Each child is independently checkpointed via RunChild. If any child // fails, the remaining are cancelled and the error is returned. -func FanOut[T, R any](w *Workflow, name string, inputs []T) ([]R, error) { +func FanOut[T, R any](w *Workflow, name string, inputs []T) (_ []R, err error) { groupKey := "fanout:" + name // Check if entire group already completed. @@ -451,9 +472,12 @@ func FanOut[T, R any](w *Workflow, name string, inputs []T) ([]R, error) { return results, nil } + sctx, done := w.startStep(stepKindFanOut, groupKey) + defer func() { done(err) }() + // Execute children in parallel. results := make([]R, len(inputs)) - g, gctx := errgroup.WithContext(w.ctx) + g, gctx := errgroup.WithContext(sctx) for i, input := range inputs { childKey := fmt.Sprintf("%s:%d", name, i) // unique checkpoint key per child @@ -525,7 +549,7 @@ func FanOut[T, R any](w *Workflow, name string, inputs []T) ([]R, error) { if encErr != nil { return nil, fmt.Errorf("workflow %s: encode fanout checkpoint %q: %w", w.run.Name, name, encErr) } - if saveErr := w.store.SaveCheckpoint(w.ctx, w.run.ID, groupKey, chkData); saveErr != nil { + if saveErr := w.store.SaveCheckpoint(sctx, w.run.ID, groupKey, chkData); saveErr != nil { return nil, fmt.Errorf("workflow %s: save fanout checkpoint %q: %w", w.run.Name, name, saveErr) } @@ -537,7 +561,7 @@ func FanOut[T, R any](w *Workflow, name string, inputs []T) ([]R, error) { // WaitForAll blocks until events matching ALL specified names are received // or the timeout expires. Each received event is individually checkpointed. // Returns an error if any subscription times out. -func (w *Workflow) WaitForAll(names []string, timeout time.Duration) ([]*event.Event, error) { +func (w *Workflow) WaitForAll(names []string, timeout time.Duration) (_ []*event.Event, err error) { groupKey := "waitall:" + strings.Join(names, ",") // Check for group checkpoint. @@ -553,9 +577,12 @@ func (w *Workflow) WaitForAll(names []string, timeout time.Duration) ([]*event.E return events, nil } + sctx, done := w.startStep(stepKindWaitAll, groupKey) + defer func() { done(err) }() + // Wait for each event in parallel. events := make([]*event.Event, len(names)) - g, gctx := errgroup.WithContext(w.ctx) + g, gctx := errgroup.WithContext(sctx) for i, name := range names { idx := i @@ -610,7 +637,7 @@ func (w *Workflow) WaitForAll(names []string, timeout time.Duration) ([]*event.E return nil, fmt.Errorf("workflow %s: marshal waitall events: %w", w.run.Name, marshalErr) } //nolint:errcheck // best-effort group checkpoint - _ = w.store.SaveCheckpoint(w.ctx, w.run.ID, groupKey, allData) + _ = w.store.SaveCheckpoint(sctx, w.run.ID, groupKey, allData) return events, nil } @@ -618,7 +645,7 @@ func (w *Workflow) WaitForAll(names []string, timeout time.Duration) ([]*event.E // WaitForAny blocks until an event matching ANY of the given names is // received or the timeout expires. Returns the first event received, // or nil on timeout. -func (w *Workflow) WaitForAny(names []string, timeout time.Duration) (*event.Event, error) { +func (w *Workflow) WaitForAny(names []string, timeout time.Duration) (_ *event.Event, err error) { stepName := "waitany:" + strings.Join(names, ",") // Check for checkpoint. @@ -637,8 +664,11 @@ func (w *Workflow) WaitForAny(names []string, timeout time.Duration) (*event.Eve return &evt, nil } + sctx, done := w.startStep(stepKindWaitAny, stepName) + defer func() { done(err) }() + // Race: subscribe to all names, return the first event. - ctx, cancel := context.WithTimeout(w.ctx, timeout) + ctx, cancel := context.WithTimeout(sctx, timeout) defer cancel() type result struct { @@ -672,7 +702,7 @@ func (w *Workflow) WaitForAny(names []string, timeout time.Duration) (*event.Eve } case <-ctx.Done(): //nolint:errcheck // best-effort timeout checkpoint - _ = w.store.SaveCheckpoint(w.ctx, w.run.ID, stepName, []byte{}) + _ = w.store.SaveCheckpoint(sctx, w.run.ID, stepName, []byte{}) return nil, nil } } @@ -680,7 +710,7 @@ done: if firstEvt == nil { //nolint:errcheck // best-effort nil-result checkpoint - _ = w.store.SaveCheckpoint(w.ctx, w.run.ID, stepName, []byte{}) + _ = w.store.SaveCheckpoint(sctx, w.run.ID, stepName, []byte{}) if lastErr != nil { return nil, fmt.Errorf("workflow %s waitany: %w", w.run.Name, lastErr) } @@ -689,13 +719,13 @@ done: // Ack and checkpoint (best-effort: event already received). //nolint:errcheck // best-effort ack after successful receive - _ = w.eventStore.AckEvent(w.ctx, firstEvt.ID) + _ = w.eventStore.AckEvent(sctx, firstEvt.ID) evtData, marshalErr := json.Marshal(firstEvt) if marshalErr != nil { return nil, fmt.Errorf("workflow %s: marshal waitany event: %w", w.run.Name, marshalErr) } //nolint:errcheck // best-effort checkpoint - _ = w.store.SaveCheckpoint(w.ctx, w.run.ID, stepName, evtData) + _ = w.store.SaveCheckpoint(sctx, w.run.ID, stepName, evtData) return firstEvt, nil } @@ -707,7 +737,7 @@ func (w *Workflow) WaitForMatch( name string, timeout time.Duration, match func(*event.Event) bool, -) (*event.Event, error) { +) (_ *event.Event, err error) { stepName := "waitmatch:" + name // Check for checkpoint. @@ -726,37 +756,40 @@ func (w *Workflow) WaitForMatch( return &evt, nil } + sctx, done := w.startStep(stepKindWaitMatch, stepName) + defer func() { done(err) }() + // Poll for matching events within the timeout. deadline := time.Now().Add(timeout) for { remaining := time.Until(deadline) if remaining <= 0 { //nolint:errcheck // best-effort timeout checkpoint - _ = w.store.SaveCheckpoint(w.ctx, w.run.ID, stepName, []byte{}) + _ = w.store.SaveCheckpoint(sctx, w.run.ID, stepName, []byte{}) return nil, nil } - evt, subErr := w.eventStore.SubscribeEvent(w.ctx, name, remaining) + evt, subErr := w.eventStore.SubscribeEvent(sctx, name, remaining) if subErr != nil { return nil, fmt.Errorf("workflow %s waitmatch %q: %w", w.run.Name, name, subErr) } if evt == nil { // Timeout. //nolint:errcheck // best-effort timeout checkpoint - _ = w.store.SaveCheckpoint(w.ctx, w.run.ID, stepName, []byte{}) + _ = w.store.SaveCheckpoint(sctx, w.run.ID, stepName, []byte{}) return nil, nil } if match(evt) { // Match found. Ack and checkpoint. //nolint:errcheck // best-effort ack after successful match - _ = w.eventStore.AckEvent(w.ctx, evt.ID) + _ = w.eventStore.AckEvent(sctx, evt.ID) evtData, marshalErr := json.Marshal(evt) if marshalErr != nil { return nil, fmt.Errorf("workflow %s: marshal waitmatch event: %w", w.run.Name, marshalErr) } //nolint:errcheck // best-effort checkpoint - _ = w.store.SaveCheckpoint(w.ctx, w.run.ID, stepName, evtData) + _ = w.store.SaveCheckpoint(sctx, w.run.ID, stepName, evtData) return evt, nil } diff --git a/workflow/telemetry.go b/workflow/telemetry.go new file mode 100644 index 0000000..c88fa45 --- /dev/null +++ b/workflow/telemetry.go @@ -0,0 +1,83 @@ +package workflow + +import ( + "context" + "time" + + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/trace" + + "github.com/xraph/dispatch/telemetry" +) + +// Step kinds, the kind label on dispatch_workflow_step_duration_seconds and +// the dispatch.workflow.step.kind span attribute. +const ( + stepKindStep = "step" + stepKindParallel = "parallel" + stepKindFanOut = "fan_out" + stepKindChild = "child" + stepKindSpawn = "spawn" + stepKindWaitEvent = "wait_event" + stepKindWaitAll = "wait_all" + stepKindWaitAny = "wait_any" + stepKindWaitMatch = "wait_match" + stepKindSleep = "sleep" + stepKindCompensate = "compensate" +) + +// WithTelemetry sets where the runner records its spans and metrics: a +// "run workflow" span per run, a "run workflow step" span per step that +// actually runs (a step replayed from its checkpoint gets none), and the run +// and step duration histograms. It returns r so callers can chain it onto +// NewRunner. engine.Build passes the engine's own. +func (r *Runner) WithTelemetry(t *telemetry.Telemetry) *Runner { + r.tel = t + + return r +} + +// startRun starts the span for one run. opts lets a background run (a +// resume, a replay, a spawned child) start as its own root with a link to +// whatever started it. +func (r *Runner) startRun(ctx context.Context, run *Run, opts ...trace.SpanStartOption) (context.Context, trace.Span) { + opts = append(opts, trace.WithAttributes( + attribute.String("dispatch.workflow.name", run.Name), + attribute.String("dispatch.workflow.run_id", run.ID.String()), + attribute.Int("dispatch.workflow.version", run.Version), + )) + + return r.tel.Start(ctx, "run workflow", opts...) +} + +// detachedRun returns ctx without its span, for a run that outlives the +// caller, and the span start options that make the run its own root linked +// back to the caller's span. +func detachedRun(ctx context.Context) (detached context.Context, opts []trace.SpanStartOption) { + opts = []trace.SpanStartOption{trace.WithNewRoot()} + if sc := trace.SpanContextFromContext(ctx); sc.IsValid() { + opts = append(opts, trace.WithLinks(trace.Link{SpanContext: sc})) + } + + return telemetry.Detach(ctx), opts +} + +// startStep starts the span and clock for a step that is about to run. The +// returned func ends both; pass it the step's error. +func (w *Workflow) startStep(kind, name string) (stepCtx context.Context, done func(error)) { + ctx, span := w.tel.Start(w.ctx, "run workflow step", trace.WithAttributes( + attribute.String("dispatch.workflow.step.kind", kind), + attribute.String("dispatch.workflow.step.name", name), + )) + started := time.Now() + + return ctx, func(err error) { + result := telemetry.ResultOK + if err != nil { + result = telemetry.ResultError + telemetry.Fail(span, "step failed", telemetry.ErrorType(err)) + } + w.tel.Workflows().Step(kind, result, time.Since(started)) + span.End() + } +} diff --git a/workflow/telemetry_test.go b/workflow/telemetry_test.go new file mode 100644 index 0000000..8b10e9a --- /dev/null +++ b/workflow/telemetry_test.go @@ -0,0 +1,207 @@ +package workflow_test + +import ( + "context" + "errors" + "fmt" + "testing" + "time" + + log "github.com/xraph/go-utils/log" + "go.opentelemetry.io/otel/codes" + sdktrace "go.opentelemetry.io/otel/sdk/trace" + "go.opentelemetry.io/otel/trace" + + "github.com/xraph/dispatch/internal/metricstest" + "github.com/xraph/dispatch/internal/oteltest" + "github.com/xraph/dispatch/store/memory" + "github.com/xraph/dispatch/telemetry" + "github.com/xraph/dispatch/workflow" +) + +type signupInput struct{ Email string } + +func telemetryRunner(t *testing.T) (*workflow.Runner, *workflow.Registry, *memory.Store, *metricstest.Factory) { + t.Helper() + s := memory.New() + reg := workflow.NewRegistry() + f := metricstest.New() + runner := workflow.NewRunner(reg, s, s, noopEmitter{}, log.NewNoopLogger()). + WithTelemetry(telemetry.New(telemetry.WithMetrics(f))) + t.Cleanup(func() { _ = runner.Shutdown(context.Background()) }) + return runner, reg, s, f +} + +func stepKinds(spans []sdktrace.ReadOnlySpan) map[string]int { + out := map[string]int{} + for _, s := range oteltest.Named(spans, "run workflow step") { + kind, _ := oteltest.Attr(s, "dispatch.workflow.step.kind") + out[kind]++ + } + return out +} + +func TestRunAndStepsAreSpansUnderTheCaller(t *testing.T) { + sr := oteltest.Record(t) + runner, reg, _, f := telemetryRunner(t) + + var inStep trace.SpanContext + workflow.RegisterDefinition(reg, workflow.NewWorkflow("signup", func(wf *workflow.Workflow, in signupInput) error { + if err := wf.Step("create-account", func(ctx context.Context) error { + inStep = trace.SpanContextFromContext(ctx) + return nil + }); err != nil { + return err + } + _, err := workflow.StepWithResult(wf, "send-welcome", func(context.Context) (string, error) { + return "", fmt.Errorf("smtp rejected %s", in.Email) + }) + return err + })) + + ctx, request := otelTracer().Start(context.Background(), "POST /signup") + if _, err := workflow.Start(ctx, runner, "signup", signupInput{Email: "alice@example.com"}); err != nil { + t.Fatal(err) + } + request.End() + + spans := sr.Ended() + runs := oteltest.Named(spans, "run workflow") + if len(runs) != 1 { + t.Fatalf("run spans = %d", len(runs)) + } + run := runs[0] + if run.Parent().SpanID() != request.SpanContext().SpanID() { + t.Error("a run the caller waits on should be a child of the caller's span") + } + if run.Status().Code != codes.Error || run.Status().Description != "workflow failed" { + t.Errorf("run status = %+v", run.Status()) + } + if got, _ := oteltest.Attr(run, "dispatch.workflow.name"); got != "signup" { + t.Errorf("workflow name = %q", got) + } + + steps := oteltest.Named(spans, "run workflow step") + if len(steps) != 2 { + t.Fatalf("step spans = %d, want 2", len(steps)) + } + for _, s := range steps { + if !oteltest.ChildOf(s, run) { + t.Errorf("step %v is not a child of the run", s.Name()) + } + } + if inStep.SpanID() != steps[0].SpanContext().SpanID() { + t.Error("the step function did not get the step span's context") + } + oteltest.AssertNoValue(t, spans, "alice@example.com") + + if n, ok := f.HistogramCount(telemetry.MetricWorkflowRuns, "result", "failed"); !ok || n != 1 { + t.Errorf("failed runs = %d, %v", n, ok) + } + if n, ok := f.HistogramCount(telemetry.MetricWorkflowStep, "kind", "step", "result", "ok"); !ok || n != 1 { + t.Errorf("ok steps = %d, %v", n, ok) + } + if n, ok := f.HistogramCount(telemetry.MetricWorkflowStep, "kind", "step", "result", "error"); !ok || n != 1 { + t.Errorf("failed steps = %d, %v", n, ok) + } +} + +func TestResumedRunsAreRootsAndReplayedStepsGetNoSpan(t *testing.T) { + sr := oteltest.Record(t) + runner, reg, s, _ := telemetryRunner(t) + + failFirst := true + workflow.RegisterDefinition(reg, workflow.NewWorkflow("import", func(wf *workflow.Workflow, _ struct{}) error { + if err := wf.Step("download", func(context.Context) error { return nil }); err != nil { + return err + } + return wf.Step("load", func(context.Context) error { + if failFirst { + failFirst = false + return errors.New("crash") + } + return nil + }) + })) + run, err := workflow.Start(context.Background(), runner, "import", struct{}{}) + if err != nil { + t.Fatal(err) + } + // Put the failed run back to running, as a crash mid-run leaves it. + run.State = workflow.RunStateRunning + run.Error = "" + run.CompletedAt = nil + if err := s.UpdateRun(context.Background(), run); err != nil { + t.Fatal(err) + } + sr.Reset() + + boot := oteltest.SpanContext(t) + if err := runner.ResumeAll(boot); err != nil { + t.Fatal(err) + } + + spans := sr.Ended() + runs := oteltest.Named(spans, "run workflow") + if len(runs) != 1 { + t.Fatalf("resumed runs = %d", len(runs)) + } + if !oteltest.IsRoot(runs[0]) { + t.Error("a resumed run should start its own trace") + } + if !oteltest.LinksTo(runs[0], trace.SpanContextFromContext(boot)) { + t.Error("a resumed run should link to whatever resumed it") + } + if got, _ := oteltest.Attr(runs[0], "dispatch.workflow.resumed"); got != "true" { + t.Errorf("resumed = %q", got) + } + // "download" replays from its checkpoint; only "load" runs. + if kinds := stepKinds(spans); kinds["step"] != 1 { + t.Errorf("step spans after resume = %v, want one", kinds) + } +} + +func TestSpawnedChildIsItsOwnTrace(t *testing.T) { + sr := oteltest.Record(t) + runner, reg, _, _ := telemetryRunner(t) + + done := make(chan struct{}) + workflow.RegisterDefinition(reg, workflow.NewWorkflow("child", func(*workflow.Workflow, struct{}) error { + close(done) + return nil + })) + workflow.RegisterDefinition(reg, workflow.NewWorkflow("parent", func(wf *workflow.Workflow, _ struct{}) error { + _, err := workflow.SpawnChild(wf, "child", struct{}{}) + return err + })) + + if _, err := workflow.Start(context.Background(), runner, "parent", struct{}{}); err != nil { + t.Fatal(err) + } + <-done + runs := sr.WaitFor(t, "run workflow", 2, 5*time.Second) + + var parent, child sdktrace.ReadOnlySpan + for _, r := range runs { + if name, _ := oteltest.Attr(r, "dispatch.workflow.name"); name == "child" { + child = r + } else { + parent = r + } + } + spawn := oteltest.Named(sr.Ended(), "run workflow step") + if len(spawn) != 1 { + t.Fatalf("spawn step spans = %d", len(spawn)) + } + if !oteltest.IsRoot(child) { + t.Error("a spawned child should start its own trace") + } + if !oteltest.LinksTo(child, spawn[0].SpanContext()) { + t.Error("a spawned child should link to the step that spawned it") + } + if child.SpanContext().TraceID() == parent.SpanContext().TraceID() { + t.Error("child shares the parent's trace") + } +} + +func otelTracer() trace.Tracer { return telemetry.New().Tracer() } From 315b1b05d552b3a9c3095b076de4e142d83d4054 Mon Sep 17 00:00:00 2001 From: Rex Raphael Date: Sat, 17 Oct 2026 23:29:22 -0500 Subject: [PATCH 06/18] feat(durable): trace claimed runtime tasks, replays and activities Worker.Run now drops whatever span its context carries before it starts polling, because the engine hands it the context forge started the extension under. Every claim used to land in that boot trace. A claim that returns a task starts one root "process durable task" span, for all six task kinds, and an empty claim starts nothing. Inside it, replaying the workflow's history is a "replay workflow history" span and each call into activity code is a "run activity" span. Workflow and run IDs are chosen by whoever starts the workflow, so they stay off spans and metrics; the spans carry the task kind, queue, namespace, build and attempt. Contention, a lost lease, a handler this build lacks and a stopping worker are ordinary outcomes and are recorded as results, not errors. You get task durations by kind and result, claim polls by kind and result, and replay duration. Options gains a Telemetry field; nothing about the trace is written to start or commit requests, task payloads or history. --- durable/runtime/telemetry.go | 149 ++++++++++++++++++ durable/runtime/telemetry_test.go | 164 ++++++++++++++++++++ durable/runtime/worker.go | 14 ++ durable/runtime/worker_activity.go | 4 +- durable/runtime/worker_children.go | 5 +- durable/runtime/worker_decision.go | 2 +- durable/runtime/worker_effect.go | 4 +- durable/runtime/worker_execution_timeout.go | 5 +- 8 files changed, 342 insertions(+), 5 deletions(-) create mode 100644 durable/runtime/telemetry.go create mode 100644 durable/runtime/telemetry_test.go diff --git a/durable/runtime/telemetry.go b/durable/runtime/telemetry.go new file mode 100644 index 0000000..6e95e34 --- /dev/null +++ b/durable/runtime/telemetry.go @@ -0,0 +1,149 @@ +package runtime + +import ( + "context" + "errors" + "time" + + "go.opentelemetry.io/otel/attribute" + semconv "go.opentelemetry.io/otel/semconv/v1.43.0" + "go.opentelemetry.io/otel/trace" + + "github.com/xraph/dispatch/durable" + "github.com/xraph/dispatch/telemetry" +) + +// Span attribute keys on durable task spans. Workflow and run IDs are +// chosen by whoever starts the workflow, so they stay off spans as well as +// metrics; the kind, queue, namespace and attempt are deployment values. +const ( + attrTaskKind = attribute.Key("dispatch.durable.task.kind") + attrTaskAttempt = attribute.Key("dispatch.durable.task.attempt") + attrNamespace = attribute.Key("dispatch.durable.namespace") + attrBuildID = attribute.Key("dispatch.durable.build_id") + attrTaskResult = attribute.Key("dispatch.durable.task.result") + attrHistoryEvents = attribute.Key("dispatch.durable.history.events") + attrActivityName = attribute.Key("dispatch.durable.activity.name") + attrDeliveryKind = attribute.Key("dispatch.durable.child_delivery.kind") + attrTimeoutKind = attribute.Key("dispatch.durable.timeout.kind") +) + +// recordPoll counts one claim poll for kind. +func (w *Worker) recordPoll(kind durable.TaskKind, claimed bool, err error) { + result := telemetry.PollEmpty + switch { + case err != nil: + result = telemetry.PollError + case claimed: + result = telemetry.PollWork + } + w.options.Telemetry.Durable().Poll(string(kind), result) +} + +// startTask starts the root span for one claimed task. A claim that came +// back empty never gets here, so an idle worker polling every +// PollInterval starts no traces. The returned func ends the span and +// records the task's duration; pass it the task's final error. +func (w *Worker) startTask(ctx context.Context, kind durable.TaskKind, queue string, attempt int64, attrs ...attribute.KeyValue) (taskCtx context.Context, finish func(error)) { + attrs = append(attrs, + semconv.MessagingSystemKey.String("dispatch"), + semconv.MessagingOperationTypeProcess, + semconv.MessagingOperationName("process"), + semconv.MessagingDestinationName(queue), + attrTaskKind.String(string(kind)), + attrTaskAttempt.Int64(attempt), + attrNamespace.String(w.options.Namespace), + attrBuildID.String(w.options.BuildID), + ) + ctx, span := w.options.Telemetry.Start(ctx, "process durable task", + trace.WithNewRoot(), + trace.WithSpanKind(trace.SpanKindConsumer), + trace.WithAttributes(attrs...), + ) + started := time.Now() + + return ctx, func(err error) { + result := taskResult(err) + span.SetAttributes(attrTaskResult.String(result)) + if result == telemetry.DurableError { + telemetry.Fail(span, "task failed", durableErrorType(err)) + } + w.options.Telemetry.Durable().Task(string(kind), result, time.Since(started)) + span.End() + } +} + +// taskResult classifies how a claimed task ended. Contention, a lost lease, +// a handler this build lacks and a stopping worker are all ordinary: the +// task stays for another attempt, so none of them is an error. +func taskResult(err error) string { + switch { + case err == nil: + return telemetry.DurableOK + case errors.Is(err, ErrHandlerNotFound): + return telemetry.DurableNoHandler + case errors.Is(err, durable.ErrLeaseLost): + return telemetry.DurableLeaseLost + case normalContention(err): + return telemetry.DurableContention + case errors.Is(err, context.Canceled), errors.Is(err, ErrWorkerDraining), errors.Is(err, ErrDrainIncomplete): + return telemetry.DurableCancelled + default: + return telemetry.DurableError + } +} + +// durableErrorType names a task failure for its exception event: a durable +// sentinel's name where one matches, else the innermost error's Go type. +func durableErrorType(err error) string { + for _, s := range []struct { + err error + name string + }{ + {ErrHistory, "runtime.ErrHistory"}, + {durable.ErrInvalid, "durable.ErrInvalid"}, + {ErrNondeterministic, "runtime.ErrNondeterministic"}, + } { + if errors.Is(err, s.err) { + return s.name + } + } + + return telemetry.ErrorType(err) +} + +// replay evaluates a workflow's history under a "replay workflow history" +// span and records how long it took. +func (w *Worker) replay(ctx context.Context, execution durable.Execution, events []durable.Event, handler WorkflowFunc) (Decision, error) { + _, span := w.options.Telemetry.Start(ctx, "replay workflow history", + trace.WithAttributes(attrHistoryEvents.Int(len(events)))) + defer span.End() + + started := time.Now() + decision, err := Evaluate(execution, events, handler) + w.options.Telemetry.Durable().Replay(time.Since(started)) + if err != nil { + telemetry.Fail(span, "replay failed", durableErrorType(err)) + } + + return decision, err +} + +// startActivity starts the span around one call into activity code. +func (w *Worker) startActivity(ctx context.Context, name string) (context.Context, trace.Span) { + return w.options.Telemetry.Start(ctx, "run activity", + trace.WithAttributes(attrActivityName.String(name))) +} + +// endActivity ends an activity span. A failure the activity returned is +// the activity's answer, recorded in history and retried by policy; only +// an error calling it at all marks the span failed. +func endActivity(span trace.Span, outcome Outcome, err error) { + switch { + case err != nil: + telemetry.Fail(span, "activity call failed", durableErrorType(err)) + case outcome.Failure != nil: + telemetry.Fail(span, "activity failed", "") + } + span.End() +} diff --git a/durable/runtime/telemetry_test.go b/durable/runtime/telemetry_test.go new file mode 100644 index 0000000..324cc5d --- /dev/null +++ b/durable/runtime/telemetry_test.go @@ -0,0 +1,164 @@ +package runtime_test + +import ( + "context" + "errors" + "sync" + "testing" + "time" + + "go.opentelemetry.io/otel/trace" + + "github.com/xraph/dispatch/durable" + drt "github.com/xraph/dispatch/durable/runtime" + "github.com/xraph/dispatch/internal/metricstest" + "github.com/xraph/dispatch/internal/oteltest" + "github.com/xraph/dispatch/store/memory" + "github.com/xraph/dispatch/telemetry" +) + +func TestClaimedTasksAreRootSpans(t *testing.T) { + sr := oteltest.Record(t) + s := memory.New() + f := metricstest.New() + options := workerOptions(t) + options.Telemetry = telemetry.New(telemetry.WithMetrics(f)) + options.Workflows["order"] = func(w *drt.Workflow, _ []byte) ([]byte, error) { + return w.Activity("charge", "charge", "", []byte("alice@example.com")).Get() + } + options.Activities["charge"] = func(context.Context, drt.ActivityInfo, []byte) ([]byte, error) { + return []byte("paid"), nil + } + w := newWorker(t, s, options) + startWorkerRun(t, w, options) + + // A context carrying a span, as an extension's Start or a request + // would hand over. Each task must still be its own trace. + ctx := oteltest.SpanContext(t) + for _, kind := range []durable.TaskKind{durable.TaskWorkflow, durable.TaskActivity, durable.TaskWorkflow} { + if worked, err := w.RunOnce(ctx, kind); err != nil || !worked { + t.Fatalf("run %s: worked=%t err=%v", kind, worked, err) + } + } + + spans := sr.Ended() + tasks := oteltest.Named(spans, "process durable task") + if len(tasks) != 3 { + t.Fatalf("task spans = %d, want 3", len(tasks)) + } + byKind := map[string][]int{} + for i, task := range tasks { + if !oteltest.IsRoot(task) { + t.Errorf("task span %d has a parent", i) + } + if task.SpanKind() != trace.SpanKindConsumer { + t.Errorf("task span %d kind = %v", i, task.SpanKind()) + } + kind, _ := oteltest.Attr(task, "dispatch.durable.task.kind") + byKind[kind] = append(byKind[kind], i) + if got, _ := oteltest.Attr(task, "dispatch.durable.task.result"); got != telemetry.DurableOK { + t.Errorf("task %s result = %q", kind, got) + } + if got, _ := oteltest.Attr(task, "messaging.destination.name"); got != "orders" { + t.Errorf("task %s queue = %q", kind, got) + } + } + if len(byKind["workflow"]) != 2 || len(byKind["activity"]) != 1 { + t.Fatalf("task kinds = %v", byKind) + } + + replays := oteltest.Named(spans, "replay workflow history") + if len(replays) != 2 { + t.Fatalf("replay spans = %d, want 2", len(replays)) + } + if !oteltest.ChildOf(replays[0], tasks[byKind["workflow"][0]]) { + t.Error("replay is not a child of its workflow task") + } + activities := oteltest.Named(spans, "run activity") + if len(activities) != 1 || !oteltest.ChildOf(activities[0], tasks[byKind["activity"][0]]) { + t.Fatalf("activity spans = %d or not under the activity task", len(activities)) + } + if got, _ := oteltest.Attr(activities[0], "dispatch.durable.activity.name"); got != "charge" { + t.Errorf("activity name = %q", got) + } + // Workflow and run IDs are caller-chosen, and inputs are payload. + oteltest.AssertNoValue(t, spans, "alice@example.com") + for _, task := range tasks { + for _, a := range task.Attributes() { + if a.Value.String() == "order" || a.Value.String() == "run" { + t.Errorf("task span carries a workflow or run ID in %s", a.Key) + } + } + } + + if n, ok := f.HistogramCount(telemetry.MetricDurableTaskDuration, "kind", "workflow", "result", "ok"); !ok || n != 2 { + t.Errorf("workflow tasks = %d, %v", n, ok) + } + if n, ok := f.HistogramCount(telemetry.MetricDurableTaskDuration, "kind", "activity", "result", "ok"); !ok || n != 1 { + t.Errorf("activity tasks = %d, %v", n, ok) + } + if v, ok := f.CounterValue(telemetry.MetricDurablePolls, "kind", "workflow", "result", telemetry.PollWork); !ok || v != 2 { + t.Errorf("workflow work polls = %v, %v", v, ok) + } + if len(f.Series(telemetry.MetricDurableReplayDuration)) != 1 { + t.Error("no replay duration series") + } +} + +// spanCheckingDurableStore records whether idle claim polls carry a span. +type spanCheckingDurableStore struct { + *memory.Store + mu sync.Mutex + claims int + traced int + claimed chan struct{} +} + +func (s *spanCheckingDurableStore) ClaimTask(ctx context.Context, request durable.ClaimRequest) (*durable.Task, error) { + s.mu.Lock() + s.claims++ + if trace.SpanContextFromContext(ctx).IsValid() { + s.traced++ + } + if s.claims == 10 { + close(s.claimed) + } + s.mu.Unlock() + return s.Store.ClaimTask(ctx, request) +} + +func TestIdleRunPollsCarryNoSpan(t *testing.T) { + sr := oteltest.Record(t) + s := &spanCheckingDurableStore{Store: memory.New(), claimed: make(chan struct{})} + f := metricstest.New() + options := workerOptions(t) + options.Telemetry = telemetry.New(telemetry.WithMetrics(f)) + options.Workflows["order"] = func(*drt.Workflow, []byte) ([]byte, error) { return nil, nil } + w := newWorker(t, s, options) + + ctx, cancel := context.WithCancel(oteltest.SpanContext(t)) + done := make(chan error, 1) + go func() { done <- w.Run(ctx) }() + select { + case <-s.claimed: + case <-time.After(5 * time.Second): + t.Fatal("worker never polled") + } + cancel() + if err := <-done; err != nil && !errors.Is(err, context.Canceled) { + t.Fatalf("Run: %v", err) + } + + s.mu.Lock() + traced := s.traced + s.mu.Unlock() + if traced != 0 { + t.Errorf("%d idle claims carried a span", traced) + } + if spans := sr.Ended(); len(spans) != 0 { + t.Errorf("idle worker started %d spans", len(spans)) + } + if v, ok := f.CounterValue(telemetry.MetricDurablePolls, "kind", "workflow", "result", telemetry.PollEmpty); !ok || v < 1 { + t.Errorf("empty workflow polls = %v, %v", v, ok) + } +} diff --git a/durable/runtime/worker.go b/durable/runtime/worker.go index f65a78a..9a69b16 100644 --- a/durable/runtime/worker.go +++ b/durable/runtime/worker.go @@ -12,6 +12,7 @@ import ( "time" "github.com/xraph/dispatch/durable" + "github.com/xraph/dispatch/telemetry" ) // ErrHandlerNotFound leaves a task available for a worker with compatible code. @@ -58,6 +59,11 @@ type Options struct { Concurrency int Workflows map[string]WorkflowFunc Activities map[string]ActivityFunc + // Telemetry receives the worker's spans and metrics: one root "process + // durable task" span per claimed task, and the task, poll and replay + // metrics. Nil starts spans on the global tracer provider and records no + // metrics. engine.WithDurableWorkflows fills it with the engine's own. + Telemetry *telemetry.Telemetry } // Worker claims durable tasks. Multiple workers may share a queue and store. @@ -146,6 +152,11 @@ func (w *Worker) StartExecution(ctx context.Context, request durable.StartReques // Processing errors are returned to the supervisor, never silently discarded. // Cancellation leaves unfinished tasks for replacement workers after expiry. func (w *Worker) Run(ctx context.Context) (result error) { + // Run polls for as long as ctx lives. Whatever span ctx carries (a Forge + // extension's boot span, a request) ended long ago by the time most + // polls run, so the pollers keep none of it; each claimed task starts + // its own root. + ctx = telemetry.Detach(ctx) if err := w.startRun(ctx); err != nil { return err } @@ -227,9 +238,12 @@ func (w *Worker) runOnce(ctx context.Context, kind durable.TaskKind, runOwned bo LeaseDuration: w.options.LeaseDuration}) }) w.claimReturned(operation, err) + w.recordPoll(kind, task != nil, err) if err != nil || task == nil { return false, err } + ctx, finish := w.startTask(ctx, kind, task.Queue, task.Attempt) + defer func() { finish(err) }() lease := newTaskLease(ctx, w, *task) defer lease.close() if kind == durable.TaskWorkflow { diff --git a/durable/runtime/worker_activity.go b/durable/runtime/worker_activity.go index 82677d9..5d9ac4e 100644 --- a/durable/runtime/worker_activity.go +++ b/durable/runtime/worker_activity.go @@ -66,8 +66,10 @@ func (w *Worker) processActivity(ctx context.Context, task durable.Task, payload } heartbeats := newHeartbeatSession(attemptCtx, w, task) handoff := &handoffSession{worker: w, lease: lease, heartbeats: heartbeats, task: task, payload: payload, buildID: execution.BuildID, attempt: attempt.Attempt} - outcome, callErr := callActivity(heartbeats.ctx, handler, ActivityInfo{Key: task.Key, CommandID: command.ID, BuildID: execution.BuildID, Attempt: attempt.Attempt, + activityCtx, activitySpan := w.startActivity(heartbeats.ctx, command.Name) + outcome, callErr := callActivity(activityCtx, handler, ActivityInfo{Key: task.Key, CommandID: command.ID, BuildID: execution.BuildID, Attempt: attempt.Attempt, deferCompletion: handoff.deferCompletion, heartbeat: heartbeats.record, heartbeatDetails: bytes.Clone(task.Progress)}, command.Input) + endActivity(activitySpan, outcome, callErr) cancelAttempt() heartbeats.close() if heartbeats.detached { diff --git a/durable/runtime/worker_children.go b/durable/runtime/worker_children.go index 5794c99..793b1a3 100644 --- a/durable/runtime/worker_children.go +++ b/durable/runtime/worker_children.go @@ -113,14 +113,17 @@ func childDecisionWithFailures(queue string, original durable.CommitRequest, fai return candidate, nil } -func (w *Worker) runChildDelivery(ctx context.Context, operation *claimOperation) (bool, error) { +func (w *Worker) runChildDelivery(ctx context.Context, operation *claimOperation) (_ bool, err error) { delivery, err := storeCall(ctx, w, func(callCtx context.Context) (*durable.ChildDelivery, error) { return w.store.ClaimChildDelivery(callCtx, durable.ChildDeliveryClaimRequest{Namespace: w.options.Namespace, BuildID: w.options.BuildID, Owner: w.options.Owner, LeaseDuration: w.options.LeaseDuration}) }) w.claimReturned(operation, err) + w.recordPoll(TaskChildDelivery, delivery != nil, err) if err != nil || delivery == nil { return false, err } + ctx, finish := w.startTask(ctx, TaskChildDelivery, w.options.Queue, delivery.Attempt, attrDeliveryKind.String(string(delivery.Kind))) + defer func() { finish(err) }() // Close/cancel claims follow the current child build. Their saved routing // still identifies the original invocation, even after it continues. toParent := delivery.Kind == durable.ChildDeliveryResult || delivery.Kind == durable.ChildDeliveryCancelAck diff --git a/durable/runtime/worker_decision.go b/durable/runtime/worker_decision.go index 0e690b6..ade83ba 100644 --- a/durable/runtime/worker_decision.go +++ b/durable/runtime/worker_decision.go @@ -26,7 +26,7 @@ func (w *Worker) processWorkflow(ctx context.Context, task durable.Task, lease * if handler == nil { return fmt.Errorf("%w: workflow %q", ErrHandlerNotFound, execution.WorkflowType) } - decision, err := Evaluate(execution, events, handler) + decision, err := w.replay(ctx, execution, events, handler) if err != nil { return err } diff --git a/durable/runtime/worker_effect.go b/durable/runtime/worker_effect.go index 6a2f691..2a658c2 100644 --- a/durable/runtime/worker_effect.go +++ b/durable/runtime/worker_effect.go @@ -36,8 +36,10 @@ func (w *Worker) processEffect(ctx context.Context, task durable.Task, lease *ta if handler == nil { return fmt.Errorf("%w: activity %q", ErrHandlerNotFound, command.Name) } - outcome, err = callActivity(ctx, handler, ActivityInfo{Key: task.Key, CommandID: command.ID, + activityCtx, activitySpan := w.startActivity(ctx, command.Name) + outcome, err = callActivity(activityCtx, handler, ActivityInfo{Key: task.Key, CommandID: command.ID, BuildID: execution.BuildID, Attempt: task.Attempt}, command.Input) + endActivity(activitySpan, outcome, err) if err != nil { return err } diff --git a/durable/runtime/worker_execution_timeout.go b/durable/runtime/worker_execution_timeout.go index a0ad94f..8c8cc40 100644 --- a/durable/runtime/worker_execution_timeout.go +++ b/durable/runtime/worker_execution_timeout.go @@ -8,14 +8,17 @@ import ( "github.com/xraph/dispatch/durable" ) -func (w *Worker) runExecutionTimeout(ctx context.Context, operation *claimOperation) (bool, error) { +func (w *Worker) runExecutionTimeout(ctx context.Context, operation *claimOperation) (_ bool, err error) { grant, err := storeCall(ctx, w, func(callCtx context.Context) (*durable.ExecutionTimeoutTask, error) { return w.store.ClaimExecutionTimeout(callCtx, durable.ExecutionTimeoutClaimRequest{Namespace: w.options.Namespace, Owner: w.options.Owner, LeaseDuration: w.options.LeaseDuration}) }) w.claimReturned(operation, err) + w.recordPoll(TaskExecutionTimeout, grant != nil, err) if err != nil || grant == nil { return false, err } + ctx, finish := w.startTask(ctx, TaskExecutionTimeout, w.options.Queue, grant.Attempt, attrTimeoutKind.String(string(grant.Kind))) + defer func() { finish(err) }() metadata := durable.ExecutionTimeout{Version: 1, Kind: grant.Kind, DeadlineAt: grant.DeadlineAt} if grant.Validate() != nil || grant.Namespace != w.options.Namespace || grant.Owner != w.options.Owner || grant.Epoch < 1 || grant.Attempt < 1 || grant.LeaseUntil.IsZero() || metadata.Validate() != nil { return true, fmt.Errorf("%w: timeout grant does not match worker routing", durable.ErrInvalid) From 9f27e11557f66ebc5d9d9d729e41afa292a9a031 Mon Sep 17 00:00:00 2001 From: Rex Raphael Date: Sat, 17 Oct 2026 23:29:22 -0500 Subject: [PATCH 07/18] feat(delivery): trace outbox deliveries and the remote sink transport The publisher starts one root "deliver outbox event" producer span per claimed delivery, with the destination, the delivery's opaque ID and its attempt count, and the sink call runs inside it. The chronicle and relay calls a sink makes are traced by those libraries. An empty claim starts nothing, and the Delivery envelope is untouched. You get delivery attempt durations by destination and result (the publisher's existing failure categories plus acknowledged) and the lag from acceptance to acknowledgement. delivery.New takes options now, and WithTelemetry is the first. The remote sink's HTTP client wraps its transport with otelhttp, keeping the same timeouts, TLS floor and redirect policy, so a call to a remote Chronicle or Relay host carries traceparent and gets a client span. The publisher's context never carries inbound baggage to forward. --- durable/delivery/ecosystem/http.go | 6 +- durable/delivery/publisher.go | 47 +++++++++++- durable/delivery/telemetry_test.go | 118 +++++++++++++++++++++++++++++ go.mod | 2 +- 4 files changed, 170 insertions(+), 3 deletions(-) create mode 100644 durable/delivery/telemetry_test.go diff --git a/durable/delivery/ecosystem/http.go b/durable/delivery/ecosystem/http.go index 68437c0..80d3003 100644 --- a/durable/delivery/ecosystem/http.go +++ b/durable/delivery/ecosystem/http.go @@ -14,6 +14,7 @@ import ( ca "github.com/xraph/chronicle/acceptance" ra "github.com/xraph/relay/acceptance" + "go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp" ) const MaxResponseBytes = 256 << 10 @@ -49,7 +50,10 @@ func NewRemote(endpoint, bearer string, timeout time.Duration, localLoopbackHTTP } } transport := &http.Transport{Proxy: nil, DialContext: (&net.Dialer{Timeout: timeout}).DialContext, TLSClientConfig: &tls.Config{MinVersion: tls.VersionTLS12}, TLSHandshakeTimeout: timeout, ResponseHeaderTimeout: timeout, MaxIdleConnsPerHost: 4, IdleConnTimeout: time.Minute} - client := &http.Client{Timeout: timeout, Transport: transport, CheckRedirect: func(_ *http.Request, _ []*http.Request) error { return http.ErrUseLastResponse }} + // The traced transport adds a client span and traceparent around the + // same policy. Calls run on the publisher's background context, which + // never carries inbound baggage to forward. + client := &http.Client{Timeout: timeout, Transport: otelhttp.NewTransport(transport), CheckRedirect: func(_ *http.Request, _ []*http.Request) error { return http.ErrUseLastResponse }} return &Remote{endpoint: endpoint, bearer: bearer, client: client}, nil } func (r *Remote) Close() { r.client.CloseIdleConnections() } diff --git a/durable/delivery/publisher.go b/durable/delivery/publisher.go index 5ece963..fca238b 100644 --- a/durable/delivery/publisher.go +++ b/durable/delivery/publisher.go @@ -9,7 +9,11 @@ import ( "sync/atomic" "time" + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/trace" + "github.com/xraph/dispatch/durable" + "github.com/xraph/dispatch/telemetry" ) // Sink accepts an immutable envelope durably. Identical retries, including after @@ -88,9 +92,20 @@ type Publisher struct { draining atomic.Bool stopGate chan struct{} interrupted bool + tel *telemetry.Telemetry } -func New(store durable.OutboxStore, config Config, sinks map[durable.Destination]Sink) (*Publisher, error) { +// Option configures a Publisher beyond its Config. +type Option func(*Publisher) + +// WithTelemetry sets where the publisher records its spans and metrics: one +// root "deliver outbox event" span per claimed delivery, and the delivery +// duration and lag histograms. The Forge extension passes the engine's own. +func WithTelemetry(t *telemetry.Telemetry) Option { + return func(p *Publisher) { p.tel = t } +} + +func New(store durable.OutboxStore, config Config, sinks map[durable.Destination]Sink, opts ...Option) (*Publisher, error) { c := config.defaults() if store == nil || !durable.DeliveryIdentifier(c.Owner) || !durable.DeliveryIdentifier(c.InstallationID) || c.Concurrency < 1 || c.Concurrency > durable.MaxDeliveryBatch || c.PollInterval <= 0 || c.CallTimeout <= 0 || c.CallTimeout >= 5*time.Minute || c.StoreTimeout <= 0 || c.StoreTimeout >= 5*time.Minute || c.LeaseDuration < time.Millisecond || c.LeaseDuration <= c.CallTimeout+c.StoreTimeout || c.LeaseDuration > 5*time.Minute || c.RetryMin <= 0 || c.RetryMax < c.RetryMin || c.RetryMax > 24*time.Hour || len(sinks) == 0 { return nil, durable.ErrInvalid @@ -110,6 +125,9 @@ func New(store durable.OutboxStore, config Config, sinks map[durable.Destination } p.sinks[destination] = sink } + for _, opt := range opts { + opt(p) + } return p, nil } @@ -232,6 +250,29 @@ func (p *Publisher) run(ctx context.Context, d durable.Destination, sink Sink) { } } func (p *Publisher) publish(ctx context.Context, d durable.Destination, sink Sink, record durable.DeliveryRecord) { + // One root span per claimed delivery. ctx descends from + // context.Background (startWorkers), and an empty claim never gets + // here, so idle polling starts no traces. + ctx, span := p.tel.Start(ctx, "deliver outbox event", + trace.WithNewRoot(), + trace.WithSpanKind(trace.SpanKindProducer), + trace.WithAttributes( + attribute.String("dispatch.outbox.destination", string(d)), + attribute.String("dispatch.outbox.delivery_id", record.Delivery.ID), + attribute.Int64("dispatch.outbox.attempt", record.Attempts), + ), + ) + started := time.Now() + result := telemetry.OutboxAcknowledged + defer func() { + span.SetAttributes(attribute.String("dispatch.outbox.result", result)) + if result != telemetry.OutboxAcknowledged { + telemetry.Fail(span, "delivery "+result, "") + } + p.tel.Outbox().Delivery(string(d), result, time.Since(started)) + span.End() + }() + category := "" envelope := record.Delivery if envelope.Destination != d || envelope.InstallationID != p.config.InstallationID || envelope.Verify() != nil { @@ -266,11 +307,15 @@ func (p *Publisher) publish(ctx context.Context, d durable.Destination, sink Sin ackErr := p.store.AcknowledgeDelivery(ackCtx, record.Token(), receipt) ackCancel() if ackErr == nil { + if !record.AcceptedAt.IsZero() { + p.tel.Outbox().Lag(string(d), time.Since(record.AcceptedAt)) + } return } category = "unavailable" } } + result = category if ctx.Err() != nil { return } diff --git a/durable/delivery/telemetry_test.go b/durable/delivery/telemetry_test.go new file mode 100644 index 0000000..2fd2a66 --- /dev/null +++ b/durable/delivery/telemetry_test.go @@ -0,0 +1,118 @@ +package delivery_test + +import ( + "context" + "errors" + "sync/atomic" + "testing" + "time" + + "go.opentelemetry.io/otel/codes" + "go.opentelemetry.io/otel/trace" + + "github.com/xraph/dispatch/durable" + "github.com/xraph/dispatch/durable/delivery" + "github.com/xraph/dispatch/internal/metricstest" + "github.com/xraph/dispatch/internal/oteltest" + "github.com/xraph/dispatch/telemetry" +) + +func TestEachDeliveryIsARootProducerSpan(t *testing.T) { + sr := oteltest.Record(t) + s := fixture(t, 1) + f := metricstest.New() + var failures atomic.Int64 + var sinkSpan atomic.Value + sink := sinkFunc(func(ctx context.Context, d durable.Delivery) (durable.SinkReceipt, error) { + sinkSpan.Store(trace.SpanContextFromContext(ctx)) + // The first attempt fails with a message quoting a value; the retry + // is acknowledged. + if failures.Add(1) == 1 { + return durable.SinkReceipt{}, errors.New("relay at alice@example.com unavailable") + } + return receipt(d), nil + }) + p, err := delivery.New(s, config("one"), map[durable.Destination]delivery.Sink{durable.DestinationChronicle: sink}, + delivery.WithTelemetry(telemetry.New(telemetry.WithMetrics(f)))) + if err != nil { + t.Fatal(err) + } + if err = p.Start(); err != nil { + t.Fatal(err) + } + spans := sr.WaitFor(t, "deliver outbox event", 2, 5*time.Second) + stop(t, p) + + results := map[string]int{} + for _, span := range spans { + if !oteltest.IsRoot(span) { + t.Error("delivery span has a parent") + } + if span.SpanKind() != trace.SpanKindProducer { + t.Errorf("kind = %v", span.SpanKind()) + } + if got, _ := oteltest.Attr(span, "dispatch.outbox.destination"); got != "chronicle" { + t.Errorf("destination = %q", got) + } + result, _ := oteltest.Attr(span, "dispatch.outbox.result") + results[result]++ + if result == telemetry.OutboxUnavailable && span.Status().Code != codes.Error { + t.Error("a failed delivery should have an error status") + } + } + if results[telemetry.OutboxUnavailable] != 1 || results[telemetry.OutboxAcknowledged] < 1 { + t.Errorf("results = %v", results) + } + if sc, _ := sinkSpan.Load().(trace.SpanContext); !sc.IsValid() { + t.Error("the sink did not run under the delivery span") + } + oteltest.AssertNoValue(t, sr.Ended(), "alice@example.com") + + if n, ok := f.HistogramCount(telemetry.MetricOutboxDeliveryDuration, "destination", "chronicle", "result", "unavailable"); !ok || n != 1 { + t.Errorf("unavailable deliveries = %d, %v", n, ok) + } + if n, ok := f.HistogramCount(telemetry.MetricOutboxDeliveryLag, "destination", "chronicle"); !ok || n < 1 { + t.Errorf("delivery lag observations = %d, %v", n, ok) + } +} + +func TestIdlePublisherStartsNoSpans(t *testing.T) { + sr := oteltest.Record(t) + s := fixture(t, 0) + polled := make(chan struct{}) + var closed atomic.Bool + store := &pollSignalStore{OutboxStore: s, polled: polled, closed: &closed} + sink := sinkFunc(func(_ context.Context, d durable.Delivery) (durable.SinkReceipt, error) { return receipt(d), nil }) + p, err := delivery.New(store, config("one"), map[durable.Destination]delivery.Sink{durable.DestinationChronicle: sink}, + delivery.WithTelemetry(telemetry.New())) + if err != nil { + t.Fatal(err) + } + if err = p.Start(); err != nil { + t.Fatal(err) + } + select { + case <-polled: + case <-time.After(5 * time.Second): + t.Fatal("publisher never polled") + } + stop(t, p) + if spans := sr.Ended(); len(spans) != 0 { + t.Errorf("idle publisher started %d spans", len(spans)) + } +} + +// pollSignalStore closes polled once the publisher has claimed a few times. +type pollSignalStore struct { + durable.OutboxStore + polled chan struct{} + closed *atomic.Bool + claims atomic.Int64 +} + +func (s *pollSignalStore) ClaimDeliveries(ctx context.Context, claim durable.DeliveryClaim) ([]durable.DeliveryRecord, error) { + if s.claims.Add(1) == 5 && s.closed.CompareAndSwap(false, true) { + close(s.polled) + } + return s.OutboxStore.ClaimDeliveries(ctx, claim) +} diff --git a/go.mod b/go.mod index a4f4512..9c53ea8 100644 --- a/go.mod +++ b/go.mod @@ -124,7 +124,7 @@ require ( github.com/xraph/go-utils v1.4.1 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.70.0 // indirect + go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.70.0 go.yaml.in/yaml/v2 v2.4.4 // indirect go.yaml.in/yaml/v3 v3.0.5 // indirect golang.org/x/crypto v0.57.0 // indirect From 4ab12a3666ee4931ffefd11dcc603b8843412ba5 Mon Sep 17 00:00:00 2001 From: Rex Raphael Date: Sat, 17 Oct 2026 23:29:22 -0500 Subject: [PATCH 08/18] feat(artifact): trace sweeper passes and count what they reclaim Start drops the boot span from the loop's context, and each pass that does work (this instance leads and the sweeper is enabled) runs under one "sweep artifacts" span with what it swept, purged, skipped and reclaimed. A follower's pass starts nothing, and RunOnce now checks leadership once per pass instead of twice. You get swept artifacts by reason (retention, orphan), purged artifacts by result (ok, skipped) and bytes reclaimed. --- artifact/sweeper/sweeper.go | 91 +++++++++++++++++++++++++----- artifact/sweeper/telemetry_test.go | 65 +++++++++++++++++++++ 2 files changed, 142 insertions(+), 14 deletions(-) create mode 100644 artifact/sweeper/telemetry_test.go diff --git a/artifact/sweeper/sweeper.go b/artifact/sweeper/sweeper.go index 7934af5..94eb530 100644 --- a/artifact/sweeper/sweeper.go +++ b/artifact/sweeper/sweeper.go @@ -8,8 +8,11 @@ import ( "time" log "github.com/xraph/go-utils/log" + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/trace" "github.com/xraph/dispatch/artifact" + "github.com/xraph/dispatch/telemetry" ) // Defaults for a sweeper built without options. @@ -55,6 +58,7 @@ type Sweeper struct { enabled bool isLeader func() bool observer Observer + tel *telemetry.Telemetry stopCh chan struct{} stopOnce sync.Once wg sync.WaitGroup @@ -108,6 +112,14 @@ func WithObserver(o Observer) Option { return func(s *Sweeper) { s.observer = o } } +// WithTelemetry sets where the sweeper records its spans and metrics: a +// root "sweep artifacts" span per pass that does work, and the swept, +// purged and bytes reclaimed counters. The Forge extension passes the +// engine's own. +func WithTelemetry(t *telemetry.Telemetry) Option { + return func(s *Sweeper) { s.tel = t } +} + // WithLogger sets the logger. func WithLogger(l log.Logger) Option { return func(s *Sweeper) { s.logger = l } @@ -154,12 +166,17 @@ func (s *Sweeper) active() bool { // retention has elapsed, then orphans — artifacts with no links at all, // which can only result from a partial failure during creation. func (s *Sweeper) SweepOnce(ctx context.Context) (Result, error) { - var res Result - if !s.active() { - return res, nil + return Result{}, nil } + return s.sweep(ctx) +} + +// sweep is SweepOnce without the leadership check. +func (s *Sweeper) sweep(ctx context.Context) (Result, error) { + var res Result + eligible, err := s.store.SweepEphemeral(ctx, artifact.SweepOpts{ Retention: s.retention, Limit: s.batchSize, @@ -169,7 +186,11 @@ func (s *Sweeper) SweepOnce(ctx context.Context) (Result, error) { return res, fmt.Errorf("dispatch/artifact/sweeper: sweep ephemeral: %w", err) } - res.Swept += s.report(ctx, eligible, "retention") + retention := s.report(ctx, eligible, "retention") + res.Swept += retention + if !s.dryRun { + s.tel.Artifacts().Swept("retention", retention) + } cutoff := time.Now().UTC().Add(-s.orphanGrace()) @@ -179,7 +200,9 @@ func (s *Sweeper) SweepOnce(ctx context.Context) (Result, error) { return res, fmt.Errorf("dispatch/artifact/sweeper: sweep orphans: %w", oerr) } - res.Swept += s.report(ctx, orphans, "orphan") + orphaned := s.report(ctx, orphans, "orphan") + res.Swept += orphaned + s.tel.Artifacts().Swept("orphan", orphaned) } return res, nil @@ -238,12 +261,22 @@ func (s *Sweeper) report(ctx context.Context, artifacts []*artifact.Artifact, re // one unreachable object cannot stall reclamation of everything else. The // next pass retries it. func (s *Sweeper) PurgeOnce(ctx context.Context) (Result, error) { - var res Result - if !s.active() || s.dryRun { - return res, nil + return Result{}, nil } + return s.purge(ctx) +} + +// purge is PurgeOnce without the leadership and dry-run checks. +func (s *Sweeper) purge(ctx context.Context) (Result, error) { + var res Result + defer func() { + s.tel.Artifacts().Purged(telemetry.PurgeOK, res.Purged) + s.tel.Artifacts().Purged(telemetry.PurgeSkipped, res.Skipped) + s.tel.Artifacts().BytesReclaimed(res.BytesReclaimed) + }() + purgeable, err := s.store.ListPurgeable(ctx, s.purgeGrace, s.batchSize) if err != nil { return res, fmt.Errorf("dispatch/artifact/sweeper: list purgeable: %w", err) @@ -298,17 +331,44 @@ func (s *Sweeper) PurgeOnce(ctx context.Context) (Result, error) { } // RunOnce performs a sweep followed by a purge. -func (s *Sweeper) RunOnce(ctx context.Context) (Result, error) { - swept, err := s.SweepOnce(ctx) - if err != nil { - return swept, err +// +// A pass that does work (this instance leads and the sweeper is enabled) +// runs under one "sweep artifacts" span, a child of ctx's span if it has +// one. The background loop gives it none, so each pass is its own trace. +// A follower's pass does nothing and starts no span. +func (s *Sweeper) RunOnce(ctx context.Context) (res Result, err error) { + if !s.active() { + return Result{}, nil } - purged, err := s.PurgeOnce(ctx) + ctx, span := s.tel.Start(ctx, "sweep artifacts", + trace.WithAttributes(attribute.Bool("dispatch.artifact.dry_run", s.dryRun))) + defer func() { + span.SetAttributes( + attribute.Int("dispatch.artifact.swept", res.Swept), + attribute.Int("dispatch.artifact.purged", res.Purged), + attribute.Int("dispatch.artifact.skipped", res.Skipped), + attribute.Int64("dispatch.artifact.bytes_reclaimed", res.BytesReclaimed), + ) + if err != nil { + telemetry.Fail(span, "sweep failed", telemetry.ErrorType(err)) + } + span.End() + }() + + swept, err := s.sweep(ctx) if err != nil { return swept, err } + var purged Result + if !s.dryRun { + purged, err = s.purge(ctx) + if err != nil { + return swept, err + } + } + return Result{ Swept: swept.Swept, Purged: purged.Purged, @@ -322,7 +382,10 @@ func (s *Sweeper) Start(ctx context.Context) error { s.startedOnce.Do(func() { s.wg.Add(1) - go s.loop(ctx) + // The loop runs for the life of the process. The span ctx carries + // (a Forge extension's boot span) does not: each pass is its own + // trace. + go s.loop(telemetry.Detach(ctx)) }) return nil diff --git a/artifact/sweeper/telemetry_test.go b/artifact/sweeper/telemetry_test.go new file mode 100644 index 0000000..c1078f4 --- /dev/null +++ b/artifact/sweeper/telemetry_test.go @@ -0,0 +1,65 @@ +package sweeper_test + +import ( + "context" + "testing" + "time" + + "github.com/xraph/dispatch/artifact/sweeper" + "github.com/xraph/dispatch/internal/metricstest" + "github.com/xraph/dispatch/internal/oteltest" + "github.com/xraph/dispatch/telemetry" +) + +func TestSweepPassIsARootSpanAndFollowersStartNone(t *testing.T) { + sr := oteltest.Record(t) + r := newRig(t) + r.createEphemeral(t, newOwner(), "temp.bin", 48*time.Hour) + f := metricstest.New() + + leader := false + s := sweeper.New(r.store, r.backend, + sweeper.WithRetention(0), + sweeper.WithPurgeGrace(0), + sweeper.WithInterval(5*time.Millisecond), + sweeper.WithLeaderCheck(func() bool { return leader }), + sweeper.WithTelemetry(telemetry.New(telemetry.WithMetrics(f)))) + + if _, err := s.RunOnce(context.Background()); err != nil { + t.Fatal(err) + } + if spans := sr.Ended(); len(spans) != 0 { + t.Fatalf("a follower's pass started %d spans", len(spans)) + } + + leader = true + // Started under a context carrying a span, as an extension's Start is. + if err := s.Start(oteltest.SpanContext(t)); err != nil { + t.Fatal(err) + } + t.Cleanup(func() { _ = s.Stop(context.Background()) }) + pass := sr.WaitFor(t, "sweep artifacts", 1, 5*time.Second)[0] + if err := s.Stop(context.Background()); err != nil { + t.Fatal(err) + } + + if !oteltest.IsRoot(pass) { + t.Error("a background sweep pass should start its own trace") + } + if got, _ := oteltest.Attr(pass, "dispatch.artifact.swept"); got != "1" { + t.Errorf("swept = %q", got) + } + if v, ok := f.CounterValue(telemetry.MetricArtifactsSwept, "reason", "retention"); !ok || v != 1 { + t.Errorf("swept metric = %v, %v", v, ok) + } + // A zero purge grace purges in the same pass that swept. + if got, _ := oteltest.Attr(pass, "dispatch.artifact.purged"); got != "1" { + t.Errorf("purged = %q", got) + } + if v, ok := f.CounterValue(telemetry.MetricArtifactsPurged, "result", telemetry.PurgeOK); !ok || v != 1 { + t.Errorf("purged metric = %v, %v", v, ok) + } + if v, ok := f.CounterValue(telemetry.MetricArtifactBytesReclaimed); !ok || v != float64(len("payload")) { + t.Errorf("bytes reclaimed = %v, %v", v, ok) + } +} From bb09eb39a83674c9b3987b9020f50b9237e1905b Mon Sep 17 00:00:00 2001 From: Rex Raphael Date: Sat, 17 Oct 2026 23:29:50 -0500 Subject: [PATCH 09/18] feat(engine): wire telemetry through every subsystem the engine builds engine.Build now builds one Telemetry from WithMetricFactory and WithTracerProvider and hands it to the runner, the pool, the cron scheduler, the workflow runner and the durable worker. The Forge extension already passes app.Metrics(), and now also hands the engine's Telemetry to the outbox publisher and artifact sweeper it builds. Engine.Telemetry exposes it for anything you assemble beside the engine. Enqueue gets an "enqueue job" producer span, a child of whatever the caller's context carries, and the attempt that runs the job links to it. DLQ replays get the same span. Only the queues you configured (the ones your workers poll, the ones with limits or resource defaults) appear as a metric label. The worker-row heartbeat, the store wake listener and the durable worker all outlive Start, and all of them used to keep the "start dispatch" boot span forge puts on Start's context. Their queries now start no span, and each unit of work starts its own root. WithMetricFactory unset keeps the legacy counters on the default collector, but leaves the labelled dispatch_* metrics off, because that collector keys series by name alone. --- engine/durable.go | 8 ++- engine/engine.go | 43 +++++++++-- engine/heartbeat.go | 6 +- engine/ops_dlq.go | 16 ++++- engine/telemetry.go | 54 ++++++++++++++ engine/telemetry_test.go | 140 ++++++++++++++++++++++++++++++++++++ extension/delivery.go | 2 +- extension/extension.go | 1 + extension/telemetry_test.go | 100 ++++++++++++++++++++++++++ 9 files changed, 359 insertions(+), 11 deletions(-) create mode 100644 engine/telemetry.go create mode 100644 engine/telemetry_test.go create mode 100644 extension/telemetry_test.go diff --git a/engine/durable.go b/engine/durable.go index 6ef07de..0687fae 100644 --- a/engine/durable.go +++ b/engine/durable.go @@ -10,6 +10,7 @@ import ( "github.com/xraph/dispatch/durable" drt "github.com/xraph/dispatch/durable/runtime" + "github.com/xraph/dispatch/telemetry" ) // Durable configuration errors prevent fallback to checkpoint execution. @@ -46,6 +47,9 @@ func (eng *Engine) buildDurable(store any) error { if !ok { return ErrDurableUnsupported } + if eng.durable.options.Telemetry == nil { + eng.durable.options.Telemetry = eng.tel + } worker, err := drt.NewWorker(backend, eng.durable.options) if err != nil { return fmt.Errorf("configure durable workflows: %w", err) @@ -149,7 +153,9 @@ func (eng *Engine) startDurable(ctx context.Context) error { if d.done != nil { return d.err } - workCtx, cancel := context.WithCancel(ctx) + // The worker polls for the life of the engine; it must not keep the + // boot span Start's ctx carries. Each claimed task starts its own root. + workCtx, cancel := context.WithCancel(telemetry.Detach(ctx)) d.cancel, d.done = cancel, make(chan struct{}) go func() { err := d.worker.Run(workCtx) diff --git a/engine/engine.go b/engine/engine.go index 7c142b9..be77cc2 100644 --- a/engine/engine.go +++ b/engine/engine.go @@ -42,6 +42,7 @@ import ( "github.com/xraph/dispatch/scope" "github.com/xraph/dispatch/store" "github.com/xraph/dispatch/stream" + "github.com/xraph/dispatch/telemetry" "github.com/xraph/dispatch/worker" "github.com/xraph/dispatch/workflow" ) @@ -163,6 +164,10 @@ type Engine struct { // nil means use gu.NewMetricsCollector default. metricFactory gu.MetricFactory + // tel is built from tracerProvider and metricFactory once the options + // have run, and handed to every subsystem Build constructs. + tel *telemetry.Telemetry + // executors is the registry job attempts are dispatched through. It // always has the in-process executor as its default. executors *exec.Registry @@ -306,8 +311,10 @@ func WithWorkerCustomKeys(keys []string) Option { } // WithTracerProvider sets a custom OTel TracerProvider for the engine. -// When set, the tracing middleware uses this provider instead of the global one. -// If not set, the global otel.GetTracerProvider() is used. +// When set, every span the engine and its subsystems start (job attempts, +// enqueues, cron fires, workflow runs, durable tasks, the tracing +// middleware) uses this provider instead of the global one. If not set, +// the global otel.GetTracerProvider() is used. func WithTracerProvider(tp trace.TracerProvider) Option { return func(eng *Engine) { eng.tracerProvider = tp @@ -316,7 +323,9 @@ func WithTracerProvider(tp trace.TracerProvider) Option { // WithMetricFactory sets the go-utils MetricFactory for engine-level metrics. // Use fapp.Metrics() in forge applications to integrate with the forge metrics system. -// If not set, a default metrics collector is used. +// If not set, a default metrics collector is used for the legacy counters and +// the labelled dispatch_* metrics (see the telemetry package) are off: the +// default collector keys series by name alone and would fold their labels. func WithMetricFactory(factory gu.MetricFactory) Option { return func(eng *Engine) { eng.metricFactory = factory @@ -391,6 +400,11 @@ func Build(d *dispatch.Dispatcher, opts ...Option) (*Engine, error) { for _, opt := range opts { opt(eng) } + eng.tel = telemetry.New( + telemetry.WithMetrics(eng.metricFactory), + telemetry.WithTracerProvider(eng.tracerProvider), + telemetry.WithQueues(eng.configuredQueues()...), + ) if err := eng.buildDurable(st); err != nil { return nil, err } @@ -420,7 +434,7 @@ func Build(d *dispatch.Dispatcher, opts ...Option) (*Engine, error) { emitter := &extRunEmitter{r: eng.extensions} eng.wfRegistry = workflow.NewRegistry() eng.eventBus = event.NewBus(es) - eng.wfRunner = workflow.NewRunner(eng.wfRegistry, ws, es, emitter, logger) + eng.wfRunner = workflow.NewRunner(eng.wfRegistry, ws, es, emitter, logger).WithTelemetry(eng.tel) // Build tracing middleware (custom provider or global). var tracingMw mw.Middleware @@ -458,7 +472,7 @@ func Build(d *dispatch.Dispatcher, opts ...Option) (*Engine, error) { runner := worker.NewRunner( eng.registry, eng.extensions, eng.jobStore, eng.dlqService, eng.bo, eng.executors, logger, allMws..., - ) + ).WithTelemetry(eng.tel) // An out-of-process rung gets a scratch directory regardless of // whether this runs — worker.Runner creates one for any attempt whose @@ -488,6 +502,7 @@ func Build(d *dispatch.Dispatcher, opts ...Option) (*Engine, error) { worker.WithPollInterval(config.PollInterval), worker.WithHeartbeatInterval(config.HeartbeatInterval), worker.WithStaleJobThreshold(config.StaleJobThreshold), + worker.WithTelemetry(eng.tel), } if config.MaxPollInterval > 0 { poolOpts = append(poolOpts, worker.WithMaxPollInterval(config.MaxPollInterval)) @@ -570,7 +585,7 @@ func Build(d *dispatch.Dispatcher, opts ...Option) (*Engine, error) { // Translate dispatch.Config cron tunables into scheduler options. // Zero values leave the scheduler's own defaults in place; only // non-zero values override. - var schedOpts []cron.SchedulerOption + schedOpts := []cron.SchedulerOption{cron.WithTelemetry(eng.tel)} if config.CronTickInterval > 0 { schedOpts = append(schedOpts, cron.WithTickInterval(config.CronTickInterval)) } @@ -704,7 +719,11 @@ func (eng *Engine) EnqueueRaw(ctx context.Context, name string, payload []byte, j.RunAt = jobOpts.RunAt } + ctx, span := eng.startEnqueueSpan(ctx, j) + defer span.End() + if err := eng.applyBindings(ctx, j, jobOpts.Bindings); err != nil { + failEnqueue(span, err) return nil, err } @@ -712,10 +731,12 @@ func (eng *Engine) EnqueueRaw(ctx context.Context, name string, payload []byte, // validated; before EnqueueJob, so an unschedulable job never // reaches the store. if err := eng.resolveResources(ctx, j, jobOpts); err != nil { + failEnqueue(span, err) return nil, err } if err := eng.commitEnqueue(ctx, j); err != nil { + failEnqueue(span, err) return nil, err } @@ -772,7 +793,9 @@ func (eng *Engine) Start(ctx context.Context) (startErr error) { // enqueues so jobs are picked up without waiting out the idle poll // backoff. Best-effort: polling remains the correctness mechanism. if wn, ok := eng.jobStore.(store.WakeNotifier); ok { - stop, err := wn.StartWakeListener(ctx, eng.pool.Wake) + // The listener outlives Start and reconnects on its own, so it + // must not keep the boot span Start's ctx carries. + stop, err := wn.StartWakeListener(telemetry.Detach(ctx), eng.pool.Wake) if err != nil { eng.logger.Warn("wake listener unavailable; relying on polling", log.String("error", err.Error()), @@ -947,6 +970,12 @@ func (eng *Engine) ClusterStore() cluster.Store { return eng.clusterStore } // WorkerID returns this engine's unique worker identifier. func (eng *Engine) WorkerID() id.WorkerID { return eng.pool.WorkerID() } +// Telemetry returns the spans and metrics the engine records through, built +// from WithMetricFactory and WithTracerProvider. The Forge extension hands it +// to the outbox publisher and artifact sweeper it builds; do the same for any +// subsystem you assemble beside the engine. +func (eng *Engine) Telemetry() *telemetry.Telemetry { return eng.tel } + // StreamBroker returns the real-time event broker, or nil if not enabled. func (eng *Engine) StreamBroker() *stream.Broker { return eng.broker } diff --git a/engine/heartbeat.go b/engine/heartbeat.go index 58dcbc6..b7dff02 100644 --- a/engine/heartbeat.go +++ b/engine/heartbeat.go @@ -10,6 +10,7 @@ import ( "github.com/xraph/dispatch" "github.com/xraph/dispatch/cluster" + "github.com/xraph/dispatch/telemetry" ) // defaultWorkerHeartbeat is the row heartbeat's interval when @@ -63,7 +64,10 @@ func (eng *Engine) startHeartbeat(ctx context.Context) { return } - hbCtx, cancel := context.WithCancel(context.WithoutCancel(ctx)) + // Detached as well as uncancelled: the loop outlives Start, and + // WithoutCancel alone keeps the boot span Start's ctx carries, which + // would put every beat's query in that finished trace. + hbCtx, cancel := context.WithCancel(telemetry.Detach(context.WithoutCancel(ctx))) done := make(chan struct{}) eng.heartbeatCancel = cancel eng.heartbeatDone = done diff --git a/engine/ops_dlq.go b/engine/ops_dlq.go index 5a419b9..c8ffe37 100644 --- a/engine/ops_dlq.go +++ b/engine/ops_dlq.go @@ -6,6 +6,8 @@ import ( "fmt" "time" + "go.opentelemetry.io/otel/trace" + "github.com/xraph/dispatch" "github.com/xraph/dispatch/dlq" "github.com/xraph/dispatch/ext" @@ -22,6 +24,9 @@ func (eng *Engine) commitEnqueue(ctx context.Context, j *job.Job) error { return err } + eng.tel.Jobs().Enqueued(eng.tel.QueueLabel(j.Queue)) + eng.tel.RememberEnqueue(j.ID.String(), trace.SpanContextFromContext(ctx)) + if eng.pool != nil { eng.pool.Wake() } @@ -46,13 +51,22 @@ func (eng *Engine) commitEnqueue(ctx context.Context, j *job.Job) error { // the job's name. EnqueueRaw never has: the worker that claims the job // may run a build this process does not. func (eng *Engine) enqueuePrepared(ctx context.Context, j *job.Job) error { + ctx, span := eng.startEnqueueSpan(ctx, j) + defer span.End() + if len(j.Resources) > 0 { if err := resource.CheckSchedulable(j.Resources, eng.MaxWorkerCapacity(ctx)); err != nil { + failEnqueue(span, err) return err } } - return eng.commitEnqueue(ctx, j) + if err := eng.commitEnqueue(ctx, j); err != nil { + failEnqueue(span, err) + return err + } + + return nil } // ReplayDLQ turns a dead letter entry back into work: a new pending job diff --git a/engine/telemetry.go b/engine/telemetry.go new file mode 100644 index 0000000..625d609 --- /dev/null +++ b/engine/telemetry.go @@ -0,0 +1,54 @@ +package engine + +import ( + "context" + "time" + + "go.opentelemetry.io/otel/attribute" + semconv "go.opentelemetry.io/otel/semconv/v1.43.0" + "go.opentelemetry.io/otel/trace" + + "github.com/xraph/dispatch/job" + "github.com/xraph/dispatch/telemetry" +) + +// configuredQueues is every queue name this engine was configured with: the +// queues its workers poll, the ones with limits, and the ones with resource +// defaults. Only these appear as a metric label; any other queue a caller +// names is recorded as telemetry.OtherQueue. +func (eng *Engine) configuredQueues() []string { + names := append([]string(nil), eng.d.Config().Queues...) + for _, c := range eng.queueConfigs { + names = append(names, c.Name) + } + for name := range eng.queueResources { + names = append(names, name) + } + + return names +} + +// startEnqueueSpan starts the producer span for one enqueue. It is a child +// of whatever the caller's ctx carries (an HTTP request, a cron fire), and +// the span context it leaves in ctx is what commitEnqueue remembers for the +// attempt to link back to. +func (eng *Engine) startEnqueueSpan(ctx context.Context, j *job.Job) (context.Context, trace.Span) { + return eng.tel.Start(ctx, "enqueue job", + trace.WithSpanKind(trace.SpanKindProducer), + trace.WithAttributes( + semconv.MessagingSystemKey.String("dispatch"), + semconv.MessagingOperationTypeSend, + semconv.MessagingOperationName("enqueue"), + semconv.MessagingDestinationName(j.Queue), + semconv.MessagingMessageID(j.ID.String()), + attribute.String("dispatch.job.name", j.Name), + attribute.Int("dispatch.job.priority", j.Priority), + attribute.Bool("dispatch.job.delayed", j.RunAt.After(time.Now().UTC())), + ), + ) +} + +// failEnqueue marks an enqueue span failed with the error's type only. +func failEnqueue(span trace.Span, err error) { + telemetry.Fail(span, "enqueue failed", telemetry.ErrorType(err)) +} diff --git a/engine/telemetry_test.go b/engine/telemetry_test.go new file mode 100644 index 0000000..b153caf --- /dev/null +++ b/engine/telemetry_test.go @@ -0,0 +1,140 @@ +package engine_test + +import ( + "context" + "sync" + "testing" + "time" + + "go.opentelemetry.io/otel/trace" + + "github.com/xraph/dispatch" + "github.com/xraph/dispatch/engine" + "github.com/xraph/dispatch/id" + "github.com/xraph/dispatch/internal/metricstest" + "github.com/xraph/dispatch/internal/oteltest" + "github.com/xraph/dispatch/job" + "github.com/xraph/dispatch/store/memory" + "github.com/xraph/dispatch/telemetry" +) + +// beatCheckingStore records whether the worker-row heartbeat, which runs +// for the life of the engine, carries a span. +type beatCheckingStore struct { + *memory.Store + mu sync.Mutex + beats int + traced int + beat chan struct{} +} + +func (s *beatCheckingStore) HeartbeatWorker(ctx context.Context, workerID id.WorkerID) error { + s.mu.Lock() + s.beats++ + if trace.SpanContextFromContext(ctx).IsValid() { + s.traced++ + } + if s.beats == 1 { + close(s.beat) + } + s.mu.Unlock() + return s.Store.HeartbeatWorker(ctx, workerID) +} + +func TestEnqueueAndAttemptAreLinkedAndLoopsKeepNoBootSpan(t *testing.T) { + sr := oteltest.Record(t) + s := &beatCheckingStore{Store: memory.New(), beat: make(chan struct{})} + d, err := dispatch.New(dispatch.WithStore(s), dispatch.WithConcurrency(1), + dispatch.WithQueues([]string{"default"}), dispatch.WithPollInterval(10*time.Millisecond)) + if err != nil { + t.Fatal(err) + } + f := metricstest.New() + eng, err := engine.Build(d, engine.WithMetricFactory(f)) + if err != nil { + t.Fatal(err) + } + engine.Register(eng, job.NewDefinition("send-email", func(context.Context, emailPayload) error { return nil })) + + ctx, request := eng.Telemetry().Tracer().Start(context.Background(), "POST /signup") + j, err := engine.Enqueue(ctx, eng, "send-email", emailPayload{To: "alice@example.com", Subject: "hi"}) + if err != nil { + t.Fatal(err) + } + request.End() + // A queue nobody configured: its name must not become a label value. + if _, err = engine.Enqueue(context.Background(), eng, "send-email", emailPayload{To: "bob@example.com"}, + job.WithQueue("customer-chosen")); err != nil { + t.Fatal(err) + } + + // Started under a context carrying a span, as forge's Start is. + if err = eng.Start(oteltest.SpanContext(t)); err != nil { + t.Fatal(err) + } + t.Cleanup(func() { + stopCtx, cancel := context.WithTimeout(context.Background(), 5*time.Second) + defer cancel() + _ = eng.Stop(stopCtx) + }) + select { + case <-s.beat: + case <-time.After(5 * time.Second): + t.Fatal("worker heartbeat never ran") + } + + sr.WaitFor(t, "process job", 1, 5*time.Second) + spans := sr.Ended() + + var enqueue []trace.SpanContext + for _, span := range oteltest.Named(spans, "enqueue job") { + if id, _ := oteltest.Attr(span, "messaging.message.id"); id == j.ID.String() { + if span.SpanKind() != trace.SpanKindProducer { + t.Errorf("enqueue kind = %v", span.SpanKind()) + } + if span.Parent().SpanID() != request.SpanContext().SpanID() { + t.Error("enqueue job is not a child of the request span") + } + enqueue = append(enqueue, span.SpanContext()) + } + } + if len(enqueue) != 1 { + t.Fatalf("enqueue spans for the job = %d", len(enqueue)) + } + + // The default chain's tracing middleware nests under the attempt. + handlerSpans := 0 + process := oteltest.Named(spans, "process job")[0] + if !oteltest.IsRoot(process) || !oteltest.LinksTo(process, enqueue[0]) { + t.Error("process job should be a root linked to its enqueue span") + } + for _, h := range oteltest.Named(spans, "run job handler") { + if oteltest.ChildOf(h, process) { + handlerSpans++ + } + } + if handlerSpans != 1 { + t.Errorf("run job handler spans under the attempt = %d", handlerSpans) + } + oteltest.AssertNoValue(t, spans, "alice@example.com") + + s.mu.Lock() + traced := s.traced + s.mu.Unlock() + if traced != 0 { + t.Errorf("%d worker heartbeats carried the boot span", traced) + } + + // The unconfigured queue collapses into "other". + if v, ok := f.CounterValue(telemetry.MetricJobsEnqueued, "queue", telemetry.OtherQueue); !ok || v != 1 { + t.Errorf("enqueued{other} = %v, %v", v, ok) + } + if v, ok := f.CounterValue(telemetry.MetricJobsEnqueued, "queue", "default"); !ok || v != 1 { + t.Errorf("enqueued{default} = %v, %v", v, ok) + } + for _, labels := range f.Series(telemetry.MetricJobsEnqueued) { + if q := labels["queue"]; q != "default" && q != telemetry.OtherQueue { + t.Errorf("queue label %q leaked into a metric", q) + } + } +} diff --git a/extension/delivery.go b/extension/delivery.go index 53dd96e..4fa6665 100644 --- a/extension/delivery.go +++ b/extension/delivery.go @@ -105,7 +105,7 @@ func (e *Extension) prepareDelivery(ctx context.Context) error { return errors.New("dispatch: audited worker namespace is required") } } - p, err := delivery.New(outbox, cfg.Publisher, cfg.Sinks) + p, err := delivery.New(outbox, cfg.Publisher, cfg.Sinks, delivery.WithTelemetry(e.eng.Telemetry())) if err != nil { return fmt.Errorf("dispatch: publisher configuration: %w", err) } diff --git a/extension/extension.go b/extension/extension.go index 20be1db..7cacc39 100644 --- a/extension/extension.go +++ b/extension/extension.go @@ -465,6 +465,7 @@ func (e *Extension) startSweeper(ctx context.Context) { sweeper.WithPurgeGrace(cfg.PurgeGrace), sweeper.WithLogger(logger), sweeper.WithLeaderCheck(e.isClusterLeader), + sweeper.WithTelemetry(e.eng.Telemetry()), ) if serr := e.sweeper.Start(ctx); serr != nil { diff --git a/extension/telemetry_test.go b/extension/telemetry_test.go new file mode 100644 index 0000000..93c8bb2 --- /dev/null +++ b/extension/telemetry_test.go @@ -0,0 +1,100 @@ +package extension_test + +import ( + "context" + "io" + "net/http" + "net/http/httptest" + "strings" + "testing" + "time" + + "github.com/xraph/forge" + "go.opentelemetry.io/otel" + + "github.com/xraph/dispatch/engine" + "github.com/xraph/dispatch/extension" + "github.com/xraph/dispatch/internal/oteltest" + "github.com/xraph/dispatch/job" + "github.com/xraph/dispatch/store/memory" +) + +func scrape(t *testing.T, app forge.App) string { + t.Helper() + p, ok := app.Metrics().(interface{ PrometheusHandler() http.Handler }) + if !ok { + t.Fatalf("app metrics %T have no Prometheus handler", app.Metrics()) + } + rr := httptest.NewRecorder() + p.PrometheusHandler().ServeHTTP(rr, httptest.NewRequestWithContext(t.Context(), http.MethodGet, "/_/metrics", nil)) + body, err := io.ReadAll(rr.Body) + if err != nil { + t.Fatal(err) + } + return string(body) +} + +func TestExtensionRecordsThroughForge(t *testing.T) { + prevTP, prevProp := otel.GetTracerProvider(), otel.GetTextMapPropagator() + t.Cleanup(func() { + otel.SetTracerProvider(prevTP) + otel.SetTextMapPropagator(prevProp) + }) + + app := forge.New(forge.WithAppName("dispatch-telemetry-test"), forge.WithAppLogger(forge.NewNoopLogger())) + rec := oteltest.NewRecorder() + if err := forge.RegisterSpanProcessor(app, rec); err != nil { + t.Fatalf("RegisterSpanProcessor: %v", err) + } + + ext := extension.New(extension.WithStore(memory.New()), extension.WithConcurrency(1), + extension.WithQueues([]string{"default"})) + if err := ext.Register(app); err != nil { + t.Fatalf("Register: %v", err) + } + engine.Register(ext.Engine(), job.NewDefinition("send-email", func(context.Context, struct{ To string }) error { return nil })) + + // forge starts every extension inside a "start " span. + startCtx, boot := forge.StartSpan(t.Context(), "start dispatch") + if err := ext.Start(startCtx); err != nil { + t.Fatalf("Start: %v", err) + } + boot.End() + t.Cleanup(func() { + ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) + defer cancel() + _ = ext.Stop(ctx) + }) + + if _, err := engine.Enqueue(t.Context(), ext.Engine(), "send-email", struct{ To string }{"alice@example.com"}); err != nil { + t.Fatal(err) + } + process := rec.WaitFor(t, "process job", 1, 5*time.Second)[0] + if process.InstrumentationScope().Name != "github.com/xraph/dispatch" { + t.Errorf("scope = %q", process.InstrumentationScope().Name) + } + for _, s := range rec.Ended() { + if s.SpanContext().TraceID() == boot.SpanContext().TraceID() && s.Name() != "start dispatch" { + t.Errorf("%q landed in the boot trace", s.Name()) + } + } + + body := scrape(t, app) + for _, want := range []string{ + `forge_dispatch_jobs_enqueued_total{queue="default"} 1`, + `forge_dispatch_job_attempt_duration_seconds_count{outcome="completed",queue="default"} 1`, + `forge_dispatch_job_queue_wait_seconds_count{queue="default"} 1`, + `forge_dispatch_job_polls_total{result="work"}`, + `forge_dispatch_jobs_active 0`, + `forge_dispatch_cron_leader`, + // The legacy counters keep their names. + `forge_dispatch_job_enqueued 1`, + } { + if !strings.Contains(body, want) { + t.Errorf("scrape is missing %s", want) + } + } + if strings.Contains(body, "alice") { + t.Error("a payload value reached the scrape") + } +} From 1dcf4d41113b8d3a9ee94a0c03cf5f46b146112c Mon Sep 17 00:00:00 2001 From: Rex Raphael Date: Sat, 17 Oct 2026 23:32:59 -0500 Subject: [PATCH 10/18] docs: document every span and metric Dispatch records The observability page now lists each span with its kind, parent and attributes, and each metric under the name forge scrapes, with every label value. It explains how a job attempt links to its enqueue, which pollers start no traces, and what never lands on a span. The legacy counters keep their own table. The README, the index, the architecture and package reference pages and AGENTS.md point at the telemetry package instead of claiming tracing lives in the middleware. The configuration example stops registering a second MetricsExtension, which double counted every event, and passes a metric factory instead. --- AGENTS.md | 3 +- README.md | 2 +- .../docs/api-reference/go-packages.mdx | 19 ++- docs/content/docs/architecture.mdx | 3 +- docs/content/docs/concepts/configuration.mdx | 2 +- docs/content/docs/index.mdx | 2 +- .../content/docs/subsystems/observability.mdx | 153 ++++++++++++++---- .../content/docs/subsystems/rate-limiting.mdx | 4 +- observability/doc.go | 11 +- 9 files changed, 149 insertions(+), 50 deletions(-) diff --git a/AGENTS.md b/AGENTS.md index 4e92229..c815ace 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -114,7 +114,8 @@ The same file adds four jobs. Native query removal guard compatibility starts a | `store/` | Aggregate `Store`, plus `memory`, `sqlite`, `postgres`, `mongo`, `redis` and `storetest` | | `ext/` | Opt-in lifecycle hook interfaces | | `audit_hook/`, `relay_hook/` | Hooks that send lifecycle events to an audit recorder and to relay | -| `middleware/`, `observability/`, `backoff/`, `scope/`, `paging/` | Job middleware, OpenTelemetry, retry delays, tenant scope, cursor paging | +| `middleware/`, `observability/`, `backoff/`, `scope/`, `paging/` | Job middleware, the legacy lifecycle counters, retry delays, tenant scope, cursor paging | +| `telemetry/` | The spans and labelled metrics every subsystem records through. A leaf: exec must not import it | | `api/`, `dwp/`, `client/`, `stream/` | REST handlers, the Dispatch Wire Protocol, the Go client, the event broker | | `security/`, `operator/` | Remote operator authentication and authorization, payload-safe durable reads and commands | | `extension/` | The Forge extension, with the dashboard contract in `extension/contract/` | diff --git a/README.md b/README.md index 7f66230..500e4bd 100644 --- a/README.md +++ b/README.md @@ -137,7 +137,7 @@ Most job queues give you jobs, and you build workflows, schedules and failure ha | More than one worker | Worker registration, heartbeats and reassignment of jobs from workers that stop heartbeating, plus a Kubernetes Lease-based cluster store in `cluster/k8s` | | Big jobs next to small ones | Resource-aware admission: jobs declare CPU, memory, disk or custom resources and workers only take what fits | | Large inputs and outputs | An artifact plane that tracks objects in [Trove](https://github.com/xraph/trove) and stages them to a local cache | -| Visibility | Logging, recovery, timeout, OpenTelemetry tracing and metrics middleware, plus lifecycle hooks for audit logs and [Relay](https://github.com/xraph/relay) webhooks | +| Visibility | OpenTelemetry spans and labelled metrics for job attempts, cron, workflows, the durable runtime, the outbox and the artifact sweeper, plus lifecycle hooks for audit logs and [Relay](https://github.com/xraph/relay) webhooks | | An admin surface | REST routes for jobs, workflow runs, the DLQ and crons, the Dispatch Wire Protocol over WebSocket, and Go, TypeScript and Python clients | The [architecture guide](https://www.xraph.com/docs/dispatch/architecture) shows how the dispatcher, the engine, the worker pool and the stores fit together. diff --git a/docs/content/docs/api-reference/go-packages.mdx b/docs/content/docs/api-reference/go-packages.mdx index 0b8d4cf..5659616 100644 --- a/docs/content/docs/api-reference/go-packages.mdx +++ b/docs/content/docs/api-reference/go-packages.mdx @@ -51,8 +51,9 @@ The engine package is the import-cycle breaker. It composes all subsystems and i | `WithExtension(x)` | func | Register an `ext.Extension` | | `WithBackoff(s)` | func | Override the retry backoff strategy | | `WithQueueConfig(cfgs...)` | func | Per-queue concurrency and rate limit settings | -| `WithTracerProvider(tp)` | func | OpenTelemetry tracer provider for the tracing middleware | -| `WithMetricFactory(f)` | func | go-utils metric factory (the Forge extension passes the app's) | +| `WithTracerProvider(tp)` | func | OpenTelemetry tracer provider for every span the engine and its subsystems start | +| `WithMetricFactory(f)` | func | go-utils metric factory for the legacy counters and the labelled `dispatch_*` metrics (the Forge extension passes the app's) | +| `(*Engine).Telemetry()` | method | The `*telemetry.Telemetry` built from those two, for subsystems you assemble beside the engine | | `WithDurableWorkflows(opts)` | func | Turn on the durable workflow runtime | | `WithStreamBroker(opts...)` | func | Turn on the stream broker DWP needs | | `WithArtifacts(svc, cache)`, `WithExecutor(e)`, `WithScratchRoot(dir)` | func | Artifact plane and execution isolation | @@ -198,7 +199,7 @@ Package-level generic functions: | `Logging(logger)` | func | Log job start and completion | | `Recover(logger)` | func | Catch panics and convert them to errors | | `Timeout(logger)` | func | Apply the job's `Timeout` as a context deadline | -| `Tracing()`, `TracingWithTracer(t)` | func | OpenTelemetry span per job | +| `Tracing()`, `TracingWithTracer(t)` | func | A `run job handler` span around the rest of the chain | | `Metrics()`, `MetricsWithFactory(f)` | func | Job duration histogram and execution counter | | `Scope()` | func | Restores the job's app and org IDs into the context | @@ -251,6 +252,18 @@ Package-level generic functions: | `NewMetricsExtension()` | func | Constructor with its own go-utils metrics collector | | `NewMetricsExtensionWithFactory(f)` | func | Constructor over a go-utils `MetricFactory` | +## telemetry + +**Import:** `github.com/xraph/dispatch/telemetry` + +| Export | Type | Purpose | +|--------|------|---------| +| `Telemetry` | struct | The tracer provider and metric instruments the subsystems record through. A nil `*Telemetry` uses the global provider and records no metrics | +| `New(opts...)` | func | Build one; `engine.Build` does this for you | +| `WithMetrics(f)`, `WithTracerProvider(tp)`, `WithQueues(names...)` | func | Options: the metric factory, the tracer provider, and the queues allowed as a label value | +| `Detach(ctx)` | func | Drop the span and baggage from a long-lived loop's context | +| `Metric*` | const | The registered metric names, such as `MetricJobAttemptDuration` | + ## id **Import:** `github.com/xraph/dispatch/id` diff --git a/docs/content/docs/architecture.mdx b/docs/content/docs/architecture.mdx index d1613e7..04d62ba 100644 --- a/docs/content/docs/architecture.mdx +++ b/docs/content/docs/architecture.mdx @@ -98,7 +98,8 @@ Extensions and middleware are independent composition axes: | `middleware` | `Middleware`, `Chain`, built-ins (Logging, Recover, Timeout, Tracing, Metrics, Scope) | | `ext` | Extension interface, lifecycle hook interfaces, `Registry` | | `backoff` | Retry backoff strategies | -| `observability` | OpenTelemetry `MetricsExtension` for system-wide counters | +| `observability` | The legacy `MetricsExtension` lifecycle counters | +| `telemetry` | The spans and labelled metrics every subsystem records through (a leaf package) | | `id` | TypeID-based identifiers (`JobID`, `RunID`, `CronID`, `DLQID`, `WorkerID` and more) | | `api` | The REST admin API as Forge routes | | `scope` | Forge scope helpers: app and org ID capture from context | diff --git a/docs/content/docs/concepts/configuration.mdx b/docs/content/docs/concepts/configuration.mdx index 5ae1b09..44a8a4f 100644 --- a/docs/content/docs/concepts/configuration.mdx +++ b/docs/content/docs/concepts/configuration.mdx @@ -62,7 +62,6 @@ The other fields (`ReapInterval`, `DefaultLeaseTTL`, `WorkerStoreCallTimeout` an ```go eng, err := engine.Build(d, - engine.WithExtension(observability.NewMetricsExtension()), engine.WithMiddleware(middleware.Logging(logger)), engine.WithBackoff(backoff.NewExponential(5*time.Second, 2*time.Hour)), engine.WithQueueConfig(queue.Config{ @@ -71,6 +70,7 @@ eng, err := engine.Build(d, RateLimit: 50, }), engine.WithTracerProvider(tracerProvider), + engine.WithMetricFactory(metricFactory), ) if err != nil { log.Fatal(err) diff --git a/docs/content/docs/index.mdx b/docs/content/docs/index.mdx index 251ccf6..2b40479 100644 --- a/docs/content/docs/index.mdx +++ b/docs/content/docs/index.mdx @@ -17,7 +17,7 @@ Dispatch is a library, not a service. You bring your own database, HTTP server a - Distributed workers: worker registration, heartbeats, leader election and reclaiming jobs from workers that stop heartbeating. - Middleware: a chain for logging, tracing, metrics, panic recovery, timeouts and Forge scope injection. - Extension hooks: opt-in lifecycle interfaces for job, workflow, cron and shutdown events. -- OpenTelemetry: metrics and tracing through the `observability` and `middleware` packages. +- OpenTelemetry: a span per job attempt, cron fire, durable task, outbox delivery and sweeper pass, and labelled metrics for each, through the `telemetry` package. See [Observability](/docs/subsystems/observability). - Relay integration: typed webhook events at every lifecycle point through `relay_hook`. - Pluggable storage: memory, PostgreSQL, SQLite and MongoDB through Grove, and Redis through Grove KV. Implement `store.Store` for anything else. diff --git a/docs/content/docs/subsystems/observability.mdx b/docs/content/docs/subsystems/observability.mdx index 2c1eb85..27f276b 100644 --- a/docs/content/docs/subsystems/observability.mdx +++ b/docs/content/docs/subsystems/observability.mdx @@ -1,61 +1,144 @@ --- title: Observability -description: Metrics and OpenTelemetry tracing for Dispatch. +description: OpenTelemetry spans and metrics for jobs, cron, workflows, the durable runtime, the outbox and the artifact sweeper. --- -Dispatch gives you two layers of observability, and `engine.Build` turns both on for you: +In a Forge app you don't configure anything. The extension passes `app.Metrics()` to the engine, forge installs the global tracer provider, and every span and metric below shows up next to the rest of your app's. Scrape `/_/metrics` and look for `forge_dispatch_`. -1. System-wide counters through `observability.MetricsExtension`, one per lifecycle event. -2. Per-job tracing and metrics through the `Tracing` and `Metrics` middleware in the default stack. - -You choose where they report with two engine options: +Outside Forge, give the engine a tracer provider and a go-utils metric factory: ```go eng, err := engine.Build(d, - engine.WithTracerProvider(tp), // an OpenTelemetry trace.TracerProvider - engine.WithMetricFactory(factory), // a go-utils metrics.MetricFactory + engine.WithTracerProvider(tp), // an OpenTelemetry trace.TracerProvider + engine.WithMetricFactory(factory), // a go-utils metrics.MetricFactory ) ``` -Without `WithTracerProvider`, the tracing middleware uses the global OpenTelemetry tracer provider. Without `WithMetricFactory`, Dispatch creates its own go-utils metrics collector named `dispatch`. The Forge extension passes the app's metrics, so counters show up next to the rest of your app's. +Without `WithTracerProvider`, spans go to the global provider. Without `WithMetricFactory`, the legacy counters go to a private go-utils collector and the labelled `dispatch_*` metrics are off. That collector keys series by name alone, so it would fold every label into one series. + +`engine.Build` hands the same settings to everything it builds: the worker pool and runner, the cron scheduler, the checkpoint workflow runner and the durable runtime. The Forge extension also hands them to the outbox publisher and the artifact sweeper. If you build one of those yourself, pass `eng.Telemetry()`: + +```go +p, err := delivery.New(outbox, cfg, sinks, delivery.WithTelemetry(eng.Telemetry())) +s := sweeper.New(store, backend, sweeper.WithTelemetry(eng.Telemetry())) +w, err := runtime.NewWorker(store, runtime.Options{ /* ... */ Telemetry: eng.Telemetry()}) +``` + +Database calls are traced and timed by Grove (`db.client` spans and `db.client.operation.duration`), HTTP routes by Forge, and the calls into Chronicle and Relay by those libraries. Dispatch adds nothing on top of those. + +## How the traces fit together + +Background work is traced one unit at a time. A job attempt, a cron fire, a durable task, an outbox delivery and a sweeper pass each start their own root span, and a poll that finds nothing starts none. The pollers and heartbeats that outlive `Start` drop the `start dispatch` boot span forge puts on its context, so their queries never land in a finished trace. + +A job crosses the store between enqueue and execution, so its attempt is its own trace. When the process that enqueued the job also runs it, the `process job` span links to the `enqueue job` span. Nothing about the trace is stored with the job, so a job enqueued by an older writer, or claimed by another worker, starts without a link. A workflow run that outlives its caller (a resumed run, a replay, a spawned child) is its own trace with a link back, the same way. + +Spans never carry payloads, error messages, user IDs or anything that names a person. A failed span gets an `Error` status with a short class such as `handler error, retrying`, and an `exception` event whose only attribute is `exception.type`: a sentinel's name (`dispatch.ErrPermanent`, `context.DeadlineExceeded`) or the error's Go type. Durable workflow and run IDs are chosen by whoever starts the workflow, so they stay off spans too. + +## Spans + +All spans use the instrumentation scope `github.com/xraph/dispatch`. -## System-wide counters +| Span | Kind | Parent | Attributes | +|------|------|--------|------------| +| `enqueue job` | Producer | the caller's span, if any | `messaging.system=dispatch`, `messaging.operation.type=send`, `messaging.operation.name=enqueue`, `messaging.destination.name` (queue), `messaging.message.id` (job ID), `dispatch.job.name`, `dispatch.job.priority`, `dispatch.job.delayed` | +| `process job` | Consumer | root, links to `enqueue job` | `messaging.system`, `messaging.operation.type=process`, `messaging.destination.name`, `messaging.message.id`, `dispatch.job.name`, `dispatch.job.attempt`, `dispatch.job.max_retries`, `dispatch.job.lease_epoch`, `dispatch.scope.app_id`, `dispatch.scope.org_id`, `dispatch.job.outcome`, `dispatch.job.exec_status`, `dispatch.job.executor`, `dispatch.job.dlq_reason`; a `lease lost` event when the heartbeat cancels the attempt | +| `run job handler` | Internal | `process job` | `dispatch.job.id`, `dispatch.job.name`, `dispatch.queue`, `dispatch.retry_count`, `dispatch.scope.app_id`, `dispatch.scope.org_id` (the tracing middleware) | +| `stage job inputs` | Internal | `run job handler` | `dispatch.job.inputs` | +| `commit job outputs` | Internal | `run job handler` | `dispatch.job.outputs` | +| `complete job` | Internal | `process job` | none | +| `schedule job retry` | Internal | `process job` | none | +| `dead-letter job` | Internal | `process job` | `dispatch.job.dlq_reason` | +| `requeue job` | Internal | `process job` | none (a launch failure, which does not use up a retry) | +| `abandon job` | Internal | `process job` or a terminal span | none (the lease moved on, or an operator cancelled the job) | +| `reclaim job leases` | Internal | root | `dispatch.lease.reclaimed`; only for a reaper pass that reclaimed something | +| `fire cron entry` | Internal | root | `dispatch.cron.id`, `dispatch.cron.name`, `dispatch.cron.job_name`, `dispatch.cron.result` | +| `run workflow` | Internal | the caller's span, or root with a link | `dispatch.workflow.name`, `dispatch.workflow.run_id`, `dispatch.workflow.version`, `dispatch.workflow.resumed` | +| `run workflow step` | Internal | `run workflow` | `dispatch.workflow.step.kind`, `dispatch.workflow.step.name`; none for a step replayed from its checkpoint | +| `process durable task` | Consumer | root | `messaging.system`, `messaging.operation.type=process`, `messaging.destination.name` (queue), `dispatch.durable.task.kind`, `dispatch.durable.task.attempt`, `dispatch.durable.namespace`, `dispatch.durable.build_id`, `dispatch.durable.task.result`, plus `dispatch.durable.timeout.kind` or `dispatch.durable.child_delivery.kind` | +| `replay workflow history` | Internal | `process durable task` | `dispatch.durable.history.events` | +| `run activity` | Internal | `process durable task` | `dispatch.durable.activity.name` | +| `deliver outbox event` | Producer | root | `dispatch.outbox.destination`, `dispatch.outbox.delivery_id`, `dispatch.outbox.attempt`, `dispatch.outbox.result` | +| `sweep artifacts` | Internal | root, or the caller's span for `RunOnce` | `dispatch.artifact.dry_run`, `dispatch.artifact.swept`, `dispatch.artifact.purged`, `dispatch.artifact.skipped`, `dispatch.artifact.bytes_reclaimed` | -`engine.Build` registers an `observability.MetricsExtension` built on the metric factory. Don't register another one, or every event counts twice. If you build one yourself for another engine, use `observability.NewMetricsExtension()` or `observability.NewMetricsExtensionWithFactory(factory)`. +Lifecycle hooks run inside these spans. `JobStarted` runs under `process job`, `JobCompleted` under `complete job`, `JobDLQ` under `dead-letter job`, and a workflow step's hooks under its step, so the Relay and Chronicle calls `relay_hook` and `audit_hook` make land in the right trace. -### Counters recorded +The remote Chronicle and Relay sink in `durable/delivery/ecosystem` wraps its transport with `otelhttp`, so a delivery to a remote host gets an HTTP client span and carries `traceparent`. -| Event | Counter | -|-------|---------| -| Job enqueued | `dispatch.job.enqueued` | -| Job completed | `dispatch.job.completed` | -| Job failed | `dispatch.job.failed` | -| Job retrying | `dispatch.job.retried` | -| Job moved to the DLQ | `dispatch.job.dlq` | -| Workflow started | `dispatch.workflow.started` | -| Workflow completed | `dispatch.workflow.completed` | -| Workflow failed | `dispatch.workflow.failed` | -| Cron fired | `dispatch.cron.fired` | +## Metrics -The counters carry no labels. How the dotted names appear in your backend depends on the exporter (Prometheus, for example, turns dots into underscores). +Names are as forge scrapes them. Every label takes only the values listed, so no series grows per job, tenant, URL or error message. The `queue` label is the queue's name when you configured it (the queues your workers poll, and the ones with limits or resource defaults) and `other` for anything else. -## Per-job tracing +### Jobs -Each job execution creates a span named `dispatch.job.execute` with these attributes: +| Metric | Type | Labels | +|--------|------|--------| +| `forge_dispatch_jobs_enqueued_total` | counter | `queue` | +| `forge_dispatch_job_attempt_duration_seconds` | histogram | `queue`; `outcome`: `completed`, `retry`, `dead_lettered`, `requeued`, `lease_lost`, `cancelled`, `store_error` | +| `forge_dispatch_jobs_dead_lettered_total` | counter | `queue`; `reason`: `retries_exhausted`, `permanent`, `launch_failures` | +| `forge_dispatch_job_queue_wait_seconds` | histogram | `queue` (time from a job becoming due to a worker starting it) | +| `forge_dispatch_job_polls_total` | counter | `result`: `work`, `empty`, `error` | +| `forge_dispatch_jobs_requeued_total` | counter | `queue`; `reason`: `rate_limited`, `no_capacity`, `shutdown` | +| `forge_dispatch_job_lease_renewals_total` | counter | `result`: `ok`, `lost`, `error` | +| `forge_dispatch_jobs_reclaimed_total` | counter | none | +| `forge_dispatch_jobs_active` | gauge | none (attempts running on this worker) | -- `dispatch.job.id` -- `dispatch.job.name` -- `dispatch.queue` -- `dispatch.retry_count` -- `dispatch.scope.app_id` -- `dispatch.scope.org_id` +An attempt's duration runs from the start of the attempt to its terminal write. -When the handler returns an error, the span records it and gets an error status. +### Cron and checkpoint workflows -## Per-job metrics +| Metric | Type | Labels | +|--------|------|--------| +| `forge_dispatch_cron_fires_total` | counter | `result`: `fired`, `locked`, `skipped`, `error` | +| `forge_dispatch_cron_fire_lag_seconds` | histogram | none (due time to enqueue) | +| `forge_dispatch_cron_leader` | gauge | none (1 while this scheduler leads) | +| `forge_dispatch_workflow_run_duration_seconds` | histogram | `result`: `completed`, `failed` | +| `forge_dispatch_workflow_step_duration_seconds` | histogram | `kind`: `step`, `parallel`, `fan_out`, `child`, `spawn`, `wait_event`, `wait_all`, `wait_any`, `wait_match`, `sleep`, `compensate`; `result`: `ok`, `error` | -The metrics middleware records a histogram `dispatch.job.duration` (seconds) and a counter `dispatch.job.executions`. Neither has labels. +### Durable runtime, outbox and artifacts + +| Metric | Type | Labels | +|--------|------|--------| +| `forge_dispatch_durable_task_duration_seconds` | histogram | `kind`: `workflow`, `activity`, `timer`, `timeout`, `child_delivery`, `execution_timeout`; `result`: `ok`, `contention`, `lease_lost`, `no_handler`, `cancelled`, `error` | +| `forge_dispatch_durable_polls_total` | counter | `kind` as above; `result`: `work`, `empty`, `error` | +| `forge_dispatch_durable_replay_duration_seconds` | histogram | none | +| `forge_dispatch_outbox_delivery_duration_seconds` | histogram | `destination`: `chronicle`, `relay`; `result`: `acknowledged`, `rejected`, `timeout`, `conflict`, `unavailable`, `invalid_receipt` | +| `forge_dispatch_outbox_delivery_lag_seconds` | histogram | `destination` (acceptance to acknowledgement) | +| `forge_dispatch_artifacts_swept_total` | counter | `reason`: `retention`, `orphan` | +| `forge_dispatch_artifacts_purged_total` | counter | `result`: `ok`, `skipped` | +| `forge_dispatch_artifact_bytes_reclaimed_total` | counter | none | + +A few queries to start from: + +```text +# Attempts failing, by queue +sum by (queue) (rate(forge_dispatch_job_attempt_duration_seconds_count{outcome=~"retry|dead_lettered"}[5m])) + +# p95 time a due job waits for a worker +histogram_quantile(0.95, sum by (le, queue) (rate(forge_dispatch_job_queue_wait_seconds_bucket[5m]))) + +# Outbox deliveries that are not getting through +sum by (destination, result) (rate(forge_dispatch_outbox_delivery_duration_seconds_count{result!="acknowledged"}[5m])) +``` + +### Legacy counters + +`engine.Build` still registers `observability.MetricsExtension` and the metrics middleware, so these keep their names and carry no labels. Don't register another `MetricsExtension`, or every event counts twice. + +| Event | Metric | +|-------|--------| +| Job enqueued | `forge_dispatch_job_enqueued` | +| Job completed | `forge_dispatch_job_completed` | +| Job failed (including a lost lease) | `forge_dispatch_job_failed` | +| Job retrying | `forge_dispatch_job_retried` | +| Job moved to the DLQ | `forge_dispatch_job_dlq` | +| Workflow started, completed, failed | `forge_dispatch_workflow_started`, `_completed`, `_failed` | +| Cron fired | `forge_dispatch_cron_fired` | +| Handler duration and executions (middleware) | `forge_dispatch_job_duration` histogram, `forge_dispatch_job_executions` counter | + +Outside Forge the names are `dispatch.job.enqueued` and so on, and how the dots appear depends on your exporter. The labelled metrics above say more, so prefer them for new dashboards. ## Building the middleware yourself `middleware.Tracing()`, `middleware.TracingWithTracer(tracer)`, `middleware.Metrics()` and `middleware.MetricsWithFactory(factory)` are exported if you compose a chain outside the engine. Inside an engine they're already in the default stack, so adding them with `engine.WithMiddleware` records everything twice. + +If you assemble a `worker.Pool` and `worker.Runner` without the engine, build a `telemetry.Telemetry` with `telemetry.New(telemetry.WithMetrics(f), telemetry.WithQueues("default"))` and pass it with `worker.WithTelemetry` and `Runner.WithTelemetry`. diff --git a/docs/content/docs/subsystems/rate-limiting.mdx b/docs/content/docs/subsystems/rate-limiting.mdx index 577620b..bd63867 100644 --- a/docs/content/docs/subsystems/rate-limiting.mdx +++ b/docs/content/docs/subsystems/rate-limiting.mdx @@ -12,7 +12,7 @@ Middleware wraps each job execution with cross-cutting logic. Each one is a `fun | Logging | `middleware.Logging(logger)` | Logs job start and completion | | Recover | `middleware.Recover(logger)` | Turns panics into errors and logs the stack | | Timeout | `middleware.Timeout(logger)` | Cancels the job context after `job.Timeout` | -| Tracing | `middleware.Tracing()`, `middleware.TracingWithTracer(t)` | Wraps execution in an OpenTelemetry span | +| Tracing | `middleware.Tracing()`, `middleware.TracingWithTracer(t)` | Wraps the rest of the chain in a `run job handler` span | | Metrics | `middleware.Metrics()`, `middleware.MetricsWithFactory(f)` | Records per-job duration and outcome | | Scope | `middleware.Scope()` | Restores the job's Forge app and org IDs into the context | @@ -24,7 +24,7 @@ Middleware wraps each job execution with cross-cutting logic. Each one is a `fun Recover -> Tracing -> Metrics -> Logging -> Scope -> Timeout -> handler ``` -The tracing and metrics middleware use the tracer provider and metric factory you pass with `engine.WithTracerProvider` and `engine.WithMetricFactory`. You don't need to register any of them yourself, and adding them again runs them twice. +The tracing and metrics middleware use the tracer provider and metric factory you pass with `engine.WithTracerProvider` and `engine.WithMetricFactory`. You don't need to register any of them yourself, and adding them again runs them twice. The worker pool wraps the whole attempt, terminal write included, in a `process job` span, and the tracing middleware's span sits under it. See [Observability](/docs/subsystems/observability). ## Adding your own diff --git a/observability/doc.go b/observability/doc.go index 2c26876..8aafc1c 100644 --- a/observability/doc.go +++ b/observability/doc.go @@ -1,8 +1,9 @@ -// Package observability provides OpenTelemetry-based metrics and tracing -// extensions for Dispatch. The MetricsExtension implements lifecycle hooks -// to record system-wide counters for job enqueue, completion, failure, +// Package observability provides the legacy lifecycle counters for +// Dispatch. The MetricsExtension implements lifecycle hooks to record +// unlabelled, system-wide counters for job enqueue, completion, failure, // retry, DLQ, workflow, and cron events. // -// For per-execution tracing and metrics, see the middleware package: -// middleware.Tracing() and middleware.Metrics(). +// The spans and labelled metrics for job attempts, cron, workflows, the +// durable runtime, the outbox and the artifact sweeper live in the +// telemetry package, and engine.Build wires both. package observability From 11db9f679bc52ed92f4ee1186504db0717dad983 Mon Sep 17 00:00:00 2001 From: Rex Raphael Date: Sat, 17 Oct 2026 23:33:48 -0500 Subject: [PATCH 11/18] fix(delivery): drop baggage before a remote sink call The remote sink's traced transport would inject whatever baggage the calling context carried. The publisher's own context never has any, but Remote is exported and a host can call it from a request, where forge has already extracted the client's baggage. call now strips it, keeps traceparent, and a test checks the remote host sees one and not the other. --- .../content/docs/subsystems/observability.mdx | 2 +- durable/delivery/ecosystem/http.go | 7 +- durable/delivery/ecosystem/telemetry_test.go | 74 +++++++++++++++++++ 3 files changed, 79 insertions(+), 4 deletions(-) create mode 100644 durable/delivery/ecosystem/telemetry_test.go diff --git a/docs/content/docs/subsystems/observability.mdx b/docs/content/docs/subsystems/observability.mdx index 27f276b..49d8fed 100644 --- a/docs/content/docs/subsystems/observability.mdx +++ b/docs/content/docs/subsystems/observability.mdx @@ -62,7 +62,7 @@ All spans use the instrumentation scope `github.com/xraph/dispatch`. Lifecycle hooks run inside these spans. `JobStarted` runs under `process job`, `JobCompleted` under `complete job`, `JobDLQ` under `dead-letter job`, and a workflow step's hooks under its step, so the Relay and Chronicle calls `relay_hook` and `audit_hook` make land in the right trace. -The remote Chronicle and Relay sink in `durable/delivery/ecosystem` wraps its transport with `otelhttp`, so a delivery to a remote host gets an HTTP client span and carries `traceparent`. +The remote Chronicle and Relay sink in `durable/delivery/ecosystem` wraps its transport with `otelhttp`, so a delivery to a remote host gets an HTTP client span and carries `traceparent`. It drops baggage first, so nothing a caller put there reaches the remote host. ## Metrics diff --git a/durable/delivery/ecosystem/http.go b/durable/delivery/ecosystem/http.go index 80d3003..bb3109d 100644 --- a/durable/delivery/ecosystem/http.go +++ b/durable/delivery/ecosystem/http.go @@ -15,6 +15,7 @@ import ( ca "github.com/xraph/chronicle/acceptance" ra "github.com/xraph/relay/acceptance" "go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp" + "go.opentelemetry.io/otel/baggage" ) const MaxResponseBytes = 256 << 10 @@ -51,8 +52,8 @@ func NewRemote(endpoint, bearer string, timeout time.Duration, localLoopbackHTTP } transport := &http.Transport{Proxy: nil, DialContext: (&net.Dialer{Timeout: timeout}).DialContext, TLSClientConfig: &tls.Config{MinVersion: tls.VersionTLS12}, TLSHandshakeTimeout: timeout, ResponseHeaderTimeout: timeout, MaxIdleConnsPerHost: 4, IdleConnTimeout: time.Minute} // The traced transport adds a client span and traceparent around the - // same policy. Calls run on the publisher's background context, which - // never carries inbound baggage to forward. + // same policy. call drops baggage, so nothing a caller's caller put + // there reaches the remote host. client := &http.Client{Timeout: timeout, Transport: otelhttp.NewTransport(transport), CheckRedirect: func(_ *http.Request, _ []*http.Request) error { return http.ErrUseLastResponse }} return &Remote{endpoint: endpoint, bearer: bearer, client: client}, nil } @@ -62,7 +63,7 @@ func (r *Remote) call(ctx context.Context, request any, expected ConflictRespons if err != nil { return false, ErrTransport } - req, err := http.NewRequestWithContext(ctx, http.MethodPost, r.endpoint, bytes.NewReader(raw)) + req, err := http.NewRequestWithContext(baggage.ContextWithoutBaggage(ctx), http.MethodPost, r.endpoint, bytes.NewReader(raw)) if err != nil { return false, ErrTransport } diff --git a/durable/delivery/ecosystem/telemetry_test.go b/durable/delivery/ecosystem/telemetry_test.go new file mode 100644 index 0000000..d21d3d2 --- /dev/null +++ b/durable/delivery/ecosystem/telemetry_test.go @@ -0,0 +1,74 @@ +package ecosystem_test + +import ( + "context" + "net/http" + "net/http/httptest" + "sync" + "testing" + "time" + + "go.opentelemetry.io/otel" + "go.opentelemetry.io/otel/baggage" + "go.opentelemetry.io/otel/propagation" + + "github.com/xraph/dispatch/durable" + "github.com/xraph/dispatch/durable/delivery/ecosystem" + "github.com/xraph/dispatch/internal/oteltest" +) + +func TestRemoteCarriesTraceparentButNoBaggage(t *testing.T) { + sr := oteltest.Record(t) + prev := otel.GetTextMapPropagator() + otel.SetTextMapPropagator(propagation.NewCompositeTextMapPropagator(propagation.TraceContext{}, propagation.Baggage{})) + t.Cleanup(func() { otel.SetTextMapPropagator(prev) }) + + var mu sync.Mutex + var headers http.Header + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + mu.Lock() + headers = r.Header.Clone() + mu.Unlock() + w.WriteHeader(http.StatusServiceUnavailable) + })) + defer server.Close() + remote, err := ecosystem.NewRemote(server.URL, "private-bearer", time.Second, true) + if err != nil { + t.Fatal(err) + } + defer remote.Close() + + member, err := baggage.NewMember("user.email", "alice") + if err != nil { + t.Fatal(err) + } + bag, err := baggage.New(member) + if err != nil { + t.Fatal(err) + } + ctx, span := otel.Tracer("test").Start(baggage.ContextWithBaggage(context.Background(), bag), "deliver outbox event") + b, d := envelope(t, durable.DestinationRelay) + req, _ := ecosystem.RelayRequest(b, d) + if _, err = remote.SendReliable(ctx, req); err == nil { + t.Fatal("a 503 should fail the call") + } + span.End() + + mu.Lock() + defer mu.Unlock() + if headers.Get("Baggage") != "" { + t.Errorf("baggage reached the remote host: %q", headers.Get("Baggage")) + } + if headers.Get("Traceparent") == "" { + t.Error("the call carried no traceparent") + } + clients := 0 + for _, s := range sr.Ended() { + if s.Parent().SpanID() == span.SpanContext().SpanID() { + clients++ + } + } + if clients != 1 { + t.Errorf("client spans under the delivery = %d, want 1", clients) + } +} From 892f90b376800df880bbe59ab765267da07af5b8 Mon Sep 17 00:00:00 2001 From: Rex Raphael Date: Sat, 17 Oct 2026 23:59:44 -0500 Subject: [PATCH 12/18] fix(delivery): stop recording a cancelled delivery as acknowledged publish started its result at acknowledged and only overwrote it after the sink call, but returns early when Stop cancels the publisher's context. A delivery interrupted by shutdown was recorded with dispatch.outbox.result=acknowledged, an unset status and an acknowledged duration observation. The result now starts at cancelled, a documented value on the delivery duration histogram, and becomes acknowledged only once the store has taken the acknowledgement. A cancelled attempt is not an error: the delivery stays claimable and the next publisher picks it up. A test stops the publisher while a sink call is in flight. --- .../content/docs/subsystems/observability.mdx | 2 +- durable/delivery/publisher.go | 8 ++- durable/delivery/telemetry_test.go | 50 +++++++++++++++++++ telemetry/metrics.go | 9 ++-- 4 files changed, 63 insertions(+), 6 deletions(-) diff --git a/docs/content/docs/subsystems/observability.mdx b/docs/content/docs/subsystems/observability.mdx index 49d8fed..45a3301 100644 --- a/docs/content/docs/subsystems/observability.mdx +++ b/docs/content/docs/subsystems/observability.mdx @@ -101,7 +101,7 @@ An attempt's duration runs from the start of the attempt to its terminal write. | `forge_dispatch_durable_task_duration_seconds` | histogram | `kind`: `workflow`, `activity`, `timer`, `timeout`, `child_delivery`, `execution_timeout`; `result`: `ok`, `contention`, `lease_lost`, `no_handler`, `cancelled`, `error` | | `forge_dispatch_durable_polls_total` | counter | `kind` as above; `result`: `work`, `empty`, `error` | | `forge_dispatch_durable_replay_duration_seconds` | histogram | none | -| `forge_dispatch_outbox_delivery_duration_seconds` | histogram | `destination`: `chronicle`, `relay`; `result`: `acknowledged`, `rejected`, `timeout`, `conflict`, `unavailable`, `invalid_receipt` | +| `forge_dispatch_outbox_delivery_duration_seconds` | histogram | `destination`: `chronicle`, `relay`; `result`: `acknowledged`, `cancelled` (Stop interrupted it; the delivery is claimed again later), `rejected`, `timeout`, `conflict`, `unavailable`, `invalid_receipt` | | `forge_dispatch_outbox_delivery_lag_seconds` | histogram | `destination` (acceptance to acknowledgement) | | `forge_dispatch_artifacts_swept_total` | counter | `reason`: `retention`, `orphan` | | `forge_dispatch_artifacts_purged_total` | counter | `result`: `ok`, `skipped` | diff --git a/durable/delivery/publisher.go b/durable/delivery/publisher.go index fca238b..504f5d7 100644 --- a/durable/delivery/publisher.go +++ b/durable/delivery/publisher.go @@ -263,10 +263,13 @@ func (p *Publisher) publish(ctx context.Context, d durable.Destination, sink Sin ), ) started := time.Now() - result := telemetry.OutboxAcknowledged + // Every path that returns early does so because Stop cancelled ctx, so + // that is the starting result. The success path and the failure + // categories overwrite it. + result := telemetry.OutboxCancelled defer func() { span.SetAttributes(attribute.String("dispatch.outbox.result", result)) - if result != telemetry.OutboxAcknowledged { + if result != telemetry.OutboxAcknowledged && result != telemetry.OutboxCancelled { telemetry.Fail(span, "delivery "+result, "") } p.tel.Outbox().Delivery(string(d), result, time.Since(started)) @@ -307,6 +310,7 @@ func (p *Publisher) publish(ctx context.Context, d durable.Destination, sink Sin ackErr := p.store.AcknowledgeDelivery(ackCtx, record.Token(), receipt) ackCancel() if ackErr == nil { + result = telemetry.OutboxAcknowledged if !record.AcceptedAt.IsZero() { p.tel.Outbox().Lag(string(d), time.Since(record.AcceptedAt)) } diff --git a/durable/delivery/telemetry_test.go b/durable/delivery/telemetry_test.go index 2fd2a66..6c6c7a4 100644 --- a/durable/delivery/telemetry_test.go +++ b/durable/delivery/telemetry_test.go @@ -116,3 +116,53 @@ func (s *pollSignalStore) ClaimDeliveries(ctx context.Context, claim durable.Del } return s.OutboxStore.ClaimDeliveries(ctx, claim) } + +func TestStopDuringADeliveryIsRecordedAsCancelled(t *testing.T) { + sr := oteltest.Record(t) + s := fixture(t, 1) + f := metricstest.New() + entered := make(chan struct{}) + var once atomic.Bool + sink := sinkFunc(func(ctx context.Context, d durable.Delivery) (durable.SinkReceipt, error) { + if once.CompareAndSwap(false, true) { + close(entered) + } + <-ctx.Done() + return durable.SinkReceipt{}, ctx.Err() + }) + cfg := config("one") + cfg.Concurrency, cfg.CallTimeout, cfg.LeaseDuration = 1, 2*time.Second, 5*time.Second + p, err := delivery.New(s, cfg, map[durable.Destination]delivery.Sink{durable.DestinationChronicle: sink}, + delivery.WithTelemetry(telemetry.New(telemetry.WithMetrics(f)))) + if err != nil { + t.Fatal(err) + } + if err = p.Start(); err != nil { + t.Fatal(err) + } + select { + case <-entered: + case <-time.After(5 * time.Second): + t.Fatal("the sink was never called") + } + // A deadline shorter than the sink call: Stop cancels the attempt. + stopCtx, cancel := context.WithTimeout(context.Background(), 20*time.Millisecond) + defer cancel() + if err = p.Stop(stopCtx); !errors.Is(err, delivery.ErrIncompleteShutdown) { + t.Fatalf("Stop = %v, want an incomplete shutdown", err) + } + + span := sr.WaitFor(t, "deliver outbox event", 1, 5*time.Second)[0] + if got, _ := oteltest.Attr(span, "dispatch.outbox.result"); got != telemetry.OutboxCancelled { + t.Errorf("result = %q, want cancelled", got) + } + if span.Status().Code != codes.Unset { + t.Errorf("status = %+v, want unset", span.Status()) + } + if n, ok := f.HistogramCount(telemetry.MetricOutboxDeliveryDuration, "destination", "chronicle", "result", telemetry.OutboxCancelled); !ok || n != 1 { + t.Errorf("cancelled deliveries = %d, %v", n, ok) + } + if _, ok := f.HistogramCount(telemetry.MetricOutboxDeliveryDuration, "destination", "chronicle", "result", telemetry.OutboxAcknowledged); ok { + t.Error("a cancelled delivery was recorded as acknowledged") + } +} diff --git a/telemetry/metrics.go b/telemetry/metrics.go index 04b9edc..d56dccc 100644 --- a/telemetry/metrics.go +++ b/telemetry/metrics.go @@ -110,10 +110,13 @@ const ( ) // Outbox delivery results, the result label on -// dispatch_outbox_delivery_duration_seconds. All but acknowledged are the -// failure categories the publisher already persists on a retry. +// dispatch_outbox_delivery_duration_seconds. Rejected through +// invalid_receipt are the failure categories the publisher already persists +// on a retry; cancelled means Stop interrupted the attempt, which leaves the +// delivery to be claimed again. const ( OutboxAcknowledged = "acknowledged" + OutboxCancelled = "cancelled" OutboxRejected = "rejected" OutboxTimeout = "timeout" OutboxConflict = "conflict" @@ -140,7 +143,7 @@ var ( taskKinds = []string{"workflow", "activity", "timer", "timeout", "child_delivery", "execution_timeout"} taskResults = []string{DurableOK, DurableContention, DurableLeaseLost, DurableNoHandler, DurableCancelled, DurableError} destinations = []string{"chronicle", "relay"} - outboxResult = []string{OutboxAcknowledged, OutboxRejected, OutboxTimeout, OutboxConflict, OutboxUnavailable, OutboxInvalidReceipt} + outboxResult = []string{OutboxAcknowledged, OutboxCancelled, OutboxRejected, OutboxTimeout, OutboxConflict, OutboxUnavailable, OutboxInvalidReceipt} sweepReasons = []string{"retention", "orphan"} purgeResults = []string{PurgeOK, PurgeSkipped} From 00e0bb1c847e696ed147272e56d90bedcbfa3fae Mon Sep 17 00:00:00 2001 From: Rex Raphael Date: Sun, 18 Oct 2026 00:00:07 -0500 Subject: [PATCH 13/18] fix(delivery): close the remote sink's idle connections again Wrapping the transport with otelhttp broke Remote.Close. http.Client.CloseIdleConnections only reaches a transport that has that method, and otelhttp's Transport has RoundTrip alone, so Close stopped dropping idle connections. Remote now keeps the *http.Transport it built and closes its idle connections directly. A test watches the server side of a pooled connection hang up when you call Close. --- durable/delivery/ecosystem/http.go | 15 ++++++--- durable/delivery/ecosystem/telemetry_test.go | 35 ++++++++++++++++++++ 2 files changed, 45 insertions(+), 5 deletions(-) diff --git a/durable/delivery/ecosystem/http.go b/durable/delivery/ecosystem/http.go index bb3109d..3c80406 100644 --- a/durable/delivery/ecosystem/http.go +++ b/durable/delivery/ecosystem/http.go @@ -34,9 +34,10 @@ type ConflictResponse struct { // Remote owns a fixed destination and never accepts URLs from delivery content. // Credentials are private and error messages contain no request or response data. type Remote struct { - endpoint string - bearer string - client *http.Client + endpoint string + bearer string + client *http.Client + transport *http.Transport } func NewRemote(endpoint, bearer string, timeout time.Duration, localLoopbackHTTP bool) (*Remote, error) { @@ -55,9 +56,13 @@ func NewRemote(endpoint, bearer string, timeout time.Duration, localLoopbackHTTP // same policy. call drops baggage, so nothing a caller's caller put // there reaches the remote host. client := &http.Client{Timeout: timeout, Transport: otelhttp.NewTransport(transport), CheckRedirect: func(_ *http.Request, _ []*http.Request) error { return http.ErrUseLastResponse }} - return &Remote{endpoint: endpoint, bearer: bearer, client: client}, nil + return &Remote{endpoint: endpoint, bearer: bearer, client: client, transport: transport}, nil } -func (r *Remote) Close() { r.client.CloseIdleConnections() } + +// Close drops idle connections. It goes to the *http.Transport directly: +// the traced wrapper around it has no CloseIdleConnections, so +// http.Client.CloseIdleConnections would not reach it. +func (r *Remote) Close() { r.transport.CloseIdleConnections() } func (r *Remote) call(ctx context.Context, request any, expected ConflictResponse, out any) (bool, error) { raw, err := json.Marshal(request) if err != nil { diff --git a/durable/delivery/ecosystem/telemetry_test.go b/durable/delivery/ecosystem/telemetry_test.go index d21d3d2..652e75d 100644 --- a/durable/delivery/ecosystem/telemetry_test.go +++ b/durable/delivery/ecosystem/telemetry_test.go @@ -2,6 +2,7 @@ package ecosystem_test import ( "context" + "net" "net/http" "net/http/httptest" "sync" @@ -72,3 +73,37 @@ func TestRemoteCarriesTraceparentButNoBaggage(t *testing.T) { t.Errorf("client spans under the delivery = %d, want 1", clients) } } + +func TestRemoteCloseDropsIdleConnections(t *testing.T) { + closed := make(chan struct{}, 1) + server := httptest.NewUnstartedServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(http.StatusServiceUnavailable) + })) + server.Config.ConnState = func(_ net.Conn, state http.ConnState) { + if state == http.StateClosed { + select { + case closed <- struct{}{}: + default: + } + } + } + server.Start() + defer server.Close() + remote, err := ecosystem.NewRemote(server.URL, "private-bearer", time.Second, true) + if err != nil { + t.Fatal(err) + } + b, d := envelope(t, durable.DestinationRelay) + req, _ := ecosystem.RelayRequest(b, d) + if _, err = remote.SendReliable(t.Context(), req); err == nil { + t.Fatal("a 503 should fail the call") + } + + // The connection is idle in the pool now; Close must hang it up. + remote.Close() + select { + case <-closed: + case <-time.After(5 * time.Second): + t.Fatal("Close left the idle connection open") + } +} From f10d53930773be8557be31eb0412bb7364cc8e5f Mon Sep 17 00:00:00 2001 From: Rex Raphael Date: Sun, 18 Oct 2026 00:00:39 -0500 Subject: [PATCH 14/18] fix(worker): mark the handler span failed when a handler panics Recover is the outermost middleware, so a panicking handler unwinds through the tracing middleware, and its "run job handler" span ended with an unset status, as if the handler had succeeded. The middleware now notices that next never returned and marks the span with the status class "panic" and exception.type "panic" before it ends. It does not recover, so the panic reaches Recover exactly as before. The pool's "process job" span does the same for a pool assembled without Recover, where the panic unwinds through runJob. --- .../content/docs/subsystems/observability.mdx | 2 +- middleware/tracing.go | 16 +++++++-- middleware/tracing_test.go | 36 +++++++++++++++++++ worker/pool.go | 12 ++++++- 4 files changed, 62 insertions(+), 4 deletions(-) diff --git a/docs/content/docs/subsystems/observability.mdx b/docs/content/docs/subsystems/observability.mdx index 45a3301..bcdca17 100644 --- a/docs/content/docs/subsystems/observability.mdx +++ b/docs/content/docs/subsystems/observability.mdx @@ -32,7 +32,7 @@ Background work is traced one unit at a time. A job attempt, a cron fire, a dura A job crosses the store between enqueue and execution, so its attempt is its own trace. When the process that enqueued the job also runs it, the `process job` span links to the `enqueue job` span. Nothing about the trace is stored with the job, so a job enqueued by an older writer, or claimed by another worker, starts without a link. A workflow run that outlives its caller (a resumed run, a replay, a spawned child) is its own trace with a link back, the same way. -Spans never carry payloads, error messages, user IDs or anything that names a person. A failed span gets an `Error` status with a short class such as `handler error, retrying`, and an `exception` event whose only attribute is `exception.type`: a sentinel's name (`dispatch.ErrPermanent`, `context.DeadlineExceeded`) or the error's Go type. Durable workflow and run IDs are chosen by whoever starts the workflow, so they stay off spans too. +Spans never carry payloads, error messages, user IDs or anything that names a person. A failed span gets an `Error` status with a short class such as `handler error, retrying`, and an `exception` event whose only attribute is `exception.type`: a sentinel's name (`dispatch.ErrPermanent`, `context.DeadlineExceeded`) or the error's Go type. A handler that panics marks `run job handler` (and `process job`, if no Recover middleware catches it) with the class `panic` and `exception.type` `panic`. Durable workflow and run IDs are chosen by whoever starts the workflow, so they stay off spans too. ## Spans diff --git a/middleware/tracing.go b/middleware/tracing.go index f73dec6..818b9d1 100644 --- a/middleware/tracing.go +++ b/middleware/tracing.go @@ -25,7 +25,9 @@ const tracerName = "github.com/xraph/dispatch" // dispatch.scope.app_id, dispatch.scope.org_id. When the handler fails the // span gets an Error status with a fixed description and an exception event // carrying only exception.type. The error's message is never recorded: a -// handler error can quote its payload. +// handler error can quote its payload. A handler that panics gets the status +// class "panic" and exception.type "panic", and the panic continues to the +// Recover middleware. func Tracing() Middleware { tracer := otel.Tracer(tracerName) return TracingWithTracer(tracer) @@ -47,9 +49,19 @@ func TracingWithTracer(tracer trace.Tracer) Middleware { ), trace.WithSpanKind(trace.SpanKindInternal), ) - defer span.End() + // Recover sits outside this middleware, so a panicking handler + // unwinds through here. Mark the span before it ends; the panic + // carries on to Recover untouched. + returned := false + defer func() { + if !returned { + telemetry.Fail(span, "panic", "panic") + } + span.End() + }() err := next(ctx) + returned = true if err != nil { telemetry.Fail(span, "handler error", telemetry.ErrorType(err)) } diff --git a/middleware/tracing_test.go b/middleware/tracing_test.go index 00eecc2..0775f04 100644 --- a/middleware/tracing_test.go +++ b/middleware/tracing_test.go @@ -234,3 +234,39 @@ func assertNoValue(t *testing.T, s sdktrace.ReadOnlySpan, needle string) { } } } + +func TestTracing_PanicMarksSpanAndKeepsPanicking(t *testing.T) { + sr, tracer := setupTestTracer() + m := mw.TracingWithTracer(tracer) + + func() { + defer func() { + if r := recover(); r != "card alice@example.com declined" { + t.Errorf("recovered %v, want the original panic", r) + } + }() + _ = m(context.Background(), newTestJob(), func(context.Context) error { + panic("card alice@example.com declined") + }) + }() + + spans := sr.Ended() + if len(spans) != 1 { + t.Fatalf("expected 1 span, got %d", len(spans)) + } + if spans[0].Status().Code != codes.Error || spans[0].Status().Description != "panic" { + t.Errorf("status = %+v, want an error with class panic", spans[0].Status()) + } + var excType string + for _, ev := range spans[0].Events() { + for _, a := range ev.Attributes { + if a.Key == "exception.type" { + excType = a.Value.AsString() + } + } + } + if excType != "panic" { + t.Errorf("exception.type = %q", excType) + } + assertNoValue(t, spans[0], "alice@example.com") +} diff --git a/worker/pool.go b/worker/pool.go index ca43394..36d0be0 100644 --- a/worker/pool.go +++ b/worker/pool.go @@ -848,7 +848,16 @@ func (p *Pool) runJob(a admitted) { rec := &attempt{} spanCtx = withAttempt(spanCtx, rec) - defer func() { endAttemptSpan(span, rec) }() + returned := false + defer func() { + // Without a Recover middleware a handler's panic unwinds through + // here; the span says so before it ends. + if !returned { + telemetry.Fail(span, "panic", "panic") + return + } + endAttemptSpan(span, rec) + }() p.extensions.EmitJobStarted(spanCtx, j) @@ -873,6 +882,7 @@ func (p *Pool) runJob(a admitted) { } execErr := p.executor.Execute(ctx, j) + returned = true if execErr != nil { p.logger.Debug("job execution failed", log.String("job_id", j.ID.String()), From 76b8d0003a8bed0e067d85f23c1bd28168089a95 Mon Sep 17 00:00:00 2001 From: Rex Raphael Date: Sun, 18 Oct 2026 00:01:21 -0500 Subject: [PATCH 15/18] fix(worker): report a shutdown mid-attempt as cancelled, not store_error Pool.Stop cancels every in-flight attempt, so a terminal write racing a deploy fails with context.Canceled and was recorded as outcome store_error with an error status. An alert on store_error would fire on every rollout. When the attempt's own context is done, the failed write is now reported as the documented cancelled outcome with no error status. store_error is left for the store actually refusing the write. A test finishes a handler after its attempt is cancelled against a store that honours the context. --- .../content/docs/subsystems/observability.mdx | 2 +- telemetry/metrics.go | 3 +- worker/runner.go | 10 +++- worker/telemetry_test.go | 51 +++++++++++++++++++ 4 files changed, 63 insertions(+), 3 deletions(-) diff --git a/docs/content/docs/subsystems/observability.mdx b/docs/content/docs/subsystems/observability.mdx index bcdca17..c3f6403 100644 --- a/docs/content/docs/subsystems/observability.mdx +++ b/docs/content/docs/subsystems/observability.mdx @@ -82,7 +82,7 @@ Names are as forge scrapes them. Every label takes only the values listed, so no | `forge_dispatch_jobs_reclaimed_total` | counter | none | | `forge_dispatch_jobs_active` | gauge | none (attempts running on this worker) | -An attempt's duration runs from the start of the attempt to its terminal write. +An attempt's duration runs from the start of the attempt to its terminal write. `cancelled` covers an operator cancelling a running job and a worker shutting down mid-attempt (Pool.Stop cancels the attempt, so its terminal write fails with its context); neither is an error. `store_error` means the store itself refused the write. ### Cron and checkpoint workflows diff --git a/telemetry/metrics.go b/telemetry/metrics.go index d56dccc..213e6c4 100644 --- a/telemetry/metrics.go +++ b/telemetry/metrics.go @@ -42,7 +42,8 @@ const ( // Job attempt outcomes, the outcome label on // dispatch_job_attempt_duration_seconds and the dispatch.job.outcome span -// attribute. +// attribute. Cancelled covers an operator's cancel and a worker shutting +// down mid-attempt; store_error means the store refused the terminal write. const ( OutcomeCompleted = "completed" OutcomeRetry = "retry" diff --git a/worker/runner.go b/worker/runner.go index d714b8e..b508a4e 100644 --- a/worker/runner.go +++ b/worker/runner.go @@ -1153,8 +1153,16 @@ func (r *Runner) handleSuccess(ctx context.Context, j *job.Job, now time.Time, e } // storeFailed reports a terminal write that failed for a reason other than -// a lost lease. +// a lost lease. When the attempt's own context is done, the pool is +// stopping (Pool.Stop cancels every in-flight attempt) and the write failed +// because its context did, not because the store did: that is reported as +// cancelled, with no error status, so a deploy does not look like a store +// outage. func (r *Runner) storeFailed(ctx context.Context, span trace.Span, err error) { + if ctx.Err() != nil { + setOutcome(ctx, telemetry.OutcomeCancelled, nil) + return + } setOutcome(ctx, telemetry.OutcomeStoreError, err) telemetry.Fail(span, "store error", jobErrorType(err)) } diff --git a/worker/telemetry_test.go b/worker/telemetry_test.go index 09fbaca..2b16030 100644 --- a/worker/telemetry_test.go +++ b/worker/telemetry_test.go @@ -381,3 +381,54 @@ func TestRequeueCountsItsReason(t *testing.T) { t.Errorf("shutdown = %v, %v", v, ok) } } + +// ctxHonouringStore fails writes whose context is done, as the SQL and +// Mongo backends do. +type ctxHonouringStore struct{ *memory.Store } + +func (s ctxHonouringStore) UpdateJob(ctx context.Context, j *job.Job) error { + if err := ctx.Err(); err != nil { + return err + } + return s.Store.UpdateJob(ctx, j) +} + +func TestShutdownDuringTheTerminalWriteIsCancelledNotStoreError(t *testing.T) { + sr := oteltest.Record(t) + mem := memory.New() + s := ctxHonouringStore{Store: mem} + f := metricstest.New() + tel := telemetry.New(telemetry.WithMetrics(f), telemetry.WithQueues("default")) + logger := log.NewNoopLogger() + reg := job.NewRegistry() + // The handler finishes after its attempt's context is cancelled, as an + // in-flight job does when Pool.Stop cancels it. + ctx, cancel := context.WithCancel(context.Background()) + job.RegisterDefinition(reg, job.NewDefinition("slow", func(context.Context, struct{}) error { + cancel() + return nil + })) + runner := worker.NewExecutor(reg, ext.NewRegistry(logger), s, dlq.NewService(mem, mem), + backoff.NewConstant(time.Hour), logger).WithTelemetry(tel) + now := time.Now().UTC() + j := &job.Job{ID: id.NewJobID(), Name: "slow", Queue: "default", Payload: []byte(`{}`), + State: job.StateRunning, MaxRetries: 3, RunAt: now} + + attemptCtx, attempt := tel.Tracer().Start(ctx, "process job") + if err := runner.Execute(attemptCtx, j); err == nil { + t.Fatal("the terminal write should have failed") + } + attempt.End() + + if n, ok := f.HistogramCount(telemetry.MetricJobAttemptDuration, "queue", "default", "outcome", telemetry.OutcomeCancelled); !ok || n != 1 { + t.Errorf("cancelled attempts = %d, %v", n, ok) + } + if _, ok := f.HistogramCount(telemetry.MetricJobAttemptDuration, "queue", "default", "outcome", telemetry.OutcomeStoreError); ok { + t.Error("a shutdown was recorded as a store error") + } + for _, span := range oteltest.Named(sr.Ended(), "complete job") { + if span.Status().Code != codes.Unset { + t.Errorf("complete job status = %+v, want unset", span.Status()) + } + } +} From 568de160affd11d50d24ddafc0d586aa2e0503a5 Mon Sep 17 00:00:00 2001 From: Rex Raphael Date: Sun, 18 Oct 2026 00:02:12 -0500 Subject: [PATCH 16/18] fix(cron): take the fire lag when the job is enqueued The lag histogram was observed after fireEntry returned, so it counted the lock release, the bookkeeping writes and the CronFired hooks as well, while the docs promise due time to enqueue. fireEntry now takes the due time and records the lag as soon as the enqueue succeeds. A test checks the observation already exists when the fire hook runs. --- cron/scheduler.go | 12 +++-- cron/telemetry_test.go | 48 +++++++++++++++++++ .../content/docs/subsystems/observability.mdx | 2 +- 3 files changed, 56 insertions(+), 6 deletions(-) diff --git a/cron/scheduler.go b/cron/scheduler.go index 1a33463..2fbf929 100644 --- a/cron/scheduler.go +++ b/cron/scheduler.go @@ -469,14 +469,11 @@ func (s *Scheduler) fire(entry *Entry, due, now time.Time) { ) defer span.End() - result := s.fireEntry(ctx, entry.ID, now) + result := s.fireEntry(ctx, entry.ID, due, now) span.SetAttributes(attribute.String("dispatch.cron.result", result)) if result == telemetry.CronError { telemetry.Fail(span, "cron fire failed", "") } - if result == telemetry.CronFired { - s.tel.Cron().Lag(time.Since(due)) - } s.tel.Cron().Fire(result) } @@ -492,7 +489,11 @@ func (s *Scheduler) fire(entry *Entry, due, now time.Time) { // lands after the re-read still sees the fire it raced go out, but // nothing here can undo the disable: the post-fire writes are // UpdateCronLastRun and UpdateCronNextRun, and neither touches enabled. -func (s *Scheduler) fireEntry(ctx context.Context, cronID id.CronID, now time.Time) string { +// +// due is when the cached entry said it was due, for the lag metric, which +// is taken the moment the job is enqueued: the lock release, bookkeeping +// writes and hooks that follow are not lag. +func (s *Scheduler) fireEntry(ctx context.Context, cronID id.CronID, due, now time.Time) string { // Acquire per-entry lock under a bounded subcontext. acqCtx, acqCancel := s.callCtxFrom(ctx) acquired, err := s.cronStore.AcquireCronLock(acqCtx, cronID, s.workerID, s.lockTTL) @@ -540,6 +541,7 @@ func (s *Scheduler) fireEntry(ctx context.Context, cronID id.CronID, now time.Ti s.releaseCronLock(ctx, cronID) return telemetry.CronError } + s.tel.Cron().Lag(time.Since(due)) // Record the fire with targeted writes only. A whole-row write here // would put back whatever enabled was when the row was read. diff --git a/cron/telemetry_test.go b/cron/telemetry_test.go index 9c2083a..d7dfc86 100644 --- a/cron/telemetry_test.go +++ b/cron/telemetry_test.go @@ -156,3 +156,51 @@ func TestIdleCronTicksStartNoSpans(t *testing.T) { t.Errorf("idle scheduler started %d spans", len(spans)) } } + +// lagCheckingEmitter records how many lag observations existed when the +// fire hook ran. +type lagCheckingEmitter struct { + f *metricstest.Factory + seen chan uint64 +} + +func (e *lagCheckingEmitter) EmitCronFired(context.Context, string, id.JobID) { + n, _ := e.f.HistogramCount(telemetry.MetricCronFireLag) + select { + case e.seen <- n: + default: + } +} + +func TestCronLagIsTakenAtTheEnqueueNotAfterTheHooks(t *testing.T) { + mem := memory.New() + f := metricstest.New() + ctx := context.Background() + workerID := id.NewWorkerID() + if err := mem.RegisterWorker(ctx, &cluster.Worker{ID: workerID, Hostname: "test", State: cluster.WorkerActive, + LastSeen: time.Now().UTC(), CreatedAt: time.Now().UTC()}); err != nil { + t.Fatal(err) + } + if ok, err := mem.AcquireLeadership(ctx, workerID, 30*time.Second); err != nil || !ok { + t.Fatalf("AcquireLeadership: %v %v", ok, err) + } + emitter := &lagCheckingEmitter{f: f, seen: make(chan uint64, 1)} + sched := cron.NewScheduler(mem, mem, (&spanEnqueuer{}).Fn(), emitter, workerID, nil, + cron.WithTickInterval(10*time.Millisecond), + cron.WithTelemetry(telemetry.New(telemetry.WithMetrics(f))), + ) + t.Cleanup(func() { _ = sched.Stop(context.Background()) }) + registerDueEntry(t, mem, "hourly", "rollup") + + if err := sched.Start(ctx); err != nil { + t.Fatal(err) + } + select { + case n := <-emitter.seen: + if n != 1 { + t.Errorf("lag observations when the fire hook ran = %d, want 1", n) + } + case <-time.After(5 * time.Second): + t.Fatal("the entry never fired") + } +} diff --git a/docs/content/docs/subsystems/observability.mdx b/docs/content/docs/subsystems/observability.mdx index c3f6403..485b5e5 100644 --- a/docs/content/docs/subsystems/observability.mdx +++ b/docs/content/docs/subsystems/observability.mdx @@ -89,7 +89,7 @@ An attempt's duration runs from the start of the attempt to its terminal write. | Metric | Type | Labels | |--------|------|--------| | `forge_dispatch_cron_fires_total` | counter | `result`: `fired`, `locked`, `skipped`, `error` | -| `forge_dispatch_cron_fire_lag_seconds` | histogram | none (due time to enqueue) | +| `forge_dispatch_cron_fire_lag_seconds` | histogram | none (from the entry's due time until its job is enqueued) | | `forge_dispatch_cron_leader` | gauge | none (1 while this scheduler leads) | | `forge_dispatch_workflow_run_duration_seconds` | histogram | `result`: `completed`, `failed` | | `forge_dispatch_workflow_step_duration_seconds` | histogram | `kind`: `step`, `parallel`, `fan_out`, `child`, `spawn`, `wait_event`, `wait_all`, `wait_any`, `wait_match`, `sleep`, `compensate`; `result`: `ok`, `error` | From cb387749896ac883f759d01ef559ae347a3feac7 Mon Sep 17 00:00:00 2001 From: Rex Raphael Date: Sun, 18 Oct 2026 00:02:19 -0500 Subject: [PATCH 17/18] docs: say what the remote sink's client span can carry on failure otelhttp writes the transport's own error text into the client span status when a request to a remote Chronicle or Relay host fails. The page now says so, and why that text can only hold the sink's scheme, host and path. --- docs/content/docs/subsystems/observability.mdx | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/docs/content/docs/subsystems/observability.mdx b/docs/content/docs/subsystems/observability.mdx index 485b5e5..72f3870 100644 --- a/docs/content/docs/subsystems/observability.mdx +++ b/docs/content/docs/subsystems/observability.mdx @@ -62,7 +62,7 @@ All spans use the instrumentation scope `github.com/xraph/dispatch`. Lifecycle hooks run inside these spans. `JobStarted` runs under `process job`, `JobCompleted` under `complete job`, `JobDLQ` under `dead-letter job`, and a workflow step's hooks under its step, so the Relay and Chronicle calls `relay_hook` and `audit_hook` make land in the right trace. -The remote Chronicle and Relay sink in `durable/delivery/ecosystem` wraps its transport with `otelhttp`, so a delivery to a remote host gets an HTTP client span and carries `traceparent`. It drops baggage first, so nothing a caller put there reaches the remote host. +The remote Chronicle and Relay sink in `durable/delivery/ecosystem` wraps its transport with `otelhttp`, so a delivery to a remote host gets an HTTP client span and carries `traceparent`. It drops baggage first, so nothing a caller put there reaches the remote host. When the request itself fails, otelhttp puts the transport's error text in that client span's status. `NewRemote` refuses an endpoint with userinfo, a query or a fragment, so the most that text can hold is your sink's scheme, host and path. ## Metrics From 5105bef00b688d1cf08c82e11e5c41fca3c9556e Mon Sep 17 00:00:00 2001 From: Rex Raphael Date: Sun, 18 Oct 2026 00:03:37 -0500 Subject: [PATCH 18/18] test(delivery): name the unused sink parameter in the cancel test revive flags the envelope parameter the cancelled-delivery test's sink never reads. It is now blank. --- durable/delivery/telemetry_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/durable/delivery/telemetry_test.go b/durable/delivery/telemetry_test.go index 6c6c7a4..831c7d2 100644 --- a/durable/delivery/telemetry_test.go +++ b/durable/delivery/telemetry_test.go @@ -123,7 +123,7 @@ func TestStopDuringADeliveryIsRecordedAsCancelled(t *testing.T) { f := metricstest.New() entered := make(chan struct{}) var once atomic.Bool - sink := sinkFunc(func(ctx context.Context, d durable.Delivery) (durable.SinkReceipt, error) { + sink := sinkFunc(func(ctx context.Context, _ durable.Delivery) (durable.SinkReceipt, error) { if once.CompareAndSwap(false, true) { close(entered) }