Express tracing does not add error tags to the service entry span

[avaly]

Describe the bug

I am trying out the Error Tracking feature and am running into some unexpected results.

It seems that the dd-trace library is not correctly marking the service entry span in an express request with an error which happens deeper in the route stack.

Reproducible with the following code:

/* eslint-disable */
const { tracer } = require('dd-trace');

tracer.init({
  env: 'local',
  service: 'express-local',
  version: 'local'
});

const http = require('http');
const express = require('express');

const app = express();

app.get('/', () => {
  throw new Error('Test Error');
});

http.createServer(app).listen(8000);

When inspecting the trace we see the error attached correctly to the deeper route span:

But when we look at the top level span:

And since the documentation clearly states that:

Error spans within a trace are processed by Error Tracking when they are located in the uppermost service span, which is also called the service entry span. The span must also contain the error.stack, error.msg, and error.type span tags in order to be tracked.

And because this service entry span is missing those error tags, we don't see the error in the Error Tracking UI:

HACKY Workaround

While searching for this issue, I stumbled upon #725.

It seems we could access the service entry span from an express error handler:

app.use((err, _req, res, _next) => {
  const span = tracer.scope().active();
  if (span) {
    const parent = span.context()._trace.started[0];
    if (parent) {
      parent.addTags({
        'error.msg': err.message,
        'error.stack': err.stack,
        'error.type': err.name,
      })
    }
  }
  res.status(500).send();
});

Needless to say, this is sub-optimal, since it's using private APIs, which could be removed in future versions.

This feature should be supported by the dd-trace library as a native feature.

Environment

• Operation system: Ubuntu
• Node version: 14.19.1
• Tracer version: 2.3.1
• Agent version: 7.34.0

[rochdev]

The main issue in a case like this is that the error is handled by a middleware. An exception would only reach the request if it's not handled at all. For example, in your above code the error is handled by the middleware and then res.status(500).send() is called manually. From the request span perspective, the request is an error because of the status code, but it doesn't know about the error object from the middleware. We could add an API to set the error on the request manually, but I don't think it's something we can do automatically.

[vanstinator]

We could add an API to set the error on the request manually, but I don't think it's something we can do automatically.

This would be a really great solution.

[avaly]

Even other tools (e.g. Sentry) offer specific express handlers for catching errors in the stack. The new API could look something like that.

[clement-heliot]

I am having the issue too. This is quite a blocker, the Error Tracking feature of DataDog is broken and unusable as-is because of this.

[rochdev]

The workaround above could be improved by using a span hook in combination to remove the need for any private API.

For example:

// at the top of the app entry point right after trace.init() is called
tracer.use('express', {
  hooks: {
    request (span, res, req) {
      if (res.error) {
        span.setTag('error', res.error);
      }
    }
  }
});

// middleware added after all other middleware
app.use((err, req, res, next) => {
  res.error = err;
  res.status(500).send();
});

While we could definitely support this better, I think this solution is good enough since it only requires adding a small middleware and a span hook to the application. We're also looking at changing our defaults to potentially automatically bubble up middleware errors depending on the status code.

[zkropotkine]

Having the same issue. However, I'm using typescript so I can't access _trace to do the following:

span.context()._trace.started[0].setTag('error', true)

And we are using hapi, which doesn't seem to work with hooks

      // at the top of the entry point right after tracer.init()
      tracer.use('hapi', {
        // hook will be executed right before the request span is finished
        hooks: {
          request: (span, req, res) => {
            console.log("PRINT THIS: =================")
          }
        }
      })

Any help will be appreciated

[zkropotkine]

I couldn't make the hook to work, not sure if it is because we are creating our Hapi server using glue.

However, I was able to access to the private api by doing the following on typescript:

const spanContext = span.context() as any
...
...
spanContext._trace.started[0].setTag('error', true)

[jrnail23]

@rochdev I have to ask... how is this actually intended to work with the express plugin (or in my case, the Koa plugin)?
If you don't handle the error at all and just let it bubble all the way up, all it does is set error: true on the entry span, and the error doesn't get to Error Tracking.

Is it because Koa (and presumably Express) have built-in default error handlers?

I just don't see a way to follow the docs and get this working out of the box without additional hacking around.
My company is pretty much going "all-in" on DataDog in search of the ever-elusive "single pane of glass", but this is the one thing that's holding us back, keeping us tied to Sentry, until we can adequately replace it.

[rochdev]

@jrnail23 We're actually revisiting this right now. There are basically tradeoffs either way, because if an error that we intercepted is later handled, it could result in false positives, but with the current approach we end up missing errors instead. We will be working on a fix as soon as we have settled on an approach that will work for all Web frameworks.

[vitkarpov]

@rochdev could you give some estimates? It'd be great if I could set up a reminder for myself.

[rochdev]

@vitkarpov For now we've decided to simply keep the last seen error if the status code is 5xx to avoid any breaking change. This also makes the change more trivial. We'll try to include it in 3.0 if possible, but otherwise we should be able to land it in 3.1. So this means this month, and possibly next week if 3.0.

[NimrodHunter]

Still not working, The error do not appear in Error Tracking

[akirillo]

I'm still experiencing this issue as well, though I'm using NextJS. Still, though, error.stack, error.msg, and error.type tags are not being applied to the span. All I'm seeing is error: true, and as such no errors are showing in the Error Tracking UI. The workaround mentioned above (using a hook to inject res.error) doesn't work because there's no error field on the res object, and I'm not sure of the best way to propagate the error through to the hook...

[rochdev]

@akirillo Is there an actual error being thrown to the middleware with either throw or next(err) or is the error handled? When there is no actual error object for the tracer to grab it will set the flag to true based on the status code since it doesn't have more information to attach on the span.

[akirillo]

i have test endpoint that looks like:

export default function handler(_req: NextApiRequest, _res: NextApiResponse) {
  throw new Error(
    '[DEBUG] This is an error used to debug the DataDog integration'
  );
}

[rochdev]

@akirillo What version of dd-trace are you using? Also, can you share a reproduction snippet?

[benwainwright]

I couldn't make the hook to work, not sure if it is because we are creating our Hapi server using glue.

However, I was able to access to the private api by doing the following on typescript:

const spanContext = span.context() as any
...
...
spanContext._trace.started[0].setTag('error', true)

If you must use a type assertion, probably sensible to use something narrower than any. Here's my version of what you did there using a custom type guard rather than an assertion:

import tracer, { Span, SpanContext } from 'dd-trace';

tracer.init();

interface ContextWithStartedExposed extends SpanContext {
  _trace: {
    started: Span[];
  };
}

const assertsHasUnderscoreTrace: (
  context: SpanContext
) => asserts context is ContextWithStartedExposed = (context) => {
  // eslint-disable-next-line @typescript-eslint/no-explicit-any
  const contextAny = context as any;

  const errorMessage =
    'Tried to set span on service entry tag using undocumented API that appears to no longer exist';

  if (!contextAny._trace) {
    throw new Error(errorMessage);
  }

  if (!contextAny._trace.started) {
    throw new Error(errorMessage);
  }
};

// ... more code

export const doSomethingWithError = (error: Error) => {
  const context = tracer.scope().active()?.context();

  if (context) {
    assertsHasUnderscoreTrace(context);

    const serviceEntrySpan = context._trace.started[0];
    serviceEntry.setTag(...);
  }
};

[billoneil]

We currently use NestJS and also have the issue where all errors just show error: true with no context and do not appear in error tracking since the message and stack trace are missing. NestJS handles errors before the express layer so the error context is always undefined.

Here is a work around we found that should work with any framework as long as you can get access to the express request. It re-uses the dd-trace/src/plugins/util/web.js addError to forcibly set the error context within our framework's (NestJS) error handling.

src/all-exceptions.filter.ts

import { Catch, ArgumentsHost } from "@nestjs/common";
import { BaseExceptionFilter } from "@nestjs/core";
import { addError } from "dd-trace/packages/dd-trace/src/plugins/util/web";

@Catch()
export class AllExceptionsFilter extends BaseExceptionFilter {
    catch(exception: unknown, host: ArgumentsHost) {
        // Without this guard any rpc, ws, or graphql calls can fail
        if (host.getType() === "http") {
            const ctx = host.switchToHttp();
            addError(ctx.getRequest(), exception);
            super.catch(exception, host);
        } else if (host.getType<GqlContextType>() === "graphql") {
            // This is a little dirty but req is not easily exposed anywhere currently
            // https://stackoverflow.com/questions/73123824/change-graphql-context-to-http-context
            // https://github.com/nestjs/docs.nestjs.com/issues/2143
            const gqlHost = GqlArgumentsHost.create(host);
            const ctx = gqlHost.getContext();
            addError(ctx.req, exception);
            // DO NOT HANDLE ERROR - gql handles errors in its own way
        }
    }
}

EDIT: I cannot get the graphql part to work it never has the express reqest context it just has the node IncomingMessage

When configuring the nest app

const { httpAdapter } = app.get(HttpAdapterHost);
app.useGlobalFilters(new AllExceptionsFilter(httpAdapter));

Had to add types to be able to import in TS

src/dd-trace.d.ts

declare module "dd-trace/packages/dd-trace/src/plugins/util/web" {
    export const addError: (req: unknown, error: unknown) => void;
}