Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Agent doesn't capture uncaught exceptions or unhandled rejections #3960

Open
1 of 3 tasks
Vectarian-Jorge opened this issue Apr 8, 2024 · 11 comments
Open
1 of 3 tasks
Assignees

Comments

@Vectarian-Jorge
Copy link

Vectarian-Jorge commented Apr 8, 2024

Describe the bug

Suddenly my Express applications do not capture errors or exceptions that cause the application to crash. Up until the 21st of February I can see both in the Error tab of the APM and in the Discover tool of ELK that there were crashes reported due to silly mistakes, like a missing environment variable. But nothing since then. And I've tried to crash the application deliberately adding throw new Error('Boom') and Promise.reject(new Error('Kaboom')) and neither is reported by the APM.

Investigating any possible changes I've made I can only think of upgrading the agent's version from 3.42.0 to 4.3.0. But I've tried with the old version and it behaves the same way.

To Reproduce

package.json
{
	"type": "module",
	"name": "experiment",
	"version": "1.0.0",
	"description": "",
	"main": "index.js",
	"scripts": {
		"test": "echo \"Error: no test specified\" && exit 1"
	},
	"author": "",
	"license": "ISC",
	"dependencies": {
		"elastic-apm-node": "^4.5.0",
		"express": "^4.19.2"
	}
}
index.js
import './apm.js'; // Must go first
import express from 'express';

const port = 3000;
const app = express();

app.get('/', (_req, res) => {
	//Promise.reject(new Error('Kaboom')); // Uncomment either of these
	res.send('Hello World!');
});

app.listen(port, () => {
	console.log(`Example app listening on port ${port}`);
});

//throw new Error('Boom'); // Uncomment either of these
apm.js
import apm from 'elastic-apm-node';

apm.start({
	environment: 'local',
	serverUrl: 'https://example.com:12345/',
});

Expected behavior

Uncaught exceptions and unhandled rejections being reported by the agent so that they can be monitored in the APM tool of ELK.

Environment (please complete the following information)

  • OS: Linux and MacOS
  • Node.js version: 16.16.0
  • APM Server version: 7.17.8
  • Agent version: 3.42.0 and 4.3.0

How are you starting the agent? (please tick one of the boxes)

  • Calling agent.start() directly (e.g. require('elastic-apm-node').start(...))
    In particular, I have a init-elastic-apm.ts file where I start the agent with a config dependent on some environment variables. Then the first line of my index.ts file is import apm from 'elastic-apm-node'.
  • Requiring elastic-apm-node/start from within the source code
  • Starting node with -r elastic-apm-node/start

Additional context

Agent config options:

Click to expand
import { hostname } from 'node:os';
import pkg from '../../package.json' assert { type: 'json' };
{
	serviceName: pkg.name.split('/')[1],
	serviceVersion: pkg.version,
	serviceNodeName: hostname(),
	environment: process.env['APP_ENV'],
	serverUrl: process.env['ELK_KIBANA_URL'],
	captureBody: 'all',
	captureExceptions: true, // <-- I've tried with default and explicit `captureExceptions`
}

package.json dependencies:

Click to expand
"@aws-sdk/client-s3": "3.245.0",
"@aws-sdk/client-timestream-write": "3.245.0",
"@bluesialia/express-graphql": "0.15.0",
"@elastic/ecs-pino-format": "1.5.0",
"@sentry/node": "7.103.0",
"bcryptjs": "2.4.3",
"body-parser": "1.20.1",
"compression": "1.7.4",
"cors": "2.8.5",
"dotenv": "16.3.1",
"elastic-apm-node": "3.42.0",
"express": "4.18.2",
"express-async-errors": "3.1.1",
"extract-files": "13.0.0",
"firebase-admin": "11.10.1",
"google-auth-library": "8.7.0",
"graphql": "16.6.0",
"graphql-scalars": "1.20.1",
"graphql-upload": "13.0.0",
"graphql-ws": "5.11.2",
"http-status": "1.6.1",
"jszip": "3.10.1",
"knex": "2.4.0",
"modern-async": "1.1.3",
"node-fetch": "3.3.2",
"objection": "3.1.4",
"objection-paginator": "0.7.1",
"paddle-sdk": "3.2.0",
"pg": "8.8.0",
"pino": "8.17.1",
"stringify-object": "5.0.0",
"wasmagic": "0.0.32"
@Vectarian-Jorge
Copy link
Author

Added a minimal example. Those 3 files. Just run node index.js with any of the throws uncommented. It'll crash and the agent won't report it.

@Vectarian-Jorge
Copy link
Author

Tried with require instead of ES modules too. Nothing.
Screenshot 2024-04-10 at 13 26 28

@david-luna david-luna self-assigned this Apr 23, 2024
@david-luna
Copy link
Member

Hi @Vectarian-Jorge

I've run you example uncommenting the li within the request handler but haven't been able to reproduce. I can see the error in Kibana.

Screenshot 2024-04-25 at 16 25 41

Are you able to get the initial line of log output from the APM agent? It looks something like this:

{"log.level":"info","@timestamp":"2024-04-25T14:35:50.282Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","agentVersion":"4.5.3","env":{"pid":30004,"proctitle":"node","os":"darwin 23.4.0","arch":"arm64","host":"moonlocal.local","timezone":"UTC+0200","runtime":"Node.js v18.16.0"},"config":{"environment":{"source":"start","value":"local"},"logLevel":{"source":"environment","value":"trace","commonName":"log_level"},"serverUrl":{"source":"environment","value":"https://eah-demo-testing.apm.us-central1.gcp.cloud.es.io/","commonName":"server_url"},"secretToken":{"source":"environment","value":"[REDACTED]","commonName":"secret_token"},"serviceName":{"source":"environment","value":"expresscmp-elastic1","commonName":"service_name"},"serviceVersion":{"source":"default","value":"1.0.0","commonName":"service_version"}},"activationMethod":"import","dependencies":{"elastic-apm-node":"^4.5.0","express":"^4.19.2"},"startTrace":["at Agent.start (/Users/david/Documents/repos/issues/el-apm-node-3960/node_modules/elastic-apm-node/lib/agent.js:294:11)","at file:///Users/david/Documents/repos/issues/el-apm-node-3960/apm.js:3:5","at ModuleJob.run (node:internal/modules/esm/module_job:194:25)"],"message":"Elastic APM Node.js Agent v4.5.3"}

If so, check if the line contains something like

"config": { "captureExceptions": { "source": "start", "value": false }

This is to check there is no other source setting the configuration option.

@david-luna
Copy link
Member

Also if you can make local edits, you can apply this change to log if the agent's exception handler is properly attached to the process.

diff --git a/lib/agent.js b/lib/agent.js
index 2a1e26df..64fe1c59 100644
--- a/lib/agent.js
+++ b/lib/agent.js
@@ -776,6 +776,8 @@ Agent.prototype.handleUncaughtExceptions = function (cb) {
     });
   };
 
+  console.log('XXX attaching uncaughtException handler to process')
+
   process.on('uncaughtException', this._uncaughtExceptionListener);
 };

to "node_modules/elastic-apm-node/lib/agent.js", restart, and reproduce. Then post here full log to check if this new line appears

@Vectarian-Jorge
Copy link
Author

Vectarian-Jorge commented Apr 29, 2024

This is the initial log line:

{"log.level":"info","@timestamp":"2024-04-29T07:49:31.180Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","agentVersion":"4.5.0","env":{"pid":99719,"proctitle":"node","os":"darwin 23.4.0","arch":"arm64","host":"REDACTED","timezone":"UTC+0100","runtime":"Node.js v20.11.0"},"config":{"captureExceptions":{"source":"start","value":true},"environment":{"source":"start","value":"local"},"logLevel":{"source":"default","value":"info","commonName":"log_level"},"serverUrl":{"source":"start","value":"REDACTED","commonName":"server_url"},"serviceName":{"source":"default","value":"experiment","commonName":"service_name"},"serviceVersion":{"source":"default","value":"1.0.0","commonName":"service_version"}},"activationMethod":"import","message":"Elastic APM Node.js Agent v4.5.0"}

This is with captureExceptions: true explicitly defined in the APM start options. If I remove the property "captureExceptions": { "source": "start", "value": true } does not show up in the log line.

With the file node_modules/elastic-apm-node/lib/agent.js modified as instructed the first 3 lines printed to console are:

{"log.level":"info","@timestamp":"2024-04-29T07:55:22.430Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","agentVersion":"4.5.0","env":{"pid":99904,"proctitle":"node","os":"darwin 23.4.0","arch":"arm64","host":"REDACTED","timezone":"UTC+0100","runtime":"Node.js v20.11.0"},"config":{"captureExceptions":{"source":"start","value":true},"environment":{"source":"start","value":"local"},"logLevel":{"source":"default","value":"info","commonName":"log_level"},"serverUrl":{"source":"start","value":"REDACTED","commonName":"server_url"},"serviceName":{"source":"default","value":"experiment","commonName":"service_name"},"serviceVersion":{"source":"default","value":"1.0.0","commonName":"service_version"}},"activationMethod":"import","message":"Elastic APM Node.js Agent v4.5.0"}
XXX attaching uncaughtException handler to process
Example app listening on port 3000

The following line would be the error Error: Kaboom and its stacktrace if I triggered it.

If I'm not mistaken. These outputs are what they should be, yet still no errors show on the APM panel.

I think I read somewhere that the agent prints something to console whenever it captures a fatal error and sends it to ELK. Is that correct? If that's the case I don't see that log either.

@david-luna
Copy link
Member

Hi @Vectarian-Jorge

as your logs show the exception handler is set when the agent starts so we can assume the agent starts correctly. Next thing to try is to set the log level to trace to see if there are any issues related to other components.

You can start you example with the defined log level like this

ELASTIC_APM_LOG_LEVEL=trace node index.js

Ref: https://www.elastic.co/guide/en/apm/agent/nodejs/current/configuration.html#log-level

once you got the logs please paste them here :)

@Vectarian-Jorge
Copy link
Author

Vectarian-Jorge commented May 3, 2024

Sorry for the delay. These are the logs:

{"log.level":"info","@timestamp":"2024-05-03T12:05:15.887Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","agentVersion":"4.5.0","env":{"pid":35372,"proctitle":"node","os":"darwin 23.4.0","arch":"arm64","host":"Vectarys-MacBook-Pro-2.local","timezone":"UTC+0100","runtime":"Node.js v20.11.0"},"config":{"environment":{"source":"start","value":"local"},"logLevel":{"source":"environment","value":"trace","commonName":"log_level"},"serverUrl":{"source":"start","value":"REDACTED","commonName":"server_url"},"serviceName":{"source":"default","value":"experiment","commonName":"service_name"},"serviceVersion":{"source":"default","value":"1.0.0","commonName":"service_version"}},"activationMethod":"import","dependencies":{"elastic-apm-node":"^4.5.0","express":"^4.19.2"},"startTrace":["at Agent.start (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/elastic-apm-node/lib/agent.js:294:11)","at file:///Users/REDACTED/Documents/GitHub/REDACTED/experiment/apm.js:3:5","at ModuleJob.run (node:internal/modules/esm/module_job:218:25)","at async ModuleLoader.import (node:internal/modules/esm/loader:329:24)","at async loadESM (node:internal/process/esm_loader:28:7)","at async handleMainPromise (node:internal/modules/run_main:113:12)"],"message":"Elastic APM Node.js Agent v4.5.0"}
XXX attaching uncaughtException handler to process
Example app listening on port 3000
{"log.level":"trace","@timestamp":"2024-05-03T12:05:15.936Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","event.module":"apmclient","message":"corking (cloudMetadataFetcher)"}
{"log.level":"debug","@timestamp":"2024-05-03T12:05:15.937Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","message":"adding Node.js module loader hooks"}
{"log.level":"debug","@timestamp":"2024-05-03T12:05:15.938Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","message":"instrumenting fetch"}
{"log.level":"debug","@timestamp":"2024-05-03T12:05:16.025Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","message":"instrumenting finalhandler@1.2.0 module (enabled=true, isImportMod=false)"}
{"log.level":"debug","@timestamp":"2024-05-03T12:05:16.055Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","message":"instrumenting http@20.11.0 module (enabled=true, isImportMod=false)"}
{"log.level":"debug","@timestamp":"2024-05-03T12:05:16.062Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","message":"shimming http.Server.prototype.emit function"}
{"log.level":"debug","@timestamp":"2024-05-03T12:05:16.063Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","message":"shimming http.ServerResponse.prototype.writeHead function"}
{"log.level":"debug","@timestamp":"2024-05-03T12:05:16.063Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","message":"shimming http.request function"}
{"log.level":"debug","@timestamp":"2024-05-03T12:05:16.063Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","message":"shimming http.get function"}
{"log.level":"debug","@timestamp":"2024-05-03T12:05:16.516Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","message":"no cloud metadata servers responded"}
{"log.level":"trace","@timestamp":"2024-05-03T12:05:16.517Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","event.module":"apmclient","message":"getCloudMetadata err: Error: no response from any callback, no cloud metadata will be set (normal outside of cloud env.)"}
{"log.level":"trace","@timestamp":"2024-05-03T12:05:16.518Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","event.module":"apmclient","_encodedMetadata":"{\"metadata\":{\"service\":{\"name\":\"experiment\",\"environment\":\"local\",\"runtime\":{\"name\":\"node\",\"version\":\"20.11.0\"},\"language\":{\"name\":\"javascript\"},\"agent\":{\"name\":\"nodejs\",\"version\":\"4.5.0\",\"activation_method\":\"import\"},\"version\":\"1.0.0\"},\"process\":{\"pid\":35372,\"ppid\":35371,\"title\":\"node\",\"argv\":[\"/Users/REDACTED/.volta/tools/image/node/20.11.0/bin/node\",\"/Users/REDACTED/Documents/GitHub/REDACTED/experiment/index.js\"]},\"system\":{\"architecture\":\"arm64\",\"platform\":\"darwin\",\"detected_hostname\":\"vectarys-macbook-pro-2.local\"}}}\n","message":"_resetEncodedMetadata"}
{"log.level":"trace","@timestamp":"2024-05-03T12:05:16.518Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","event.module":"apmclient","message":"uncorked (cloudMetadataFetcher)"}
{"log.level":"trace","@timestamp":"2024-05-03T12:05:16.520Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","event.module":"apmclient","reqId":"d1ccfe910a8c43a330ed20c0b21fd021","message":"intake request start"}
{"log.level":"trace","@timestamp":"2024-05-03T12:05:16.521Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","event.module":"apmclient","fullTimeMs":2.910459,"numEvents":1,"numBytes":848,"message":"_write: encode object"}
{"log.level":"trace","@timestamp":"2024-05-03T12:05:16.521Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","event.module":"apmclient","reqId":"d1ccfe910a8c43a330ed20c0b21fd021","message":"intakeReq \"socket\": unref it"}
{"log.level":"trace","@timestamp":"2024-05-03T12:05:16.705Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","event.module":"apmclient","_encodedMetadata":"{\"metadata\":{\"service\":{\"name\":\"experiment\",\"environment\":\"local\",\"runtime\":{\"name\":\"node\",\"version\":\"20.11.0\"},\"language\":{\"name\":\"javascript\"},\"agent\":{\"name\":\"nodejs\",\"version\":\"4.5.0\"},\"version\":\"1.0.0\"},\"process\":{\"pid\":35372,\"ppid\":35371,\"title\":\"node\",\"argv\":[\"/Users/REDACTED/.volta/tools/image/node/20.11.0/bin/node\",\"/Users/REDACTED/Documents/GitHub/REDACTED/experiment/index.js\"]},\"system\":{\"architecture\":\"arm64\",\"platform\":\"darwin\",\"detected_hostname\":\"vectarys-macbook-pro-2.local\"}}}\n","message":"_resetEncodedMetadata"}
{"log.level":"debug","@timestamp":"2024-05-03T12:05:16.705Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","event.module":"apmclient","apmServerVersion":"7.17.8","message":"fetched APM Server version"}
{"log.level":"debug","@timestamp":"2024-05-03T12:05:16.788Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","remoteConf":{},"message":"central config received"}
{"log.level":"trace","@timestamp":"2024-05-03T12:05:26.523Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","event.module":"apmclient","reqId":"d1ccfe910a8c43a330ed20c0b21fd021","message":"gzipStream \"finish\""}
{"log.level":"trace","@timestamp":"2024-05-03T12:05:26.523Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","event.module":"apmclient","reqId":"d1ccfe910a8c43a330ed20c0b21fd021","timeout":10000,"message":"start intakeResTimer"}
{"log.level":"trace","@timestamp":"2024-05-03T12:05:26.524Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","event.module":"apmclient","reqId":"d1ccfe910a8c43a330ed20c0b21fd021","message":"gzipStream \"end\""}
{"log.level":"trace","@timestamp":"2024-05-03T12:05:26.524Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","event.module":"apmclient","reqId":"d1ccfe910a8c43a330ed20c0b21fd021","concluded":false,"message":"completePart gzipStream"}
{"log.level":"trace","@timestamp":"2024-05-03T12:05:26.525Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","event.module":"apmclient","reqId":"d1ccfe910a8c43a330ed20c0b21fd021","message":"intakeReq \"finish\""}
{"log.level":"trace","@timestamp":"2024-05-03T12:05:26.525Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","event.module":"apmclient","reqId":"d1ccfe910a8c43a330ed20c0b21fd021","concluded":false,"message":"completePart intakeReq"}
{"log.level":"trace","@timestamp":"2024-05-03T12:05:26.741Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","event.module":"apmclient","reqId":"d1ccfe910a8c43a330ed20c0b21fd021","statusCode":202,"reqFinished":true,"message":"intakeReq \"response\""}
{"log.level":"trace","@timestamp":"2024-05-03T12:05:26.742Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","event.module":"apmclient","reqId":"d1ccfe910a8c43a330ed20c0b21fd021","message":"intakeRes \"end\""}
{"log.level":"trace","@timestamp":"2024-05-03T12:05:26.742Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","event.module":"apmclient","reqId":"d1ccfe910a8c43a330ed20c0b21fd021","concluded":false,"message":"completePart intakeRes"}
{"log.level":"trace","@timestamp":"2024-05-03T12:05:26.742Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","event.module":"apmclient","reqId":"d1ccfe910a8c43a330ed20c0b21fd021","timeline":[[10004.787334,"completePart gzipStream",null],[10005.435417,"completePart intakeReq",null],[10222.505709,"completePart intakeRes",null]],"bytesWritten":689,"backoffDelayMs":0,"message":"conclude intake request: success"}
{"log.level":"debug","@timestamp":"2024-05-03T12:05:28.441Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","message":"intercepted request event call to http.Server.prototype.emit for /"}
Error: Kaboom
    at file:///Users/REDACTED/Documents/GitHub/REDACTED/experiment/index.js:8:17
    at Layer.handle [as handle_request] (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/layer.js:95:5)
    at next (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/route.js:149:13)
    at Route.dispatch (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/route.js:119:3)
    at Layer.handle [as handle_request] (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/layer.js:95:5)
    at /Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/index.js:284:15
    at Function.process_params (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/index.js:346:12)
    at next (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/index.js:280:10)
    at expressInit (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/middleware/init.js:40:5)
    at Layer.handle [as handle_request] (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/layer.js:95:5)
    at trim_prefix (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/index.js:328:13)
    at /Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/index.js:286:9
    at Function.process_params (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/index.js:346:12)
    at next (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/index.js:280:10)
    at query (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/middleware/query.js:45:5)
    at Layer.handle [as handle_request] (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/layer.js:95:5)
    at trim_prefix (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/index.js:328:13)
    at /Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/index.js:286:9
    at Function.process_params (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/index.js:346:12)
    at next (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/index.js:280:10)
    at Function.handle (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/index.js:175:3)
    at Function.handle (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/application.js:181:10)
    at Server.app (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/express.js:39:9)
    at Server.emit (node:events:518:28)
    at Server.emit (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/elastic-apm-node/lib/instrumentation/http-shared.js:162:19)
    at parserOnIncoming (node:_http_server:1143:12)
    at HTTPParser.parserOnHeadersComplete (node:_http_common:119:17)
{"log.level":"debug","@timestamp":"2024-05-03T12:05:28.443Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","message":"start trace {\"trans\":\"a5911165e833e6d5\",\"trace\":\"b5a867d9f885ed3b1fb893999295692c\",\"name\":\"unnamed\",\"type\":\"custom\"}"}
{"log.level":"debug","@timestamp":"2024-05-03T12:05:28.443Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","ctxmgr":"AsyncLocalStorageRunContextManager( RunContext(Transaction(a5911165e833e6d5, 'unnamed')) )","message":"supersedeWithTransRunContext(<Trans a5911165e833e6d5>)"}
{"log.level":"debug","@timestamp":"2024-05-03T12:05:28.447Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","message":"setting transaction result {\"trans\":\"a5911165e833e6d5\",\"trace\":\"b5a867d9f885ed3b1fb893999295692c\",\"result\":\"HTTP 2xx\"}"}
{"log.level":"debug","@timestamp":"2024-05-03T12:05:28.450Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","message":"setting default transaction name: GET / {\"trans\":\"a5911165e833e6d5\",\"trace\":\"b5a867d9f885ed3b1fb893999295692c\"}"}
{"log.level":"debug","@timestamp":"2024-05-03T12:05:28.450Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","ctxmgr":"AsyncLocalStorageRunContextManager( RunContext() )","message":"addEndedTransaction(GET /)"}
{"log.level":"debug","@timestamp":"2024-05-03T12:05:28.471Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","message":"sending transaction {\"trans\":\"a5911165e833e6d5\",\"trace\":\"b5a867d9f885ed3b1fb893999295692c\"}"}
{"log.level":"debug","@timestamp":"2024-05-03T12:05:28.472Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","trans":"a5911165e833e6d5","name":"GET /","trace":"b5a867d9f885ed3b1fb893999295692c","type":"request","result":"HTTP 2xx","duration":8.322,"message":"ended transaction"}
{"log.level":"debug","@timestamp":"2024-05-03T12:05:28.473Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","error":{"type":"Error","message":"Kaboom","stack_trace":"Error: Kaboom\n    at file:///Users/REDACTED/Documents/GitHub/REDACTED/experiment/index.js:8:17\n    at Layer.handle [as handle_request] (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/layer.js:95:5)\n    at next (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/route.js:149:13)\n    at Route.dispatch (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/route.js:119:3)\n    at Layer.handle [as handle_request] (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/layer.js:95:5)\n    at /Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/index.js:284:15\n    at Function.process_params (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/index.js:346:12)\n    at next (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/index.js:280:10)\n    at expressInit (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/middleware/init.js:40:5)\n    at Layer.handle [as handle_request] (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/layer.js:95:5)\n    at trim_prefix (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/index.js:328:13)\n    at /Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/index.js:286:9\n    at Function.process_params (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/index.js:346:12)\n    at next (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/index.js:280:10)\n    at query (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/middleware/query.js:45:5)\n    at Layer.handle [as handle_request] (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/layer.js:95:5)\n    at trim_prefix (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/index.js:328:13)\n    at /Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/index.js:286:9\n    at Function.process_params (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/index.js:346:12)\n    at next (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/index.js:280:10)\n    at Function.handle (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/router/index.js:175:3)\n    at Function.handle (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/application.js:181:10)\n    at Server.app (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/express/lib/express.js:39:9)\n    at Server.emit (node:events:518:28)\n    at Server.emit (/Users/REDACTED/Documents/GitHub/REDACTED/experiment/node_modules/elastic-apm-node/lib/instrumentation/http-shared.js:162:19)\n    at parserOnIncoming (node:_http_server:1143:12)\n    at HTTPParser.parserOnHeadersComplete (node:_http_common:119:17)"},"message":"Elastic APM caught unhandled exception"}
{"log.level":"debug","@timestamp":"2024-05-03T12:05:28.487Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","message":"Sending error to Elastic APM: {\"id\":\"3e27eb0c4421460c747a227e7bd63cb2\"}"}
{"log.level":"trace","@timestamp":"2024-05-03T12:05:28.488Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","event.module":"apmclient","reqId":"08a56d5d3e89749ce116dd30188cd1f5","message":"intake request start"}
{"log.level":"trace","@timestamp":"2024-05-03T12:05:28.488Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","event.module":"apmclient","encodeTimeMs":0.509208,"fullTimeMs":0.911917,"numEvents":2,"numBytes":11425,"message":"_writeBatch"}
{"log.level":"trace","@timestamp":"2024-05-03T12:05:28.488Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","event.module":"apmclient","reqId":"08a56d5d3e89749ce116dd30188cd1f5","message":"intakeReq \"socket\": unref it"}
{"log.level":"trace","@timestamp":"2024-05-03T12:05:28.488Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","event.module":"apmclient","activeIntakeReq":true,"lambdaEnd":false,"message":"_writeFlush"}
{"log.level":"trace","@timestamp":"2024-05-03T12:05:28.489Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","event.module":"apmclient","reqId":"08a56d5d3e89749ce116dd30188cd1f5","message":"gzipStream \"finish\""}
{"log.level":"trace","@timestamp":"2024-05-03T12:05:28.489Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","event.module":"apmclient","reqId":"08a56d5d3e89749ce116dd30188cd1f5","timeout":10000,"message":"start intakeResTimer"}
{"log.level":"trace","@timestamp":"2024-05-03T12:05:28.489Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","event.module":"apmclient","reqId":"08a56d5d3e89749ce116dd30188cd1f5","message":"gzipStream \"end\""}
{"log.level":"trace","@timestamp":"2024-05-03T12:05:28.489Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","event.module":"apmclient","reqId":"08a56d5d3e89749ce116dd30188cd1f5","concluded":false,"message":"completePart gzipStream"}
{"log.level":"trace","@timestamp":"2024-05-03T12:05:28.489Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","event.module":"apmclient","reqId":"08a56d5d3e89749ce116dd30188cd1f5","message":"intakeReq \"finish\""}
{"log.level":"trace","@timestamp":"2024-05-03T12:05:28.489Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","event.module":"apmclient","reqId":"08a56d5d3e89749ce116dd30188cd1f5","concluded":false,"message":"completePart intakeReq"}
{"log.level":"debug","@timestamp":"2024-05-03T12:05:28.545Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","message":"intercepted request event call to http.Server.prototype.emit for /favicon.ico"}
{"log.level":"debug","@timestamp":"2024-05-03T12:05:28.545Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","message":"start trace {\"trans\":\"a10c68672ac1eb8d\",\"trace\":\"978e2fefc32f12abe8caa754a76a913d\",\"name\":\"unnamed\",\"type\":\"custom\"}"}
{"log.level":"debug","@timestamp":"2024-05-03T12:05:28.545Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","ctxmgr":"AsyncLocalStorageRunContextManager( RunContext(Transaction(a10c68672ac1eb8d, 'unnamed')) )","message":"supersedeWithTransRunContext(<Trans a10c68672ac1eb8d>)"}
{"log.level":"debug","@timestamp":"2024-05-03T12:05:28.547Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","message":"setting transaction result {\"trans\":\"a10c68672ac1eb8d\",\"trace\":\"978e2fefc32f12abe8caa754a76a913d\",\"result\":\"HTTP 4xx\"}"}
{"log.level":"debug","@timestamp":"2024-05-03T12:05:28.547Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","message":"could not extract route name from request {\"url\":\"/favicon.ico\",\"type\":\"undefined\",\"null\":false,\"route\":false,\"regex\":false,\"mountstack\":false,\"trans\":\"a10c68672ac1eb8d\",\"trace\":\"978e2fefc32f12abe8caa754a76a913d\"}"}
{"log.level":"debug","@timestamp":"2024-05-03T12:05:28.547Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","message":"setting default transaction name: GET unknown route {\"trans\":\"a10c68672ac1eb8d\",\"trace\":\"978e2fefc32f12abe8caa754a76a913d\"}"}
{"log.level":"debug","@timestamp":"2024-05-03T12:05:28.548Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","ctxmgr":"AsyncLocalStorageRunContextManager( RunContext() )","message":"addEndedTransaction(GET unknown route)"}
{"log.level":"debug","@timestamp":"2024-05-03T12:05:28.548Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","message":"sending transaction {\"trans\":\"a10c68672ac1eb8d\",\"trace\":\"978e2fefc32f12abe8caa754a76a913d\"}"}
{"log.level":"debug","@timestamp":"2024-05-03T12:05:28.548Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","trans":"a10c68672ac1eb8d","name":"GET unknown route","trace":"978e2fefc32f12abe8caa754a76a913d","type":"request","result":"HTTP 4xx","duration":2.794,"message":"ended transaction"}
{"log.level":"trace","@timestamp":"2024-05-03T12:05:28.577Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","event.module":"apmclient","reqId":"08a56d5d3e89749ce116dd30188cd1f5","statusCode":202,"reqFinished":true,"message":"intakeReq \"response\""}
{"log.level":"trace","@timestamp":"2024-05-03T12:05:28.577Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","event.module":"apmclient","reqId":"08a56d5d3e89749ce116dd30188cd1f5","message":"intakeRes \"end\""}
{"log.level":"trace","@timestamp":"2024-05-03T12:05:28.577Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","event.module":"apmclient","reqId":"08a56d5d3e89749ce116dd30188cd1f5","concluded":false,"message":"completePart intakeRes"}
{"log.level":"trace","@timestamp":"2024-05-03T12:05:28.577Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","event.module":"apmclient","reqId":"08a56d5d3e89749ce116dd30188cd1f5","timeline":[[1.202958,"completePart gzipStream",null],[1.588833,"completePart intakeReq",null],[89.3285,"completePart intakeRes",null]],"bytesWritten":2373,"backoffDelayMs":0,"message":"conclude intake request: success"}
{"log.level":"trace","@timestamp":"2024-05-03T12:05:28.578Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","event.module":"apmclient","fullTimeMs":0.407,"numEvents":1,"numBytes":1301,"message":"_write: encode object"}

@Vectarian-Jorge
Copy link
Author

I see the line that says Sending error to Elastic APM: {"id":"3e27eb0c4421460c747a227e7bd63cb2"} yet I still see nothing in the APM Web UI. I'm going to try to look for the ID 3e27eb0c4421460c747a227e7bd63cb2 somewhere. I'll post again if I find it anywhere.

@david-luna
Copy link
Member

I do not see anything wrong in this log

this line

{"log.level":"trace","@timestamp":"2024-05-03T12:05:28.577Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","event.module":"apmclient","reqId":"08a56d5d3e89749ce116dd30188cd1f5","timeline":[[1.202958,"completePart gzipStream",null],[1.588833,"completePart intakeReq",null],[89.3285,"completePart intakeRes",null]],"bytesWritten":2373,"backoffDelayMs":0,"message":"conclude intake request: success"}

reveals that the http client received a successful response from the endpoint.

To discard any other communication issue we should check if the URL configured in the agent is pointing to the APM server or any other component like a proxy. @Vectarian-Jorge could you please check it?

I ran my tests with the same node and agent version specified in the issue but a different APM server version (8.12.1). I'll try to run the tests with same APM server 7.17.8 to discard any version incompatibility

@david-luna
Copy link
Member

Ran the test with

  • Elastic cloud stack 7.17.8
  • elastic-apm-node@4.5.3

slight modification of the server script to test more cases

import './apm.js'; // Must go first
import express from 'express';

const port = 3000;
const app = express();

app.get('/reject', (_req, res) => {
	Promise.reject(new Error('Rejection')); // 1. This is unhandled so ti should be reported
	res.send('Hello World!');
});
app.get('/error', (_req, res) => {
	throw new Error('Exception'); // 2. This is handled by express, no error
});

app.listen(port, () => {
	console.log(`Example app listening on port ${port}`);
});

throw new Error('Boom'); // 3. This should also be reported, comment to test rejection (1)

The service errors appear in Kibana
Screenshot 2024-05-10 at 12 05 45

@Vectarian-Jorge I'm inclined to check the transit from the agent to the APM server. Have you checked for any proxy/nodes in between the app and the APM server?

@Vectarian-Jorge
Copy link
Author

Thanks for checking all this @david-luna.

@PeterBero, you may need to check with Tomas about any possible proxy.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

2 participants