apm-agent-nodejs Data ingestion not working with apm-agent-nodejs v3.29.0

Describe the bug Data ingestion from APM agent not working on express application when using the latest release of the agent module for Node.

To Reproduce Steps to reproduce the behavior:

ELK Configuration (docker) elasticsearch: v7.10.0 kibana: v7.10.0 apm-server: v7.10.0
Node Application Configarution node: v14.17 express: v4.17.2 typescript: v4.5.5 apm-agent-nodejs: v3.29.0
Usage

import apm from 'elastic-apm-node';
import ...

// configures apm agent
apm.start({
  serviceName: process.env.ELASTIC_SERVICE_NAME,
  secretToken: process.env.ELASTIC_SECRET_TOKEN,
  serverUrl: process.env.ELASTIC_SERVER_URL,
  transactionSampleRate: Number(process.env.ELASTIC_TRANSACTION_SAMPLE_RATE),
  environment: process.env.ELASTIC_ENVIRONMENT,
  verifyServerCert: process.env.ELASTIC_VERIFY_SERVER_CERT === 'true',
  serverTimeout: process.env.ELASTIC_SERVER_TIMEOUT,
  serviceVersion: process.env.ELASTIC_SERVICE_VERSION,
});

// creates express app
const app = express();
...

Expected behavior Be able to access in the UI the application as a registered service and view its transactions, error logs and general health metrics.

Debug logs

Click to expand

{"log.level":"trace","@timestamp":"2022-02-15T18:06:24.076Z","log":{"logger":"elastic-apm-node"},"pid":2854230,"ppid":2854229,"arch":"x64","platform":"linux","node":"v14.17.6","agent":"3.29.0","startTrace":["at Agent.start (/home/david_archanjo/node_projects/petclinic/node_modules/elastic-apm-node/lib/agent.js:233:11)","at Object.<anonymous> (/home/david_archanjo/node_projects/petclinic/src/main/node/petclinic.application.ts:32:5)","at Module._compile (internal/modules/cjs/loader.js:1072:14)","at Module.m._compile (/home/david_archanjo/node_projects/petclinic/node_modules/ts-node/src/index.ts:530:23)","at Module._extensions..js (internal/modules/cjs/loader.js:1101:10)","at Object.require.extensions.<computed> [as .ts] (/home/david_archanjo/node_projects/petclinic/node_modules/ts-node/src/index.ts:533:12)","at Module.load (internal/modules/cjs/loader.js:937:32)","at Function.Module._load (internal/modules/cjs/loader.js:778:12)","at Function.executeUserEntryPoint [as runMain] (internal/modules/run_main.js:76:12)","at main (/home/david_archanjo/node_projects/petclinic/node_modules/ts-node/src/bin.ts:212:14)","at Object.<anonymous> (/home/david_archanjo/node_projects/petclinic/node_modules/ts-node/src/bin.ts:470:3)","at Module._compile (internal/modules/cjs/loader.js:1072:14)","at Object.Module._extensions..js (internal/modules/cjs/loader.js:1101:10)","at Module.load (internal/modules/cjs/loader.js:937:32)","at Function.Module._load (internal/modules/cjs/loader.js:778:12)","at Function.executeUserEntryPoint [as runMain] (internal/modules/run_main.js:76:12)","at internal/main/run_main_module.js:17:47"],"main":"<could not determine>","dependencies":"<could not determine>","conf":{"ignoreUrlStr":[],"ignoreUrlRegExp":[],"ignoreUserAgentStr":[],"ignoreUserAgentRegExp":[],"transactionIgnoreUrlRegExp":[],"sanitizeFieldNamesRegExp":["/^password$/i","/^passwd$/i","/^pwd$/i","/^secret$/i","/^.*key$/i","/^.*token.*$/i","/^.*session.*$/i","/^.*credit.*$/i","/^.*card.*$/i","/^.*auth.*$/i","/^set\\x2dcookie$/i","/^pw$/i","/^pass$/i","/^connect\\.sid$/i"],"ignoreMessageQueuesRegExp":[],"abortedErrorThreshold":25,"active":true,"apiRequestSize":786432,"apiRequestTime":10,"asyncHooks":true,"breakdownMetrics":true,"captureBody":"off","captureErrorLogStackTraces":"messages","captureExceptions":true,"captureHeaders":true,"captureSpanStackTraces":true,"centralConfig":true,"cloudProvider":"auto","contextPropagationOnly":false,"disableInstrumentations":[],"disableSend":false,"environment":"dev","errorOnAbortedRequests":false,"filterHttpHeaders":true,"ignoreMessageQueues":[],"instrument":true,"instrumentIncomingHTTPRequests":true,"logLevel":"trace","logUncaughtExceptions":false,"longFieldMaxLength":10000,"maxQueueSize":1024,"metricsInterval":30,"metricsLimit":1000,"sanitizeFieldNames":["password","passwd","pwd","secret","*key","*token*","*session*","*credit*","*card*","*auth*","set-cookie","pw","pass","connect.sid"],"serverTimeout":90,"sourceLinesErrorAppFrames":5,"sourceLinesErrorLibraryFrames":5,"sourceLinesSpanAppFrames":0,"sourceLinesSpanLibraryFrames":0,"spanFramesMinDuration":0.01,"stackTraceLimit":50,"transactionIgnoreUrls":[],"transactionMaxSpans":500,"transactionSampleRate":1,"useElasticTraceparentHeader":true,"usePathAsTransactionName":false,"verifyServerCert":false,"serviceName":"petclinic","secretToken":"[REDACTED]","serverUrl":"[REDACTED]","serviceVersion":"1.0.0-0","serverHost":"[REDACTED]","serverPort":8200},"ecs":{"version":"1.6.0"},"message":"agent configured correctly"}
{"log.level":"trace","@timestamp":"2022-02-15T18:06:24.078Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","ecs":{"version":"1.6.0"},"message":"corking (cloudMetadataFetcher)"}
{"log.level":"debug","@timestamp":"2022-02-15T18:06:24.085Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"adding hook to Node.js module loader"}
{"log.level":"debug","@timestamp":"2022-02-15T18:06:24.102Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming [email protected] module"}
{"log.level":"debug","@timestamp":"2022-02-15T18:06:24.107Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"shimming pg.Client.prototype.query"}
{"log.level":"debug","@timestamp":"2022-02-15T18:06:24.184Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","apmServerVersion":"7.10.0","ecs":{"version":"1.6.0"},"message":"fetched APM Server version"}
{"log.level":"debug","@timestamp":"2022-02-15T18:06:24.215Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"no cloud metadata servers responded"}
{"log.level":"trace","@timestamp":"2022-02-15T18:06:24.215Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","ecs":{"version":"1.6.0"},"message":"getCloudMetadata err: Error: no response from any callback, no cloud metadata will be set (normal outside of cloud env.)"}
{"log.level":"trace","@timestamp":"2022-02-15T18:06:24.216Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","_encodedMetadata":"{\"metadata\":{\"service\":{\"name\":\"petclinic\",\"environment\":\"dev\",\"runtime\":{\"name\":\"node\",\"version\":\"14.17.6\"},\"language\":{\"name\":\"javascript\"},\"agent\":{\"name\":\"nodejs\",\"version\":\"3.29.0\"},\"version\":\"1.0.0-0\"},\"process\":{\"pid\":2854230,\"ppid\":2854229,\"title\":\"node\",\"argv\":[\"/home/david_archanjo/node_projects/petclinic/node_modules/.bin/ts-node\",\"/home/david_archanjo/node_projects/petclinic/src/main/node/petclinic.application.ts\"]},\"system\":{\"hostname\":\"nbqfc-2rs9qj3\",\"architecture\":\"x64\",\"platform\":\"linux\",\"container\":{\"id\":\"13392923-9364-471c-aad8-fa20b4518e90\"}}}}\n","ecs":{"version":"1.6.0"},"message":"_resetEncodedMetadata"}
{"log.level":"trace","@timestamp":"2022-02-15T18:06:24.216Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","ecs":{"version":"1.6.0"},"message":"uncorked (cloudMetadataFetcher)"}
{"log.level":"trace","@timestamp":"2022-02-15T18:06:24.218Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"296f05793cea0815a090f23425ed97a6","ecs":{"version":"1.6.0"},"message":"intake request start"}
{"log.level":"trace","@timestamp":"2022-02-15T18:06:24.218Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","fullTimeMs":2.246574,"numEvents":1,"numBytes":870,"ecs":{"version":"1.6.0"},"message":"_write: encode object"}
{"log.level":"trace","@timestamp":"2022-02-15T18:06:24.219Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"296f05793cea0815a090f23425ed97a6","ecs":{"version":"1.6.0"},"message":"intakeReq \"socket\": unref it"}
{"log.level":"debug","@timestamp":"2022-02-15T18:06:24.850Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted call to pg.Client.prototype.query"}
{"log.level":"debug","@timestamp":"2022-02-15T18:06:24.850Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"no active transaction found - cannot build new span"}
{"log.level":"debug","@timestamp":"2022-02-15T18:06:25.978Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted call to pg.Client.prototype.query"}
{"log.level":"debug","@timestamp":"2022-02-15T18:06:25.978Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"no active transaction found - cannot build new span"}
{"log.level":"debug","@timestamp":"2022-02-15T18:06:26.023Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted call to pg.Client.prototype.query"}
{"log.level":"debug","@timestamp":"2022-02-15T18:06:26.023Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"no active transaction found - cannot build new span"}
{"log.level":"debug","@timestamp":"2022-02-15T18:06:26.045Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted call to pg.Client.prototype.query"}
{"log.level":"debug","@timestamp":"2022-02-15T18:06:26.045Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"no active transaction found - cannot build new span"}
{"log.level":"debug","@timestamp":"2022-02-15T18:06:26.066Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted call to pg.Client.prototype.query"}
{"log.level":"debug","@timestamp":"2022-02-15T18:06:26.066Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"no active transaction found - cannot build new span"}
{"log.level":"debug","@timestamp":"2022-02-15T18:06:26.088Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted call to pg.Client.prototype.query"}
{"log.level":"debug","@timestamp":"2022-02-15T18:06:26.091Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"no active transaction found - cannot build new span"}
{"log.level":"debug","@timestamp":"2022-02-15T18:06:26.128Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted call to pg.Client.prototype.query"}
{"log.level":"debug","@timestamp":"2022-02-15T18:06:26.129Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"no active transaction found - cannot build new span"}
{"log.level":"debug","@timestamp":"2022-02-15T18:06:26.161Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted call to pg.Client.prototype.query"}
{"log.level":"debug","@timestamp":"2022-02-15T18:06:26.162Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"no active transaction found - cannot build new span"}
{"log.level":"debug","@timestamp":"2022-02-15T18:06:26.162Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted call to pg.Client.prototype.query"}
{"log.level":"debug","@timestamp":"2022-02-15T18:06:26.162Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"no active transaction found - cannot build new span"}
{"log.level":"debug","@timestamp":"2022-02-15T18:06:26.162Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted call to pg.Client.prototype.query"}
{"log.level":"debug","@timestamp":"2022-02-15T18:06:26.162Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"no active transaction found - cannot build new span"}
{"log.level":"debug","@timestamp":"2022-02-15T18:06:26.162Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted call to pg.Client.prototype.query"}
{"log.level":"debug","@timestamp":"2022-02-15T18:06:26.162Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"no active transaction found - cannot build new span"}
{"log.level":"debug","@timestamp":"2022-02-15T18:06:26.309Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted call to pg.Client.prototype.query"}
{"log.level":"debug","@timestamp":"2022-02-15T18:06:26.309Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"no active transaction found - cannot build new span"}
{"log.level":"debug","@timestamp":"2022-02-15T18:06:26.337Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted call to pg.Client.prototype.query"}
{"log.level":"debug","@timestamp":"2022-02-15T18:06:26.337Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"no active transaction found - cannot build new span"}
{"log.level":"debug","@timestamp":"2022-02-15T18:06:26.370Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted call to pg.Client.prototype.query"}
{"log.level":"debug","@timestamp":"2022-02-15T18:06:26.370Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"no active transaction found - cannot build new span"}
{"log.level":"debug","@timestamp":"2022-02-15T18:06:26.397Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"intercepted call to pg.Client.prototype.query"}
{"log.level":"debug","@timestamp":"2022-02-15T18:06:26.397Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"no active transaction found - cannot build new span"}
{"log.level":"trace","@timestamp":"2022-02-15T18:06:34.219Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"296f05793cea0815a090f23425ed97a6","ecs":{"version":"1.6.0"},"message":"gzipStream \"finish\""}
{"log.level":"trace","@timestamp":"2022-02-15T18:06:34.219Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"296f05793cea0815a090f23425ed97a6","timeout":10000,"ecs":{"version":"1.6.0"},"message":"start intakeResTimer"}
{"log.level":"trace","@timestamp":"2022-02-15T18:06:34.220Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"296f05793cea0815a090f23425ed97a6","ecs":{"version":"1.6.0"},"message":"gzipStream \"end\""}
{"log.level":"trace","@timestamp":"2022-02-15T18:06:34.220Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"296f05793cea0815a090f23425ed97a6","concluded":false,"ecs":{"version":"1.6.0"},"message":"completePart gzipStream"}
{"log.level":"trace","@timestamp":"2022-02-15T18:06:34.221Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"296f05793cea0815a090f23425ed97a6","ecs":{"version":"1.6.0"},"message":"intakeReq \"finish\""}
{"log.level":"trace","@timestamp":"2022-02-15T18:06:34.221Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"296f05793cea0815a090f23425ed97a6","concluded":false,"ecs":{"version":"1.6.0"},"message":"completePart intakeReq"}
{"log.level":"trace","@timestamp":"2022-02-15T18:06:34.232Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"296f05793cea0815a090f23425ed97a6","statusCode":202,"reqFinished":true,"ecs":{"version":"1.6.0"},"message":"intakeReq \"response\""}
{"log.level":"trace","@timestamp":"2022-02-15T18:06:34.233Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"296f05793cea0815a090f23425ed97a6","ecs":{"version":"1.6.0"},"message":"intakeRes \"end\""}
{"log.level":"trace","@timestamp":"2022-02-15T18:06:34.233Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"296f05793cea0815a090f23425ed97a6","concluded":false,"ecs":{"version":"1.6.0"},"message":"completePart intakeRes"}
{"log.level":"trace","@timestamp":"2022-02-15T18:06:34.233Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"296f05793cea0815a090f23425ed97a6","timeline":[[10002.910561,"completePart gzipStream",null],[10003.533113,"completePart intakeReq",null],[10015.388615,"completePart intakeRes",null]],"bytesWritten":678,"backoffDelayMs":0,"ecs":{"version":"1.6.0"},"message":"conclude intake request: success"}
{"log.level":"trace","@timestamp":"2022-02-15T18:06:54.118Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"8c0af4b47559cd8043f12ca447b5598f","ecs":{"version":"1.6.0"},"message":"intake request start"}
{"log.level":"trace","@timestamp":"2022-02-15T18:06:54.119Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","fullTimeMs":2.863338,"numEvents":1,"numBytes":903,"ecs":{"version":"1.6.0"},"message":"_write: encode object"}
{"log.level":"trace","@timestamp":"2022-02-15T18:06:54.119Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"8c0af4b47559cd8043f12ca447b5598f","ecs":{"version":"1.6.0"},"message":"intakeReq \"socket\": unref it"}
{"log.level":"trace","@timestamp":"2022-02-15T18:07:04.120Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"8c0af4b47559cd8043f12ca447b5598f","ecs":{"version":"1.6.0"},"message":"gzipStream \"finish\""}
{"log.level":"trace","@timestamp":"2022-02-15T18:07:04.120Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"8c0af4b47559cd8043f12ca447b5598f","timeout":10000,"ecs":{"version":"1.6.0"},"message":"start intakeResTimer"}
{"log.level":"trace","@timestamp":"2022-02-15T18:07:04.121Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"8c0af4b47559cd8043f12ca447b5598f","ecs":{"version":"1.6.0"},"message":"gzipStream \"end\""}
{"log.level":"trace","@timestamp":"2022-02-15T18:07:04.121Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"8c0af4b47559cd8043f12ca447b5598f","concluded":false,"ecs":{"version":"1.6.0"},"message":"completePart gzipStream"}
{"log.level":"trace","@timestamp":"2022-02-15T18:07:04.121Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"8c0af4b47559cd8043f12ca447b5598f","ecs":{"version":"1.6.0"},"message":"intakeReq \"finish\""}
{"log.level":"trace","@timestamp":"2022-02-15T18:07:04.121Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"8c0af4b47559cd8043f12ca447b5598f","concluded":false,"ecs":{"version":"1.6.0"},"message":"completePart intakeReq"}
{"log.level":"trace","@timestamp":"2022-02-15T18:07:04.122Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"8c0af4b47559cd8043f12ca447b5598f","statusCode":202,"reqFinished":true,"ecs":{"version":"1.6.0"},"message":"intakeReq \"response\""}
{"log.level":"trace","@timestamp":"2022-02-15T18:07:04.122Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"8c0af4b47559cd8043f12ca447b5598f","ecs":{"version":"1.6.0"},"message":"intakeRes \"end\""}
{"log.level":"trace","@timestamp":"2022-02-15T18:07:04.122Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"8c0af4b47559cd8043f12ca447b5598f","concluded":false,"ecs":{"version":"1.6.0"},"message":"completePart intakeRes"}
{"log.level":"trace","@timestamp":"2022-02-15T18:07:04.122Z","log":{"logger":"elastic-apm-node"},"event.module":"apmclient","reqId":"8c0af4b47559cd8043f12ca447b5598f","timeline":[[10003.439965,"completePart gzipStream",null],[10003.839416,"completePart intakeReq",null],[10004.893472,"completePart intakeRes",null]],"bytesWritten":720,"backoffDelayMs":0,"ecs":{"version":"1.6.0"},"message":"conclude intake request: success"}

UPDATE As workaround, we managed to get the instrumentation working in our applications by using forcibly the agent in the v3.20.0. We had to change nothing on the code or any other configuration.

Feb 15 '22 18:02 davidarchanjo

Hi @davidarchanjo. Thank you very much for including your code example and the trace log!

I suspect the issue is that you have imports before the apm.start(...) that starts the agent:

import apm from 'elastic-apm-node';
import ...

// configures apm agent
apm.start({
// ...

This means that those import ...d modules (for example 'express') will be imported before the APM agent has had a chance to install its require-hook that it needs to automatically instrument those modules.

Your trace log shows the APM agent only instrumenting the pg module on startup, and not the express module:

[2022-02-15T18:06:24.085Z] DEBUG (elastic-apm-node): adding hook to Node.js module loader
[2022-02-15T18:06:24.102Z] DEBUG (elastic-apm-node): shimming [email protected] module
[2022-02-15T18:06:24.107Z] DEBUG (elastic-apm-node): shimming pg.Client.prototype.query

If you change the start of your "petclinic.application.ts" to something like:

import apm from 'elastic-apm-node';
// configures apm agent
apm.start({
  serviceName: process.env.ELASTIC_SERVICE_NAME,
  secretToken: process.env.ELASTIC_SECRET_TOKEN,
  serverUrl: process.env.ELASTIC_SERVER_URL,
  transactionSampleRate: Number(process.env.ELASTIC_TRANSACTION_SAMPLE_RATE),
  environment: process.env.ELASTIC_ENVIRONMENT,
  verifyServerCert: process.env.ELASTIC_VERIFY_SERVER_CERT === 'true',
  serverTimeout: process.env.ELASTIC_SERVER_TIMEOUT,
  serviceVersion: process.env.ELASTIC_SERVICE_VERSION,
});

import ...

// creates express app
const app = express();
...

does that then work?

If not, then it would be helpful if you could post the relevant section of the compiled JavaScript code that is being executed and possibly your "tsconfig.json" file.

Feb 15 '22 18:02 trentm

I forgot to say that using the elastic-apm-nodejs v3.20.0 the ingestion worked!

Feb 15 '22 19:02 davidarchanjo

I had to change nothing on the code.. including the imports' ordering

Feb 15 '22 19:02 davidarchanjo

I forgot to say that using the elastic-apm-nodejs v3.20.0 the ingestion worked!

Hrm, okay.

Is it possible that other things changed in your repo when you updated elastic-apm-node from v3.20 to v3.29? E.g. TypeScript version? tsconfig.json parameters?
Are you able to switch back to v3.20.0 of the agent and try again, generating a trace log again, as a sanity check? And then post the top of the compiled .js file and the trace log.
If you can then verify that "v3.20.0 works" and "v3.29.0 fails", it would help me a lot if you were able to try the intermediate versions to narrow down the agent changes:

    "3.20.0": "2021-08-12T16:32:23.474Z",
    "3.21.0": "2021-09-15T23:06:21.532Z",
    "3.21.1": "2021-09-17T00:33:56.444Z",
    "3.22.0": "2021-10-21T19:30:42.629Z",
    "3.23.0": "2021-10-26T00:12:07.596Z",
    "3.24.0": "2021-11-09T21:36:47.222Z",
    "3.25.0": "2021-11-24T17:45:40.314Z",
    "3.26.0": "2021-12-07T23:28:56.473Z",
    "3.27.0": "2022-01-17T19:11:09.446Z",
    "3.28.0": "2022-02-08T23:11:17.737Z",
    "3.29.0": "2022-02-11T00:42:58.654Z"

Are you able to post the "dependencies" from your package.json, in case anything stands out there for me?
Are you running via ts-node here directly? Or are you compiling with tsc and executing the compiled .js file?

Feb 15 '22 19:02 trentm

Later I'm gonna try to find on which exact version the problem happens. About running via ts-node or from compiled files with tsc, our Node applications run in production in compiled .js, but the bug happens regardless of the way we executed them.

Feb 15 '22 19:02 davidarchanjo

Later I'm gonna try to find on which exact version the problem happens.

Thanks!

but the bug happens regardless of the way we executed them.

Understood. I'm just interested in seeing the compiled .js for the "works" and "doesn't work" cases to see exactly what node.js is executing. That'll help me see where the issue might be.

Feb 15 '22 19:02 trentm

@davidarchanjo Did you end up getting things working?

May 26 '22 23:05 trentm

Hey, Is there any update regarding this issue? We are experiencing a similar issue with version 3.30.0 . There are no transactions created anymore for an incoming express request, thus no custom spans can be created. Thanks.

Jul 13 '22 07:07 rozingmichael

@rozingmichael do you have a code sample or set of steps that reproduce your problem? There's myriad things that can interfere with transaction creation -- but usually if we can see your code we can figure out what's going on.

Jul 13 '22 23:07 astorm

I'm closing this for now because we haven't heard back. Please re-open if you are still seeing this and have some more info that we can use to debug it.

Jul 26 '23 14:07 trentm