elastic / elastic/apm-agent-nodejs

an outgoing `http.request(...)` that fails with an 'error' event is not ended

Open
#2,856 1 comment 0 reactions 0 assignees View on GitHub
8.10-candidate agent-nodejs bug
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

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.