datadog + serverless + async_hooks not working as expected

[mjmarianetti]

Expected Behavior

Using async_hooks to manage context inside a lambda function would allow the datadog layer to properly inject all logs with span_id and trace_id

Actual Behavior

Logs are injected with service and version but span_id and trace_id are missing.

Have a class that is used to wrap all operations for a given request and maintain context between each log. Our logger is winston

context.ts file
--------------  
class RequestContextResource extends AsyncResource {
  data: RequestContext;

  constructor() {
    super('RequestContextResource');
    this.data = {};
  }
}

export class ContextService {
  constructor() {
      this.resource = new RequestContextResource();
    }

  public async wrap<T>(callback: () => Promise<T>): Promise<T> {
      return new Promise<T>((resolve, reject) => {
        this.resource.runInAsyncScope(
          () => {
            callback()
              .then(result => resolve(result))
              .catch(error => reject(error))
              .finally(() => {
                // Clean up the context after the callback has completed
               this.resource.data = {};
              });
          },
          null,
          {triggerAsyncId: this.resource.asyncId},
        );
      });
    }

  public addContext(data: unknown): void {
   for (const key of Object.keys(data)) {
      if (Object.prototype.hasOwnProperty.call(data, key)) {
        this.resource.data[key] = data[key];
      }
    }
  }

  public debug(message) {
     winston.debug(message, this.resource.data);
  }

  }

lambda.ts file
--------------  
const context = new ContextService();
handler = return context.wrap((lambdaEvent) => {
  context.addContext({requestId: lambdaEvent.requestId})
  context.debug(`this is a log message`)
  context.addContext({userId: lambdaEvent.userId})
  context.debug(`this is another log message`)
});

Calling this function with lambdaEvent = {userId: "1234", requestId: "321321"} we would expect the following result

  {
    "dd": {
        "service": "service-name",
        "version": "1.0.0",
        "trace_id":"xxxxxx", ---> this is missing in the logs
        "span_id":"xxxxxx" ---> this is missing in the logs
    },
    "level": "debug",
    "message": "this is a log message",
    "requestId": "321321"
}
{
    "dd": {
        "service": "service-name",
        "version": "1.0.0",
        "trace_id":"xxxxxx", ---> this is missing in the logs
        "span_id":"xxxxxx" ---> this is missing in the logs
    },
    "level": "debug",
    "message": "this is another log message",
    "requestId": "321321",
    "userId: "1234"
}  

Steps to Reproduce the Problem

1. Wrap the lambda handler with a function that allow you to add context to your requests
2. Call the lambda handler
3. Expect to have span_id and trace_id being injected in cloudwatch log output from the lambda function.

Extra information:

• The above approach works just fine for docker containers using it with this configuration

  import tracer from 'dd-trace';
  tracer.init({
  service: 'service_name',
  logInjection: true,
  });

• This started happening when we migrated from cls_hooked to async_hooks for performance

Specifications

• Datadog Lambda Layer version: 95
• Node version: 16.x
• datadog-lambda-js: 7.97.0

• dd-trace: 4.16.0

  serverless.yml

plugins:

• serverless-plugin-datadog
• serverless-webpack
• ... webpack:
  packagerOptions: scripts:

  optional, only needed when they are included as transitive dependencies

  - rm -rf node_modules/datadog-lambda-js node_modules/dd-trace

  includeModules: forceExclude:

  • aws-sdk
  • dd-trace
  • datadog-lambda-js packager: 'npm' ... datadog: addExtension: false flushMetricsToLogs: true enableXrayTracing: false enableDDTracing: true enableTags: true forwarderArn: arn:aws:lambda:xxxxxxxxxxx

Stacktrace