otel & pino integration

[ValiuchenkoVladyslav]

Environment

bun v1.3.11

related deps:
"@opentelemetry/api": "^1.9.1",
"@opentelemetry/core": "^2.7.1",
"@opentelemetry/resources": "^2.7.1",
"@opentelemetry/sdk-node": "^0.217.0",
"@opentelemetry/sdk-trace-base": "^2.7.1",
"@opentelemetry/semantic-conventions": "^1.40.0",

"@orpc/experimental-pino": "^1.14.2",
"@orpc/otel": "^1.14.2",
"@orpc/server": "^1.14.1",
"pino": "^10.3.1",

Reproduction

Heres my setup:

otel

import { resourceFromAttributes } from "@opentelemetry/resources";
import { NodeSDK } from "@opentelemetry/sdk-node";
import {
   ATTR_SERVICE_NAME,
   ATTR_SERVICE_VERSION,
} from "@opentelemetry/semantic-conventions";
import { ORPCInstrumentation } from "@orpc/otel";
import { VERSION } from "~/env";

import { ClickhouseExporter } from "./instrumentation.exporter";

const sdk = new NodeSDK({
   autoDetectResources: false,

   resource: resourceFromAttributes({
      [ATTR_SERVICE_NAME]: "chat-backend",
      [ATTR_SERVICE_VERSION]: VERSION,
   }),

   traceExporter: new ClickhouseExporter(),

   instrumentations: [new ORPCInstrumentation()],
});

sdk.start();

orpc handler

import { LoggingHandlerPlugin } from "@orpc/experimental-pino";
import { RPCHandler } from "@orpc/server/fetch";
import {
   CORSPlugin,
   RequestHeadersPlugin,
   ResponseHeadersPlugin,
} from "@orpc/server/plugins";

import { env } from "~/env";
import { os } from "~/os/http";
import { logger } from "~/logger";

import { signInPass, signInPassConfirm } from "./route/auth/sign-in-pass";
import { signOut } from "./route/auth/sign-out";
import { signUpPass, signUpPassConfirm } from "./route/auth/sign-up-pass";

const router = os.router({
   auth: {
      signUpPass,
      signUpPassConfirm,
      signInPass,
      signInPassConfirm,

      signOut,
   },
});

export const http = new RPCHandler(router, {
   plugins: [
      new CORSPlugin({
         origin: env.FRONTEND_ORIGIN,
         credentials: true,
      }),

      new RequestHeadersPlugin(),
      new ResponseHeadersPlugin(),

      new LoggingHandlerPlugin({
         logger,
         logRequestResponse: true,
         logRequestAbort: true,
      }),
   ],
});

pino logger

import { context, trace } from "@opentelemetry/api";
import pino from "pino";
import { env, VERSION } from "~/env";

export const logger = pino({
   base: {
      service: "chat-backend",
      version: VERSION,
   },

   level: env.NODE_ENV === "production" ? "info" : "debug",

   mixin() {
      const ctx = trace.getSpan(context.active())?.spanContext();

      return ctx ? {
         traceId: ctx.traceId,
         spanId: ctx.spanId,
      } : {
         traceId: "root",
         spanId: "root", 
      };
   },
});

Describe the bug

"request received" and "request handled" logs from pino integration happen outside otel context

Example:

{"level":30,"time":1778541162556,"service":"chat-backend","version":"dev","traceId":"root","spanId":"root","msg":"Server started"}
{"level":30,"time":1778541166713,"service":"chat-backend","version":"dev","rpc":{"id":"5df967a5-8ac3-45dc-a29d-ceda28657be0","system":"orpc"},"req":{"url":"http://localhost:3000/auth/signInPassConfirm","method":"POST","headers":{"content-type":"application/json","content-length":"19"}},"traceId":"root","spanId":"root","msg":"request received"}
{"level":30,"time":1778541166718,"service":"chat-backend","version":"dev","rpc":{"id":"5df967a5-8ac3-45dc-a29d-ceda28657be0","system":"orpc"},"req":{"url":"http://localhost:3000/auth/signInPassConfirm","method":"POST","headers":{"content-type":"application/json","content-length":"19"}},"rpc":{"id":"5df967a5-8ac3-45dc-a29d-ceda28657be0","system":"orpc","method":"auth.signInPassConfirm"},"traceId":"d3504a95e76e576a096883d27d83edca","spanId":"867c1eec415ac1bb","msg":"test log inside handler"}
{"level":50,"time":1778541166719,"service":"chat-backend","version":"dev","rpc":{"id":"5df967a5-8ac3-45dc-a29d-ceda28657be0","system":"orpc"},"req":{"url":"http://localhost:3000/auth/signInPassConfirm","method":"POST","headers":{"content-type":"application/json","content-length":"19"}},"rpc":{"id":"5df967a5-8ac3-45dc-a29d-ceda28657be0","system":"orpc","method":"auth.signInPassConfirm"},"traceId":"d3504a95e76e576a096883d27d83edca","spanId":"9871022480332985","err":{"type":"ORPCError","message":"Missing claims","stack":"Error: Missing claims\n    at <anonymous> (/home/anon/Documents/chat/node_modules/.bun/@orpc+server@1.14.2+e40b0dfdd726a224/node_modules/@orpc/server/dist/shared/server.BOmqcs4W.mjs:78:20)\n    at <anonymous> (/home/anon/Documents/chat/backend/src/route/auth/sign-in-pass.ts:66:23)\n    at <anonymous> (/home/anon/Documents/chat/node_modules/.bun/@orpc+shared@1.14.2+e40b0dfdd726a224/node_modules/@orpc/shared/dist/index.mjs:131:20)\n    at run (node:async_hooks:62:22)\n    at runWithSpan (/home/anon/Documents/chat/node_modules/.bun/@orpc+shared@1.14.2+e40b0dfdd726a224/node_modules/@orpc/shared/dist/index.mjs:142:19)\n    at <anonymous> (/home/anon/Documents/chat/node_modules/.bun/@orpc+server@1.14.2+e40b0dfdd726a224/node_modules/@orpc/server/dist/shared/server.BOmqcs4W.mjs:229:15)\n    at processTicksAndRejections (native:7:39)","defined":true,"code":"BAD_REQUEST","status":400},"msg":"Missing claims"}
{"level":30,"time":1778541166720,"service":"chat-backend","version":"dev","rpc":{"id":"5df967a5-8ac3-45dc-a29d-ceda28657be0","system":"orpc"},"req":{"url":"http://localhost:3000/auth/signInPassConfirm","method":"POST","headers":{"content-type":"application/json","content-length":"19"}},"rpc":{"id":"5df967a5-8ac3-45dc-a29d-ceda28657be0","system":"orpc","method":"auth.signInPassConfirm"},"traceId":"root","spanId":"root","msg":"request handled","res":{"status":400}}

but context is present for orpc errors and custom logs inside my handler (which is expected)

Additional context

No response

Logs

[dosubot]

This is an architectural limitation in how LoggingHandlerPlugin and ORPCInstrumentation interact. The root cause is that LoggingHandlerPlugin registers a rootInterceptor, which executes before the OpenTelemetry span is created by runWithSpan() inside the StandardHandler.

The execution order looks like this [1]:

rootInterceptor starts → "request received" ❌ (no span exists yet)
  → next() is called
    → runWithSpan() creates the OTel span ✅
      → interceptors run (has span context)
      → handler executes (has span context)
      → span ends
  → next() returns
"request handled" ❌ (span already ended)
rootInterceptor ends

The LoggingHandlerPlugin logs both messages in its rootInterceptor — before calling next() ("request received") and after it returns ("request handled") — which is outside the active span lifecycle.

Workaround: If you need trace context on those logs, you could write a custom plugin that uses interceptors instead of rootInterceptors. The interceptors array runs inside the runWithSpan() callback [2], so trace.getSpan(context.active()) would return the active span:

import { StandardHandlerPlugin } from '@orpc/server/standard'

class TracedLoggingPlugin implements StandardHandlerPlugin<any> {
  init(options) {
    options.interceptors ??= []
    options.interceptors.unshift(async (interceptorOptions) => {
      // ✅ OTel context is active here
      logger.info('request received')
      const result = await interceptorOptions.next(interceptorOptions)
      logger.info({ msg: 'request handled', res: { status: result.response.status } })
      return result
    })
  }
}

The tradeoff is that interceptors only fire for matched procedures (not 404s), whereas rootInterceptors fire for all requests.

Ideally the framework could create the span before invoking rootInterceptors so that logging plugins get trace context automatically — this might be worth considering as an enhancement.

To reply, just mention @dosu.

---

Docs are dead. Just use Dosu.

[dinwwwh]

Why do you need both the Pino plugin and OTEL if OTEL plugin already captures errors in spans?

[ValiuchenkoVladyslav]

i use otel for traces and metrics and pino for structured logging (not only errors) and i want them to be correlated

[dinwwwh]

@dosu is completely correct about the current limitation. I'll think about fixing it in v2, or possibly using interceptors instead of rootInterceptors (though that comes with some drawbacks).

[dosubot]

Thanks for confirming! For the v2 consideration, one approach that could preserve the benefits of both would be creating the OTel span at the very start of the rootInterceptors chain (or just before it), so that all rootInterceptors — including logging — execute within the active trace context. Early-exit plugins like CORS could still avoid creating child spans by simply not instrumenting their logic, while the parent request span would still exist for context propagation.

Alternatively, a lighter option could be exposing a hook or callback in the LoggingHandlerPlugin that lets users inject context (like trace/span IDs) into log entries manually, without changing the interceptor architecture.

To reply, just mention @dosu.

---

Share context across your team and agents. Try Dosu.