fix(http): stop listening to request's close event once it has emitted response

[SimenB]

Which problem is this PR solving?

See #2575 (comment)

Fixes #2575

Short description of the changes

Change like suggested in the issue made

Type of change

Please delete options that are not relevant.

• Bug fix (non-breaking change which fixes an issue)
• New feature (non-breaking change which adds functionality)
• Breaking change (fix or feature that would cause existing functionality to not work as expected)
• This change requires a documentation update

How Has This Been Tested?

I haven't tested it

Checklist:

• Followed the style guidelines of this project
• Unit tests have been added
• Documentation has been updated

[codecov]

Codecov Report

Merging #3625 (6688ca2) into main (6676414) will decrease coverage by 0.02%.
The diff coverage is 75.00%.

❗ Current head 6688ca2 differs from pull request most recent head 0277808. Consider uploading reports for the commit 0277808 to get more accurate results

Additional details and impacted files

@@            Coverage Diff             @@
##             main    #3625      +/-   ##
==========================================
- Coverage   93.43%   93.42%   -0.02%     
==========================================
  Files         290      290              
  Lines        8849     8863      +14     
  Branches     1834     1838       +4     
==========================================
+ Hits         8268     8280      +12     
- Misses        581      583       +2     

Impacted Files	Coverage Δ
...ges/opentelemetry-instrumentation-http/src/http.ts	93.29% <75.00%> (-0.98%)	⬇️

... and 2 files with indirect coverage changes

[SimenB]

Is the failing test my fault? It looks like an OOM or something when running the http instrumentation test, so seems reasonable. I don't have access to a windows machine tho, so unable to reproduce it

[dyladan]

Looks good to me. @vmarchaud please confirm but based on discussion on the issue I think you also thought this was ok

[dyladan]

The test failure is an out of memory that is unrelated

[MSNev]

The test failure is an out of memory that is unrelated

It might be related to the changed from end -> close causing something in the test infra to use a little bit more memory on windows.

@SimenB can you try adding this to the unit-test.yml a value of 4096 (or maybe event 3072 should work based on the 2076 amount in the failed test case

[SimenB]

Doesn't seem like it helped 😞

#3626 is failing with the same error, so doesn't seem like it's the code change here, though. But weird it's not an issue on main...

[SimenB]

I deployed this at work and now pretty much every single http span is giving the same Can not execute the operation on ended Span error 😅 So this is not the correct fix.

I guess we can add a guard to the setStatus call? Checking if the span has been closed

[dyladan]

close shouldn't be emitted twice so i'm not sure why you would be double closing spans after this PR

[SimenB]

My guess is request's close has already closed the span:

opentelemetry-js/experimental/packages/opentelemetry-instrumentation-http/src/http.ts

Lines 403 to 408 in 9b4f2a5

	request.on('close', () => {
	this._diag.debug('outgoingRequest on request close()');
	if (!request.aborted) {
	this._closeHttpSpan(span, SpanKind.CLIENT, startTime, metricAttributes);
	}
	});

Not sure of the timing between close for request vs. response

[dyladan]

My guess is request's close has already closed the span:

opentelemetry-js/experimental/packages/opentelemetry-instrumentation-http/src/http.ts

Lines 403 to 408 in 9b4f2a5

	request.on('close', () => {
	this._diag.debug('outgoingRequest on request close()');
	if (!request.aborted) {
	this._closeHttpSpan(span, SpanKind.CLIENT, startTime, metricAttributes);
	}
	});

Not sure of the timing between close for request vs. response

Ah yeah. It's probably not a closing issue since _closeHttpSpan checks if the span is closed first, but setting status in the response end/close handler that is failing.

[dyladan]

The possible event orderings are listed in https://nodejs.org/api/http.html#httprequesturl-options-callback

In most cases it looks like request#close is the last even emitted. response#end seems only to be emitted on a successful request and response#close is only emitted on premature connection closing.

[SimenB]

My guess is request's close has already closed the span:

opentelemetry-js/experimental/packages/opentelemetry-instrumentation-http/src/http.ts

Lines 403 to 408 in 9b4f2a5

	request.on('close', () => {
	this._diag.debug('outgoingRequest on request close()');
	if (!request.aborted) {
	this._closeHttpSpan(span, SpanKind.CLIENT, startTime, metricAttributes);
	}
	});

Not sure of the timing between close for request vs. response

Ah yeah. It's probably not a closing issue since _closeHttpSpan checks if the span is closed first, but setting status in the response end/close handler that is failing.

Yep, it's the setStatus call that fails

[weyert]

Maybe it's worth looking what on-finished (https://www.npmjs.com/package/on-finished) is doing?

[dyladan]

Maybe it's worth looking what on-finished (https://www.npmjs.com/package/on-finished) is doing?

Looks like it listens for end or finish on the request, whichever comes first (https://github.com/jshttp/on-finished/blob/c94df7d1692539d2504ccf46ceea8e8913ebe0a0/index.js#L105), as well as error or close on the underlying socket, whichever comes first (https://github.com/jshttp/on-finished/blob/c94df7d1692539d2504ccf46ceea8e8913ebe0a0/index.js#L115).

Most of the rest of the code is error handling, handling multiple callback registrations, etc.

It also wraps the callback in an async resource https://github.com/jshttp/on-finished/blob/c94df7d1692539d2504ccf46ceea8e8913ebe0a0/index.js#L213-L234

[vmarchaud]

lgtm for the fix itself if you find it fixes the case

EDIT: Wondering also if the behavior is not different across node version ?

[vmarchaud]

not sure if its worth to check that the fix doesnt create any leak that for some reasons is only a problem in windows ?

[SimenB]

#3628

[SimenB]

Would using stream.finished on both the request and response be an alternative, and make sure to check that both have been called (or there was an error I guess) before closing the span?

I'm not sure how that works for keep-alive requests. But I guess keep-alives might be on the socket level and not the request/response pair?

[dyladan]

Would using stream.finished on both the request and response be an alternative, and make sure to check that both have been called (or there was an error I guess) before closing the span?

I'm not sure how that works for keep-alive requests. But I guess keep-alives might be on the socket level and not the request/response pair?

I'm also not sure. I think emulating on-finished seems like the safest course of action here. All of these events are well documented and on-finished is a very popular project with a huge production audience. I think we can be pretty sure of their solution.

We don't need most of what on-finished is doing in terms of multiple callback registration, async resource, etc because we're not calling user callbacks. The biggest issue I can think of is that registering an error handler may have side effects. We can get around this by using https://nodejs.org/api/events.html#eventserrormonitor

[SimenB]

@legendecas is this something you could ask the stream/http folks (largely the same group of people I guess 😅) in node about? 🙂

[legendecas]

The behavior mentioned in #2575 can be constantly reproduced with the following script:

const { diag, DiagConsoleLogger, DiagLogLevel } = require('@opentelemetry/api');
const { NodeTracerProvider } = require('@opentelemetry/sdk-trace-node');
const { registerInstrumentations } = require('@opentelemetry/instrumentation');
const { HttpInstrumentation } = require('@opentelemetry/instrumentation-http');

diag.setLogger(new DiagConsoleLogger(), DiagLogLevel.ALL);
const provider = new NodeTracerProvider();
provider.register();
registerInstrumentations({
    instrumentations: [
        new HttpInstrumentation(),
    ],
    tracerProvider: provider
});

const http = require('http');

http.createServer((req, res) => {
  // Force flush http response header to trigger client response callback.
  res.write('');
  setTimeout(() => {
    req.socket.destroy();
  }, 100);
}).listen(9999);


const events = ['end', 'close', 'error'];
const req = http.request(`http://localhost:9999`, (res) => {
  console.log('client on response');
  events.forEach(e => {
    res.on(e, () => {
      console.log(`client response ${e}`);
    });
  });
});
events.forEach(e => {
  req.on(e, () => {
    console.log(`client request ${e}`);
  });
});
// Force flush http request header to trigger server request callback.
req.write('');

Example output:

@opentelemetry/instrumentation-http outgoingRequest on response()
client on response
@opentelemetry/instrumentation-http outgoingRequest on request close()
client request close
@opentelemetry/instrumentation-http outgoingRequest on error() Error: aborted
    at connResetException (node:internal/errors:705:14)
    at Socket.socketCloseListener (node:_http_client:454:19)
    at Socket.emit (node:events:525:35)
    at TCP.<anonymous> (node:net:301:12)
    at TCP.callbackTrampoline (node:internal/async_hooks:130:17) {
  code: 'ECONNRESET'
}
Can not execute the operation on ended Span {traceId: 59bb9fca68b111da095354701fbfd0fc, spanId: 60eece63dc4f177d}
Can not execute the operation on ended Span {traceId: 59bb9fca68b111da095354701fbfd0fc, spanId: 60eece63dc4f177d}
Can not execute the operation on ended Span {traceId: 59bb9fca68b111da095354701fbfd0fc, spanId: 60eece63dc4f177d}
Can not execute the operation on ended Span {traceId: 59bb9fca68b111da095354701fbfd0fc, spanId: 60eece63dc4f177d}
Can not execute the operation on ended Span {traceId: 59bb9fca68b111da095354701fbfd0fc, spanId: 60eece63dc4f177d}
client response error
client response close

I believe the correct fix would be suppressing the req.on('close') listener once the req.on('response') has been triggered. If the socket is closed prematurely before the response header is received, the listener on request 'close' event is necessary since the response event has not been emitted and the response event listeners are not installed. However, when the response header is received, the span should only be ended either when the response is ended or errored.

[SimenB]

Sounds reasonable 👍 Is this something you'll work on? I don't think I'll personally have the time for at least a week, but I can probably take a look then

[legendecas]

My bandwidth is pretty limited in one or two weeks so please go ahead with this when you get the chance.

[weyert]

How can we progress this PR? Would be nice if can make @dyladan next release :)

[SimenB]

Some help on the tests would be great! I think that's the only thing missing.

I've moved on to other things at work (using the patch from this PR, so not blocked by it), so it's currently hard to find the time for this.

[weyert]

Some help on the tests would be great! I think that's the only thing missing.

I've moved on to other things at work (using the patch from this PR, so not blocked by it), so it's currently hard to find the time for this.

You mean solving the failing tests or adding new ones? I give it an attempt.

[SimenB]

Some help on the tests would be great! I think that's the only thing missing.
I've moved on to other things at work (using the patch from this PR, so not blocked by it), so it's currently hard to find the time for this.

You mean solving the failing tests or adding new ones? I give it an attempt.

I've pushed a test to this branch that I think encompasses the fix, so in theory getting it to pass should be sufficient 🙂 That test might be faulty somehow tho, so it might be better to throw it out and write a new one.

[legendecas]

Took some time to investigate the test failure. I found that nock's HTTP client implementation behaves differently with node's native one in immature client closes: if the request was destroyed with request.destroy(new Error()) when the response is received, no error events are emitted with response. While Node's implementation would propagate the request's error to response when response is received.

Updated the patch to accommodate this behavior.

@SimenB does the change look good to you? If so, would you mind marking the PR as ready for review?

[SimenB]

oh, oops, missed your message @legendecas! 😅 let me try to restore your commit

[SimenB]

Yeah, your changes look reasonable to me! I can attempt to deploy this patch at work as well (tomorrow - currently Sunday 21:30 here 😅), and if it looks good after a day or so, I think this PR should finally be ready 🙂

EDIT: Deployed now, will report back

[SimenB]

This has been trucking along just fine throughout the day without issue, so I think this is good to go!

[ryan-codaio]

We have noticed GitHub having transient issues cloning/pulling in our CI today. The unit test failure looks related, so it would be worth rerunning tests, although I don't have permissions to do so

[SimenB]

Thanks for your help with this @legendecas!