Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

chore(instr-undici): updates/tweaks for new undici instrumentation #2085

Merged
merged 9 commits into from
Apr 10, 2024

Conversation

trentm
Copy link
Contributor

@trentm trentm commented Apr 4, 2024

  • 'codecov' npm script was copypasta from core repo
  • update to same test-all-versions ver as other pkgs in the workspace
  • update undici to latest (it is a security update)
  • add label-prs workflow support pkg:instrumentation-undici
  • reduce number of versions tested with TAV
  • skip a particular failing test case for very old undici versions

I also added the pkg: label for this instr: https://github.com/open-telemetry/opentelemetry-js-contrib/labels?q=undici

- 'codecov' npm script was copypasta from core repo
- update to same test-all-versions ver as other pkgs in the workspace
- update undici to latest (it is a security update)
- add label-prs workflow support pkg:instrumentation-undici
@trentm trentm self-assigned this Apr 4, 2024
Copy link

codecov bot commented Apr 4, 2024

Codecov Report

Merging #2085 (705b83d) into main (dfb2dff) will decrease coverage by 0.21%.
Report is 49 commits behind head on main.
The diff coverage is 20.00%.

❗ Current head 705b83d differs from pull request most recent head 53d3f08. Consider uploading reports for the commit 53d3f08 to get more accurate results

Additional details and impacted files
@@            Coverage Diff             @@
##             main    #2085      +/-   ##
==========================================
- Coverage   90.97%   90.77%   -0.21%     
==========================================
  Files         146      148       +2     
  Lines        7492     7675     +183     
  Branches     1502     1539      +37     
==========================================
+ Hits         6816     6967     +151     
- Misses        676      708      +32     
Files Coverage Δ
plugins/node/instrumentation-undici/src/undici.ts 96.23% <20.00%> (ø)

... and 13 files with indirect coverage changes

@trentm
Copy link
Contributor Author

trentm commented Apr 4, 2024

This .tav.yml change reduces the num,ber of undici versions tested from 77 to 14:

Before:

% npx tav --dry-run --verbose | rg match
-- 20 package versions matching filter: 6.0.0, 6.0.1, 6.1.0, 6.2.0, 6.2.1, 6.3.0, 6.4.0, 6.5.0, 6.6.0, 6.6.1, 6.6.2, 6.7.0, 6.7.1, 6.8.0, 6.9.0, 6.10.0, 6.10.1, 6.10.2, 6.11.0, 6.11.1
-- 57 package versions matching filter: 5.0.0, 5.1.0, 5.1.1, 5.2.0, 5.3.0, 5.4.0, 5.5.0, 5.5.1, 5.6.0, 5.6.1, 5.7.0, 5.8.0, 5.8.1, 5.8.2, 5.9.0, 5.9.1, 5.10.0, 5.11.0, 5.12.0, 5.13.0, 5.14.0, 5.15.0, 5.15.1, 5.15.2, 5.16.0, 5.17.0, 5.17.1, 5.18.0, 5.19.0, 5.19.1, 5.20.0, 5.21.0, 5.21.1, 5.21.2, 5.22.0, 5.22.1, 5.23.0, 5.24.0, 5.25.0, 5.25.1, 5.25.2, 5.25.3, 5.25.4, 5.26.0, 5.26.1, 5.26.2, 5.26.3, 5.26.4, 5.26.5, 5.27.0, 5.27.1, 5.27.2, 5.28.0, 5.28.1, 5.28.2, 5.28.3, 5.28.4

After:

% npx tav --dry-run --verbose | rg match
-- 7 package versions matching filter: 6.0.0, 6.1.0, 6.4.0, 6.6.1, 6.8.0, 6.10.2, 6.11.1
-- 7 package versions matching filter: 5.0.0, 5.7.0, 5.15.0, 5.21.1, 5.26.0, 5.28.2, 5.28.4

@trentm
Copy link
Contributor Author

trentm commented Apr 4, 2024

There is a test failure in the TAV tests for earlier 5.x versions. This test case:

    it('should create valid spans for different request methods', async function () {

(Note: I isolated just this test case for my debugging, because I think there might be some pollution between tests... or perhaps just a timing issue because the issue is with an async socket close event.)

If you change that to it.only to run just that test, here is a failure:

% npm install --no-save undici@5.11.0
...

% npm test
...
  UndiciInstrumentation `undici` tests
    enable()
      1) should create valid spans for different request methods

  0 passing (142ms)
  1 failing

  1) UndiciInstrumentation `undici` tests
       enable()
         should create valid spans for different request methods:
     Uncaught SocketError: closed
      at Socket.onSocketClose (node_modules/undici/lib/client.js:967:31)
      at Socket.emit (node:events:517:28)
      at TCP.<anonymous> (node:net:350:12)
      at TCP.callbackTrampoline (node:internal/async_hooks:130:17)
...

This passes with undici@5.12.0.

Here is a small test script showing the behaviour difference:

% cat use-undici-with-weird-method.js
const undici = require('undici')
const anActualServer = 'http://127.0.0.1:8200/'
async function main() {
  let res
  try {
    res = await undici.request(anActualServer, {
      method: 'get'
    })
  } catch (reqErr) {
    console.log('reqErr: ', reqErr);
  }
  console.log('res:', res.statusCode, res.headers);
  let body
  try {
    body = await res.body.text()
  } catch (bodyErr) {
    console.log('bodyErr: ', bodyErr);
  }
  console.log('body:', body);
}
main()

The failing case (undici@5.11.0):

% node use-undici-with-weird-method.js
res: 400 { connection: 'close' }
bodyErr:  SocketError: closed
    at Socket.onSocketClose (/Users/trentm/tm/opentelemetry-js-contrib12/plugins/node/instrumentation-undici/node_modules/undici/lib/client.js:967:31)
    at Socket.emit (node:events:517:28)
    at TCP.<anonymous> (node:net:350:12) {
  code: 'UND_ERR_SOCKET',
  socket: {
    localAddress: undefined,
    localPort: undefined,
    remoteAddress: undefined,
    remotePort: undefined,
    remoteFamily: undefined,
    timeout: undefined,
    bytesWritten: 64,
    bytesRead: 47
  }
}
body: undefined

The passing test case (undici@5.12.0):

% npm install --no-save undici@5.12.0
...

% node use-undici-with-weird-method.js
res: 400 { connection: 'close' }
body:

The undici.test.ts code cannot trap this error event with its current try/catch.

I stopped digging in here. We are talking really old undici versions:

  '5.11.0': '2022-10-03T15:42:59.406Z',
  '5.12.0': '2022-10-27T15:01:02.770Z',

I suggest we just limit support to >=5.12.0.
Thoughts?

@trentm
Copy link
Contributor Author

trentm commented Apr 4, 2024

Options for this test failure:

  1. Make this instr only work for undici 5.12.0 and later.
  2. Skip this test for less than undici 5.11.0.
  3. Someone dig into the test case.

I am inclined to do option 2.

@trentm
Copy link
Contributor Author

trentm commented Apr 4, 2024

^^ that commit does option 2

@trentm
Copy link
Contributor Author

trentm commented Apr 4, 2024

Here is a passing TAV run:

% npm run test-all-versions -- -q

> @opentelemetry/instrumentation-undici@0.1.0 test-all-versions
> tav -q

-- required packages ["undici@6.11.1"]
-- installing ["undici@6.11.1"]
-- running test "npm run test" with undici (env: {})
-- required packages ["undici@6.10.2"]
-- installing ["undici@6.10.2"]
-- running test "npm run test" with undici (env: {})
-- required packages ["undici@6.8.0"]
-- installing ["undici@6.8.0"]
-- running test "npm run test" with undici (env: {})
-- required packages ["undici@6.6.1"]
-- installing ["undici@6.6.1"]
-- running test "npm run test" with undici (env: {})
-- required packages ["undici@6.4.0"]
-- installing ["undici@6.4.0"]
-- running test "npm run test" with undici (env: {})
-- required packages ["undici@6.1.0"]
-- installing ["undici@6.1.0"]
-- running test "npm run test" with undici (env: {})
-- required packages ["undici@6.0.0"]
-- installing ["undici@6.0.0"]
-- running test "npm run test" with undici (env: {})
-- required packages ["undici@5.28.4"]
-- installing ["undici@5.28.4"]
-- running test "npm run test" with undici (env: {})
-- required packages ["undici@5.28.2"]
-- installing ["undici@5.28.2"]
-- running test "npm run test" with undici (env: {})
-- required packages ["undici@5.26.0"]
-- installing ["undici@5.26.0"]
-- running test "npm run test" with undici (env: {})
-- required packages ["undici@5.21.1"]
-- installing ["undici@5.21.1"]
-- running test "npm run test" with undici (env: {})
-- required packages ["undici@5.15.0"]
-- installing ["undici@5.15.0"]
-- running test "npm run test" with undici (env: {})
-- required packages ["undici@5.7.0"]
-- installing ["undici@5.7.0"]
-- running test "npm run test" with undici (env: {})
-- required packages ["undici@5.0.0"]
-- installing ["undici@5.0.0"]
-- running test "npm run test" with undici (env: {})
-- ok

@trentm trentm marked this pull request as ready for review April 4, 2024 23:46
@trentm trentm requested review from a team and david-luna April 4, 2024 23:46
@david-luna
Copy link
Contributor

@trentm there is code to catch this case and skip the test. I think I've made the check too specific for the error message and this could change between versions of undici and/or node

the intent was to skip only for the versions that throw. I'm not 100% sure if versions prior to v5.11.0 work but the might

the comment:

// In version v5 if `undici` you get the following error when requesting with a method

the check:

We could relax that check to skip on socket error since is an expected exception from the lib.

@david-luna
Copy link
Contributor

I suggest we just limit support to >=5.12.0.

I think is a good idea

@@ -225,6 +225,10 @@ pkg:instrumentation-tedious:
- any-glob-to-any-file:
- plugins/node/instrumentation-tedious/**
- packages/opentelemetry-test-utils/**
pkg:instrumentation-undici:
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

good catch! I think we should merge this before we do a 1st release of this instrumentation

cc: @pichlermarc

plugins/node/instrumentation-undici/test/undici.test.ts Outdated Show resolved Hide resolved
plugins/node/instrumentation-undici/test/undici.test.ts Outdated Show resolved Hide resolved
@david-luna
Copy link
Contributor

there is also another failure in TAV testing. Test fails for version 6.11.0 where the headers changed format but request does not have addHeader API. I guess this was considered a bug since a new version bas released shortly

npm info undici time

{
  ...
  '6.11.0': '2024-04-02T10:40:33.293Z',
  '5.28.4': '2024-04-02T16:36:40.050Z',
  '6.11.1': '2024-04-02T16:44:56.065Z'
}

so in the test we got the following error

 1) UndiciInstrumentation `undici` tests
       enable()
         should create valid spans for "dispatch" method:
     Uncaught TypeError: request.addHeader is not a function
      at UndiciInstrumentation.onRequestCreated (src/undici.ts:77:4)
      at Channel.publish (node:diagnostics_channel:56:9)
      at new Request (/home/runner/work/opentelemetry-js-contrib/opentelemetry-js-contrib/node_modules/undici/lib/core/request.js:192:23)
      at Client.[dispatch] (/home/runner/work/opentelemetry-js-contrib/opentelemetry-js-contrib/node_modules/undici/lib/dispatcher/client.js:304:21)
      at Intercept (/home/runner/work/opentelemetry-js-contrib/opentelemetry-js-contrib/node_modules/undici/lib/interceptor/redirect-interceptor.js:11:16)
      at Client.[Intercepted Dispatch] (/home/runner/work/opentelemetry-js-contrib/opentelemetry-js-contrib/node_modules/undici/lib/dispatcher/dispatcher-base.js:158:12)
      at Client.dispatch (/home/runner/work/opentelemetry-js-contrib/opentelemetry-js-contrib/node_modules/undici/lib/dispatcher/dispatcher-base.js:179:40)
      at /home/runner/work/opentelemetry-js-contrib/opentelemetry-js-contrib/plugins/node/instrumentation-undici/test/undici.test.ts:502:16
      at new Promise (<anonymous>)
      at Context.<anonymous> (test/undici.test.ts:501:13)
      at processImmediate (node:internal/timers:476:21)
      at process.callbackTrampoline (node:internal/async_hooks:130:17)

In that case the headers are placed in an array of strings so we can check and push the headers there. This is the change

diff --git a/plugins/node/instrumentation-undici/src/undici.ts b/plugins/node/instrumentation-undici/src/undici.ts
index 262bea42..e69015b7 100644
--- a/plugins/node/instrumentation-undici/src/undici.ts
+++ b/plugins/node/instrumentation-undici/src/undici.ts
@@ -270,10 +270,12 @@ export class UndiciInstrumentation extends InstrumentationBase {
     for (let i = 0; i < headerEntries.length; i++) {
       const [k, v] = headerEntries[i];

-      if (typeof request.headers === 'string') {
-        request.headers += `${k}: ${v}\r\n`;
-      } else {
+      if (typeof request.addHeader === 'function') {
         request.addHeader(k, v);
+      } else if (Array.isArray(request.headers)) {
+        request.headers.push(k, v);
+      } else if (typeof request.headers === 'string') {
+        request.headers += `${k}: ${v}\r\n`;
       }
     }
     this._recordFromReq.set(request, { span, attributes, startTime });

Conditions now are more strict and if none match instrumentation will assume and do nothing to avoid runtime errors.

@@ -1,8 +1,12 @@
undici:
jobs:
- versions: ">=5 <6"
- versions:
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think is a good idea to reduce the number of versions

@trentm
Copy link
Contributor Author

trentm commented Apr 5, 2024

We could relax that check to skip on socket error since is an expected exception from the lib.

If I'm understanding the cases that fail for me, I don't think the try/catch will catch this exception. It currently results in an uncaughtException. It might be an "error" event on one of the streams. I'm not sure.

I suggest we just limit support to >=5.12.0.

I think is a good idea

That is what I called Option 1. I thought it was perhaps a shame to drop support for all of [5.0.0, 5.12.0) just because this one test of an edge case wasn't passing our tests. However, I think either way is fine. No one should be using such an old undici.

if we drop support for <5.12.0 this won't be necessary. Neither the try/catch of this test

I'll give that a try.

@trentm
Copy link
Contributor Author

trentm commented Apr 5, 2024

[Re: the "request.addHeader" failure]

I guess this was considered a bug since a new version bas released shortly

Yes. Discussed in this issue: nodejs/undici#3043

Well, perhaps "yes" with quotes, because one of the maintainers is saying "diagnostic channels support is experimental so breaking changes can come." I haven't fully read/grokked this, but the suggestion is that the request object is meant to be immutable at this point? If so, then the diag channel stuff in undici will be useless for context propagation. That would be a big loss. We shall see.

Matteo clarifies at nodejs/undici#3043 (comment) that the APM use case is valid, so that's very helpful here.

We could support earlier versions of 5.x, but there is little point
because those releases are so old.
@trentm trentm requested a review from david-luna April 5, 2024 20:39
@trentm trentm enabled auto-merge (squash) April 10, 2024 15:59
@trentm trentm merged commit 1af4901 into open-telemetry:main Apr 10, 2024
7 checks passed
@trentm trentm deleted the tm-instr-undici-follow-ups branch April 10, 2024 15:59
trentm added a commit to trentm/opentelemetry-js-contrib that referenced this pull request Apr 18, 2024
Test all versions (TAV) tests were failing with Node.js 14 and 16
because of subtle behaviour changes in socket end handling in
Node.js and undici for a test that tries a bogus request. This
restores earlier work-around code mistakenly removed in open-telemetry#2085.
pichlermarc pushed a commit that referenced this pull request Apr 18, 2024
Test all versions (TAV) tests were failing with Node.js 14 and 16
because of subtle behaviour changes in socket end handling in
Node.js and undici for a test that tries a bogus request. This
restores earlier work-around code mistakenly removed in #2085.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants