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();