apm-agent-nodejs: APM agent (and so app) dies when using the bodyParser plugin in restify application - unhandled exception prevent route completion
Describe the bug
When using ES APM Agent in an restify app and the bodyParser Plugin at the same time, the app dies with the first request/an exception is thrown by APM which cannot be handled. APM agent writes his own error wrappedHandler (node_modules/elastic-apm-node/lib/instrumentation/modules/restify.js)
but afterwards the request dies.
To Reproduce Steps to reproduce the behavior:
- Create a npm project (elastic-apm-node version doesn’t matter - bug exists in 1.x and 2.x)
{
"name": "apm-test",
"version": "1.0.0",
"description": "",
"main": "index.js",
"scripts": {
"test": "echo \"Error: no test specified\" && exit 1"
},
"author": "",
"license": "ISC",
"dependencies": {
"elastic-apm-node": "^1.14.3",
"restify": "^7.2.3"
}
}
- Create a simple server
// // Add this to the VERY top of the first file loaded in your app
var apm = require('elastic-apm-node').start({
serviceName: 'development_apm-test',
// Set custom APM Server URL (default: http://localhost:8200)
serverUrl: 'http://XXXX:8200',
})
var restify = require('restify');
function respond(req, res, next) {
res.send('hello ' + req.params.name);
next();
}
var server = restify.createServer();
server.use(restify.plugins.jsonBodyParser());
server.get('/hello/:name', respond);
server.head('/hello/:name', respond);
server.listen(8080, function() {
console.log('%s listening at %s', server.name, server.url);
});
- Call the app’s endpoint in the browser…
http://localhost:8080/hello/waldi
- See in the console
logging error XXXX-XXX-XXX with Elastic APM
and the request is dead. - Output in Kibana/ES:
{
"library_frame": true,
"exclude_from_grouping": false,
"filename": "node_modules/elastic-apm-node/lib/instrumentation/modules/restify.js",
"abs_path": "~/apm-test/node_modules/elastic-apm-node/lib/instrumentation/modules/restify.js",
"line": {
"number": 37,
"context": " return handler.apply(this, arguments)"
},
"function": "wrappedHandler",
"context": {
"pre": [
" }",
" })"
],
"post": [
" }",
" }"
]
}
},
{
"exclude_from_grouping": false,
"library_frame": true,
"filename": "node_modules/restify/lib/chain.js",
"abs_path": "~/apm-test/node_modules/restify/lib/chain.js",
"line": {
"number": 164,
"context": " handler(req, res, next);"
},
"function": "call",
"context": {
"pre": [
" } else if (!hasError && arity < 4) {",
" // request-handling middleware"
],
"post": [
" return;",
" }"
]
}
},
{
"library_frame": true,
"exclude_from_grouping": false,
"filename": "node_modules/restify/lib/chain.js",
"abs_path": "~/apm-test/node_modules/restify/lib/chain.js",
"line": {
"number": 120,
"context": " call(handler, err, req, res, self.onceNext ? self._once(next) : next);"
},
"function": "next",
"context": {
"pre": [
"",
" // call the handler"
],
"post": [
" }",
""
]
}
},
{
"library_frame": true,
"exclude_from_grouping": false,
"filename": "node_modules/restify/lib/chain.js",
"abs_path": "~/apm-test/node_modules/restify/lib/chain.js",
"line": {
"number": 123,
"context": " next();"
},
"function": "run",
"context": {
"pre": [
" }",
""
],
"post": [
" return;",
"};"
]
}
},
{
"library_frame": true,
"exclude_from_grouping": false,
"filename": "node_modules/restify/lib/server.js",
"abs_path": "~/apm-test/node_modules/restify/lib/server.js",
"line": {
"number": 1002,
"context": " self.useChain.run(req, res, function useChainDone(err) {"
},
"function": "_runUse",
"context": {
"pre": [
" req._timeUseStart = process.hrtime();",
""
],
"post": [
" // Execution time of a handler with error can be significantly lower",
" req._timeUseEnd = process.hrtime();"
]
}
},
{
"library_frame": true,
"exclude_from_grouping": false,
"abs_path": "~/apm-test/node_modules/restify/lib/server.js",
"filename": "node_modules/restify/lib/server.js",
"line": {
"number": 916,
"context": " self._runUse(req, res, function afterUse() {"
},
"function": "_runRoute",
"context": {
"pre": [
" self.emit('routed', req, res, req.route);",
""
],
"post": [
" // DTrace",
" if (self.dtrace) {"
]
}
},
{
"library_frame": true,
"exclude_from_grouping": false,
"abs_path": "~/apm-test/node_modules/restify/lib/server.js",
"filename": "node_modules/restify/lib/server.js",
"line": {
"number": 886,
"context": " self._runRoute(req, res);"
},
"function": "_afterPre",
"context": {
"pre": [
" }",
""
],
"post": [
"};",
""
]
}
},
{
"library_frame": true,
"exclude_from_grouping": false,
"filename": "node_modules/restify/lib/server.js",
"abs_path": "~/apm-test/node_modules/restify/lib/server.js",
"line": {
"number": 854,
"context": " self._afterPre(err, req, res);"
},
"function": "preChainDone",
"context": {
"pre": [
" // Execution time of a handler with error can be significantly lower",
" req._timePreEnd = process.hrtime();"
],
"post": [
" });",
"};"
]
}
},
{
"library_frame": true,
"exclude_from_grouping": false,
"filename": "timers.js",
"abs_path": "timers.js",
"line": {
"number": 634
},
"function": "processImmediate"
},
{
"library_frame": true,
"exclude_from_grouping": false,
"filename": "domain.js",
"abs_path": "domain.js",
"line": {
"number": 120
},
"function": "topLevelDomainCallback"
}
Expected behavior App runs normal without beeing influenced or interrupted by APM.
Environment (please complete the following information)
- OS: OSX 10.14.1; Docker Image node:alpine latest.
- Node.js version: v10.4.1
- APM Server version: 6.2.3
- Agent version: 1.x or 2.x doesn’t matter
How are you starting the agent? (please tick one of the boxes)
- Calling
agent.start()
directly (e.g.require('elastic-apm-node').start(...)
) - Requiring
elastic-apm-node/start
from within the source code - Starting node with
-r elastic-apm-node/start
About this issue
- Original URL
- State: closed
- Created 6 years ago
- Comments: 22 (10 by maintainers)
Commits related to this issue
- fix(restify): support an array of handlers If an array of handlers is given as an argument to `server.use` instead of just a single function, the agent would cause an exception to be rasied. This co... — committed to watson/apm-agent-nodejs by watson 6 years ago
- fix(restify): support an array of handlers If an array of handlers is given as an argument to `server.use` instead of just a single function, the agent would cause an exception to be raised. This co... — committed to watson/apm-agent-nodejs by watson 6 years ago
- fix(restify): support an array of handlers If an array of handlers is given as an argument to `server.use` instead of just a single function, the agent would cause an exception to be raised. This co... — committed to watson/apm-agent-nodejs by watson 6 years ago
- fix(restify): support an array of handlers (#709) If an array of handlers is given as an argument to `server.use` instead of just a single function, the agent would cause an exception to be raised.... — committed to elastic/apm-agent-nodejs by watson 6 years ago
- fix(restify): support an array of handlers (#709) If an array of handlers is given as an argument to `server.use` instead of just a single function, the agent would cause an exception to be raised. ... — committed to watson/apm-agent-nodejs by watson 6 years ago
@watson works like a charm.
@watson you are correct, it was docker volumes shenanigans at play. it works as expected now, thank you!
Hopefully today. We’re just working on backporting the changes to 1.x
@waswrongassembled yes that should be possible. I’ll make sure to backport the fix once it lands in master