search

elastic / apm-agent-nodejs

https://www.elastic.co/guide/en/apm/agent/nodejs/current/index.html
BSD 2-Clause "Simplified" License
582 stars 225 forks source link

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

Closed davidarchanjo closed 1 year ago

davidarchanjo commented 2 years ago

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:

  1. ELK Configuration (docker) elasticsearch: v7.10.0 kibana: v7.10.0 apm-server: v7.10.0

  2. Node Application Configarution node: v14.17 express: v4.17.2 typescript: v4.5.5 apm-agent-nodejs: v3.29.0

  3. 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**
<details>
<summary>Click to expand</summary>

{"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. (/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. [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. (/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":"","dependencies":"","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 pg@8.7.3 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"}


</details>

**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.
trentm commented 2 years ago

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 pg@8.7.3 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.

davidarchanjo commented 2 years ago

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

davidarchanjo commented 2 years ago

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

trentm commented 2 years ago

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

Hrm, okay.

  1. 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?
  2. 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.
  3. 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"
  4. Are you able to post the "dependencies" from your package.json, in case anything stands out there for me?
  5. Are you running via ts-node here directly? Or are you compiling with tsc and executing the compiled .js file?
davidarchanjo commented 2 years ago

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.

trentm commented 2 years ago

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.

trentm commented 2 years ago

@davidarchanjo Did you end up getting things working?

rozingmichael commented 2 years ago

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.

astorm commented 2 years ago

@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.

trentm commented 1 year ago

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.