elastic / elastic/apm-agent-nodejs
an outgoing `http.request(...)` that fails with an 'error' event is not ended
- Dominant language
- JavaScript
- Stars
- 594
- Forks
- 244
- Avg merge
- 1d 8h
- Merged PRs (30d)
- 16
Description
Using this example script:
```js
// http-req-error.js
const apm = require('./').start({ // elastic-apm-node
serviceName: 'http-req-error'
})
const http = require('http')
const trans = apm.startTransaction('trans')
const req = http.request('http://localhost:6666', function (res) {
console.log('res: %s %s', res.statusCode, res.headers)
res.on('data', chunk => {
console.log('res "data": %s', chunk)
})
res.on('end', function () {
console.log('res "end"')
})
})
req.on('error', err => { console.log('req "error":', err) })
req.end()
setTimeout(() => {
trans.end()
}, 1000)
```
and this patch:
```diff
diff --git a/lib/instrumentation/http-shared.js b/lib/instrumentation/http-shared.js
index 32cbb53a..ed4f075f 100644
--- a/lib/instrumentation/http-shared.js
+++ b/lib/instrumentation/http-shared.js
@@ -188,6 +188,7 @@ exports.traceOutgoingRequest = function (agent, moduleName, method) {
// is added instead of when `response` is emitted.
const emit = req.emit
req.emit = function wrappedEmit (type, res) {
+ console.log('XXX req.emit type: ', type)
if (type === 'response') onResponse(res)
if (type === 'abort') onAbort(type)
return emit.apply(req, arguments)
```
We see this (with node v18; the stack is slightly different for different node versions):
```
% node http-req-error.js
XXX added trace-context headers
XXX have an http span still here
XXX req.emit type: socket
XXX req.emit type: prefinish
XXX req.emit type: error
req "error": Error: connect ECONNREFUSED ::1:6666
at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1247:16)
at TCPConnectWrap.callbackTrampoline (node:internal/async_hooks:130:17) {
errno: -61,
code: 'ECONNREFUSED',
syscall: 'connect',
address: '::1',
port: 6666
}
XXX req.emit type: close
```
and we get this trace:
```
trace a7d4f2
`- transaction 77aa08 "trans" (1006.22ms, outcome=unknown)
```
There is at least one **bug** here that there isn't a span. The span *was* started by our instrumentation, but it wasn't ended.
### notes
1. We could watch for `error` in `function wrappedEmit` to catch this. We could potentially also use the `close` event. However, I'd want to dig into whether that `close` is always emitted for all node versions we support.
2. Should we `captureError` here on the 'error' event? I think so, but I'd like to discuss with others.
3. The current watching for `abort` in `wrappedEmit` should potentially be changed to use `close` in newer versions of node, because [`'abort'` was deprecated in node v17.0.0, v16.12.0](https://nodejs.org/api/http.html#event-abort)
Contributor guide
Assessment
This issue has not been assessed yet.