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

Fix: #1840 feat: node 15 support #1841

Closed
wants to merge 1 commit into from
Closed

Conversation

kevcodez
Copy link

@kevcodez kevcodez commented Oct 28, 2020

  • Add Node.js 15 to package.json engine field.
  • Add Node.js version 15.x to CI build matrix.

@cla-checker-service
Copy link

cla-checker-service bot commented Oct 28, 2020

💚 CLA has been signed

@apmmachine
Copy link
Contributor

apmmachine commented Oct 28, 2020

❕ Build Aborted

The PR is not allowed to run in the CI yet

the below badges are clickable and redirect to their specific view in the CI or DOCS
Pipeline View Test View Changes Artifacts

Expand to view the summary

Build stats

  • Build Cause: Branch indexing

  • Reason: The PR is not allowed to run in the CI yet

  • Start Time: 2020-12-23T00:59:10.221+0000

  • Duration: 3 min 45 sec

  • Commit: 18b150c

Steps errors 1

Expand to view the steps failures

Error signal
  • Took 0 min 0 sec . View more details on here
  • Description: githubPrCheckApproved: The PR is not allowed to run in the CI yet. (Only users with write permission

Log output

Expand to view the last 100 lines of log output

[2020-12-23T01:01:28.560Z] Using shallow fetch with depth 3
[2020-12-23T01:01:28.561Z] Pruning obsolete local branches
[2020-12-23T01:01:29.236Z] Merging remotes/origin/master commit 4cbe2f9e85f3d23808ddbec4e2833205c4550ae8 into PR head commit 18b150c2b2f4257db315ba8e3595ab2477add142
[2020-12-23T01:01:28.504Z]  > git config remote.origin.url [email protected]:elastic/apm-agent-nodejs.git # timeout=10
[2020-12-23T01:01:28.520Z]  > git config --add remote.origin.fetch +refs/heads/*:refs/remotes/origin/* # timeout=10
[2020-12-23T01:01:28.532Z]  > git config remote.origin.url [email protected]:elastic/apm-agent-nodejs.git # timeout=10
[2020-12-23T01:01:28.541Z]  > git rev-parse --verify HEAD # timeout=10
[2020-12-23T01:01:28.553Z] No valid HEAD. Skipping the resetting
[2020-12-23T01:01:28.553Z]  > git clean -fdx # timeout=10
[2020-12-23T01:01:28.566Z] Fetching upstream changes from [email protected]:elastic/apm-agent-nodejs.git
[2020-12-23T01:01:28.566Z] using GIT_SSH to set credentials GitHub user @elasticmachine SSH key
[2020-12-23T01:01:28.571Z]  > git fetch --no-tags --progress --prune -- [email protected]:elastic/apm-agent-nodejs.git +refs/pull/1841/head:refs/remotes/origin/PR-1841 +refs/heads/master:refs/remotes/origin/master # timeout=15
[2020-12-23T01:01:29.245Z]  > git config core.sparsecheckout # timeout=10
[2020-12-23T01:01:29.256Z]  > git checkout -f 18b150c2b2f4257db315ba8e3595ab2477add142 # timeout=15
[2020-12-23T01:01:29.315Z]  > git remote # timeout=10
[2020-12-23T01:01:29.320Z]  > git config --get remote.origin.url # timeout=10
[2020-12-23T01:01:29.325Z] using GIT_SSH to set credentials GitHub user @elasticmachine SSH key
[2020-12-23T01:01:29.328Z]  > git merge 4cbe2f9e85f3d23808ddbec4e2833205c4550ae8 # timeout=10
[2020-12-23T01:01:29.444Z] Merge succeeded, producing 352011819c735c29486d8eac9dc004f6b8e25da1
[2020-12-23T01:01:29.444Z] Checking out Revision 352011819c735c29486d8eac9dc004f6b8e25da1 (PR-1841)
[2020-12-23T01:01:29.438Z]  > git rev-parse HEAD^{commit} # timeout=10
[2020-12-23T01:01:29.448Z]  > git config core.sparsecheckout # timeout=10
[2020-12-23T01:01:29.452Z]  > git checkout -f 352011819c735c29486d8eac9dc004f6b8e25da1 # timeout=15
[2020-12-23T01:01:33.085Z] Commit message: "Merge commit '4cbe2f9e85f3d23808ddbec4e2833205c4550ae8' into HEAD"
[2020-12-23T01:01:33.094Z] First time build. Skipping changelog.
[2020-12-23T01:01:33.094Z] Cleaning workspace
[2020-12-23T01:01:33.089Z]  > git rev-list --no-walk 7e82246560eeca92b03aa3f1b070b54e66fa9b43 # timeout=10
[2020-12-23T01:01:33.097Z]  > git rev-parse --verify HEAD # timeout=10
[2020-12-23T01:01:33.105Z] Resetting working tree
[2020-12-23T01:01:33.105Z]  > git reset --hard # timeout=10
[2020-12-23T01:01:33.129Z]  > git clean -fdx # timeout=10
[2020-12-23T01:01:34.024Z] Masking supported pattern matches of $JOB_GCS_BUCKET or $NOTIFY_TO
[2020-12-23T01:01:34.079Z] Timeout set to expire in 3 hr 0 min
[2020-12-23T01:01:34.093Z] The timestamps step is unnecessary when timestamps are enabled for all Pipeline builds.
[2020-12-23T01:01:34.292Z] [INFO] Number of builds to be searched 10
[2020-12-23T01:01:34.486Z] [INFO] 'shallow' is forced to be disabled when running on PullRequests
[2020-12-23T01:01:34.500Z] Running in /var/lib/jenkins/workspace/ejs_apm-agent-nodejs-mbp_PR-1841/src/github.com/elastic/apm-agent-nodejs
[2020-12-23T01:01:34.516Z] [INFO] gitCheckout: Checkout SCM PR-1841 with some customisation.
[2020-12-23T01:01:34.544Z] [INFO] Override default checkout
[2020-12-23T01:01:34.585Z] Sleeping for 10 sec
[2020-12-23T01:01:44.737Z] using credential f6c7695a-671e-4f4f-a331-acdce44ff9ba
[2020-12-23T01:01:44.874Z] Cloning the remote Git repository
[2020-12-23T01:01:44.891Z] Cloning repository [email protected]:elastic/apm-agent-nodejs.git
[2020-12-23T01:01:44.914Z]  > git init /var/lib/jenkins/workspace/ejs_apm-agent-nodejs-mbp_PR-1841/src/github.com/elastic/apm-agent-nodejs # timeout=10
[2020-12-23T01:01:44.922Z] Using reference repository: /var/lib/jenkins/.git-references/apm-agent-nodejs.git
[2020-12-23T01:01:44.923Z] Fetching upstream changes from [email protected]:elastic/apm-agent-nodejs.git
[2020-12-23T01:01:44.923Z]  > git --version # timeout=10
[2020-12-23T01:01:44.928Z]  > git --version # 'git version 2.17.1'
[2020-12-23T01:01:44.928Z] using GIT_SSH to set credentials GitHub user @elasticmachine SSH key
[2020-12-23T01:01:44.931Z]  > git fetch --tags --progress -- [email protected]:elastic/apm-agent-nodejs.git +refs/heads/*:refs/remotes/origin/* # timeout=10
[2020-12-23T01:01:46.374Z] Checking out Revision 18b150c2b2f4257db315ba8e3595ab2477add142 (origin/PR-1841)
[2020-12-23T01:01:46.426Z] Commit message: "feat: node 15 support"
[2020-12-23T01:01:46.426Z] First time build. Skipping changelog.
[2020-12-23T01:01:45.784Z]  > git config remote.origin.url [email protected]:elastic/apm-agent-nodejs.git # timeout=10
[2020-12-23T01:01:45.791Z]  > git config --add remote.origin.fetch +refs/heads/*:refs/remotes/origin/* # timeout=10
[2020-12-23T01:01:45.799Z]  > git config remote.origin.url [email protected]:elastic/apm-agent-nodejs.git # timeout=10
[2020-12-23T01:01:45.807Z] Fetching upstream changes from [email protected]:elastic/apm-agent-nodejs.git
[2020-12-23T01:01:45.807Z] using GIT_SSH to set credentials GitHub user @elasticmachine SSH key
[2020-12-23T01:01:45.811Z]  > git fetch --tags --progress -- [email protected]:elastic/apm-agent-nodejs.git +refs/pull/1841/head:refs/remotes/origin/PR-1841 +refs/heads/master:refs/remotes/origin/master # timeout=10
[2020-12-23T01:01:46.369Z]  > git rev-parse origin/PR-1841^{commit} # timeout=10
[2020-12-23T01:01:46.377Z]  > git config core.sparsecheckout # timeout=10
[2020-12-23T01:01:46.380Z]  > git checkout -f 18b150c2b2f4257db315ba8e3595ab2477add142 # timeout=10
[2020-12-23T01:01:47.402Z] Masking supported pattern matches of $GIT_USERNAME or $GIT_PASSWORD
[2020-12-23T01:01:48.185Z] + git fetch https://****:****@github.com/elastic/apm-agent-nodejs.git +refs/pull/*/head:refs/remotes/origin/pr/*
[2020-12-23T01:01:48.811Z] Running in /var/lib/jenkins/workspace/ejs_apm-agent-nodejs-mbp_PR-1841/src/github.com/elastic/apm-agent-nodejs/.git
[2020-12-23T01:01:48.841Z] Archiving artifacts
[2020-12-23T01:01:49.483Z] + git rev-parse HEAD
[2020-12-23T01:01:49.845Z] + git rev-parse HEAD
[2020-12-23T01:01:50.154Z] + git rev-parse origin/pr/1841
[2020-12-23T01:01:50.211Z] [INFO] githubEnv: Found Git Build Cause: pr
[2020-12-23T01:01:50.661Z] Masking supported pattern matches of $GITHUB_TOKEN
[2020-12-23T01:01:51.629Z] [INFO] githubPrCheckApproved: Title: Fix: #1840 feat: node 15 support - User: kevcodez - Author Association: FIRST_TIME_CONTRIBUTOR
[2020-12-23T01:01:51.894Z] ERROR: githubPrCheckApproved: The PR is not allowed to run in the CI yet
[2020-12-23T01:01:51.894Z] ERROR: githubPrCheckApproved: The PR is not allowed to run in the CI yet. (Only users with write permissions can do so.)
[2020-12-23T01:01:51.928Z] [INFO] Let's stop build #50. The PR is not allowed to run in the CI yet
[2020-12-23T01:01:51.944Z] Sleeping for 5 sec
[2020-12-23T01:01:52.956Z] Stage "Test" skipped due to earlier failure(s)
[2020-12-23T01:01:52.996Z] Stage "TAV Test" skipped due to earlier failure(s)
[2020-12-23T01:01:53.034Z] Stage "Edge Test" skipped due to earlier failure(s)
[2020-12-23T01:01:53.094Z] Stage "Nightly Test" skipped due to earlier failure(s)
[2020-12-23T01:01:53.096Z] Stage "Nightly Test - No async hooks" skipped due to earlier failure(s)
[2020-12-23T01:01:53.098Z] Stage "RC Test" skipped due to earlier failure(s)
[2020-12-23T01:01:53.099Z] Stage "RC Test - No async hooks" skipped due to earlier failure(s)
[2020-12-23T01:01:53.163Z] Failed in branch Nightly Test
[2020-12-23T01:01:53.164Z] Failed in branch Nightly Test - No async hooks
[2020-12-23T01:01:53.165Z] Failed in branch RC Test
[2020-12-23T01:01:53.165Z] Failed in branch RC Test - No async hooks
[2020-12-23T01:01:53.242Z] Stage "Integration Tests" skipped due to earlier failure(s)
[2020-12-23T01:01:53.301Z] Stage "Release" skipped due to earlier failure(s)
[2020-12-23T01:01:53.327Z] Stage "Release" skipped due to earlier failure(s)
[2020-12-23T01:01:53.417Z] Stage "Benchmarks" skipped due to earlier failure(s)
[2020-12-23T01:01:54.142Z] Running on Jenkins in /var/lib/jenkins/workspace/ejs_apm-agent-nodejs-mbp_PR-1841
[2020-12-23T01:01:54.433Z] [INFO] getVaultSecret: Getting secrets
[2020-12-23T01:01:54.838Z] Masking supported pattern matches of $VAULT_ADDR or $VAULT_ROLE_ID or $VAULT_SECRET_ID
[2020-12-23T01:01:55.890Z] + chmod 755 generate-build-data.sh
[2020-12-23T01:01:55.890Z] + ./generate-build-data.sh https://apm-ci.elastic.co/blue/rest/organizations/jenkins/pipelines/apm-agent-nodejs/apm-agent-nodejs-mbp/PR-1841/ https://apm-ci.elastic.co/blue/rest/organizations/jenkins/pipelines/apm-agent-nodejs/apm-agent-nodejs-mbp/PR-1841/runs/50 ABORTED 165406
[2020-12-23T01:01:56.441Z] INFO: curl https://apm-ci.elastic.co/blue/rest/organizations/jenkins/pipelines/apm-agent-nodejs/apm-agent-nodejs-mbp/PR-1841/runs/50/steps/?limit=10000 -o steps-info.json
[2020-12-23T01:01:56.992Z] INFO: curl https://apm-ci.elastic.co/blue/rest/organizations/jenkins/pipelines/apm-agent-nodejs/apm-agent-nodejs-mbp/PR-1841/runs/50/tests/?status=FAILED -o tests-errors.json
[2020-12-23T01:01:57.242Z] Retry 1/3 exited 22, retrying in 1 seconds...
[2020-12-23T01:01:58.154Z] Retry 2/3 exited 22, retrying in 2 seconds...

@kevcodez kevcodez changed the title #1840 feat: node 15 support Fix: #1840 feat: node 15 support Oct 28, 2020
@astorm
Copy link
Contributor

astorm commented Oct 28, 2020

@kevcodez -- thanks for the contribution (and the gentle reminder 😄). The CI errors you're seeing are not Node 15 related -- ioredis released a change that broke support in node 8 (which is their prerogative, of course 😄 ). We've got an issue open to get our CI adjusted. Once we have that adjusted, we can rerun the jobs here and see how Node 15 does.

Copy link
Member

@trentm trentm left a comment

Choose a reason for hiding this comment

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

@kevcodez Thanks!

@@ -1,4 +1,6 @@
NODEJS_VERSION:
- "15"
- "15.0"
Copy link
Member

Choose a reason for hiding this comment

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

How about dropping "15.0" and just have "15" here? I'm inclined to not bother explicitly supporting the first minor-level release of odd (i.e. non-LTS) node releases (https://github.com/nodejs/Release#release-phases). IMO, the main value of supporting the odd-numbered releases is to (a) prepare for changes coming in the subsequent even-numbered LTS release and (b) to help users of this module that are doing the same.

@astorm Do you have an opinion?

Copy link
Author

Choose a reason for hiding this comment

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

I don't know if I have a say in this :D However, this seems very reasonable. V15 will not receive any support in 6 months from now anyway

@trentm
Copy link
Member

trentm commented Oct 29, 2020

jenkins run the tests

@trentm
Copy link
Member

trentm commented Oct 30, 2020

@kevcodez Can you force push with an updated commit message to pass the "commitlint" check, please.
https://travis-ci.org/github/elastic/apm-agent-nodejs/jobs/739539145

Something like the following should work I think:

feat: node 15 support

Fixes #1840

@trentm
Copy link
Member

trentm commented Oct 30, 2020

There is a test failure with node v15 that I haven't looked into yet: https://travis-ci.org/github/elastic/apm-agent-nodejs/jobs/739539136

Have you been able to run the tests (npm test, requires docker) locally with node v15?

@kevcodez
Copy link
Author

kevcodez commented Oct 30, 2020

Force pushed the commit message.

@kevcodez
Copy link
Author

Locally, the test neither runs with Node 14 or 15.

@kevcodez
Copy link
Author

kevcodez commented Nov 6, 2020

@trentm Node 15 uses NPM 7 which seems to properly check peer dependencies. apm-agent-nodejs uses graphql 15.x and express-graphl 0.9.x (which only supports graphl 14.x).

Downgrading to graphql 14.x breaks three tests. Upgrading express-graphql to 0.11.x also breaks tests, could you have a look?

@trentm trentm added the agent-nodejs Make available for APM Agents project planning. label Nov 16, 2020
@trentm
Copy link
Member

trentm commented Nov 23, 2020

@kevcodez Sorry I dropped the ball here for a while. I'll try to take a look soon.

@trentm
Copy link
Member

trentm commented Nov 23, 2020

FWIW, that peerDeps failure from npm 7 looks like this:

% TAV=graphql ./node_modules/.bin/tav
-- running preinstall "npm uninstall express-graphql" for graphql
...
-- required packages ["[email protected]"]
-- installing ["[email protected]"]
-- error installing ["[email protected]"] (npm ERR! code ERESOLVE
npm ERR! ERESOLVE unable to resolve dependency tree
npm ERR!
npm ERR! Found: [email protected]
npm ERR! node_modules/graphql
npm ERR!   dev graphql@"15.4.0" from the root project
npm ERR!   peer graphql@"^0.12.0 || ^0.13.0 || ^14.0.0 || ^15.0.0" from [email protected]
npm ERR!   node_modules/apollo-cache-control
npm ERR!     apollo-cache-control@"^0.11.4" from [email protected]
npm ERR!     node_modules/apollo-server-core
npm ERR!       apollo-server-core@"^2.19.0" from [email protected]
npm ERR!       node_modules/apollo-server-express
npm ERR!         dev apollo-server-express@"^2.10.1" from the root project
npm ERR!   14 more (apollo-graphql, apollo-link, apollo-server-core, ...)
npm ERR!
npm ERR! Could not resolve dependency:
npm ERR! peer graphql@"^14.4.1" from [email protected]
npm ERR! node_modules/express-graphql
npm ERR!
npm ERR! Fix the upstream dependency conflict, or retry
npm ERR! this command with --force, or --legacy-peer-deps
npm ERR! to accept an incorrect (and potentially broken) dependency resolution.
npm ERR!
npm ERR! See /Users/trentm/.npm/eresolve-report.txt for a full report.

npm ERR! A complete log of this run can be found in:
npm ERR!     /Users/trentm/.npm/_logs/2020-11-23T23_01_04_198Z-debug.log

One potential workaround is https://docs.npmjs.com/cli/v7/using-npm/config#legacy-peer-deps
e.g.:

% npm_config_legacy_peer_deps=true TAV=graphql ./node_modules/.bin/tav --compat
Testing compatibility with graphql:
✔ 15.4.0
✔ 14.7.0
✔ 15.3.0
✔ 15.2.0
✔ 15.1.0
✔ 15.0.0
...

@trentm
Copy link
Member

trentm commented Nov 23, 2020

@kevcodez How about as a start you add this patch to your branch:

diff --git a/.npmrc b/.npmrc
index 43c97e7..76c904f 100644
--- a/.npmrc
+++ b/.npmrc
@@ -1 +1,9 @@
 package-lock=false
+
+# Workaround unresolvable peerDependencies between express-graphql, graphql,
+# and apollo-server-express. npm v7 (included with node v15) makes these
+# peerDependencies issues an install error. Until the community catches up
+# and resolves peerDependencies issues or this modules tests are setup to
+# not have competing deps in "devDependencies", we revert to the pre-v7
+# behavior. https://docs.npmjs.com/cli/v7/using-npm/config#legacy-peer-deps
+legacy-peer-deps=true
diff --git a/package.json b/package.json
index c470099..596a389 100644
--- a/package.json
+++ b/package.json
@@ -145,7 +145,7 @@
     "generic-pool": "^3.7.1",
     "get-port": "^5.1.1",
     "got": "^9.6.0",
-    "graphql": "^14.7.0",
+    "graphql": "^15.4.0",
     "handlebars": "^4.7.3",
     "hapi": "^18.1.0",
     "https-pem": "^2.0.0",

Also it would be good if you could merge in recent changes from master (or rebase on master, whichever you prefer).

After the above patch I still see 3 errors from npm test, which I think are more likely real issues with node v15 interaction.

@kevcodez
Copy link
Author

@trentm Rebased on master, added your patch.

I've seen that the transaction result is success rather than HTTP 2xx, which is the fallback if it cannot be determined. Seems like the instrumentation does not work in Node 15.

Trying to get the tests to run locally...

@trentm
Copy link
Member

trentm commented Nov 27, 2020

Failures in "test/instrumentation/modules/http/aborted-requests-enabled.js" with node v15:

% node test/instrumentation/modules/http/aborted-requests-enabled.js
TAP version 13
# client-side abort below error threshold - call end
ok 1 should not have any samples to begin with
ok 2 client request should emit ECONNRESET error
ok 3 should have one transaction
ok 4 should have zero spans
ok 5 should have expected transaction name
ok 6 should have expected transaction type
ok 7 should have expected transaction result
ok 8 should have expected transaction context.request.method
ok 9 should send transaction
# client-side abort above error threshold - call end
ok 10 should not have any samples to begin with
ok 11 should be strictly equal
ok 12 should be truthy
ok 13 should have one transaction
ok 14 should have zero spans
ok 15 should have expected transaction name
ok 16 should have expected transaction type
not ok 17 should have expected transaction result
  ---
    operator: equal
    expected: 'HTTP 2xx'
    actual:   'success'
    at: assert (/Users/trentm/el/apm-agent-nodejs-node15/test/instrumentation/modules/http/_assert.js:13:5)
    stack: |-
      Error: should have expected transaction result
          at Test.assert [as _assert] (/Users/trentm/el/apm-agent-nodejs-node15/node_modules/tape/lib/test.js:260:54)
          at Test.bound [as _assert] (/Users/trentm/el/apm-agent-nodejs-node15/node_modules/tape/lib/test.js:84:32)
          at Test.strictEqual (/Users/trentm/el/apm-agent-nodejs-node15/node_modules/tape/lib/test.js:424:10)
          at Test.bound [as strictEqual] (/Users/trentm/el/apm-agent-nodejs-node15/node_modules/tape/lib/test.js:84:32)
          at assert (/Users/trentm/el/apm-agent-nodejs-node15/test/instrumentation/modules/http/_assert.js:13:5)
          at /Users/trentm/el/apm-agent-nodejs-node15/test/instrumentation/modules/http/aborted-requests-enabled.js:66:5
          at Object._write (/Users/trentm/el/apm-agent-nodejs-node15/test/_mock_http_client.js:40:50)
          at Object.sendTransaction (/Users/trentm/el/apm-agent-nodejs-node15/test/_mock_http_client.js:47:12)
          at Instrumentation.addEndedTransaction (/Users/trentm/el/apm-agent-nodejs-node15/lib/instrumentation/index.js:215:22)
          at Instrumentation.wrappedAddEndedTransaction (/Users/trentm/el/apm-agent-nodejs-node15/lib/instrumentation/async-hooks.js:62:34)
  ...
ok 18 should have expected transaction context.request.method
ok 19 should send transactions
# client-side abort below error threshold - don't call end
ok 20 should not have any samples to begin with
# client-side abort above error threshold - don't call end
ok 21 should not have any samples to begin with
ok 22 should be strictly equal
ok 23 should be truthy
# server-side abort below error threshold and socket closed - call end
ok 24 should not have any samples to begin with
ok 25 should have closed socket
ok 26 should not have ended transaction
ok 27 should have one transaction
ok 28 should have zero spans
ok 29 should have expected transaction name
ok 30 should have expected transaction type
not ok 31 should have expected transaction result
  ---
    operator: equal
    expected: 'HTTP 2xx'
    actual:   'success'
    at: assert (/Users/trentm/el/apm-agent-nodejs-node15/test/instrumentation/modules/http/_assert.js:13:5)
    stack: |-
      Error: should have expected transaction result
          at Test.assert [as _assert] (/Users/trentm/el/apm-agent-nodejs-node15/node_modules/tape/lib/test.js:260:54)
          at Test.bound [as _assert] (/Users/trentm/el/apm-agent-nodejs-node15/node_modules/tape/lib/test.js:84:32)
          at Test.strictEqual (/Users/trentm/el/apm-agent-nodejs-node15/node_modules/tape/lib/test.js:424:10)
          at Test.bound [as strictEqual] (/Users/trentm/el/apm-agent-nodejs-node15/node_modules/tape/lib/test.js:84:32)
          at assert (/Users/trentm/el/apm-agent-nodejs-node15/test/instrumentation/modules/http/_assert.js:13:5)
          at Object._write (/Users/trentm/el/apm-agent-nodejs-node15/test/_mock_http_client.js:40:50)
          at Object.sendTransaction (/Users/trentm/el/apm-agent-nodejs-node15/test/_mock_http_client.js:47:12)
          at Instrumentation.addEndedTransaction (/Users/trentm/el/apm-agent-nodejs-node15/lib/instrumentation/index.js:215:22)
          at Instrumentation.wrappedAddEndedTransaction (/Users/trentm/el/apm-agent-nodejs-node15/lib/instrumentation/async-hooks.js:62:34)
          at Instrumentation.agent._instrumentation.addEndedTransaction (/Users/trentm/el/apm-agent-nodejs-node15/test/instrumentation/modules/http/aborted-requests-enabled.js:194:25)
  ...
ok 32 should have expected transaction context.request.method
ok 33 should send transactions
ok 34 should have ended transaction
# server-side abort above error threshold and socket closed - call end
ok 35 should not have any samples to begin with
ok 36 should be strictly equal
ok 37 should be truthy
ok 38 should have closed socket
ok 39 should not have ended transaction
ok 40 should have one transaction
ok 41 should have zero spans
ok 42 should have expected transaction name
ok 43 should have expected transaction type
not ok 44 should have expected transaction result
  ---
    operator: equal
    expected: 'HTTP 2xx'
    actual:   'success'
    at: assert (/Users/trentm/el/apm-agent-nodejs-node15/test/instrumentation/modules/http/_assert.js:13:5)
    stack: |-
      Error: should have expected transaction result
          at Test.assert [as _assert] (/Users/trentm/el/apm-agent-nodejs-node15/node_modules/tape/lib/test.js:260:54)
          at Test.bound [as _assert] (/Users/trentm/el/apm-agent-nodejs-node15/node_modules/tape/lib/test.js:84:32)
          at Test.strictEqual (/Users/trentm/el/apm-agent-nodejs-node15/node_modules/tape/lib/test.js:424:10)
          at Test.bound [as strictEqual] (/Users/trentm/el/apm-agent-nodejs-node15/node_modules/tape/lib/test.js:84:32)
          at assert (/Users/trentm/el/apm-agent-nodejs-node15/test/instrumentation/modules/http/_assert.js:13:5)
          at Object._write (/Users/trentm/el/apm-agent-nodejs-node15/test/_mock_http_client.js:40:50)
          at Object.sendTransaction (/Users/trentm/el/apm-agent-nodejs-node15/test/_mock_http_client.js:47:12)
          at Instrumentation.addEndedTransaction (/Users/trentm/el/apm-agent-nodejs-node15/lib/instrumentation/index.js:215:22)
          at Instrumentation.wrappedAddEndedTransaction (/Users/trentm/el/apm-agent-nodejs-node15/lib/instrumentation/async-hooks.js:62:34)
          at Instrumentation.agent._instrumentation.addEndedTransaction (/Users/trentm/el/apm-agent-nodejs-node15/test/instrumentation/modules/http/aborted-requests-enabled.js:237:25)
  ...
ok 45 should have expected transaction context.request.method
ok 46 should send transactions
ok 47 should have ended transaction
# server-side abort below error threshold and socket closed - don't call end
ok 48 should not have any samples to begin with
ok 49 should have closed socket
ok 50 should not have ended transaction
# server-side abort above error threshold and socket closed - don't call end
ok 51 should not have any samples to begin with
ok 52 should be strictly equal
ok 53 should be truthy
ok 54 should have closed socket
ok 55 should have ended transaction
# server-side abort below error threshold but socket not closed - call end
ok 56 should not have any samples to begin with
ok 57 should have one transaction
ok 58 should have zero spans
ok 59 should have expected transaction name
ok 60 should have expected transaction type
ok 61 should have expected transaction result
ok 62 should have expected transaction context.request.method
ok 63 should send transactions
# server-side abort above error threshold but socket not closed - call end
ok 64 should not have any samples to begin with
ok 65 should have one transaction
ok 66 should have zero spans
ok 67 should have expected transaction name
ok 68 should have expected transaction type
ok 69 should have expected transaction result
ok 70 should have expected transaction context.request.method
ok 71 should send transactions

1..71
# tests 71
# pass  68
# fail  3

These are happening because of this change in node v15: https://github.com/nodejs/node/pull/31818/files#diff-48d21edbddb6e855d1ee5716c49bcdc0d913c11ee8a24a98ea7dbc60cd253556L661-R706
This changed the behaviour of res.write such that res.writeHead() is not called if the server socket has ended. Some of the test code here (the check of trans.result) depends on writeHead being called, because the agent wraps that call to set trans.result. The workaround is to explicitly res.writeHead() before whatever actions in the various tests result in the server socket being closed. Note that for the earlier tests there was a race between (a) closing the client-side of the socket resulting eventually in the server-side socket closing and (b) the test code calling the first res.send() in a setTimeout.

@kevcodez Can you add this patch to your branch, please: https://gist.github.com/trentm/8dd8d2e35958d2624f797d53d75c3609

@trentm
Copy link
Member

trentm commented Nov 27, 2020

After that change the regular test suite (npm test) passes for me.

@kevcodez
Copy link
Author

@trentm Thank you for helping out. 🍻 I was unable to get the tests to run on my Mac so this was impossible to test for me.

Rebased with master, applied your diff, squashed the commits. The tests pass.

@trentm
Copy link
Member

trentm commented Nov 30, 2020

jenkins run the tests

@trentm
Copy link
Member

trentm commented Nov 30, 2020

jenkins run the module tests

@trentm
Copy link
Member

trentm commented Nov 30, 2020

@elasticmachine, run elasticsearch-ci/docs

@trentm
Copy link
Member

trentm commented Nov 30, 2020

jenkins run the module tests for ALL

@trentm
Copy link
Member

trentm commented Nov 30, 2020

Failures with the "hapi" test-all-versions tests:

% TAV=hapi ./node_modules/.bin/tav --compat
Testing compatibility with hapi:
✔ 17.8.5
✖ 18.1.0
✔ 17.8.4
✖ 18.0.1
✔ 17.8.3
✔ 17.8.2
✖ 18.0.0
✔ 17.8.1
✔ 17.8.0
✔ 17.7.0
✖ 17.6.4
✔ 17.6.3
✔ 17.6.2
✔ 17.6.1
✔ 17.6.0
✔ 17.5.5
✔ 17.5.4
✔ 17.5.3
✔ 17.5.2
✔ 17.5.1
✔ 17.5.0
✔ 17.4.0
✔ 17.3.1
✔ 17.3.0
✔ 17.2.3
✔ 17.2.2
✔ 17.2.1
✔ 17.2.0
✔ 17.1.1
✔ 17.1.0
✔ 17.0.2
✔ 17.0.1
✔ 17.0.0
✔ 16.7.0
✔ 16.6.5
✔ 16.6.4
✔ 16.6.3
✔ 16.6.2
✔ 16.6.1
✔ 16.6.0
✔ 16.5.2
✔ 16.5.1
✔ 16.5.0
✔ 16.4.3
✔ 16.4.2
✔ 16.4.1
✔ 16.4.0
✔ 16.3.1
✔ 16.3.0
✔ 16.2.0
✔ 16.1.1
✔ 16.1.0
✔ 16.0.3
✔ 16.0.2
✔ 16.0.1
✔ 16.0.0

Ouch, a re-run of that shows inconsistency on which hapi versions there are errors with:

% TAV=hapi ./node_modules/.bin/tav --compat
Testing compatibility with hapi:
✖ 17.8.5
✔ 18.1.0
✖ 17.8.4
✔ 18.0.1
✖ 17.8.3
✔ 17.8.2
✖ 18.0.0
✔ 17.8.1
✔ 17.8.0
✔ 17.7.0
✖ 17.6.4
✔ 17.6.3
✔ 17.6.2
✔ 17.6.1
✔ 17.6.0
✔ 17.5.5
✔ 17.5.4
✔ 17.5.3
✔ 17.5.2
✔ 17.5.1
✔ 17.5.0
✔ 17.4.0
✔ 17.3.1
✔ 17.3.0
✔ 17.2.3
✔ 17.2.2
✔ 17.2.1
✔ 17.2.0
✔ 17.1.1
✔ 17.1.0
✔ 17.0.2
✔ 17.0.1
✔ 17.0.0

✔ 16.7.0
✔ 16.6.5
✔ 16.6.4
✔ 16.6.3
✔ 16.6.2
✔ 16.6.1
✔ 16.6.0
✔ 16.5.2
✔ 16.5.1
✔ 16.5.0
✔ 16.4.3
✔ 16.4.2
✔ 16.4.1
✔ 16.4.0
✔ 16.3.1
✔ 16.3.0
✔ 16.2.0
✔ 16.1.1
✔ 16.1.0
✔ 16.0.3
✔ 16.0.2
✔ 16.0.1
✔ 16.0.0

There is some bug in installing the hapi module when there is already a hapi module installed:

% rm -rf node_modules/hapi

% npm install [email protected]
npm WARN deprecated [email protected]: This version contains severe security issues and defects and should not be used! Please upgrade to the latest version of @hapi/hapi or consider a commercial license (https://github.com/hapijs/hapi/issues/4114)

added 30 packages, and audited 1703 packages in 4s

91 packages are looking for funding
  run `npm fund` for details

24 vulnerabilities (12 low, 10 high, 2 critical)

To address issues that do not require attention, run:
  npm audit fix

To address all issues possible (including breaking changes), run:
  npm audit fix --force

Some issues need review, and may require choosing
a different dependency.

Run `npm audit` for details.

% ls node_modules/hapi
LICENSE             lib                 npm-shrinkwrap.json
README.md           node_modules        package.json

% npm install [email protected]

removed 1 package, changed 1 package, and audited 1702 packages in 3s

91 packages are looking for funding
  run `npm fund` for details

24 vulnerabilities (12 low, 10 high, 2 critical)

To address issues that do not require attention, run:
  npm audit fix

To address all issues possible (including breaking changes), run:
  npm audit fix --force

Some issues need review, and may require choosing
a different dependency.

Run `npm audit` for details.

% ls node_modules/hapi
node_modules

The "hapi" module installation is now broken.

@trentm
Copy link
Member

trentm commented Nov 30, 2020

SPecifically the error we get from testing is a failure to load "node_modules/hapi/package.json":

-- running test "node test/instrumentation/modules/hapi/basic-legacy-path.js" with hapi
node:internal/modules/cjs/loader:922
  throw err;
  ^

Error: Cannot find module 'hapi/package.json'
Require stack:
- /Users/trentm/el/apm-agent-nodejs-node15/test/instrumentation/modules/hapi/shared.js
- /Users/trentm/el/apm-agent-nodejs-node15/test/instrumentation/modules/hapi/basic-legacy-path.js
    at Function.Module._resolveFilename (node:internal/modules/cjs/loader:919:15)
    at Module.Hook._require.Module.require (/Users/trentm/el/apm-agent-nodejs-node15/node_modules/require-in-the-middle/index.js:61:29)
    at require (node:internal/modules/cjs/helpers:92:18)
    at module.exports (/Users/trentm/el/apm-agent-nodejs-node15/test/instrumentation/modules/hapi/shared.js:12:13)
    at Object.<anonymous> (/Users/trentm/el/apm-agent-nodejs-node15/test/instrumentation/modules/hapi/basic-legacy-path.js:3:20)
    at Module._compile (node:internal/modules/cjs/loader:1102:14)
    at Object.Module._extensions..js (node:internal/modules/cjs/loader:1131:10)
    at Module.load (node:internal/modules/cjs/loader:967:32)
    at Function.Module._load (node:internal/modules/cjs/loader:807:14)
    at Function.executeUserEntryPoint [as runMain] (node:internal/modules/run_main:76:12)
    at node:internal/main/run_main_module:17:47 {
  code: 'MODULE_NOT_FOUND',
  requireStack: [
    '/Users/trentm/el/apm-agent-nodejs-node15/test/instrumentation/modules/hapi/shared.js',
    '/Users/trentm/el/apm-agent-nodejs-node15/test/instrumentation/modules/hapi/basic-legacy-path.js'
  ]
}
-- fatal: Test exited with code 1

because npm@7 failed to install that correctly when changing hapi versions.

"Silly"-level logging from npm doesn't show anything obvious:

% npm -ddd install [email protected]
npm verb cli [
npm verb cli   '/Users/trentm/.nvm/versions/node/v15.2.1/bin/node',
npm verb cli   '/Users/trentm/.nvm/versions/node/v15.2.1/bin/npm',
npm verb cli   '-ddd',
npm verb cli   'install',
npm verb cli   '[email protected]'
npm verb cli ]
npm info using [email protected]
npm info using [email protected]
npm timing config:load:defaults Completed in 1ms
npm timing config:load:file:/Users/trentm/.nvm/versions/node/v15.2.1/lib/node_modules/npm/npmrc Completed in 1ms
npm timing config:load:builtin Completed in 1ms
npm timing config:load:cli Completed in 1ms
npm timing config:load:env Completed in 0ms
npm timing config:load:file:/Users/trentm/tmp/p/.npmrc Completed in 1ms
npm timing config:load:project Completed in 1ms
npm timing config:load:file:/Users/trentm/.npmrc Completed in 0ms
npm timing config:load:user Completed in 0ms
npm timing config:load:file:/Users/trentm/.nvm/versions/node/v15.2.1/etc/npmrc Completed in 1ms
npm timing config:load:global Completed in 1ms
npm timing config:load:cafile Completed in 0ms
npm timing config:load:validate Completed in 0ms
npm timing config:load:setUserAgent Completed in 0ms
npm timing config:load:setEnvs Completed in 1ms
npm timing config:load Completed in 6ms
npm verb npm-session e6e0b0d22c4d0b6d
npm timing npm:load Completed in 13ms
npm timing arborist:ctor Completed in 0ms
npm timing arborist:ctor Completed in 0ms
npm timing arborist:ctor Completed in 0ms
npm timing arborist:ctor Completed in 0ms
npm timing idealTree:init Completed in 40ms
npm timing idealTree:userRequests Completed in 0ms
npm sill idealTree buildDeps
npm sill fetch manifest [email protected]
npm http fetch GET 304 https://registry.npmjs.org/hapi 227ms (from cache)
npm sill placeDep ROOT [email protected] REPLACE for: [email protected] want: 18.1.0
npm sill fetch manifest [email protected]
npm http fetch GET 304 https://registry.npmjs.org/catbox-memory 74ms (from cache)
npm timing idealTree:#root Completed in 314ms
npm timing idealTree:buildDeps Completed in 314ms
npm timing idealTree:fixDepFlags Completed in 1ms
npm timing idealTree Completed in 358ms
npm timing reify:loadTrees Completed in 358ms
npm sill reify mark deleted [ '/Users/trentm/tmp/p/node_modules/hapi/node_modules/catbox-memory' ]
npm timing reify:diffTrees Completed in 1ms
npm sill reify mark retired [ '/Users/trentm/tmp/p/node_modules/hapi' ]
npm sill reify moves {
npm sill reify   '/Users/trentm/tmp/p/node_modules/hapi': '/Users/trentm/tmp/p/node_modules/.hapi-lcBLvRVs'
npm sill reify }
npm timing reify:retireShallow Completed in 1ms
npm timing reify:createSparse Completed in 0ms
npm timing reify:loadBundles Completed in 0ms
npm timing reify:unpack Completed in 0ms
npm timing reify:unretire Completed in 14ms
npm timing build:queue Completed in 0ms
npm timing build:deps Completed in 1ms
npm timing build Completed in 1ms
npm timing reify:build Completed in 1ms
npm timing reify:trash Completed in 10ms
npm timing reify:save Completed in 1ms
npm http fetch POST 200 https://registry.npmjs.org/-/npm/v1/security/advisories/bulk 135ms
npm timing auditReport:getReport Completed in 136ms
npm timing metavuln:cache:get:security-advisory:subtext:oKYQwvhR5kwQssnktXzQ6W3L27waJ/Mr7dKrYCFFM/Yjh9ogDy5F6MsdiN/dUfXy5oJGoAOh4a/orB269Ekdxw== Completed in 5ms
npm timing metavuln:cache:get:security-advisory:subtext:nzUg9UxPhqzovhDi7aOE43X63xwWz+qYxUOxyAYWT+W636daW6k3SCfSQB+AOvwZDfL8hdoPR7yYaK0l0ahqqg== Completed in 4ms
npm timing metavuln:cache:get:security-advisory:subtext:13DBX2fwExKkK/5bkq8Ak3efuNOY/YBpaR4X4iR5oP3CwYOb3yLo5o2o3mHIOoIlO5/ECpyZWpAZejO9wY9ciw== Completed in 4ms
npm timing metavuln:cache:get:security-advisory:hapi:l73apeluL7Sebbn4INsXYbw+q9Gxe65B0y11U5nMP89dKQHopD6hwL+o9/EFFg+d4eGhhhiD3bUstwQblq+wjA== Completed in 4ms
npm timing metavuln:cache:get:security-advisory:ammo:8nZa7zHAHPQb3vTvWlns+sG0cpP26FQTgEZo3boGLpSX8NUo3Dt7ntQcUSelErICzXtxqmOMSXwy/QjcA2nOMg== Completed in 5ms
npm http fetch GET 304 https://registry.npmjs.org/subtext 107ms (from cache)
npm timing metavuln:packument:subtext Completed in 108ms
npm timing metavuln:load:security-advisory:subtext:1168 Completed in 0ms
npm timing metavuln:calculate:security-advisory:subtext:1168 Completed in 109ms
npm timing metavuln:load:security-advisory:subtext:1479 Completed in 1ms
npm timing metavuln:calculate:security-advisory:subtext:1479 Completed in 108ms
npm timing metavuln:load:security-advisory:subtext:1478 Completed in 0ms
npm timing metavuln:calculate:security-advisory:subtext:1478 Completed in 108ms
npm http fetch GET 304 https://registry.npmjs.org/hapi 179ms (from cache)
npm timing metavuln:packument:hapi Completed in 182ms
npm timing metavuln:load:security-advisory:hapi:1481 Completed in 3ms
npm timing metavuln:calculate:security-advisory:hapi:1481 Completed in 185ms
npm http fetch GET 304 https://registry.npmjs.org/ammo 187ms (from cache)
npm timing metavuln:packument:ammo Completed in 187ms
npm timing metavuln:load:security-advisory:ammo:1472 Completed in 0ms
npm timing metavuln:calculate:security-advisory:ammo:1472 Completed in 188ms
npm timing metavuln:cache:get:security-advisory:hapi:pvoq1zCHPnYLO32R20NII4WRsIibhhbhBwO4g4d6INaaAktr0/4HZ2SV+l0Z4e5aL3YvG3vqJ/cUjI9l15uZnQ== Completed in 1ms
npm timing metavuln:load:security-advisory:hapi:oKYQwvhR5kwQssnktXzQ6W3L27waJ/Mr7dKrYCFFM/Yjh9ogDy5F6MsdiN/dUfXy5oJGoAOh4a/orB269Ekdxw== Completed in 1ms
npm timing metavuln:calculate:security-advisory:hapi:oKYQwvhR5kwQssnktXzQ6W3L27waJ/Mr7dKrYCFFM/Yjh9ogDy5F6MsdiN/dUfXy5oJGoAOh4a/orB269Ekdxw== Completed in 2ms
npm timing metavuln:cache:get:security-advisory:hapi:Ktpnvmo19YkApJcVVCfbRmeeA9ayBYQHNqTqgfCmDkT9uxa/RSrB6CU09jVRXXMsqcf42JGG7kf18zBp0T8rTA== Completed in 2ms
npm timing metavuln:load:security-advisory:hapi:8nZa7zHAHPQb3vTvWlns+sG0cpP26FQTgEZo3boGLpSX8NUo3Dt7ntQcUSelErICzXtxqmOMSXwy/QjcA2nOMg== Completed in 1ms
npm timing metavuln:calculate:security-advisory:hapi:8nZa7zHAHPQb3vTvWlns+sG0cpP26FQTgEZo3boGLpSX8NUo3Dt7ntQcUSelErICzXtxqmOMSXwy/QjcA2nOMg== Completed in 3ms
npm timing auditReport:init Completed in 315ms
npm timing reify:audit Completed in 451ms
npm timing reify Completed in 813ms
npm sill CHANGE node_modules/hapi
npm sill REMOVE node_modules/hapi/node_modules/catbox-memory

removed 1 package, changed 1 package, and audited 29 packages in 964ms

3 high severity vulnerabilities

Some issues need review, and may require choosing
a different dependency.

Run `npm audit` for details.
npm timing command:install Completed in 825ms
npm verb exit 0
npm timing npm Completed in 975ms
npm info ok

% ls node_modules/hapi
node_modules

I get the same behaviour with the latest npm 7.x installed.

My guess is that there is some race in npm when attempting to change "node_modules/hapi" versions and that it is more likely to be hit with the larger set of deps that "hapi" has. I don't think that is a very solid guess because I reliably hit it on both the Jenkins build agent and on my dev mac. It appears to happen when moving between a hapi@17 and hapi@18.

I don't see an obviously related issue at: https://github.com/npm/cli/issues?q=is%3Aissue+is%3Aopen+label%3A%22Release+7.x%22

I've opened npm/cli#2267 for this.

@trentm
Copy link
Member

trentm commented Nov 30, 2020

I have a patch to work around that npm issue for now:

https://gist.github.com/trentm/9103d7ea9f2db2e7ec8fa21ac712f200

@kevcodez Are you able to add this to your branch?
Also, if you could merge in recent changes from master, that would help as well. Thanks!

[11:44:55 trentm@pink:~/el/apm-agent-nodejs-node15 (n:15 git:master)]
% TAV=hapi ./node_modules/.bin/tav --compat
Testing compatibility with hapi:
✔ 17.8.5
✔ 18.1.0
✔ 17.8.4
✔ 18.0.1
✔ 17.8.3
✔ 17.8.2
✔ 18.0.0
✔ 17.8.1
✔ 17.8.0
✔ 17.7.0
✔ 17.6.4
✔ 17.6.3
✔ 17.6.2
✔ 17.6.1
✔ 17.6.0
✔ 17.5.5
✔ 17.5.4
✔ 17.5.3
✔ 17.5.2
✔ 17.5.1
✔ 17.5.0
✔ 17.4.0
✔ 17.3.1
✔ 17.3.0
✔ 17.2.3
✔ 17.2.2
✔ 17.2.1
✔ 17.2.0
✔ 17.1.1
✔ 17.1.0
✔ 17.0.2
✔ 17.0.1
✔ 17.0.0

✔ 16.7.0
✔ 16.6.5
✔ 16.6.4
✔ 16.6.3
✔ 16.6.2
✔ 16.6.1
✔ 16.6.0
✔ 16.5.2
✔ 16.5.1
✔ 16.5.0
✔ 16.4.3
✔ 16.4.2
✔ 16.4.1
✔ 16.4.0
✔ 16.3.1
✔ 16.3.0
✔ 16.2.0
✔ 16.1.1
✔ 16.1.0
✔ 16.0.3
✔ 16.0.2
✔ 16.0.1
✔ 16.0.0

@kevcodez
Copy link
Author

@trentm Rebased on master, applied your patch.

@trentm
Copy link
Member

trentm commented Nov 30, 2020

jenkins run the module tests for ALL

@trentm
Copy link
Member

trentm commented Dec 1, 2020

Sigh. Next set of failures is the "express" TAV tests:

% TAV=express ./node_modules/.bin/tav --compat
Testing compatibility with express:
✔ 4.17.1
✔ 4.17.0
✔ 4.16.4
✔ 4.16.3
✔ 4.16.2
✔ 4.16.1
✔ 4.16.0
✔ 4.15.5
✔ 4.15.4
✔ 4.15.3
✔ 4.15.2
✔ 4.15.1
✔ 4.15.0
✔ 4.14.1
✔ 4.14.0
✔ 4.13.4
✔ 4.13.3
✔ 4.13.2
✔ 4.13.1
✔ 4.13.0
✔ 4.12.4
✔ 4.12.3
✔ 4.12.2
✔ 4.12.1
✔ 4.12.0
✔ 4.11.2
✔ 4.11.1
✔ 4.11.0
✔ 4.10.8
✔ 4.10.7
✔ 4.10.6
✔ 4.10.5
✖ 4.10.4
✖ 4.10.3
✖ 4.10.2
✖ 4.10.1
✖ 4.10.0
✖ 4.9.8
✖ 4.9.7
✖ 4.9.6
✖ 4.9.5
✖ 4.9.4
✖ 4.9.3
✖ 4.9.2
✖ 4.9.1
✖ 4.9.0
✖ 4.8.8
✖ 4.8.7
✖ 4.8.6
✖ 4.8.5
✖ 4.8.4
✖ 4.8.3
✖ 4.8.2
✖ 4.8.1
✖ 4.8.0
✖ 4.7.4
✖ 4.7.3
✖ 4.7.2
✖ 4.7.1
✖ 4.7.0
✖ 4.6.1
✖ 4.6.0
✔ 4.5.1
✔ 4.5.0
✔ 4.4.5
✔ 4.4.4
✔ 4.4.3
✔ 4.4.2
✔ 4.4.1
✔ 4.4.0
✔ 4.3.2
✔ 4.3.1
✔ 4.3.0
✔ 4.2.0
✔ 4.1.2
✔ 4.1.1
✔ 4.1.0
✔ 4.0.0

I'm looking.

@trentm
Copy link
Member

trentm commented Dec 1, 2020

@kevcodez I noticed your current rebased commit has changed all (or most) uses of single-quotes in ".tav.yml" to double-quotes. Would you be able to revert that change. It adds noise to the diff. Was that done by some normalization in your editor, perhaps?

@trentm
Copy link
Member

trentm commented Dec 1, 2020

The TAV=express failure is in this test:

% node test/instrumentation/modules/express/basic.js
TAP version 13
# app.use('/') - GET /
(node:50967) [DEP0066] DeprecationWarning: OutgoingMessage.prototype._headers is deprecated
(Use `node --trace-deprecation ...` to show where the warning was created)
ok 1 has a transaction
ok 2 transaction name is GET unknown route
ok 3 transaction type is request
ok 4 null
ok 5 should have expected response body
# app.use('/') - POST /
ok 6 has a transaction
ok 7 transaction name is POST unknown route
ok 8 transaction type is request
ok 9 null
ok 10 should have expected response body
# app.get('/') - GET /
ok 11 has a transaction
ok 12 transaction name is GET /
ok 13 transaction type is request
ok 14 null
ok 15 should have expected response body
# app.post('/') - POST /
ok 16 has a transaction
ok 17 transaction name is POST /
ok 18 transaction type is request
ok 19 null
ok 20 should have expected response body
# app.head('/') - HEAD /
ok 21 has a transaction
ok 22 transaction name is HEAD /
ok 23 transaction type is request
/Users/trentm/el/apm-agent-nodejs-node15/test/instrumentation/modules/express/basic.js:387
    throw err
    ^

Error [ERR_INTERNAL_ASSERTION] [ERR_INTERNAL_ASSERTION]: This is caused by either a bug in Node.js or incorrect usage of Node.js internals.
Please open an issue with this stack trace at https://github.com/nodejs/node/issues

    at new NodeError (node:internal/errors:277:15)
    at assert (node:internal/assert:14:11)
    at ServerResponse.detachSocket (node:_http_server:243:3)
    at resOnFinish (node:_http_server:812:7)
    at ServerResponse.emit (node:events:341:22)
    at onFinish (node:_http_outgoing:799:10)
    at afterWrite (node:internal/streams/writable:496:5)
    at afterWriteTick (node:internal/streams/writable:483:10)
    at processTicksAndRejections (node:internal/process/task_queues:79:21) {
  code: 'ERR_INTERNAL_ASSERTION'
}

This happens from node's internals blowing this assert: https://github.com/nodejs/node/blob/v15.2.1/lib/_http_server.js#L243
Conditions to hit that assert seem to be:

  1. a node.js HTTP server calling res.end('some content') twice
  2. using node v15
  3. instrumented with this APM agent

Condition #1 happens with an Express app is responding to a HEAD request for express versions 4.6.0 to 4.10.4.
The change in express that fixed it (for the [email protected] release) to not call double-call .end() is: expressjs/express@2ccb6cf

The change in node v15 that changed the behaviour of asserting on double-calling of res.end() is, I think, this one: nodejs/node@d005f49 However, I'm not confident on this.

Here is an example simple node.js app ("foo.js") that demonstrates being able to hit that internal assertion:

var apm = require('./').start({
  // So we can see the ERR_INTERNAL_ASSERTION without having to dig into the
  // error object reported to the APM server.
  captureExceptions: false
})

const http = require('http');
const hostname = '127.0.0.1';
const port = 3000;
const server = http.createServer((req, res) => {
  res.statusCode = 200;
  res.setHeader('Content-Type', 'text/plain');
  res.end('Hello World', 'utf8');
  res.end('oops');    // <--- Oops, double-calling `res.end` here.
});
server.listen(port, hostname, () => {
  console.log(`Server running at http://${hostname}:${port}/`);
});

Start the app:

% node --version
v15.2.1
% node foo.js
Server running at http://127.0.0.1:3000/

then call it:

% curl -i localhost:3000/
HTTP/1.1 200 OK
Content-Type: text/plain
Date: Tue, 01 Dec 2020 22:54:12 GMT
Connection: keep-alive
Keep-Alive: timeout=5
Content-Length: 11

Hello World

and it will exit with that internal assertion:

% node foo.js
Server running at http://127.0.0.1:3000/
node:internal/assert:14
    throw new ERR_INTERNAL_ASSERTION(message);
    ^

Error [ERR_INTERNAL_ASSERTION] [ERR_INTERNAL_ASSERTION]: This is caused by either a bug in Node.js or incorrect usage of Node.js internals.
Please open an issue with this stack trace at https://github.com/nodejs/node/issues

    at new NodeError (node:internal/errors:277:15)
    at assert (node:internal/assert:14:11)
    at ServerResponse.detachSocket (node:_http_server:243:3)
    at resOnFinish (node:_http_server:812:7)
    at ServerResponse.emit (node:events:341:22)
    at onFinish (node:_http_outgoing:799:10)
    at afterWrite (node:internal/streams/writable:496:5)
    at afterWriteTick (node:internal/streams/writable:483:10)
    at processTicksAndRejections (node:internal/process/task_queues:79:21) {
  code: 'ERR_INTERNAL_ASSERTION'
}

However if you use node v14 for the app, this internal assertion is not hit.

Likewise this internal assertion is not hit if the APM instrumentation is not enabled. Instead, a separate "write after end" error is hit:

% node foo.js
Server running at http://127.0.0.1:3000/
node:events:306
      throw er; // Unhandled 'error' event
      ^

Error [ERR_STREAM_WRITE_AFTER_END] [ERR_STREAM_WRITE_AFTER_END]: write after end
    at new NodeError (node:internal/errors:277:15)
    at write_ (node:_http_outgoing:717:11)
    at ServerResponse.end (node:_http_outgoing:817:5)
    at Server.<anonymous> (/Users/trentm/el/apm-agent-nodejs-node15/foo.js:15:7)
    at Server.emit (node:events:329:20)
    at parserOnIncoming (node:_http_server:919:12)
    at HTTPParser.parserOnHeadersComplete (node:_http_common:126:17)
Emitted 'error' event on ServerResponse instance at:
    at emitErrorNt (node:_http_outgoing:695:9)
    at processTicksAndRejections (node:internal/process/task_queues:81:21) {
  code: 'ERR_STREAM_WRITE_AFTER_END'
}

I need to dig into this more to understand what part of the APM instrumentation is causing this difference.

@trentm
Copy link
Member

trentm commented Dec 16, 2020

I tracked this down a little bit, and I believe it is related to the "end-of-stream" usage in the Node.js agent's "lib/instrumentation/http-shared.js". My next TODO is to create a small repro case that does not include this full agent.

@trentm
Copy link
Member

trentm commented Dec 23, 2020

Related: elastic/apm-nodejs-http-client#124

@trentm
Copy link
Member

trentm commented Apr 20, 2021

@kevcodez Sorry this has languished. I will likely open a separate PR soon to add this and (now) node v16 support -- crediting your start here.

@trentm trentm mentioned this pull request Apr 21, 2021
6 tasks
@trentm
Copy link
Member

trentm commented Apr 21, 2021

FWIW, the double-res.end() crash has gone away in the latest node 15 (node v15.14.0).

trentm added a commit that referenced this pull request Apr 21, 2021
trentm added a commit that referenced this pull request Apr 30, 2021
#2055)

This borrows work from @kevcodez and myself on #1841.

- enable node 16/15 testing for the GH Actions and Jenkins tests
- ensure OpenSSL SECLEVEL=0 for tests, required for http2.js test to pass in
  node:16 docker image
- fix hang with POST-handler + @hapi/[email protected] + node v16; we can just move on
  to hapi v20
- switching to hapi@20 means we need to skip out of hapi tests for node v10 and
  below

Fixes: #1840
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
agent-nodejs Make available for APM Agents project planning.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Add support for Node.js 15/16
4 participants