async_hooks: don't reuse resource in HttpAgent when queued

[puzpuzpuz]

Fixes: #34401
Refs: #27581

Checklist

This PR is a continuation of the http.Agent async resource reuse fix started in #27581. It deals with the case when a socket is not available immediately and, thus, the request is pushed into agent's queue.

• make -j4 test (UNIX), or vcbuild test (Windows) passes
• tests and/or benchmarks are included
• commit message follows commit guidelines

[puzpuzpuz]

@Flarna is it too much to ask you to review this one (as it seems to be related with #27581)?

[puzpuzpuz]

Pushed an additional test to verify http.Agent + ALS bundle, like it was in the bug report.

[puzpuzpuz]

@nodejs/async_hooks I'd appreciate some reviews here. 🙏🏻

[vdeturckheim]

LGTM - do we have a benchmark for this? It should not impact too much but still.

[puzpuzpuz]

LGTM - do we have a benchmark for this? It should not impact too much but still.

I've checked existing benchmarks and the benchmark/http/client-request-body.js one may be the right fit for these changes, as it uses new http.Agent({ maxSockets: 1 }). I'll run it for this PR.

[puzpuzpuz]

Here is the benchmark/http/client-request-body.js benchmark result (https://ci.nodejs.org/view/Node.js%20benchmark/job/benchmark-node-micro-benchmarks/647):

17:56:08                                                                       confidence improvement accuracy (*)    (**)   (***)
17:56:08  http/client-request-body.js method='end' len=1024 type='asc' dur=5                   0.12 %       ±6.10%  ±8.12% ±10.57%
17:56:08  http/client-request-body.js method='end' len=1024 type='buf' dur=5            *     -6.37 %       ±5.97%  ±7.94% ±10.34%
17:56:08  http/client-request-body.js method='end' len=1024 type='utf' dur=5                  -5.08 %       ±6.43%  ±8.56% ±11.14%
17:56:08  http/client-request-body.js method='end' len=256 type='asc' dur=5                   -0.48 %       ±7.70% ±10.25% ±13.34%
17:56:08  http/client-request-body.js method='end' len=256 type='buf' dur=5                   -5.44 %       ±6.60%  ±8.79% ±11.44%
17:56:08  http/client-request-body.js method='end' len=256 type='utf' dur=5                   -3.62 %       ±6.58%  ±8.76% ±11.40%
17:56:08  http/client-request-body.js method='end' len=32 type='asc' dur=5              *     -8.07 %       ±6.11%  ±8.13% ±10.59%
17:56:08  http/client-request-body.js method='end' len=32 type='buf' dur=5              *     -6.99 %       ±5.93%  ±7.89% ±10.26%
17:56:08  http/client-request-body.js method='end' len=32 type='utf' dur=5                     2.44 %       ±6.35%  ±8.47% ±11.06%
17:56:08  http/client-request-body.js method='write' len=1024 type='asc' dur=5                -2.92 %       ±6.96%  ±9.26% ±12.05%
17:56:08  http/client-request-body.js method='write' len=1024 type='buf' dur=5                -4.82 %       ±6.09%  ±8.11% ±10.55%
17:56:08  http/client-request-body.js method='write' len=1024 type='utf' dur=5                -1.19 %       ±6.72%  ±8.94% ±11.65%
17:56:08  http/client-request-body.js method='write' len=256 type='asc' dur=5           *     -8.19 %       ±6.68%  ±8.89% ±11.57%
17:56:08  http/client-request-body.js method='write' len=256 type='buf' dur=5                  0.81 %       ±6.89%  ±9.17% ±11.93%
17:56:08  http/client-request-body.js method='write' len=256 type='utf' dur=5                 -0.51 %       ±6.03%  ±8.03% ±10.45%
17:56:08  http/client-request-body.js method='write' len=32 type='asc' dur=5                  -2.12 %       ±7.13%  ±9.49% ±12.36%
17:56:08  http/client-request-body.js method='write' len=32 type='buf' dur=5                  -1.29 %       ±6.14%  ±8.16% ±10.63%
17:56:08  http/client-request-body.js method='write' len=32 type='utf' dur=5                  -3.73 %       ±6.82%  ±9.09% ±11.85%
17:56:08 
17:56:08 Be aware that when doing many comparisons the risk of a false-positive
17:56:08 result increases. In this case there are 18 comparisons, you can thus
17:56:08 expect the following amount of false-positive results:
17:56:08   0.90 false positives, when considering a   5% risk acceptance (*, **, ***),
17:56:08   0.18 false positives, when considering a   1% risk acceptance (**, ***),
17:56:08   0.02 false positives, when considering a 0.1% risk acceptance (***)

[puzpuzpuz]

I've done another run of the benchmark and this time it gave slightly different results: https://ci.nodejs.org/view/Node.js%20benchmark/job/benchmark-node-micro-benchmarks/650

Looks like the benchmark involves a lot of jitter, yet it makes me thinking that there is no significant performance degradation introduced by this fix. After all, AsyncResource doesn't do a lot of operations when hooks are disabled.

[nodejs-github-bot]

CI: https://ci.nodejs.org/job/node-test-pull-request/32482/

[Flarna]

@Flarna is it too much to ask you to review this one (as it seems to be related with #27581)?

Sorry for my late response, I was on vacation. Will try to review soon.

[puzpuzpuz]

@Flarna no problem at all. Thanks for the update!

[puzpuzpuz]

@Flarna I've noticed one more place where we might loose async context. I'm talking about Agent.removeSocket() method which may be called in .on('free') listener: https://github.com/nodejs/node/blob/master/lib/_http_agent.js#L162

removeSocket() method itself seems to be reading queued requests: https://github.com/nodejs/node/blob/master/lib/_http_agent.js#L426
and then it may execute the first suitable request on a newly created socket:
https://github.com/nodejs/node/blob/master/lib/_http_agent.js#L445

So, I wonder if I should wrap this.createSocket() call on L448 with restored AsyncResource (if the resource is present, of course). WDYT?

[Flarna]

@puzpuzpuz I'm not that deep into the HttpAgent flow. Maybe start by creating a test which reproduces the problem you think you found. If you fail it's maybe a code path which can't happen.

[puzpuzpuz]

@puzpuzpuz I'm not that deep into the HttpAgent flow. Maybe start by creating a test which reproduces the problem you think you found. If you fail it's maybe a code path which can't happen.

@Flarna yeah, I see. Then I'm going to double check the path and try to reproduce it with a test. Going to update this PR, if necessary, and notify the reviewers.

[puzpuzpuz]

@Flarna yeah, I see. Then I'm going to double check the path and try to reproduce it with a test. Going to update this PR, if necessary, and notify the reviewers.

Update. I've checked the code path and we should be ok with the fix, as the removeSocket() method to .on('free') listener invocation which in its turn restores the async context for the queued request.

Going to re-run CI tests and land the fix.

[nodejs-github-bot]

CI: https://ci.nodejs.org/job/node-test-pull-request/32553/

[puzpuzpuz]

Landed in 019ea07

[puzpuzpuz]

@vdeturckheim @Flarna many thanks for your reviews!

[codebytere]

Blocked on #32801