Traverse context to find active span/transaction #1964

dgieselaar · 2021-02-04T13:58:18Z

(Keeping this in draft, as I expect this PR is mostly just suitable for discussion)

I'm running into an issue where if the active span for the current async context ends, and a new span immediately starts, the ended span is the parent of the new span.

This PR attempts to address this issue by:

when a span ends, unset the active span for the current async context
when activeSpan or currentTransaction is requested, walk back up the context hierarchy to return the first span or transaction it finds

This assumes that each transaction/span is executed in its own async context. If that's not the case, weird things might happen.

apmmachine · 2021-02-04T14:12:25Z

💔 Tests Failed

the below badges are clickable and redirect to their specific view in the CI or DOCS

Expand to view the summary

Build stats

Build Cause: Branch indexing
Start Time: 2021-06-03T00:59:19.406+0000
Duration: 11 min 6 sec
Commit: 85a5295

Test stats 🧪

Test	Results
Failed	18
Passed	0
Skipped	0
Total	18

Trends 🧪

Test errors

Expand to view the tests failures

> Show only the first 10 test failures

`Test / Node.js-14-async-hooks-false / [empty] – *-output-junit.xml`

no error details

Expand to view the stacktrace

 Test report file /var/lib/jenkins/workspace/ejs_apm-agent-nodejs-mbp_PR-1964/src/github.com/elastic/apm-agent-nodejs/*-output-junit.xml was length 0

`Test / Node.js-14 / [empty] – *-output-junit.xml`

no error details

Expand to view the stacktrace

 Test report file /var/lib/jenkins/workspace/ejs_apm-agent-nodejs-mbp_PR-1964/src/github.com/elastic/apm-agent-nodejs/*-output-junit.xml was length 0

`Test / Node.js-14.0-async-hooks-false / [empty] – *-output-junit.xml`

no error details

Expand to view the stacktrace

 Test report file /var/lib/jenkins/workspace/ejs_apm-agent-nodejs-mbp_PR-1964/src/github.com/elastic/apm-agent-nodejs/*-output-junit.xml was length 0

`Test / Node.js-14.0 / [empty] – *-output-junit.xml`

no error details

Expand to view the stacktrace

 Test report file /var/lib/jenkins/workspace/ejs_apm-agent-nodejs-mbp_PR-1964/src/github.com/elastic/apm-agent-nodejs/*-output-junit.xml was length 0

`Test / Node.js-13-async-hooks-false / [empty] – *-output-junit.xml`

no error details

Expand to view the stacktrace

 Test report file /var/lib/jenkins/workspace/ejs_apm-agent-nodejs-mbp_PR-1964/src/github.com/elastic/apm-agent-nodejs/*-output-junit.xml was length 0

`Test / Node.js-13 / [empty] – *-output-junit.xml`

no error details

Expand to view the stacktrace

 Test report file /var/lib/jenkins/workspace/ejs_apm-agent-nodejs-mbp_PR-1964/src/github.com/elastic/apm-agent-nodejs/*-output-junit.xml was length 0

`Test / Node.js-12 / [empty] – *-output-junit.xml`

no error details

Expand to view the stacktrace

 Test report file /var/lib/jenkins/workspace/ejs_apm-agent-nodejs-mbp_PR-1964/src/github.com/elastic/apm-agent-nodejs/*-output-junit.xml was length 0

`Test / Node.js-12.0 / [empty] – *-output-junit.xml`

no error details

Expand to view the stacktrace

 Test report file /var/lib/jenkins/workspace/ejs_apm-agent-nodejs-mbp_PR-1964/src/github.com/elastic/apm-agent-nodejs/*-output-junit.xml was length 0

`Test / Node.js-10.0-async-hooks-false / [empty] – *-output-junit.xml`

no error details

Expand to view the stacktrace

 Test report file /var/lib/jenkins/workspace/ejs_apm-agent-nodejs-mbp_PR-1964/src/github.com/elastic/apm-agent-nodejs/*-output-junit.xml was length 0

`Test / Node.js-10 / [empty] – *-output-junit.xml`

no error details

Expand to view the stacktrace

 Test report file /var/lib/jenkins/workspace/ejs_apm-agent-nodejs-mbp_PR-1964/src/github.com/elastic/apm-agent-nodejs/*-output-junit.xml was length 0

Steps errors

Expand to view the steps failures

Show only the first 10 steps failures

`Run Tests`

Took 0 min 3 sec . View more details on here
Description: .ci/scripts/test.sh -b "release" -t "" "8"

`Run Tests`

Took 0 min 1 sec . View more details on here
Description: .ci/scripts/test.sh -b "release" -t "" "8"

`Run Tests`

Took 0 min 4 sec . View more details on here
Description: .ci/scripts/test.sh -b "release" -t "" "8"

`Run Tests`

Took 0 min 1 sec . View more details on here
Description: .ci/scripts/test.sh -b "release" -t "" "8"

`Run Tests`

Took 0 min 2 sec . View more details on here
Description: .ci/scripts/test.sh -b "release" -t "" "8.6"

`Run Tests`

Took 0 min 1 sec . View more details on here
Description: .ci/scripts/test.sh -b "release" -t "" "8.6"

`Run Tests`

Took 0 min 2 sec . View more details on here
Description: .ci/scripts/test.sh -b "release" -t "" "8.6"

`Run Tests`

Took 0 min 1 sec . View more details on here
Description: .ci/scripts/test.sh -b "release" -t "" "8.6"

`Windows Batch Script`

Took 0 min 5 sec . View more details on here
Description: node test/test.js

`Error signal`

Took 0 min 0 sec . View more details on here
Description: hudson.AbortException: script returned exit code 1

Log output

Expand to view the last 100 lines of log output

[2021-06-03T01:10:22.355Z]     stack: |-
[2021-06-03T01:10:22.355Z]       Error: .end() already called: should be truthy
[2021-06-03T01:10:22.355Z]           at Test.assert [as _assert] (C:\Users\jenkins\workspace\ejs_apm-agent-nodejs-mbp_PR-1964\src\github.com\elastic\apm-agent-nodejs\node_modules\tape\lib\test.js:304:54)
[2021-06-03T01:10:22.355Z]           at Test.bound [as _assert] (C:\Users\jenkins\workspace\ejs_apm-agent-nodejs-mbp_PR-1964\src\github.com\elastic\apm-agent-nodejs\node_modules\tape\lib\test.js:91:32)
[2021-06-03T01:10:22.356Z]           at Test.fail (C:\Users\jenkins\workspace\ejs_apm-agent-nodejs-mbp_PR-1964\src\github.com\elastic\apm-agent-nodejs\node_modules\tape\lib\test.js:398:10)
[2021-06-03T01:10:22.356Z]           at Test.bound [as fail] (C:\Users\jenkins\workspace\ejs_apm-agent-nodejs-mbp_PR-1964\src\github.com\elastic\apm-agent-nodejs\node_modules\tape\lib\test.js:91:32)
[2021-06-03T01:10:22.356Z]           at Test.assert [as _assert] (C:\Users\jenkins\workspace\ejs_apm-agent-nodejs-mbp_PR-1964\src\github.com\elastic\apm-agent-nodejs\node_modules\tape\lib\test.js:282:14)
[2021-06-03T01:10:22.356Z]           at Test.bound [as _assert] (C:\Users\jenkins\workspace\ejs_apm-agent-nodejs-mbp_PR-1964\src\github.com\elastic\apm-agent-nodejs\node_modules\tape\lib\test.js:91:32)
[2021-06-03T01:10:22.356Z]           at Test.assert (C:\Users\jenkins\workspace\ejs_apm-agent-nodejs-mbp_PR-1964\src\github.com\elastic\apm-agent-nodejs\node_modules\tape\lib\test.js:423:10)
[2021-06-03T01:10:22.356Z]           at Test.bound [as ok] (C:\Users\jenkins\workspace\ejs_apm-agent-nodejs-mbp_PR-1964\src\github.com\elastic\apm-agent-nodejs\node_modules\tape\lib\test.js:91:32)
[2021-06-03T01:10:22.356Z]           at C:\Users\jenkins\workspace\ejs_apm-agent-nodejs-mbp_PR-1964\src\github.com\elastic\apm-agent-nodejs\test\agent.js:1261:13
[2021-06-03T01:10:22.356Z]           at C:\Users\jenkins\workspace\ejs_apm-agent-nodejs-mbp_PR-1964\src\github.com\elastic\apm-agent-nodejs\lib\agent.js:421:12
[2021-06-03T01:10:22.356Z]           at C:\Users\jenkins\workspace\ejs_apm-agent-nodejs-mbp_PR-1964\src\github.com\elastic\apm-agent-nodejs\lib\agent.js:391:19
[2021-06-03T01:10:22.356Z]           at elasticAPMCallbackWrapper (C:\Users\jenkins\workspace\ejs_apm-agent-nodejs-mbp_PR-1964\src\github.com\elastic\apm-agent-nodejs\lib\instrumentation\index.js:310:27)
[2021-06-03T01:10:22.356Z]           at afterWrite (C:\Users\jenkins\workspace\ejs_apm-agent-nodejs-mbp_PR-1964\src\github.com\elastic\apm-agent-nodejs\node_modules\readable-stream\lib\_stream_writable.js:469:3)
[2021-06-03T01:10:22.356Z]           at onwrite (C:\Users\jenkins\workspace\ejs_apm-agent-nodejs-mbp_PR-1964\src\github.com\elastic\apm-agent-nodejs\node_modules\readable-stream\lib\_stream_writable.js:461:7)
[2021-06-03T01:10:22.356Z]           at Client.WritableState.onwrite [as _onflushed] (C:\Users\jenkins\workspace\ejs_apm-agent-nodejs-mbp_PR-1964\src\github.com\elastic\apm-agent-nodejs\node_modules\readable-stream\lib\_stream_writable.js:160:5)
[2021-06-03T01:10:22.356Z]           at completePart (C:\Users\jenkins\workspace\ejs_apm-agent-nodejs-mbp_PR-1964\src\github.com\elastic\apm-agent-nodejs\node_modules\elastic-apm-http-client\index.js:761:16)
[2021-06-03T01:10:22.356Z]           at ClientRequest.<anonymous> (C:\Users\jenkins\workspace\ejs_apm-agent-nodejs-mbp_PR-1964\src\github.com\elastic\apm-agent-nodejs\node_modules\elastic-apm-http-client\index.js:880:7)
[2021-06-03T01:10:22.356Z]           at ClientRequest.emit (events.js:376:20)
[2021-06-03T01:10:22.356Z]           at Socket.socketCloseListener (_http_client.js:449:11)
[2021-06-03T01:10:22.356Z]           at Socket.emit (events.js:388:22)
[2021-06-03T01:10:22.356Z]           at TCP.<anonymous> (net.js:673:12)
[2021-06-03T01:10:22.356Z]           at TCP.callbackTrampoline (internal/async_hooks.js:134:14)
[2021-06-03T01:10:22.356Z]   ...
[2021-06-03T01:10:22.356Z] # patches
[2021-06-03T01:10:22.356Z] # #clearPatches(name)
[2021-06-03T01:10:22.356Z] ok 807 should be truthy
[2021-06-03T01:10:22.356Z] ok 808 should not throw
[2021-06-03T01:10:22.356Z] ok 809 should be falsy
[2021-06-03T01:10:22.356Z] ok 810 should not throw
[2021-06-03T01:10:22.356Z] # #addPatch(name, moduleName)
[2021-06-03T01:10:22.615Z] ok 811 should be deeply equivalent
[2021-06-03T01:10:22.615Z] # #addPatch(name, function) - does not exist
[2021-06-03T01:10:22.615Z] ok 812 should be truthy
[2021-06-03T01:10:22.615Z] ok 813 should be truthy
[2021-06-03T01:10:22.615Z] ok 814 should be truthy
[2021-06-03T01:10:22.615Z] ok 815 should be truthy
[2021-06-03T01:10:22.615Z] ok 816 should be deeply equivalent
[2021-06-03T01:10:22.615Z] # #removePatch(name, handler)
[2021-06-03T01:10:22.615Z] ok 817 should be falsy
[2021-06-03T01:10:22.615Z] ok 818 should be truthy
[2021-06-03T01:10:22.615Z] ok 819 should be falsy
[2021-06-03T01:10:22.615Z] ok 820 should be truthy
[2021-06-03T01:10:22.615Z] ok 821 should be falsy
[2021-06-03T01:10:22.615Z] # #registerMetric(name, labels, callback)
[2021-06-03T01:10:22.615Z] ok 822 should be strictly equal
[2021-06-03T01:10:22.615Z] ok 823 should be strictly equal
[2021-06-03T01:10:22.615Z] ok 824 should be strictly equal
[2021-06-03T01:10:22.615Z] ok 825 should be strictly equal
[2021-06-03T01:10:22.615Z] ok 826 should be strictly equal
[2021-06-03T01:10:22.615Z] ok 827 should be strictly equal
[2021-06-03T01:10:22.615Z] ok 828 should be strictly equal
[2021-06-03T01:10:22.615Z] ok 829 should be strictly equal
[2021-06-03T01:10:22.615Z] ok 830 should be strictly equal
[2021-06-03T01:10:22.615Z] ok 831 should be strictly equal
[2021-06-03T01:10:22.615Z] 
[2021-06-03T01:10:22.615Z] 1..831
[2021-06-03T01:10:22.615Z] # tests 831
[2021-06-03T01:10:22.615Z] # pass  820
[2021-06-03T01:10:22.615Z] # fail  11
[2021-06-03T01:10:22.615Z] 
[2021-06-03T01:10:22.873Z] C:\Users\jenkins\workspace\ejs_apm-agent-nodejs-mbp_PR-1964\src\github.com\elastic\apm-agent-nodejs\test\test.js:133
[2021-06-03T01:10:22.873Z]     if (err) throw err
[2021-06-03T01:10:22.873Z]              ^
[2021-06-03T01:10:22.873Z] 
[2021-06-03T01:10:22.873Z] Error: non-zero error code
[2021-06-03T01:10:22.873Z]     at ChildProcess.<anonymous> (C:\Users\jenkins\workspace\ejs_apm-agent-nodejs-mbp_PR-1964\src\github.com\elastic\apm-agent-nodejs\test\test.js:37:19)
[2021-06-03T01:10:22.873Z]     at ChildProcess.emit (events.js:376:20)
[2021-06-03T01:10:22.873Z]     at maybeClose (internal/child_process.js:1055:16)
[2021-06-03T01:10:22.873Z]     at Process.ChildProcess._handle.onexit (internal/child_process.js:288:5) {
[2021-06-03T01:10:22.873Z]   code: 'ENONZERO',
[2021-06-03T01:10:22.873Z]   exitCode: 1
[2021-06-03T01:10:22.873Z] }
[2021-06-03T01:10:22.906Z] JUnit archiving no yet in place
[2021-06-03T01:10:22.969Z] Failed in branch Windows-Node.js-14
[2021-06-03T01:10:23.082Z] [INFO] getVaultSecret: Getting secrets
[2021-06-03T01:10:23.133Z] Masking supported pattern matches of $VAULT_ADDR or $VAULT_ROLE_ID or $VAULT_SECRET_ID
[2021-06-03T01:10:24.377Z] Stage "TAV Test" skipped due to earlier failure(s)
[2021-06-03T01:10:24.416Z] Stage "Edge Test" skipped due to earlier failure(s)
[2021-06-03T01:10:24.459Z] Stage "Nightly Test" skipped due to earlier failure(s)
[2021-06-03T01:10:24.464Z] Stage "Nightly Test - No async hooks" skipped due to earlier failure(s)
[2021-06-03T01:10:24.468Z] Stage "RC Test" skipped due to earlier failure(s)
[2021-06-03T01:10:24.473Z] Stage "RC Test - No async hooks" skipped due to earlier failure(s)
[2021-06-03T01:10:24.537Z] Failed in branch Nightly Test
[2021-06-03T01:10:24.541Z] Failed in branch Nightly Test - No async hooks
[2021-06-03T01:10:24.546Z] Failed in branch RC Test
[2021-06-03T01:10:24.553Z] Failed in branch RC Test - No async hooks
[2021-06-03T01:10:24.615Z] Stage "Integration Tests" skipped due to earlier failure(s)
[2021-06-03T01:10:24.655Z] Stage "Release" skipped due to earlier failure(s)
[2021-06-03T01:10:24.669Z] Stage "Release" skipped due to earlier failure(s)
[2021-06-03T01:10:24.733Z] Stage "Benchmarks" skipped due to earlier failure(s)
[2021-06-03T01:10:24.955Z] Running on worker-1095690 in /var/lib/jenkins/workspace/ejs_apm-agent-nodejs-mbp_PR-1964
[2021-06-03T01:10:24.997Z] [INFO] getVaultSecret: Getting secrets
[2021-06-03T01:10:25.037Z] Masking supported pattern matches of $VAULT_ADDR or $VAULT_ROLE_ID or $VAULT_SECRET_ID
[2021-06-03T01:10:27.014Z] + chmod 755 generate-build-data.sh
[2021-06-03T01:10:27.014Z] + ./generate-build-data.sh https://apm-ci.elastic.co/blue/rest/organizations/jenkins/pipelines/apm-agent-nodejs/apm-agent-nodejs-mbp/PR-1964/ https://apm-ci.elastic.co/blue/rest/organizations/jenkins/pipelines/apm-agent-nodejs/apm-agent-nodejs-mbp/PR-1964/runs/45 FAILURE 666209
[2021-06-03T01:10:27.014Z] INFO: curl https://apm-ci.elastic.co/blue/rest/organizations/jenkins/pipelines/apm-agent-nodejs/apm-agent-nodejs-mbp/PR-1964/runs/45/steps/?limit=10000 -o steps-info.json
[2021-06-03T01:10:52.091Z] INFO: curl https://apm-ci.elastic.co/blue/rest/organizations/jenkins/pipelines/apm-agent-nodejs/apm-agent-nodejs-mbp/PR-1964/runs/45/tests/?status=FAILED -o tests-errors.json
[2021-06-03T01:10:52.091Z] INFO: curl https://apm-ci.elastic.co/blue/rest/organizations/jenkins/pipelines/apm-agent-nodejs/apm-agent-nodejs-mbp/PR-1964/runs/45/log/ -o pipeline-log.txt

trentm · 2021-02-04T20:33:12Z

@dgieselaar This looks pretty good! Thanks for this. I think we should pursue this. I also (eventually) want to get a sense of the possible performance impact here because the async hook functions are hot spots.

My understanding improved when (locally) renaming resources to triggerAsyncIdFromAsyncId. There is a fourth argument to the async hook's function init called "resource" that means something different.

dgieselaar · 2021-02-05T21:22:42Z

@trentm I was thinking about the performance issue as well. I'll try to have a look at profiling next week, it's also going to be useful for me to learn more about the Kibana instrumentation performance overhead we discussed.

Other than the perf issue I think I also not fully understand the consequences of this change. But it does feel like a step in the right direction.

I hope to get back to this ~next week after I've had a look at the performance implications.

For example, this handles the problem case from #1964

trentm · 2021-10-27T16:37:26Z

I believe this is fixed by #2181

Traverse context to find active span/transaction

507a90d

github-actions bot added the agent-nodejs Make available for APM Agents project planning. label Feb 4, 2021

dgieselaar added 2 commits February 4, 2021 15:00

Lint

5226087

Fix tests

180a813

No exclusive tests

85a5295

trentm mentioned this pull request Feb 4, 2021

fix: spans started in same async op should be children #1890

Closed

dgieselaar mentioned this pull request Feb 5, 2021

[APM] Add custom spans around async operations elastic/kibana#90403

Merged

dgieselaar mentioned this pull request May 4, 2021

Improve Task Manager instrumentation elastic/kibana#99160

Merged

trentm added a commit that referenced this pull request Aug 21, 2021

handling subtleties with how span.end() impacts the run context

bceeacd

For example, this handles the problem case from #1964

trentm mentioned this pull request Aug 26, 2021

Spans not shown in the UI when their parent is missing #2160

Open

trentm mentioned this pull request Oct 16, 2021

new "run context" management to fix numerous span hierarchy issues #2181

Merged

5 tasks

trentm closed this Oct 27, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Traverse context to find active span/transaction #1964

Traverse context to find active span/transaction #1964

dgieselaar commented Feb 4, 2021 •

edited

Loading

apmmachine commented Feb 4, 2021 •

edited

Loading

Build stats

Test stats 🧪

Trends 🧪

`Test / Node.js-14-async-hooks-false / [empty] – *-output-junit.xml`

`Test / Node.js-14 / [empty] – *-output-junit.xml`

`Test / Node.js-14.0-async-hooks-false / [empty] – *-output-junit.xml`

`Test / Node.js-14.0 / [empty] – *-output-junit.xml`

`Test / Node.js-13-async-hooks-false / [empty] – *-output-junit.xml`

`Test / Node.js-13 / [empty] – *-output-junit.xml`

`Test / Node.js-12 / [empty] – *-output-junit.xml`

`Test / Node.js-12.0 / [empty] – *-output-junit.xml`

`Test / Node.js-10.0-async-hooks-false / [empty] – *-output-junit.xml`

`Test / Node.js-10 / [empty] – *-output-junit.xml`

`Run Tests`

`Run Tests`

`Run Tests`

`Run Tests`

`Run Tests`

`Run Tests`

`Run Tests`

`Run Tests`

`Windows Batch Script`

`Error signal`

trentm commented Feb 4, 2021

dgieselaar commented Feb 5, 2021

trentm commented Oct 27, 2021

Traverse context to find active span/transaction #1964

Traverse context to find active span/transaction #1964

Conversation

dgieselaar commented Feb 4, 2021 • edited Loading

apmmachine commented Feb 4, 2021 • edited Loading

💔 Tests Failed

Build stats

Test stats 🧪

Trends 🧪

Test errors

Test / Node.js-14-async-hooks-false / [empty] – *-output-junit.xml

Test / Node.js-14 / [empty] – *-output-junit.xml

Test / Node.js-14.0-async-hooks-false / [empty] – *-output-junit.xml

Test / Node.js-14.0 / [empty] – *-output-junit.xml

Test / Node.js-13-async-hooks-false / [empty] – *-output-junit.xml

Test / Node.js-13 / [empty] – *-output-junit.xml

Test / Node.js-12 / [empty] – *-output-junit.xml

Test / Node.js-12.0 / [empty] – *-output-junit.xml

Test / Node.js-10.0-async-hooks-false / [empty] – *-output-junit.xml

Test / Node.js-10 / [empty] – *-output-junit.xml

Steps errors

Run Tests

Run Tests

Run Tests

Run Tests

Run Tests

Run Tests

Run Tests

Run Tests

Windows Batch Script

Error signal

Log output

trentm commented Feb 4, 2021

dgieselaar commented Feb 5, 2021

trentm commented Oct 27, 2021

dgieselaar commented Feb 4, 2021 •

edited

Loading

apmmachine commented Feb 4, 2021 •

edited

Loading

`Test / Node.js-14-async-hooks-false / [empty] – *-output-junit.xml`

`Test / Node.js-14 / [empty] – *-output-junit.xml`

`Test / Node.js-14.0-async-hooks-false / [empty] – *-output-junit.xml`

`Test / Node.js-14.0 / [empty] – *-output-junit.xml`

`Test / Node.js-13-async-hooks-false / [empty] – *-output-junit.xml`

`Test / Node.js-13 / [empty] – *-output-junit.xml`

`Test / Node.js-12 / [empty] – *-output-junit.xml`

`Test / Node.js-12.0 / [empty] – *-output-junit.xml`

`Test / Node.js-10.0-async-hooks-false / [empty] – *-output-junit.xml`

`Test / Node.js-10 / [empty] – *-output-junit.xml`

`Run Tests`

`Run Tests`

`Run Tests`

`Run Tests`

`Run Tests`

`Run Tests`

`Run Tests`

`Run Tests`

`Windows Batch Script`

`Error signal`