Opentelemetry-js: Nested Child spans are not getting parented correctly
Please answer these questions before submitting a bug report.
What version of OpenTelemetry are you using? 0.15.0
What version of Node are you using? v14.15.5
Please provide the code you used to setup the OpenTelemetry SDK : https://github.com/mnadeem/nodejs-opentelemetry-tempo
What did you do? Created Child Spans
const doSomeWorkInNewNestedSpan = (parentSpan) => {
const childSpan = tracer.startSpan('doSomeWorkInNewNestedSpan', {
parentSpan, attributes: { 'code.function' : 'doSomeWorkInNewNestedSpan' }
});
childSpan.setAttribute('code.filepath', "test2");
//Do some work
doSomeHeavyWork();
childSpan.end();
}
If possible, provide a recipe for reproducing the error.: Follow the guidelines in https://github.com/mnadeem/nodejs-opentelemetry-tempo
What did you expect to see? Nested Child spans should be parented correctly
Something like this nested and stair cased (from https://github.com/mnadeem/boot-opentelemetry-tempo)
What did you see instead? Nested child spans are not parented correctly
Additional context
Add any other context about the problem here.
mnadeem
All 16 comments
Using parent option in tracer.startSpan has been removed via #1612 because it was removed from the spec.
It's needed to use context for this. Either passing it manual like here or using context.with() as shown here.
There might come helpers to ease this (see #1923).
Flarna
on 18 Feb 2021
I am getting TypeError: _api.default.setSpan is not a function any help would be greatly appreciated
1
2
import opentelemetry, {context, getSpan } from '@opentelemetry/api';
````
const childSpan = tracer.startSpan('doSomeWorkInNewSpan', {
attributes: { 'code.function' : 'doSomeWorkInNewSpan' }
});
opentelemetry.context.with(opentelemetry.setSpan(opentelemetry.context.active(), childSpan), () => {
console.log('Client traceId ', span.context().traceId);
});
````
TypeError: _api.default.setSpan is not a function
at doSomeWorkInNewSpan (E:\githubRepos\nodejs-opentelemetry-tempo\src\/server.js:44:46)
at E:\githubRepos\nodejs-opentelemetry-tempo\src\/server.js:33:5
at Layer.handle [as handle_request] (E:\githubRepos\nodejs-opentelemetry-tempo\node_modules\express\lib\router\layer.js:95:5)
at next (E:\githubRepos\nodejs-opentelemetry-tempo\node_modules\express\lib\router\route.js:137:13)
at Route.dispatch (E:\githubRepos\nodejs-opentelemetry-tempo\node_modules\express\lib\router\route.js:112:3)
at E:\githubRepos\nodejs-opentelemetry-tempo\node_modules\@opentelemetry\plugin-express\build\src\express.js:182:41
at Layer.handle [as handle_request] (E:\githubRepos\nodejs-opentelemetry-tempo\node_modules\express\lib\router\layer.js:95:5)
at E:\githubRepos\nodejs-opentelemetry-tempo\node_modules\express\lib\router\index.js:281:22
at Function.process_params (E:\githubRepos\nodejs-opentelemetry-tempo\node_modules\express\lib\router\index.js:335:12)
at next (E:\githubRepos\nodejs-opentelemetry-tempo\node_modules\express\lib\router\index.js:275:10)
mnadeem
on 18 Feb 2021
Seems something is wrong with our imports here. Looks like you use import but not typescript. I assume some other transpiler is used here.
can you reproduce this by using plain JavaScript or Typescript?
Flarna
on 18 Feb 2021
I am using Babel https://github.com/mnadeem/nodejs-opentelemetry-tempo/blob/main/package.json
I don't have project setup for typescript, further I would have to learn Typescript
mnadeem
on 18 Feb 2021
I never used babel so can't help here. But I think instead _api.default.setSpan it should be _api.setSpan so it's related to import and this is where babel does some magic in your sample.
Flarna
on 18 Feb 2021
If I do it little differently
import opentelemetry, {context, getSpan } from '@opentelemetry/api';
mnadeem
on 18 Feb 2021
What about import { setSpan, getSpan } from '@opentelemetry/api';?
Flarna
on 18 Feb 2021
const opentelemetry = require('@opentelemetry/api');
const {context, getSpan } = opentelemetry;
````
app.get('/health', (req, res) => {
const parentSpan = getSpan(opentelemetry.context.active());
doSomeHeavyWork();
doSomeWorkInNewSpan(parentSpan);
return res.status(200).send({ message: "Health is good" });
});
const doSomeWorkInNewSpan = (parentSpan) => {
const ctx = opentelemetry.setSpan(opentelemetry.context.active(), parentSpan);
const childSpan = tracer.startSpan('doWork', undefined, ctx);
childSpan.setAttribute('code.filepath', "test");
doSomeHeavyWork();
doSomeWorkInNewNestedSpan(childSpan);
childSpan.end();
}
````
I am not getting exception now, however nested span is not working now as well.
Note: the version is 0.15.0
mnadeem
on 18 Feb 2021
Following does not give any error, however same result as above
```
import { context, setSpan, getSpan } from '@opentelemetry/api';
````
````
app.get('/health', (req, res) => {
const parentSpan = getSpan(context.active());
doSomeHeavyWork();
doSomeWorkInNewSpan(parentSpan);
return res.status(200).send({ message: "Health is good" });
});
const doSomeWorkInNewSpan = (parentSpan) => {
const ctx = setSpan(context.active(), parentSpan);
const childSpan = tracer.startSpan('doWork', undefined, ctx);
childSpan.setAttribute('code.filepath', "test");
doSomeHeavyWork();
doSomeWorkInNewNestedSpan(childSpan);
childSpan.end();
}
````
mnadeem
on 18 Feb 2021
Here is the output of consoleexporter
{
traceId: 'be4f519b1f0075825e9427ff2b98d2d4',
parentId: '13bed0fa605b94f1',
name: 'middleware - query',
id: 'f74fcf045a928b0c',
kind: 0,
timestamp: 1613645844985924,
duration: 312,
attributes: {
component: 'express',
'express.name': 'query',
'express.type': 'middleware'
},
status: { code: 1 },
events: []
}
{
traceId: 'be4f519b1f0075825e9427ff2b98d2d4',
parentId: '13bed0fa605b94f1',
name: 'middleware - expressInit',
id: '75eb87b09dd84165',
kind: 0,
timestamp: 1613645844991599,
duration: 303,
attributes: {
component: 'express',
'express.name': 'expressInit',
'express.type': 'middleware'
},
status: { code: 1 },
events: []
}
{
traceId: 'be4f519b1f0075825e9427ff2b98d2d4',
parentId: '13bed0fa605b94f1',
name: 'middleware - <anonymous>',
id: '67b78f1fe81d7024',
kind: 0,
timestamp: 1613645844994591,
duration: 206,
attributes: {
component: 'express',
'express.name': '<anonymous>',
'express.type': 'middleware'
},
status: { code: 1 },
events: []
}
{
traceId: 'be4f519b1f0075825e9427ff2b98d2d4',
parentId: '13bed0fa605b94f1',
name: 'middleware - jsonParser',
id: '336f1d7900ccbfb7',
kind: 0,
timestamp: 1613645844997762,
duration: 222,
attributes: {
component: 'express',
'express.name': 'jsonParser',
'express.type': 'middleware'
},
status: { code: 1 },
events: []
}
{
traceId: 'be4f519b1f0075825e9427ff2b98d2d4',
parentId: '13bed0fa605b94f1',
name: 'middleware - corsMiddleware',
id: 'dd3071dd37a2f3d4',
kind: 0,
timestamp: 1613645845001133,
duration: 490,
attributes: {
component: 'express',
'express.name': 'corsMiddleware',
'express.type': 'middleware'
},
status: { code: 1 },
events: []
}
{
traceId: 'be4f519b1f0075825e9427ff2b98d2d4',
parentId: '13bed0fa605b94f1',
name: 'middleware - addCorsHeaders',
id: '0abaa3c0fdc3bb81',
kind: 0,
timestamp: 1613645845004420,
duration: 153,
attributes: {
component: 'express',
'express.name': 'addCorsHeaders',
'express.type': 'middleware'
},
status: { code: 1 },
events: []
}
{
traceId: 'be4f519b1f0075825e9427ff2b98d2d4',
parentId: '13bed0fa605b94f1',
name: 'middleware - addTraceId',
id: '21fdc5ad584db508',
kind: 0,
timestamp: 1613645845006335,
duration: 80,
attributes: {
component: 'express',
'express.name': 'addTraceId',
'express.type': 'middleware'
},
status: { code: 1 },
events: []
}
{
traceId: 'be4f519b1f0075825e9427ff2b98d2d4',
parentId: '13bed0fa605b94f1',
name: 'middleware - measureRequestDuration',
id: 'c9b8a360ed6028f9',
kind: 0,
timestamp: 1613645845009802,
duration: 86,
attributes: {
component: 'express',
'express.name': 'measureRequestDuration',
'express.type': 'middleware'
},
status: { code: 1 },
events: []
}
{
traceId: 'be4f519b1f0075825e9427ff2b98d2d4',
parentId: '13bed0fa605b94f1',
name: 'request handler - /health',
id: '20cdf60888bf948a',
kind: 0,
timestamp: 1613645845012158,
duration: 16,
attributes: {
component: 'express',
'http.route': '/health',
'express.name': '/health',
'express.type': 'request_handler'
},
status: { code: 1 },
events: []
}
{
traceId: 'be4f519b1f0075825e9427ff2b98d2d4',
parentId: '13bed0fa605b94f1',
name: 'doSomeWorkInNewNestedSpan',
id: 'f6c5672875accd06',
kind: 0,
timestamp: 1613645845015718,
duration: 213,
attributes: {
'code.function': 'doSomeWorkInNewNestedSpan',
'code.filepath': 'test2'
},
status: { code: 1 },
events: []
}
{
traceId: 'be4f519b1f0075825e9427ff2b98d2d4',
parentId: '13bed0fa605b94f1',
name: 'doWork',
id: '6966619959f1ca61',
kind: 0,
timestamp: 1613645845015104,
duration: 3764,
attributes: { 'code.filepath': 'test' },
status: { code: 1 },
events: []
}
{
traceId: 'afbfcb316fd995d365ed894b0b7e0202',
parentId: undefined,
name: 'HTTP GET',
id: '1e8ffac029ab260c',
kind: 1,
timestamp: 1613645844983562,
duration: 39472,
attributes: {
'http.url': 'http://localhost:5555/health',
'http.host': 'localhost:5555',
'net.host.name': 'localhost',
'http.method': 'GET',
'http.route': '/health',
'http.target': '/health',
'http.user_agent': 'Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/88.0.4324.182 Safari/537.36',
'http.flavor': '1.1',
'net.transport': 'IP.TCP',
'net.host.ip': '::1',
'net.host.port': 5555,
'net.peer.ip': '::1',
'net.peer.port': 55604,
'http.status_code': 304,
'http.status_text': 'NOT MODIFIED'
},
status: { code: 0 },
events: []
}
{
traceId: 'be4f519b1f0075825e9427ff2b98d2d4',
parentId: undefined,
name: 'GET /health',
id: '13bed0fa605b94f1',
kind: 1,
timestamp: 1613645844984685,
duration: 44070,
attributes: {
'http.url': 'http://localhost:5555/health',
'http.host': 'localhost:5555',
'net.host.name': 'localhost',
'http.method': 'GET',
'http.route': '/health',
'http.target': '/health',
'http.user_agent': 'Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/88.0.4324.182 Safari/537.36',
'http.flavor': '1.1',
'net.transport': 'IP.TCP',
'net.host.ip': '::1',
'net.host.port': 5555,
'net.peer.ip': '::1',
'net.peer.port': 55604,
'http.status_code': 304,
'http.status_text': 'NOT MODIFIED'
},
status: { code: 0 },
events: []
}
mnadeem
on 18 Feb 2021
in your last sample the implementation of doSomeWorkInNewNestedSpan is missing. If it is still implemented as in the initial post it can't work as you don't pass the child span via context nor is it set active.
Flarna
on 18 Feb 2021
Thanks a bundle @Flarna
It is working like a charm now
mnadeem
on 18 Feb 2021
@Flarna
Any help on Approach # 2 , utilizing context.with
doSomeWorkInNewNestedSpan should be parent of doSomeWorkInNewNested2Span
````
const doSomeWorkInNewNestedSpan = (parentSpan) => {
const ctx = setSpan(context.active(), parentSpan);
const childSpan = tracer.startSpan('doSomeWorkInNewNestedSpan', {
parentSpan, attributes: { 'code.function' : 'doSomeWorkInNewNestedSpan' }
}, ctx);
childSpan.setAttribute('code.filepath', "test2");
//Do some work
doSomeHeavyWork();
doSomeWorkInNewNested2Span(childSpan);
childSpan.end();
}
const doSomeWorkInNewNested2Span = (parentSpan) => {
const childSpan = tracer.startSpan('doSomeWorkInNewNested2Span');
context.with(setSpan(context.active(), childSpan), () => {
logger.info('Client traceId %s:%s', childSpan.context().traceId, childSpan.context().spanId);
childSpan.end();
});
}
````
That is not the care write now
mnadeem
on 18 Feb 2021
Try context.with(api.setSpan(api.context.active(), span), doSomeWorkInNewNested2Span);.
Flarna
on 18 Feb 2021
Thanks a bundle @Flarna
Working like a charm now.
https://github.com/mnadeem/nodejs-opentelemetry-tempo This would be helpful for folks understanding Opentelemetry and using BabelJs and Grafana Tempo
mnadeem
on 18 Feb 2021
We are discussing/working on a convenience API for this that will make this api.withSpan(span, doSomeWorkInNewNested2Span) which should make this less confusing for new users.
I am also working on a new documentation which should simplify these common use cases.
dyladan
on 1 Mar 2021
Related issues
naseemkullah
路
5Comments
blumamir
路
4Comments
legendecas
路
3Comments
BowlingX
路
6Comments
obecny
路
6Comments