Nested Child spans are not getting parented correctly

[mnadeem]

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.

[Flarna]

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).

[mnadeem]

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)

[Flarna]

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?

[mnadeem]

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

[Flarna]

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.

[mnadeem]

If I do it little differently

import opentelemetry, {context, getSpan } from '@opentelemetry/api';

[Flarna]

What about import { setSpan, getSpan } from '@opentelemetry/api';?

[mnadeem]

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]

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]

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: []
}

[Flarna]

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.

[mnadeem]

Thanks a bundle @Flarna

It is working like a charm now

[mnadeem]

@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

[Flarna]

Try context.with(api.setSpan(api.context.active(), span), doSomeWorkInNewNested2Span);.

[mnadeem]

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

[dyladan]

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.

[davehorton]

FWIW I'm a Node.js programmer of 10 years, spent an hour reading this thread and many others + docs, and still cant figure out how to do something as simple (or should be simple) as making a child span link properly to parent.

[gDaugirdas]

FWIW I'm a Node.js programmer of 10 years, spent an hour reading this thread and many others + docs, and still cant figure out how to do something as simple (or should be simple) as making a child span link properly to parent.

Any progress on this? Literally same here, some working code-snipped would help

[Flarna]

What's wrong with this sample?

[davehorton]

That is actually what I was looking for (and have basically since implemented). Most of the examples I was seeing relied on the use of context.with which due to the nature of my code I could not use. Thanks

[dyladan]

Takeaway here I guess is to add documentation to the website

[dyladan]

Opened a follow-up documentation task. Closing this as there is no bug. Please feel free to reopen or comment if you disagree.