Tests using the Jest plugin cannot access tracing scope

[mdbenjam]

Describe the bug
When enabling Jest tracing I expect to see connected traces for operation in my test. For example, if the test makes an http request, I expect to see that request as a sub span of the full test span.

However, in the CI tool I only ever see the top level span. Looking in the APM tool I can find relevant http spans from the test, but they're not connected to the span for the full test. They seem to be orphaned.

Digging in, I believe the reason for this is within a test global._ddtrace is not defined. I think this is because the global context within the test appears to be somewhat isolated from the global context of the test runner. I added

this.global._ddtrace = global._ddtrace

here: https://github.com/DataDog/dd-trace-js/blob/v2.5.0/packages/datadog-plugin-jest/src/jest-environment.js#L107 and got the spans to all show up together in the CI tool. I'm not familiar enough with Jest Environments to know if this is the correct fix.

Environment

• Operation system: OSX 12.2.1
• **Node version: v14.17.6 **
• **Tracer version: 2.5.0 **
• **Agent version: 7.35.0 **

[mdbenjam]

If the above fix seems reasonable, I'm happy to open a pull request for it!

[mdbenjam]

I added a sample pull request to address this issue. It works locally, but I'm not sure if it's the right fix.

[juan-fernandez]

hi @mdbenjam ! Thanks for the explanation and possible fix.

Are you using the CI Visibility instrumentation of jest? https://docs.datadoghq.com/continuous_integration/setup_tests/javascript/?tab=jest

This should initialise the tracer where it matters: in the environment of the tests. Initializing in a different way might result in what you describe.

[mdbenjam]

Hi @juan-fernandez , thanks so much for the quick response!

I did follow the instructions on that page but am still seeing the issue. I've made a minimal reproduction here.

This test is currently failing and will pass when the current tracing scope is not null. Which I assume should be the behavior that's expected.

I tried to follow the setup on the link you sent, though note I removed the if (process.env.DD_ENV === 'ci') { check since I always wanted to initialize the library.

Let me know if something in the setup doesn't look right to you!

[mdbenjam]

Sadly I just realized my "fix" doesn't work when tests are concurrent

[juan-fernandez]

thanks for the follow up!

So the fact that the tracer is not available in the test context is a bug and it needs fixing: thanks for noticing! Your solution looks promising, I'll have a look and let you know.

I can't reproduce the http requests spans being orphaned though. They seem to be children of the test span in my tests: could you add to your reproduction case the way you do requests? Or just let me know here, so that I can try it myself 😄

Example of the resulting trace in your repo:

About your last comment:

Sadly I just realized my "fix" doesn't work when tests are concurrent

how is it not working? How are the tests setup?

[mdbenjam]

Hey @juan-fernandez ,

About your last comment:
Sadly I just realized my "fix" doesn't work when tests are concurrent
how is it not working? How are the tests setup?

Sorry that was somewhat vague. We run a bunch of our tests with jests' test.concurrent and this seems to break my fix. I made a branch on my test repo to demonstrate this. That repo pulls in my fix (so you might need to run yarn) and marks the test as concurrent.

I can't reproduce the http requests spans being orphaned though. They seem to be children of the test span in my tests: could you add to your reproduction case the way you do requests?

So I was not seeing the traces on our real test (I hadn't looked for the actual traces in my example test case 🤦 ), but I realized today that the real test in our code base I was trying was marked as test.concurrent. I just changed our test to use test instead and all the spans are there!

So I think there might be a separate issue where test.concurrent is not getting processed correctly. I just made another branch to demonstrate this: https://github.com/mdbenjam/ddtrace-jest-example/tree/concurrent-without-fix

[juan-fernandez]

hey @mdbenjam , thanks for the info and the branches.

So I hadn't actually tested the behavior of the plugin with test.concurrent. It seems like it behaves strangely:

https://github.com/facebook/jest/blob/main/packages/jest-circus/src/legacy-code-todo-rewrite/jestAdapterInit.ts#L85-L87

The test function is called "right away", before handleTestEvent is called with event.name == test_start (https://github.com/facebook/jest/tree/main/packages/jest-circus#overview). We use test_start to bind the test function to the correct async resource, so that operations like http requests are children of the test span. In this case by the time we bind it, it is "too late". It seems normal timings are a bit off when using test.concurrent too: jestjs/jest#7997

I'll try to fix it, and in any case in the mean time we should add a known limitation to the docs.

It seems the support for test.concurrent is "experimental" for the moment: https://jestjs.io/docs/api#testconcurrentname-fn-timeout so I don't know how much we'll be able to do. I'll keep you updated! 😄

[juan-fernandez]

the same happens with testRunner: 'jest-jasmine2': the test function is called before Spec.execute is called: https://github.com/facebook/jest/blob/main/packages/jest-jasmine2/src/jasmine/Spec.ts#L174. It seems test.concurrent completely skips the normal lifecycle of a test in jest. I'll see if we can do something about this

[mdbenjam]

@juan-fernandez I'm also new to test.concurrent, this codebase is my first time encountering it, and it does look like it's kind of broken :(. Thanks for looking into it!

[juan-fernandez]

#2003 (inspired in your PR) should fix this issue for anything other than test.concurrent. We'll try to tackle test.concurrent at a different PR, if it's at all possible.

[mdbenjam]

Thanks for the update! The PR looks good. I've closed mine in favor of yours.

As for test.concurrent the more I've dug into it, the more I think the underlying issue is really in Jest and it's not clear if anything can be done about it without some pretty significant rewriting of how Jest handles concurrency. I plan to file an issue on their repo, but in the meantime I split our tests into separate files to take advantage of Jest's standard file level parallelization. This way I can use test instead of test.concurrent.

[juan-fernandez]

thanks for your update too!

but in the meantime I split our tests into separate files to take advantage of Jest's standard file level parallelization. This way I can use test instead of test.concurrent.

Thanks for sharing this too. I think this is a great idea 👍