From a9acb3ff93bb1319aa1a822f1c1f3b54c8c27b77 Mon Sep 17 00:00:00 2001 From: Jonny Rhea <5555162+jrhea@users.noreply.github.com> Date: Wed, 14 Jan 2026 11:58:30 -0600 Subject: [PATCH] rpc, internal/telemetry: add OpenTelemetry tracing for JSON-RPC calls (#33452) Add Open Telemetry tracing inside the RPC server to help attribute runtime costs within `handler.handleCall()`. In particular, it allows us to distinguish time spent decoding arguments, invoking methods via reflection, and actually executing the method and constructing/encoding JSON responses. --------- Co-authored-by: lightclient --- cmd/keeper/go.mod | 2 +- cmd/keeper/go.sum | 12 +- go.mod | 18 ++- go.sum | 37 ++++-- internal/telemetry/telemetry.go | 104 +++++++++++++++++ rpc/client.go | 2 +- rpc/handler.go | 94 ++++++++++++---- rpc/server.go | 22 +++- rpc/service.go | 6 +- rpc/tracing_test.go | 192 ++++++++++++++++++++++++++++++++ 10 files changed, 436 insertions(+), 53 deletions(-) create mode 100644 internal/telemetry/telemetry.go create mode 100644 rpc/tracing_test.go diff --git a/cmd/keeper/go.mod b/cmd/keeper/go.mod index a42be042aa..cee1ce05a7 100644 --- a/cmd/keeper/go.mod +++ b/cmd/keeper/go.mod @@ -34,7 +34,7 @@ require ( github.com/tklauser/numcpus v0.6.1 // indirect golang.org/x/crypto v0.36.0 // indirect golang.org/x/sync v0.12.0 // indirect - golang.org/x/sys v0.36.0 // indirect + golang.org/x/sys v0.39.0 // indirect gopkg.in/yaml.v2 v2.4.0 // indirect ) diff --git a/cmd/keeper/go.sum b/cmd/keeper/go.sum index 133a3b10b1..b93969cc60 100644 --- a/cmd/keeper/go.sum +++ b/cmd/keeper/go.sum @@ -96,12 +96,12 @@ github.com/prometheus/procfs v0.9.0 h1:wzCHvIvM5SxWqYvwgVL7yJY8Lz3PKn49KQtpgMYJf github.com/prometheus/procfs v0.9.0/go.mod h1:+pB4zwohETzFnmlpe6yd2lSc+0/46IYZRB/chUwxUZY= github.com/prysmaticlabs/gohashtree v0.0.4-beta h1:H/EbCuXPeTV3lpKeXGPpEV9gsUpkqOOVnWapUyeWro4= github.com/prysmaticlabs/gohashtree v0.0.4-beta/go.mod h1:BFdtALS+Ffhg3lGQIHv9HDWuHS8cTvHZzrHWxwOtGOs= -github.com/rogpeppe/go-internal v1.12.0 h1:exVL4IDcn6na9z1rAb56Vxr+CgyK3nn3O+epU5NdKM8= -github.com/rogpeppe/go-internal v1.12.0/go.mod h1:E+RYuTGaKKdloAfM02xzb0FW3Paa99yedzYV+kq4uf4= +github.com/rogpeppe/go-internal v1.14.1 h1:UQB4HGPB6osV0SQTLymcB4TgvyWu6ZyliaW0tI/otEQ= +github.com/rogpeppe/go-internal v1.14.1/go.mod h1:MaRKkUm5W0goXpeCfT7UZI6fk/L7L7so1lCWt35ZSgc= github.com/shirou/gopsutil v3.21.4-0.20210419000835-c7a38de76ee5+incompatible h1:Bn1aCHHRnjv4Bl16T8rcaFjYSrGrIZvpiGO6P3Q4GpU= github.com/shirou/gopsutil v3.21.4-0.20210419000835-c7a38de76ee5+incompatible/go.mod h1:5b4v6he4MtMOwMlS0TUMTu2PcXUg8+E1lC7eC3UO/RA= -github.com/stretchr/testify v1.10.0 h1:Xv5erBjTwe/5IxqUQTdXv5kgmIvbHo3QQyRwhJsOfJA= -github.com/stretchr/testify v1.10.0/go.mod h1:r2ic/lqez/lEtzL7wO/rwa5dbSLXVDPFyf8C91i36aY= +github.com/stretchr/testify v1.11.1 h1:7s2iGBzp5EwR7/aIZr8ao5+dra3wiQyKjjFuvgVKu7U= +github.com/stretchr/testify v1.11.1/go.mod h1:wZwfW3scLgRK+23gO65QZefKpKQRnfz6sD981Nm4B6U= github.com/supranational/blst v0.3.16-0.20250831170142-f48500c1fdbe h1:nbdqkIGOGfUAD54q1s2YBcBz/WcsxCO9HUQ4aGV5hUw= github.com/supranational/blst v0.3.16-0.20250831170142-f48500c1fdbe/go.mod h1:jZJtfjgudtNl4en1tzwPIV3KjUnQUvG3/j+w+fVonLw= github.com/tklauser/go-sysconf v0.3.12 h1:0QaGUFOdQaIVdPgfITYzaTegZvdCjmYO52cSFAEVmqU= @@ -118,8 +118,8 @@ golang.org/x/sys v0.0.0-20190916202348-b4ddaad3f8a3/go.mod h1:h1NjWce9XRLGQEsW7w golang.org/x/sys v0.1.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.8.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.11.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= -golang.org/x/sys v0.36.0 h1:KVRy2GtZBrk1cBYA7MKu5bEZFxQk4NIDV6RLVcC8o0k= -golang.org/x/sys v0.36.0/go.mod h1:OgkHotnGiDImocRcuBABYBEXf8A9a87e/uXjp9XT3ks= +golang.org/x/sys v0.39.0 h1:CvCKL8MeisomCi6qNZ+wbb0DN9E5AATixKsvNtMoMFk= +golang.org/x/sys v0.39.0/go.mod h1:OgkHotnGiDImocRcuBABYBEXf8A9a87e/uXjp9XT3ks= golang.org/x/text v0.23.0 h1:D71I7dUrlY+VX0gQShAThNGHFxZ13dGLBHQLVl1mJlY= golang.org/x/text v0.23.0/go.mod h1:/BLNzu4aZCJ1+kcD0DNRotWKage4q2rGVAg4o22unh4= google.golang.org/protobuf v1.34.2 h1:6xV6lTsCfpGD21XK49h7MhtcApnLqkfYgPcdHftf6hg= diff --git a/go.mod b/go.mod index 66f3a3ffa5..7bfb6d25d7 100644 --- a/go.mod +++ b/go.mod @@ -31,7 +31,7 @@ require ( github.com/golang-jwt/jwt/v4 v4.5.2 github.com/golang/snappy v1.0.0 github.com/google/gofuzz v1.2.0 - github.com/google/uuid v1.3.0 + github.com/google/uuid v1.6.0 github.com/gorilla/websocket v1.4.2 github.com/graph-gophers/graphql-go v1.3.0 github.com/hashicorp/go-bexpr v0.1.10 @@ -56,16 +56,19 @@ require ( github.com/rs/cors v1.7.0 github.com/shirou/gopsutil v3.21.4-0.20210419000835-c7a38de76ee5+incompatible github.com/status-im/keycard-go v0.2.0 - github.com/stretchr/testify v1.10.0 + github.com/stretchr/testify v1.11.1 github.com/supranational/blst v0.3.16-0.20250831170142-f48500c1fdbe github.com/syndtr/goleveldb v1.0.1-0.20210819022825-2ae1ddf74ef7 github.com/urfave/cli/v2 v2.27.5 + go.opentelemetry.io/otel v1.39.0 + go.opentelemetry.io/otel/sdk v1.39.0 + go.opentelemetry.io/otel/trace v1.39.0 go.uber.org/automaxprocs v1.5.2 go.uber.org/goleak v1.3.0 golang.org/x/crypto v0.36.0 golang.org/x/exp v0.0.0-20230626212559-97b1e661b5df golang.org/x/sync v0.12.0 - golang.org/x/sys v0.36.0 + golang.org/x/sys v0.39.0 golang.org/x/text v0.23.0 golang.org/x/time v0.9.0 golang.org/x/tools v0.29.0 @@ -74,6 +77,13 @@ require ( gopkg.in/yaml.v3 v3.0.1 ) +require ( + github.com/go-logr/logr v1.4.3 // indirect + github.com/go-logr/stdr v1.2.2 // indirect + go.opentelemetry.io/auto/sdk v1.2.1 // indirect + go.opentelemetry.io/otel/metric v1.39.0 // indirect +) + require ( github.com/Azure/azure-sdk-for-go/sdk/azcore v1.7.0 // indirect github.com/Azure/azure-sdk-for-go/sdk/internal v1.3.0 // indirect @@ -136,7 +146,7 @@ require ( github.com/prometheus/common v0.42.0 // indirect github.com/prometheus/procfs v0.9.0 // indirect github.com/rivo/uniseg v0.2.0 // indirect - github.com/rogpeppe/go-internal v1.12.0 // indirect + github.com/rogpeppe/go-internal v1.14.1 // indirect github.com/russross/blackfriday/v2 v2.1.0 // indirect github.com/tklauser/go-sysconf v0.3.12 // indirect github.com/tklauser/numcpus v0.6.1 // indirect diff --git a/go.sum b/go.sum index ad066abc03..c9978a3d9e 100644 --- a/go.sum +++ b/go.sum @@ -136,6 +136,11 @@ github.com/ghodss/yaml v1.0.0/go.mod h1:4dBDuWmgqj2HViK6kFavaiC9ZROes6MMH2rRYeME github.com/go-chi/chi/v5 v5.0.0/go.mod h1:BBug9lr0cqtdAhsu6R4AAdvufI0/XBzAQSsUqJpoZOs= github.com/go-errors/errors v1.4.2 h1:J6MZopCL4uSllY1OfXM374weqZFFItUbrImctkmUxIA= github.com/go-errors/errors v1.4.2/go.mod h1:sIVyrIiJhuEF+Pj9Ebtd6P/rEYROXFi3BopGUQ5a5Og= +github.com/go-logr/logr v1.2.2/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A= +github.com/go-logr/logr v1.4.3 h1:CjnDlHq8ikf6E492q6eKboGOC0T8CDaOvkHCIg8idEI= +github.com/go-logr/logr v1.4.3/go.mod h1:9T104GzyrTigFIr8wt5mBrctHMim0Nb2HLGrmQ40KvY= +github.com/go-logr/stdr v1.2.2 h1:hSWxHoqTgW2S2qGc0LTAI563KZ5YKYRhT3MFKZMbjag= +github.com/go-logr/stdr v1.2.2/go.mod h1:mMo/vtBO5dYbehREoey6XUKy/eSumjCCveDpRre4VKE= github.com/go-ole/go-ole v1.2.5/go.mod h1:pprOEPIfldk/42T2oK7lQ4v4JSDwmV0As9GaiUsvbm0= github.com/go-ole/go-ole v1.3.0 h1:Dt6ye7+vXGIKZ7Xtk4s6/xVdGDQynvom7xCFEdWr6uE= github.com/go-ole/go-ole v1.3.0/go.mod h1:5LS6F96DhAwUc7C+1HLexzMXY1xGRSryjyPPKW6zv78= @@ -170,16 +175,16 @@ github.com/google/go-cmp v0.3.1/go.mod h1:8QqcDgzrUqlUb/G2PQTWiueGozuR1884gddMyw github.com/google/go-cmp v0.4.0/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/gNBxE= github.com/google/go-cmp v0.5.2/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/gNBxE= github.com/google/go-cmp v0.5.8/go.mod h1:17dUlkBOakJ0+DkrSSNjCkIjxS6bF9zb3elmeNGIjoY= -github.com/google/go-cmp v0.6.0 h1:ofyhxvXcZhMsU5ulbFiLKl/XBFqE1GSq7atu8tAmTRI= -github.com/google/go-cmp v0.6.0/go.mod h1:17dUlkBOakJ0+DkrSSNjCkIjxS6bF9zb3elmeNGIjoY= +github.com/google/go-cmp v0.7.0 h1:wk8382ETsv4JYUZwIsn6YpYiWiBsYLSJiTsyBybVuN8= +github.com/google/go-cmp v0.7.0/go.mod h1:pXiqmnSA92OHEEa9HXL2W4E7lf9JzCmGVUdgjX3N/iU= github.com/google/go-querystring v1.1.0 h1:AnCroh3fv4ZBgVIf1Iwtovgjaw/GiKJo8M8yD/fhyJ8= github.com/google/go-querystring v1.1.0/go.mod h1:Kcdr2DB4koayq7X8pmAG4sNG59So17icRSOU623lUBU= github.com/google/gofuzz v1.2.0 h1:xRy4A+RhZaiKjJ1bPfwQ8sedCA+YS2YcCHW6ec7JMi0= github.com/google/gofuzz v1.2.0/go.mod h1:dBl0BpW6vV/+mYPU4Po3pmUjxk6FQPldtuIdl/M65Eg= github.com/google/pprof v0.0.0-20230207041349-798e818bf904 h1:4/hN5RUoecvl+RmJRE2YxKWtnnQls6rQjjW5oV7qg2U= github.com/google/pprof v0.0.0-20230207041349-798e818bf904/go.mod h1:uglQLonpP8qtYCYyzA+8c/9qtqgA3qsXGYqCPKARAFg= -github.com/google/uuid v1.3.0 h1:t6JiXgmwXMjEs8VusXIJk2BXHsn+wx8BZdTaoZ5fu7I= -github.com/google/uuid v1.3.0/go.mod h1:TIyPZe4MgqvfeYDBFedMoGGpEw/LqOeaOT+nhxU+yHo= +github.com/google/uuid v1.6.0 h1:NIvaJDMOsjHA8n1jAhLSgzrAzy1Hgr+hNrb57e+94F0= +github.com/google/uuid v1.6.0/go.mod h1:TIyPZe4MgqvfeYDBFedMoGGpEw/LqOeaOT+nhxU+yHo= github.com/gorilla/mux v1.8.0/go.mod h1:DVbg23sWSpFRCP0SfiEN6jmj59UnW/n46BH5rLB71So= github.com/gorilla/websocket v1.4.2 h1:+/TMaTYc4QFitKJxsQ7Yye35DkWvkdLcvGKqM+x0Ufc= github.com/gorilla/websocket v1.4.2/go.mod h1:YR8l580nyteQvAITg2hZ9XVh4b55+EU/adAjf1fMHhE= @@ -322,8 +327,8 @@ github.com/rivo/uniseg v0.2.0 h1:S1pD9weZBuJdFmowNwbpi7BJ8TNftyUImj/0WQi72jY= github.com/rivo/uniseg v0.2.0/go.mod h1:J6wj4VEh+S6ZtnVlnTBMWIodfgj8LQOQFoIToxlJtxc= github.com/rogpeppe/go-internal v1.6.1/go.mod h1:xXDCJY+GAPziupqXw64V24skbSoqbTEfhy4qGm1nDQc= github.com/rogpeppe/go-internal v1.9.0/go.mod h1:WtVeX8xhTBvf0smdhujwtBcq4Qrzq/fJaraNFVN+nFs= -github.com/rogpeppe/go-internal v1.12.0 h1:exVL4IDcn6na9z1rAb56Vxr+CgyK3nn3O+epU5NdKM8= -github.com/rogpeppe/go-internal v1.12.0/go.mod h1:E+RYuTGaKKdloAfM02xzb0FW3Paa99yedzYV+kq4uf4= +github.com/rogpeppe/go-internal v1.14.1 h1:UQB4HGPB6osV0SQTLymcB4TgvyWu6ZyliaW0tI/otEQ= +github.com/rogpeppe/go-internal v1.14.1/go.mod h1:MaRKkUm5W0goXpeCfT7UZI6fk/L7L7so1lCWt35ZSgc= github.com/rs/cors v1.7.0 h1:+88SsELBHx5r+hZ8TCkggzSstaWNbDvThkVK8H6f9ik= github.com/rs/cors v1.7.0/go.mod h1:gFx+x8UowdsKA9AchylcLynDq+nNFfI8FkUZdN/jGCU= github.com/russross/blackfriday/v2 v2.1.0 h1:JIOH55/0cWyOuilr9/qlrm0BSXldqnqwMsf35Ld67mk= @@ -343,8 +348,8 @@ github.com/stretchr/testify v1.7.1/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/ github.com/stretchr/testify v1.8.0/go.mod h1:yNjHg4UonilssWZ8iaSj1OCr/vHnekPRkoO+kdMU+MU= github.com/stretchr/testify v1.8.3/go.mod h1:sz/lmYIOXD/1dqDmKjjqLyZ2RngseejIcXlSw2iwfAo= github.com/stretchr/testify v1.8.4/go.mod h1:sz/lmYIOXD/1dqDmKjjqLyZ2RngseejIcXlSw2iwfAo= -github.com/stretchr/testify v1.10.0 h1:Xv5erBjTwe/5IxqUQTdXv5kgmIvbHo3QQyRwhJsOfJA= -github.com/stretchr/testify v1.10.0/go.mod h1:r2ic/lqez/lEtzL7wO/rwa5dbSLXVDPFyf8C91i36aY= +github.com/stretchr/testify v1.11.1 h1:7s2iGBzp5EwR7/aIZr8ao5+dra3wiQyKjjFuvgVKu7U= +github.com/stretchr/testify v1.11.1/go.mod h1:wZwfW3scLgRK+23gO65QZefKpKQRnfz6sD981Nm4B6U= github.com/supranational/blst v0.3.16-0.20250831170142-f48500c1fdbe h1:nbdqkIGOGfUAD54q1s2YBcBz/WcsxCO9HUQ4aGV5hUw= github.com/supranational/blst v0.3.16-0.20250831170142-f48500c1fdbe/go.mod h1:jZJtfjgudtNl4en1tzwPIV3KjUnQUvG3/j+w+fVonLw= github.com/syndtr/goleveldb v1.0.1-0.20210819022825-2ae1ddf74ef7 h1:epCh84lMvA70Z7CTTCmYQn2CKbY8j86K7/FAIr141uY= @@ -363,6 +368,18 @@ github.com/xrash/smetrics v0.0.0-20240521201337-686a1a2994c1/go.mod h1:Ohn+xnUBi github.com/yuin/goldmark v1.1.27/go.mod h1:3hX8gzYuyVAZsxl0MRgGTJEmQBFcNTphYh9decYSb74= github.com/yuin/goldmark v1.2.1/go.mod h1:3hX8gzYuyVAZsxl0MRgGTJEmQBFcNTphYh9decYSb74= github.com/yuin/goldmark v1.4.13/go.mod h1:6yULJ656Px+3vBD8DxQVa3kxgyrAnzto9xy5taEt/CY= +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/otel v1.39.0 h1:8yPrr/S0ND9QEfTfdP9V+SiwT4E0G7Y5MO7p85nis48= +go.opentelemetry.io/otel v1.39.0/go.mod h1:kLlFTywNWrFyEdH0oj2xK0bFYZtHRYUdv1NklR/tgc8= +go.opentelemetry.io/otel/metric v1.39.0 h1:d1UzonvEZriVfpNKEVmHXbdf909uGTOQjA0HF0Ls5Q0= +go.opentelemetry.io/otel/metric v1.39.0/go.mod h1:jrZSWL33sD7bBxg1xjrqyDjnuzTUB0x1nBERXd7Ftcs= +go.opentelemetry.io/otel/sdk v1.39.0 h1:nMLYcjVsvdui1B/4FRkwjzoRVsMK8uL/cj0OyhKzt18= +go.opentelemetry.io/otel/sdk v1.39.0/go.mod h1:vDojkC4/jsTJsE+kh+LXYQlbL8CgrEcwmt1ENZszdJE= +go.opentelemetry.io/otel/sdk/metric v1.39.0 h1:cXMVVFVgsIf2YL6QkRF4Urbr/aMInf+2WKg+sEJTtB8= +go.opentelemetry.io/otel/sdk/metric v1.39.0/go.mod h1:xq9HEVH7qeX69/JnwEfp6fVq5wosJsY1mt4lLfYdVew= +go.opentelemetry.io/otel/trace v1.39.0 h1:2d2vfpEDmCJ5zVYz7ijaJdOF59xLomrvj7bjt6/qCJI= +go.opentelemetry.io/otel/trace v1.39.0/go.mod h1:88w4/PnZSazkGzz/w84VHpQafiU4EtqqlVdxWy+rNOA= go.uber.org/automaxprocs v1.5.2 h1:2LxUOGiR3O6tw8ui5sZa2LAaHnsviZdVOUZw4fvbnME= go.uber.org/automaxprocs v1.5.2/go.mod h1:eRbA25aqJrxAbsLO0xy5jVwPt7FQnRgjW+efnwa1WM0= go.uber.org/goleak v1.3.0 h1:2K3zAYmnTNqV73imy9J1T3WC+gmCePx2hEGkimedGto= @@ -444,8 +461,8 @@ golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.7.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.8.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.11.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= -golang.org/x/sys v0.36.0 h1:KVRy2GtZBrk1cBYA7MKu5bEZFxQk4NIDV6RLVcC8o0k= -golang.org/x/sys v0.36.0/go.mod h1:OgkHotnGiDImocRcuBABYBEXf8A9a87e/uXjp9XT3ks= +golang.org/x/sys v0.39.0 h1:CvCKL8MeisomCi6qNZ+wbb0DN9E5AATixKsvNtMoMFk= +golang.org/x/sys v0.39.0/go.mod h1:OgkHotnGiDImocRcuBABYBEXf8A9a87e/uXjp9XT3ks= golang.org/x/term v0.0.0-20201117132131-f5c789dd3221/go.mod h1:Nr5EML6q2oocZ2LXRh80K7BxOlk5/8JxuGnuhpl+muw= golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo= golang.org/x/term v0.0.0-20210927222741-03fcf44c2211/go.mod h1:jbD1KX2456YbFQfuXm/mYQcufACuNUgVhRMnK/tPxf8= diff --git a/internal/telemetry/telemetry.go b/internal/telemetry/telemetry.go new file mode 100644 index 0000000000..6bd16da66c --- /dev/null +++ b/internal/telemetry/telemetry.go @@ -0,0 +1,104 @@ +// Copyright 2026 The go-ethereum Authors +// This file is part of the go-ethereum library. +// +// The go-ethereum library is free software: you can redistribute it and/or modify +// it under the terms of the GNU Lesser General Public License as published by +// the Free Software Foundation, either version 3 of the License, or +// (at your option) any later version. +// +// The go-ethereum library is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU Lesser General Public License for more details. +// +// You should have received a copy of the GNU Lesser General Public License +// along with the go-ethereum library. If not, see . + +package telemetry + +import ( + "context" + "fmt" + + "go.opentelemetry.io/otel" + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/codes" + semconv "go.opentelemetry.io/otel/semconv/v1.38.0" + "go.opentelemetry.io/otel/trace" +) + +// Attribute is an alias for attribute.KeyValue. +type Attribute = attribute.KeyValue + +// StringAttribute creates an attribute with a string value. +func StringAttribute(key, val string) Attribute { + return attribute.String(key, val) +} + +// Int64Attribute creates an attribute with an int64 value. +func Int64Attribute(key string, val int64) Attribute { + return attribute.Int64(key, val) +} + +// BoolAttribute creates an attribute with a bool value. +func BoolAttribute(key string, val bool) Attribute { + return attribute.Bool(key, val) +} + +// StartSpan creates a SpanKind=INTERNAL span. +func StartSpan(ctx context.Context, spanName string, attributes ...Attribute) (context.Context, trace.Span, func(error)) { + return StartSpanWithTracer(ctx, otel.Tracer(""), spanName, attributes...) +} + +// StartSpanWithTracer requires a tracer to be passed in and creates a SpanKind=INTERNAL span. +func StartSpanWithTracer(ctx context.Context, tracer trace.Tracer, name string, attributes ...Attribute) (context.Context, trace.Span, func(error)) { + return startSpan(ctx, tracer, trace.SpanKindInternal, name, attributes...) +} + +// RPCInfo contains information about the RPC request. +type RPCInfo struct { + System string + Service string + Method string + RequestID string +} + +// StartServerSpan creates a SpanKind=SERVER span at the JSON-RPC boundary. +// The span name is formatted as $rpcSystem.$rpcService/$rpcMethod +// (e.g. "jsonrpc.engine/newPayloadV4") which follows the Open Telemetry +// semantic convensions: https://opentelemetry.io/docs/specs/semconv/rpc/rpc-spans/#span-name. +func StartServerSpan(ctx context.Context, tracer trace.Tracer, rpc RPCInfo, others ...Attribute) (context.Context, func(error)) { + var ( + name = fmt.Sprintf("%s.%s/%s", rpc.System, rpc.Service, rpc.Method) + attributes = append([]Attribute{ + semconv.RPCSystemKey.String(rpc.System), + semconv.RPCServiceKey.String(rpc.Service), + semconv.RPCMethodKey.String(rpc.Method), + semconv.RPCJSONRPCRequestID(rpc.RequestID), + }, + others..., + ) + ) + ctx, _, end := startSpan(ctx, tracer, trace.SpanKindServer, name, attributes...) + return ctx, end +} + +// startSpan creates a span with the given kind. +func startSpan(ctx context.Context, tracer trace.Tracer, kind trace.SpanKind, spanName string, attributes ...Attribute) (context.Context, trace.Span, func(error)) { + ctx, span := tracer.Start(ctx, spanName, trace.WithSpanKind(kind)) + if len(attributes) > 0 { + span.SetAttributes(attributes...) + } + return ctx, span, endSpan(span) +} + +// endSpan ends the span and handles error recording. +func endSpan(span trace.Span) func(error) { + return func(err error) { + if err != nil { + span.RecordError(err) + span.SetStatus(codes.Error, err.Error()) + } + span.End() + } +} diff --git a/rpc/client.go b/rpc/client.go index 9dc36a6105..8d81503d59 100644 --- a/rpc/client.go +++ b/rpc/client.go @@ -119,7 +119,7 @@ func (c *Client) newClientConn(conn ServerCodec) *clientConn { ctx := context.Background() ctx = context.WithValue(ctx, clientContextKey{}, c) ctx = context.WithValue(ctx, peerInfoContextKey{}, conn.peerInfo()) - handler := newHandler(ctx, conn, c.idgen, c.services, c.batchItemLimit, c.batchResponseMaxSize) + handler := newHandler(ctx, conn, c.idgen, c.services, c.batchItemLimit, c.batchResponseMaxSize, nil) return &clientConn{conn, handler} } diff --git a/rpc/handler.go b/rpc/handler.go index 462519d872..4ac3a26df1 100644 --- a/rpc/handler.go +++ b/rpc/handler.go @@ -28,7 +28,10 @@ import ( "sync" "time" + "github.com/ethereum/go-ethereum/internal/telemetry" "github.com/ethereum/go-ethereum/log" + "go.opentelemetry.io/otel" + "go.opentelemetry.io/otel/trace" ) // handler handles JSON-RPC messages. There is one handler per connection. Note that @@ -65,6 +68,7 @@ type handler struct { allowSubscribe bool batchRequestLimit int batchResponseMaxSize int + tracerProvider trace.TracerProvider subLock sync.Mutex serverSubs map[ID]*Subscription @@ -73,9 +77,10 @@ type handler struct { type callProc struct { ctx context.Context notifiers []*Notifier + isBatch bool } -func newHandler(connCtx context.Context, conn jsonWriter, idgen func() ID, reg *serviceRegistry, batchRequestLimit, batchResponseMaxSize int) *handler { +func newHandler(connCtx context.Context, conn jsonWriter, idgen func() ID, reg *serviceRegistry, batchRequestLimit, batchResponseMaxSize int, tracerProvider trace.TracerProvider) *handler { rootCtx, cancelRoot := context.WithCancel(connCtx) h := &handler{ reg: reg, @@ -90,6 +95,7 @@ func newHandler(connCtx context.Context, conn jsonWriter, idgen func() ID, reg * log: log.Root(), batchRequestLimit: batchRequestLimit, batchResponseMaxSize: batchResponseMaxSize, + tracerProvider: tracerProvider, } if conn.remoteAddr() != "" { h.log = h.log.New("conn", conn.remoteAddr()) @@ -197,6 +203,7 @@ func (h *handler) handleBatch(msgs []*jsonrpcMessage) { // Process calls on a goroutine because they may block indefinitely: h.startCallProc(func(cp *callProc) { + cp.isBatch = true var ( timer *time.Timer cancel context.CancelFunc @@ -497,40 +504,65 @@ func (h *handler) handleCall(cp *callProc, msg *jsonrpcMessage) *jsonrpcMessage if msg.isSubscribe() { return h.handleSubscribe(cp, msg) } - var callb *callback if msg.isUnsubscribe() { - callb = h.unsubscribeCb - } else { - // Check method name length - if len(msg.Method) > maxMethodNameLength { - return msg.errorResponse(&invalidRequestError{fmt.Sprintf("method name too long: %d > %d", len(msg.Method), maxMethodNameLength)}) + args, err := parsePositionalArguments(msg.Params, h.unsubscribeCb.argTypes) + if err != nil { + return msg.errorResponse(&invalidParamsError{err.Error()}) } - callb = h.reg.callback(msg.Method) + return h.runMethod(cp.ctx, msg, h.unsubscribeCb, args) } + + // Check method name length + if len(msg.Method) > maxMethodNameLength { + return msg.errorResponse(&invalidRequestError{fmt.Sprintf("method name too long: %d > %d", len(msg.Method), maxMethodNameLength)}) + } + callb, service, method := h.reg.callback(msg.Method) + + // If the method is not found, return an error. if callb == nil { return msg.errorResponse(&methodNotFoundError{method: msg.Method}) } + // Start root span for the request. + var err error + rpcInfo := telemetry.RPCInfo{ + System: "jsonrpc", + Service: service, + Method: method, + RequestID: string(msg.ID), + } + attrib := []telemetry.Attribute{ + telemetry.BoolAttribute("rpc.batch", cp.isBatch), + } + ctx, spanEnd := telemetry.StartServerSpan(cp.ctx, h.tracer(), rpcInfo, attrib...) + defer spanEnd(err) + + // Start tracing span before parsing arguments. + _, _, pSpanEnd := telemetry.StartSpanWithTracer(ctx, h.tracer(), "rpc.parsePositionalArguments") args, err := parsePositionalArguments(msg.Params, callb.argTypes) + pSpanEnd(err) if err != nil { return msg.errorResponse(&invalidParamsError{err.Error()}) } start := time.Now() - answer := h.runMethod(cp.ctx, msg, callb, args) + + // Start tracing span before running the method. + rctx, _, rSpanEnd := telemetry.StartSpanWithTracer(ctx, h.tracer(), "rpc.runMethod") + answer := h.runMethod(rctx, msg, callb, args) + if answer.Error != nil { + err = errors.New(answer.Error.Message) + } + rSpanEnd(err) // Collect the statistics for RPC calls if metrics is enabled. - // We only care about pure rpc call. Filter out subscription. - if callb != h.unsubscribeCb { - rpcRequestGauge.Inc(1) - if answer.Error != nil { - failedRequestGauge.Inc(1) - } else { - successfulRequestGauge.Inc(1) - } - rpcServingTimer.UpdateSince(start) - updateServeTimeHistogram(msg.Method, answer.Error == nil, time.Since(start)) + rpcRequestGauge.Inc(1) + if answer.Error != nil { + failedRequestGauge.Inc(1) + } else { + successfulRequestGauge.Inc(1) } - + rpcServingTimer.UpdateSince(start) + updateServeTimeHistogram(msg.Method, answer.Error == nil, time.Since(start)) return answer } @@ -568,17 +600,33 @@ func (h *handler) handleSubscribe(cp *callProc, msg *jsonrpcMessage) *jsonrpcMes n := &Notifier{h: h, namespace: namespace} cp.notifiers = append(cp.notifiers, n) ctx := context.WithValue(cp.ctx, notifierKey{}, n) - return h.runMethod(ctx, msg, callb, args) } +// tracer returns the OpenTelemetry Tracer for RPC call tracing. +func (h *handler) tracer() trace.Tracer { + if h.tracerProvider == nil { + // Default to global TracerProvider if none is set. + // Note: If no TracerProvider is set, the default is a no-op TracerProvider. + // See https://pkg.go.dev/go.opentelemetry.io/otel#GetTracerProvider + return otel.Tracer("") + } + return h.tracerProvider.Tracer("") +} + // runMethod runs the Go callback for an RPC method. -func (h *handler) runMethod(ctx context.Context, msg *jsonrpcMessage, callb *callback, args []reflect.Value) *jsonrpcMessage { +func (h *handler) runMethod(ctx context.Context, msg *jsonrpcMessage, callb *callback, args []reflect.Value, attributes ...telemetry.Attribute) *jsonrpcMessage { result, err := callb.call(ctx, msg.Method, args) if err != nil { return msg.errorResponse(err) } - return msg.response(result) + _, _, spanEnd := telemetry.StartSpanWithTracer(ctx, h.tracer(), "rpc.encodeJSONResponse", attributes...) + response := msg.response(result) + if response.Error != nil { + err = errors.New(response.Error.Message) + } + spanEnd(err) + return response } // unsubscribe is the callback function for all *_unsubscribe calls. diff --git a/rpc/server.go b/rpc/server.go index 599e31fb41..94d4a3e13e 100644 --- a/rpc/server.go +++ b/rpc/server.go @@ -25,6 +25,7 @@ import ( "sync/atomic" "github.com/ethereum/go-ethereum/log" + "go.opentelemetry.io/otel/trace" ) const MetadataApi = "rpc" @@ -55,15 +56,17 @@ type Server struct { batchResponseLimit int httpBodyLimit int wsReadLimit int64 + tracerProvider trace.TracerProvider } // NewServer creates a new server instance with no registered handlers. func NewServer() *Server { server := &Server{ - idgen: randomIDGenerator(), - codecs: make(map[ServerCodec]struct{}), - httpBodyLimit: defaultBodyLimit, - wsReadLimit: wsDefaultReadLimit, + idgen: randomIDGenerator(), + codecs: make(map[ServerCodec]struct{}), + httpBodyLimit: defaultBodyLimit, + wsReadLimit: wsDefaultReadLimit, + tracerProvider: nil, } server.run.Store(true) // Register the default service providing meta information about the RPC service such @@ -129,6 +132,15 @@ func (s *Server) ServeCodec(codec ServerCodec, options CodecOption) { c.Close() } +// setTracerProvider configures the OpenTelemetry TracerProvider for RPC call tracing. +// Note: This method (and the TracerProvider field in the Server/Handler struct) is +// primarily intended for testing. In particular, it allows tests to configure an +// isolated TracerProvider without changing the global provider, avoiding +// interference between tests running in parallel. +func (s *Server) setTracerProvider(tp trace.TracerProvider) { + s.tracerProvider = tp +} + func (s *Server) trackCodec(codec ServerCodec) bool { s.mutex.Lock() defer s.mutex.Unlock() @@ -156,7 +168,7 @@ func (s *Server) serveSingleRequest(ctx context.Context, codec ServerCodec) { return } - h := newHandler(ctx, codec, s.idgen, &s.services, s.batchItemLimit, s.batchResponseLimit) + h := newHandler(ctx, codec, s.idgen, &s.services, s.batchItemLimit, s.batchResponseLimit, s.tracerProvider) h.allowSubscribe = false defer h.close(io.EOF, nil) diff --git a/rpc/service.go b/rpc/service.go index 0f62d7eb7c..8462a5a59a 100644 --- a/rpc/service.go +++ b/rpc/service.go @@ -92,14 +92,14 @@ func (r *serviceRegistry) registerName(name string, rcvr interface{}) error { } // callback returns the callback corresponding to the given RPC method name. -func (r *serviceRegistry) callback(method string) *callback { +func (r *serviceRegistry) callback(method string) (cb *callback, service, methodName string) { before, after, found := strings.Cut(method, serviceMethodSeparator) if !found { - return nil + return nil, "", "" } r.mu.Lock() defer r.mu.Unlock() - return r.services[before].callbacks[after] + return r.services[before].callbacks[after], before, after } // subscription returns a subscription callback in the given service. diff --git a/rpc/tracing_test.go b/rpc/tracing_test.go new file mode 100644 index 0000000000..89cd31a075 --- /dev/null +++ b/rpc/tracing_test.go @@ -0,0 +1,192 @@ +// Copyright 2025 The go-ethereum Authors +// This file is part of the go-ethereum library. +// +// The go-ethereum library is free software: you can redistribute it and/or modify +// it under the terms of the GNU Lesser General Public License as published by +// the Free Software Foundation, either version 3 of the License, or +// (at your option) any later version. +// +// The go-ethereum library is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU Lesser General Public License for more details. +// +// You should have received a copy of the GNU Lesser General Public License +// along with the go-ethereum library. If not, see . + +package rpc + +import ( + "context" + "net/http/httptest" + "testing" + + "go.opentelemetry.io/otel/attribute" + sdktrace "go.opentelemetry.io/otel/sdk/trace" + "go.opentelemetry.io/otel/sdk/trace/tracetest" +) + +// attributeMap converts a slice of attributes to a map. +func attributeMap(attrs []attribute.KeyValue) map[string]string { + m := make(map[string]string) + for _, a := range attrs { + switch a.Value.Type() { + case attribute.STRING: + m[string(a.Key)] = a.Value.AsString() + case attribute.BOOL: + if a.Value.AsBool() { + m[string(a.Key)] = "true" + } else { + m[string(a.Key)] = "false" + } + default: + m[string(a.Key)] = a.Value.Emit() + } + } + return m +} + +// newTracingServer creates a new server with tracing enabled. +func newTracingServer(t *testing.T) (*Server, *sdktrace.TracerProvider, *tracetest.InMemoryExporter) { + t.Helper() + exporter := tracetest.NewInMemoryExporter() + tp := sdktrace.NewTracerProvider(sdktrace.WithSyncer(exporter)) + t.Cleanup(func() { _ = tp.Shutdown(context.Background()) }) + server := newTestServer() + server.setTracerProvider(tp) + t.Cleanup(server.Stop) + return server, tp, exporter +} + +// TestTracingHTTP verifies that RPC spans are emitted when processing HTTP requests. +func TestTracingHTTP(t *testing.T) { + t.Parallel() + server, tracer, exporter := newTracingServer(t) + httpsrv := httptest.NewServer(server) + t.Cleanup(httpsrv.Close) + client, err := DialHTTP(httpsrv.URL) + if err != nil { + t.Fatalf("failed to dial: %v", err) + } + t.Cleanup(client.Close) + + // Make a successful RPC call. + var result echoResult + if err := client.Call(&result, "test_echo", "hello", 42, &echoArgs{S: "world"}); err != nil { + t.Fatalf("RPC call failed: %v", err) + } + + // Flush and verify that we emitted the expected span. + if err := tracer.ForceFlush(context.Background()); err != nil { + t.Fatalf("failed to flush: %v", err) + } + spans := exporter.GetSpans() + if len(spans) == 0 { + t.Fatal("no spans were emitted") + } + var rpcSpan *tracetest.SpanStub + for i := range spans { + if spans[i].Name == "jsonrpc.test/echo" { + rpcSpan = &spans[i] + break + } + } + if rpcSpan == nil { + t.Fatalf("jsonrpc.test/echo span not found.") + } + attrs := attributeMap(rpcSpan.Attributes) + if attrs["rpc.system"] != "jsonrpc" { + t.Errorf("expected rpc.system=jsonrpc, got %v", attrs["rpc.system"]) + } + if attrs["rpc.service"] != "test" { + t.Errorf("expected rpc.service=test, got %v", attrs["rpc.service"]) + } + if attrs["rpc.method"] != "echo" { + t.Errorf("expected rpc.method=echo, got %v", attrs["rpc.method"]) + } + if _, ok := attrs["rpc.jsonrpc.request_id"]; !ok { + t.Errorf("expected rpc.jsonrpc.request_id attribute to be set") + } +} + +// TestTracingBatchHTTP verifies that RPC spans are emitted for batched JSON-RPC calls over HTTP. +func TestTracingBatchHTTP(t *testing.T) { + t.Parallel() + server, tracer, exporter := newTracingServer(t) + httpsrv := httptest.NewServer(server) + t.Cleanup(httpsrv.Close) + client, err := DialHTTP(httpsrv.URL) + if err != nil { + t.Fatalf("failed to dial: %v", err) + } + t.Cleanup(client.Close) + + // Make a successful batch RPC call. + batch := []BatchElem{ + { + Method: "test_echo", + Args: []any{"hello", 42, &echoArgs{S: "world"}}, + Result: new(echoResult), + }, + { + Method: "test_echo", + Args: []any{"your", 7, &echoArgs{S: "mom"}}, + Result: new(echoResult), + }, + } + if err := client.BatchCall(batch); err != nil { + t.Fatalf("batch RPC call failed: %v", err) + } + + // Flush and verify we emitted spans for each batch element. + if err := tracer.ForceFlush(context.Background()); err != nil { + t.Fatalf("failed to flush: %v", err) + } + spans := exporter.GetSpans() + if len(spans) == 0 { + t.Fatal("no spans were emitted") + } + var found int + for i := range spans { + if spans[i].Name == "jsonrpc.test/echo" { + attrs := attributeMap(spans[i].Attributes) + if attrs["rpc.system"] == "jsonrpc" && + attrs["rpc.service"] == "test" && + attrs["rpc.method"] == "echo" && + attrs["rpc.batch"] == "true" { + found++ + } + } + } + if found != len(batch) { + t.Fatalf("expected %d matching batch spans, got %d", len(batch), found) + } +} + +// TestTracingSubscribeUnsubscribe verifies that subscribe and unsubscribe calls +// do not emit any spans. +// Note: This works because client.newClientConn() passes nil as the tracer provider. +func TestTracingSubscribeUnsubscribe(t *testing.T) { + t.Parallel() + server, tracer, exporter := newTracingServer(t) + client := DialInProc(server) + t.Cleanup(client.Close) + + // Subscribe to notifications. + sub, err := client.Subscribe(context.Background(), "nftest", make(chan int), "someSubscription", 1, 1) + if err != nil { + t.Fatalf("subscribe failed: %v", err) + } + + // Unsubscribe. + sub.Unsubscribe() + + // Flush and check that no spans were emitted. + if err := tracer.ForceFlush(context.Background()); err != nil { + t.Fatalf("failed to flush: %v", err) + } + spans := exporter.GetSpans() + if len(spans) != 0 { + t.Errorf("expected no spans for subscribe/unsubscribe, got %d", len(spans)) + } +}