I'm trying to perform manual instrumentation in NodeJs (v18.16.1) using opentelemetry. The scenario is very simple, I'm making an axios HTTP call to a dummy JSON API and I want to collect the generated trace.
Dependencies:
"@opentelemetry/api": "^1.3.0",
"@opentelemetry/auto-instrumentations-node": "^0.38.0",
"@opentelemetry/context-async-hooks": "^1.15.0",
"@opentelemetry/instrumentation": "^0.41.0",
"@opentelemetry/instrumentation-http": "^0.35.1",
"@opentelemetry/resources": "^1.9.1",
"@opentelemetry/sdk-metrics": "^1.9.1",
"@opentelemetry/sdk-node": "^0.35.1",
"@opentelemetry/sdk-trace-base": "^1.9.1",
"@opentelemetry/sdk-trace-node": "^1.9.1",
"@opentelemetry/semantic-conventions": "^1.9.1",
"axios": "^1.4.0"
The setup is the following:
otel/tracing.js
file:
const opentelemetry = require('@opentelemetry/api')
const { Resource } = require("@opentelemetry/resources");
const { SemanticResourceAttributes } = require("@opentelemetry/semantic-conventions");
const { NodeTracerProvider } = require("@opentelemetry/sdk-trace-node");
const { registerInstrumentations } = require("@opentelemetry/instrumentation");
const { ConsoleSpanExporter, SimpleSpanProcessor} = require("@opentelemetry/sdk-trace-base");
const { AsyncHooksContextManager } = require('@opentelemetry/context-async-hooks');
const {
HttpInstrumentation,
} = require("@opentelemetry/instrumentation-http");
const contextManager = new AsyncHooksContextManager();
contextManager.enable()
opentelemetry.context.setGlobalContextManager(contextManager)
registerInstrumentations({
instrumentations: [new HttpInstrumentation()],
});
const resource =
Resource.default().merge(
new Resource({
[SemanticResourceAttributes.SERVICE_NAME]: 'poc-otel-tracing',
[SemanticResourceAttributes.SERVICE_VERSION]: "0.1.0",
})
);
const provider = new NodeTracerProvider({
resource: resource
});
const exporter = new ConsoleSpanExporter();
const processor = new SimpleSpanProcessor(exporter);
provider.addSpanProcessor(processor);
provider.register();
// process.on('exit', function() {
// void exporter.shutdown()
// });
src/index.ts
file
import axios from "axios";
import opentelemetry, {Span} from "@opentelemetry/api";
const tracer = opentelemetry.trace.getTracer('poc-otel-tracing');
const API_BASE_URL = 'https://jsonplaceholder.typicode.com/posts';
const func = async() => {
const rootSpan = tracer.startSpan('root-span')
await apiCall(rootSpan)
rootSpan.end()
}
const apiCall = async (parentSpan: Span) => {
const ctx = opentelemetry.trace.setSpan(opentelemetry.context.active(), parentSpan)
const childSpan = tracer.startSpan('api-call', undefined, ctx)
try {
await axios.get(API_BASE_URL);
} catch (e) {
childSpan.recordException(e);
}
childSpan.end()
}
void func()
Note that I'm using typescript, and I'm using npm run build && node --require "./otel/tracing.js" dist/index.js
to run the compiled JS and to require the otel/tracing.js script.
The console output is the following:
{
traceId: '15b261f7332feb1fdc79cff5a280529b',
parentId: undefined,
traceState: undefined,
name: 'HTTPS GET',
id: '477643c3a9536749',
kind: 2,
timestamp: 1690206903281000,
duration: 128485,
attributes: {
'http.url': 'https://jsonplaceholder.typicode.com/posts',
'http.method': 'GET',
'http.target': '/posts',
'net.peer.name': 'jsonplaceholder.typicode.com',
'http.host': 'jsonplaceholder.typicode.com:443',
'net.peer.ip': '172.64.162.6',
'net.peer.port': 443,
'http.status_code': 200,
'http.status_text': 'OK',
'http.flavor': '1.1',
'net.transport': 'ip_tcp'
},
status: { code: 0 },
events: [],
links: []
}
{
traceId: 'ba35dbc454728c2bbc5b30a435dec3bb',
parentId: 'a3897743fb82276c',
traceState: undefined,
name: 'api-call',
id: 'ec3d00cb4ad95d26',
kind: 0,
timestamp: 1690206903278000,
duration: 136158,
attributes: {},
status: { code: 0 },
events: [],
links: []
}
{
traceId: 'ba35dbc454728c2bbc5b30a435dec3bb',
parentId: undefined,
traceState: undefined,
name: 'root-span',
id: 'a3897743fb82276c',
kind: 0,
timestamp: 1690206903278000,
duration: 136633,
attributes: {},
status: { code: 0 },
events: [],
links: []
}
I don't understand why the span created for the axios http call is not correlated with the 'api-call' span (i.e. the span generated by axios should have 'api-call' as parent span) and should be part of the same trace.
Here's the output I would expect:
{
traceId: 'ba35dbc454728c2bbc5b30a435dec3bb',
parentId: 'a3897743fb82276c',
traceState: undefined,
name: 'HTTPS GET',
id: '477643c3a9536749',
kind: 2,
timestamp: 1690206903281000,
duration: 128485,
attributes: {
'http.url': 'https://jsonplaceholder.typicode.com/posts',
'http.method': 'GET',
'http.target': '/posts',
'net.peer.name': 'jsonplaceholder.typicode.com',
'http.host': 'jsonplaceholder.typicode.com:443',
'net.peer.ip': '172.64.162.6',
'net.peer.port': 443,
'http.status_code': 200,
'http.status_text': 'OK',
'http.flavor': '1.1',
'net.transport': 'ip_tcp'
},
status: { code: 0 },
events: [],
links: []
}
{
traceId: 'ba35dbc454728c2bbc5b30a435dec3bb',
parentId: 'a3897743fb82276c',
traceState: undefined,
name: 'api-call',
id: 'ec3d00cb4ad95d26',
kind: 0,
timestamp: 1690206903278000,
duration: 136158,
attributes: {},
status: { code: 0 },
events: [],
links: []
}
{
traceId: 'ba35dbc454728c2bbc5b30a435dec3bb',
parentId: undefined,
traceState: undefined,
name: 'root-span',
id: 'a3897743fb82276c',
kind: 0,
timestamp: 1690206903278000,
duration: 136633,
attributes: {},
status: { code: 0 },
events: [],
links: []
}
Could someone help me understand what I'm doing wrong? Thanks in advance!
The cause: The trace information is not propagated to the request (via axios in your case)
The fix: extract trace info from the context, and inject it to request headers
const traceHeaders = {};
// inject context to trace headers for propagtion to the next service
propagation.inject(context.active(), traceHeaders);
// pass the trace headers to your request
const config = {
headers: traceHeaders
};
await axios.get(API_BASE_URL, config);
Hope it works for you. In case you need, I have the detailed setup documented here, with a link to a complete source