Unable to intercept/send APM transactions in NestJS using elastic-apm-node package

Frank_Corona · May 9, 2023, 6:48pm

Kibana version: v8.6.2

ECS version: 1.6.0

APM Agent language and version: "elastic-apm-node": "3.44.1"

Fresh install or upgraded from other version? Fresh Install

Is there anything special in your setup? For example, are you using the Logstash or Kafka outputs? Are you using a load balancer in front of the APM Servers? Have you changed index pattern, generated custom templates, changed agent configuration etc.

I do not change my index patterns and not using any custom templates or updated agent configuration.

Description of the problem including expected versus actual behavior. Please include screenshots (if relevant):

Configured a NestJS application with the following parameters:

// src/main.ts
async function bootstrap(): Promise<any> {
  const config = new ConfigurationService();

  require('elastic-apm-node').start({
    serviceName: 'debug_serviceName',
    secretToken: config.get('ELASTIC_APM_SECRET_TOKEN'),
    serverUrl: config.get('ELASTIC_APM_SERVER_URL'),
    environment: config.get('ELASTIC_APM_ENVIRONMENT'),
    active: config.get('ELASTIC_APM_ACTIVE'),
    logLevel: 'debug',
  });

However, on initializing the application and sending some transactions through some HTTP Req in the application controller, I'm not available to see transaction details on my APM server. Looking into some traces, I can say that my APM agent is already connected to the APM server due to I can see the Kubernetes pod inside the instances related to my agent service.

Also, going in deep with the traces, I configure another service from scratch using NestJS and got this trace information during the initiation procedure of the agent:

{"log.level":"debug","@timestamp":"2023-05-09T15:18:22.742Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"adding hook to Node.js module loader"}
{"log.level":"debug","@timestamp":"2023-05-09T15:18:22.743Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"instrumenting fetch"}
{"log.level":"debug","@timestamp":"2023-05-09T15:18:22.797Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming finalhandler@1.2.0 module"}
{"log.level":"debug","@timestamp":"2023-05-09T15:18:22.815Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming http@18.15.0 module"}
{"log.level":"debug","@timestamp":"2023-05-09T15:18:22.819Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming http.Server.prototype.emit function"}
{"log.level":"debug","@timestamp":"2023-05-09T15:18:22.819Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming http.ServerResponse.prototype.writeHead function"}
{"log.level":"debug","@timestamp":"2023-05-09T15:18:22.819Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming http.request function"}
{"log.level":"debug","@timestamp":"2023-05-09T15:18:22.819Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming http.get function"}
{"log.level":"debug","@timestamp":"2023-05-09T15:18:22.923Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming express@4.18.2 module"}
{"log.level":"debug","@timestamp":"2023-05-09T15:18:22.925Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming express.Router.use function"}
{"log.level":"debug","@timestamp":"2023-05-09T15:18:22.925Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming express.static function"}
{"log.level":"debug","@timestamp":"2023-05-09T15:18:22.926Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"copying property mime from express.static"}
{"log.level":"debug","@timestamp":"2023-05-09T15:18:22.926Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming https@18.15.0 module"}
{"log.level":"debug","@timestamp":"2023-05-09T15:18:22.927Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming https.Server.prototype.emit function"}
{"log.level":"debug","@timestamp":"2023-05-09T15:18:22.927Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming https.request function"}
{"log.level":"debug","@timestamp":"2023-05-09T15:18:22.927Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming https.get function"}

Along with that, from this scratch service, I can send and see all transactions using the same agent configuration from my main service (Where I have the issue).

Based on this I compare traces between both services on the agent initiation stage and my main service looks like this:

yarn run v1.22.19
$ export NODE_ENV=development && export NODE_TLS_REJECT_UNAUTHORIZED=0 && nodemon
[nodemon] 2.0.22
[nodemon] to restart at any time, enter `rs`
[nodemon] watching path(s): src/**/*
[nodemon] watching extensions: ts
[nodemon] starting `ts-node -r tsconfig-paths/register src/main.ts`
{"log.level":"debug","@timestamp":"2023-05-09T18:08:12.360Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"adding hook to Node.js module loader"}
{"log.level":"debug","@timestamp":"2023-05-09T18:08:12.361Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"instrumenting fetch"}
(node:74913) Warning: Setting the NODE_TLS_REJECT_UNAUTHORIZED environment variable to '0' makes TLS connections and HTTPS requests insecure by disabling certificate verification.
(Use `node --trace-warnings ...` to show where the warning was created)
[Nest] 74913  - 05/09/2023, 3:08:12 PM     LOG [NestFactory] Starting Nest application...
[Nest] 74913  - 05/09/2023, 3:08:12 PM     LOG [InstanceLoader] MongooseModule dependencies initialized +47ms
[Nest] 74913  - 05/09/2023, 3:08:12 PM     LOG [InstanceLoader] ConfigurationModule dependencies initialized +1ms
[Nest] 74913  - 05/09/2023, 3:08:12 PM     LOG [InstanceLoader] PassportModule dependencies initialized +0ms
[Nest] 74913  - 05/09/2023, 3:08:12 PM     LOG [InstanceLoader] HttpModule dependencies initialized +1ms
[Nest] 74913  - 05/09/2023, 3:08:12 PM     LOG [InstanceLoader] CacheModule dependencies initialized +0ms
[Nest] 74913  - 05/09/2023, 3:08:12 PM     LOG [InstanceLoader] DiscoveryModule dependencies initialized +23ms
[Nest] 74913  - 05/09/2023, 3:08:12 PM    WARN [BulkChargeHandler] Register handler
[Nest] 74913  - 05/09/2023, 3:08:12 PM     LOG [BulkChargeHandler] Using topic: bulkCharge
[Nest] 74913  - 05/09/2023, 3:08:12 PM    WARN [DownloadCSVHandler] Register handler
[Nest] 74913  - 05/09/2023, 3:08:12 PM     LOG [DownloadCSVHandler] Using topic: downloadCSV
[Nest] 74913  - 05/09/2023, 3:08:12 PM     LOG [InstanceLoader] AuthModule dependencies initialized +2ms
[Nest] 74913  - 05/09/2023, 3:08:12 PM     LOG [InstanceLoader] EventEmitterModule dependencies initialized +1ms
[Nest] 74913  - 05/09/2023, 3:08:12 PM     LOG [InstanceLoader] ScheduleModule dependencies initialized +0ms
[Nest] 74913  - 05/09/2023, 3:08:12 PM     LOG [InstanceLoader] SentEventModule dependencies initialized +1ms
{"log.level":"debug","@timestamp":"2023-05-09T18:08:12.456Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"no cloud metadata servers responded"}
{"log.level":"debug","@timestamp":"2023-05-09T18:08:12.978Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","apmServerVersion":"8.6.2","ecs":{"version":"1.6.0"},"message":"fetched APM Server version"}
{"log.level":"debug","@timestamp":"2023-05-09T18:08:12.986Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"no active transaction found - cannot build new span"}
{"log.level":"debug","@timestamp":"2023-05-09T18:08:12.992Z","log":{"logger":"elastic-apm-node"},"remoteConf":{},"ecs":{"version":"1.6.0"},"message":"central config received"}
[Nest] 74913  - 05/09/2023, 3:08:13 PM     LOG [DownloadCSVHandler] Using subscription: downloadCSVSubscription
[Nest] 74913  - 05/09/2023, 3:08:13 PM    WARN [DownloadCSVHandler] Waiting for messages...

Based on both outputs I can identify that I've some differences, for example, in the service with the issue I'm not seeing anyone trace related to initializing the HTTP module and maybe this is the root cause of not being able to intercept HTTP req and send a new transaction to my APM server.

Packages versions
Affected services are currently running with these packages.

"dependencies": {
    "@google-cloud/precise-date": "3.0.1",
    "@google-cloud/pubsub": "3.4.1",
    "@google-cloud/storage": "6.9.5",
    "@nestjs/axios": "2.0.0",
    "@nestjs/cache-manager": "1.0.0",
    "@nestjs/common": "9.4.0",
    "@nestjs/core": "9.4.0",
    "@nestjs/event-emitter": "1.4.1",
    "@nestjs/microservices": "7.6.18",
    "@nestjs/mongoose": "9.2.2",
    "@nestjs/passport": "9.0.3",
    "@nestjs/platform-express": "9.4.0",
    "@nestjs/schedule": "2.2.1",
    "@nestjs/swagger": "6.3.0",
    "@samsystem/logger": "1.3.2",
    "@types/multer": "1.4.7",
    "@types/nunjucks": "3.2.2",
    "async-csv": "2.1.3",
    "axios": "1.4.0",
    "base-64": "1.0.0",
    "cache-manager": "5.2.1",
    "class-transformer": "0.5.1",
    "class-validator": "0.14.0",
    "csv-writer": "1.6.0",
    "dotenv": "16.0.3",
    "elastic-apm-node": "3.44.1",
    "handlebars": "4.7.7",
    "joi": "17.9.2",
    "jwks-rsa": "3.0.1",
    "jwt-decode": "3.1.2",
    "moment": "2.29.4",
    "moment-timezone": "0.5.43",
    "mongoose": "7.1.0",
    "mongoose-delete": "0.5.4",
    "multer": "1.4.5-lts.1",
    "nunjucks": "3.2.4",
    "passport": "0.6.0",
    "passport-jwt": "4.0.1",
    "pdf-merger-js": "^4.3.0",
    "puppeteer": "19.8.5",
    "ramda": "0.29.0",
    "reflect-metadata": "0.1.13",
    "rxjs": "7.8.1",
    "swagger-ui-express": "4.6.3",
    "typescript": "5.0.4",
    "uuid": "9.0.0",
    "xml2js": "0.5.0"
  },

Looks like some configurations are currently preventing my main (affected) service agent intercept the HTTP req and send it to APM server.

Here it's my main initiation file:

import { NestFactory } from '@nestjs/core';
import { ValidationPipe } from '@nestjs/common';

import { AppModule } from './app.module';
import { ConfigurationService } from './configuration/services/configuration.service';
import { setupPaymentSwagger } from './swagger/swagger';
import { AllExceptionsFilter } from './modules/common/filters/allExceptions.filter';
import { GCloudPubSubServer } from './modules/microservice/gcloud-pub-sub.server';

async function bootstrap(): Promise<any> {
  const config = new ConfigurationService();

  // Add this to the VERY top of the first file loaded in your app
  require('elastic-apm-node').start({
    // https://www.elastic.co/guide/en/apm/agent/nodejs/master/configuration.html#configuration
    serviceName: 'debug_payment_service',
    secretToken: config.get('ELASTIC_APM_SECRET_TOKEN'),
    serverUrl: config.get('ELASTIC_APM_SERVER_URL'),
    environment: config.get('ELASTIC_APM_ENVIRONMENT'),
    active: config.get('ELASTIC_APM_ACTIVE'),
    logLevel: 'debug',
  });

  const app = await NestFactory.create(AppModule, {
    cors: true,
  });

  // App blobal definitions.
  const apiPrefix = config.get('API_PREFIX');
  app.useGlobalPipes(new ValidationPipe());
  app.setGlobalPrefix(apiPrefix);

  // Setup Swagger for all modules.
  const docsPrefix = config.get('DOCS_PREFIX');
  setupPaymentSwagger(app, apiPrefix, docsPrefix);

  // Setup for keep listening for PuSub messages
  const GCloudPubSubServerOptions = {
    authOptions: {
      projectId: config.get('GCP_PROJECT'),
      keyFilename: config.get('GOOGLE_APPLICATION_CREDENTIALS'),
    },
    subscriptionIds: [
    ],
    subscriberOptions: {
      ackDeadline: 30,
    },
  };

  app.connectMicroservice({
    strategy: new GCloudPubSubServer(GCloudPubSubServerOptions),
  });
  await app.startAllMicroservices();

  app.useGlobalFilters(new AllExceptionsFilter(config));

  // Start the app
  await app.listen(config.get('PORT'));
}

bootstrap();

trentm · May 9, 2023, 10:14pm

Hi @Frank_Corona. Thanks for the question.

From that configuration file, my guess is that the elastic-apm-node agent will be started too late. By the time bootstrap() calls require('elastic-apm-node').start() all of the above import ...s will already have run -- including, I'm guessing, importing the http module. That often (but not always) means that elastic-apm-node will not be able to instrument the http (and other modules) before your application code gets a handle on an uninstrumented version. When your application later uses the http module, it will possibly be using the uninstrumented version.

Is the main initiation file / startup code for your "scratch service" different?

Starting the agent | APM Node.js Agent Reference [4.x] | Elastic describes one way you could try to avoid this issue, and ensure that the APM agent is started before your other imports execute. That documentation page describes the various ways you can start the APM agent and also has some sections describing some common surprises.

Frank_Corona · May 10, 2023, 12:55pm

Hi @trentm thanks for the quick answer.

Sure I'll check your proposal for changes and documentation.
However, answering your question related to my "scratch" service about the initialization file looks like this:

import { NestFactory } from '@nestjs/core';
import * as apm from 'elastic-apm-node';
import { AppModule } from './app.module';

async function bootstrap() {
  apm.start({
    serviceName: 'serviceName',
    serverUrl: 'serverUrl',
    secretToken: 'secretToken',
    environment: 'envName',
    active: true,
    logLevel: 'debug',
  });

  const app = await NestFactory.create(AppModule);
  await app.listen(3003);
}
bootstrap();

This is the service where I do not have any issues and transactions are sent to the APM server without issues.

Frank_Corona · May 10, 2023, 5:06pm

Hi, @trentm based on your suggestions move the initialization of the APM agent to a separate module and imported it at the beginning of my NestJS application, and now works as expected. My outstanding was that we were loading a previous module that prevented the correct initialization of the APM agent.

Thanks for your support

trentm · May 10, 2023, 6:21pm

Great. Glad to hear you got it working.

system · May 31, 2023, 2:22pm

This topic was automatically closed 20 days after the last reply. New replies are no longer allowed.