feat: support serializing circular refs properly

[G-Rath]

Summary

This is a really hacky attempt to kick off resolving issues with circular refs - right now I'm looking to figure out where the right place(s) to put things are, which'll be followed up by implementing support for jest-worker to take custom (de)serializers as described in this comment by @SimenB

I would be doing this locally, but I'm suspect as I think I'm really close but for some reason the test is timing out and I can't pin down why.

If I remove the circular ref line (the foo.ref = foo;) the test passes fine both with and without my hack, but if it has a ref it fails with:

thrown: "Exceeded timeout of 70000 ms for a test."

Fixes #10577
Fixes #11617
Closes #11624

Test plan

Have the handles circular inequality properly test passing.

[G-Rath]

@SimenB do you have any tips on how to debug this timeout failure? I've compared a good chunk of values in jest-worker, jest-runner, and jest-core for both without my code & with it and with & without the circle ref, and I've not been able to find any differences - all the same events seem to be firing, functions resolving as expected, etc.

I figure there's a good chance the issue is that something doesn't support avoiding circular refs and so its just going around and around without ever returning, but I can't find what the actual thing is 😓

[SimenB]

Huh, weird it times out on circle but not gh actions... does it time out locally?

[G-Rath]

Yeah I was surprised by that too, but wasn't sure if it was running all the tests in GHA as doing test-ci-partial:parallel but I've not looked into much.

It always times out locally for me.

[SimenB]

ah, right. circle runs in band which breaks probably, while GH actions run with workers. Try to run the failing test and e.g. all tests in expect and it probably passes?

[G-Rath]

You mean like yarn jest e2e/__tests__/circularInequality.test.ts expect? that still results in the timeout failure for me.

[G-Rath]

@SimenB I think this is good to go logic-wise, it's just the weird timeout issue that's blocking it (which I am at a bit of a loss on)

[SimenB]

@G-Rath I changed the waitUntil in the test to

await waitUntil(({stderr, stdout}) => {
  console.log({stderr, stdout});
  return stderr.includes('Ran all test suites.');
});

and it logs an error

  console.log
    {
      stderr: '(node:42266) UnhandledPromiseRejectionWarning: TypeError: Converting circular structure to JSON\n' +
        "    --> starting at object with constructor 'Object'\n" +
        "    --- property 'ref' closes the circle\n" +
        '    at stringify (<anonymous>)\n' +
        '    at writeChannelMessage (internal/child_process/serialization.js:127:20)\n' +
        '    at process.target._send (internal/child_process.js:812:17)\n' +
        '    at process.target.send (internal/child_process.js:710:19)\n' +
        '    at reportSuccess (/Users/simen/repos/jest/packages/jest-worker/build/workers/processChild.js:67:11)\n' +
        '(Use `node --trace-warnings ...` to show where the warning was created)\n',
      stdout: ''
    }

      at log (e2e/__tests__/circularInequality.test.ts:52:13)

  console.log
    {
      stderr: '(node:42266) UnhandledPromiseRejectionWarning: TypeError: Converting circular structure to JSON\n' +
        "    --> starting at object with constructor 'Object'\n" +
        "    --- property 'ref' closes the circle\n" +
        '    at stringify (<anonymous>)\n' +
        '    at writeChannelMessage (internal/child_process/serialization.js:127:20)\n' +
        '    at process.target._send (internal/child_process.js:812:17)\n' +
        '    at process.target.send (internal/child_process.js:710:19)\n' +
        '    at reportSuccess (/Users/simen/repos/jest/packages/jest-worker/build/workers/processChild.js:67:11)\n' +
        '(Use `node --trace-warnings ...` to show where the warning was created)\n' +
        '(node:42266) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 2)\n' +
        '(node:42266) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.\n' +
        '(node:42265) UnhandledPromiseRejectionWarning: TypeError: Converting circular structure to JSON\n' +
        "    --> starting at object with constructor 'Object'\n" +
        "    --- property 'ref' closes the circle\n" +
        '    at stringify (<anonymous>)\n' +
        '    at writeChannelMessage (internal/child_process/serialization.js:127:20)\n' +
        '    at process.target._send (internal/child_process.js:812:17)\n' +
        '    at process.target.send (internal/child_process.js:710:19)\n' +
        '    at reportSuccess (/Users/simen/repos/jest/packages/jest-worker/build/workers/processChild.js:67:11)\n' +
        '(Use `node --trace-warnings ...` to show where the warning was created)\n' +
        '(node:42265) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 2)\n' +
        '(node:42265) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.\n',
      stdout: ''
    }

      at log (e2e/__tests__/circularInequality.test.ts:52:13)

[SimenB]

At the very least flatted is missing here: https://github.com/facebook/jest/blob/6b18aedda0149effa9930e5c8994d7dd940e387a/packages/jest-worker/src/workers/NodeThreadsWorker.ts#L179-L181 and in https://github.com/facebook/jest/blob/6b18aedda0149effa9930e5c8994d7dd940e387a/packages/jest-worker/src/workers/processChild.ts

---

You can look at how I had a serializer at first in 5e8ae67 (#10981).

I think the concerns raised in that PR are valid though - not everybody using jest-worker will want a custom serializer, so we need to make it pluggable.

[SimenB]

@G-Rath I've merged in main which has #11909, so the test fails instead if timing out now 🙂

[SimenB]

We need to make sure it fails when running in parallel as well though, that's weird...

[G-Rath]

I think the concerns raised in that PR are valid though - not everybody using jest-worker will want a custom serializer, so we need to make it pluggable.

I agree long-term, but short-term am focusing on fixing first then will look to optimise for performance (partly because I couldn't an already existing "worker options" object being passed around that I could easily add to for this)

We need to make sure it fails when running in parallel as well though

What do you mean by that? Is that what you were meaning here when you said "Running this test on its own is fine, but having 2 of them and running in test mode leads to", or is this something else?

I'm just reacquainting myself with this PR and trying to figure out what the underlying issue is that I need to solve given you originally tried something similar but had to revert (in particular because the error looks nasty, and I'm not sure how you'd go about solving it but that could just be because I'm not understanding what is going on).

So far I've managed to progress this by applying the stringify/parse to the missing places which looks to have done the job, except the snapshot is incorrect (which I'm assuming is because I've missing something else, given the snapshotted error is in TestScheduler)

This is the test failure message/snapshot diff

 FAIL  e2e/__tests__/circularInequality.test.ts (5.127 s)
  ✕ handles circular inequality properly (4319 ms)

  ● handles circular inequality properly

    expect(received).toMatchSnapshot()

    Snapshot name: `handles circular inequality properly 1`

    - Snapshot  - 34
    + Received  +  8

      FAIL __tests__/test-1.js
    -   ● test
    -
    -     expect(received).toEqual(expected) // deep equality
    -
    -     - Expected  - 1
    -     + Received  + 3
    -
    -     - Object {}
    -     + Object {
    -     +   "ref": [Circular],
    -     + }
    +   ● Test suite failed to run

    -       3 |   foo.ref = foo;
    -       4 |
    -     > 5 |   expect(foo).toEqual({});
    -         |               ^
    -       6 | });
    +     TypeError: Cannot read property 'length' of undefined

    -       at Object.toEqual (__tests__/test-1.js:5:15)
    +       at onResult (../../c/Users/G-Rath/workspace/projects-oss/jest/packages/jest-core/build/TestScheduler.js:171:34)
    +           at Array.map (<anonymous>)

      FAIL __tests__/test-2.js
    -   ● test
    +   ● Test suite failed to run

    -     expect(received).toEqual(expected) // deep equality
    +     TypeError: Cannot read property 'length' of undefined

    -     - Expected  - 1
    -     + Received  + 3
    -
    -     - Object {}
    -     + Object {
    -     +   "ref": [Circular],
    -     + }
    -
    -       3 |   foo.ref = foo;
    -       4 |
    -     > 5 |   expect(foo).toEqual({});
    -         |               ^
    -       6 | });
    -

    -       at Object.toEqual (__tests__/test-2.js:5:15)
    +       at onResult (../../c/Users/G-Rath/workspace/projects-oss/jest/packages/jest-core/build/TestScheduler.js:171:34)
    +           at Array.map (<anonymous>)


      54 |
      55 |   const {summary, rest} = extractSortedSummary(stderr);
    > 56 |   expect(wrap(rest)).toMatchSnapshot();

         |                      ^
      57 |   expect(wrap(summary)).toMatchSnapshot();
      58 | });
      59 |

      at Object.toMatchSnapshot (e2e/__tests__/circularInequality.test.ts:56:22)
          at runMicrotasks (<anonymous>)

[codecov-commenter]

Codecov Report

Merging #11467 (a595026) into main (48f68a5) will increase coverage by 0.00%.
The diff coverage is 86.66%.

@@           Coverage Diff           @@
##             main   #11467   +/-   ##
=======================================
  Coverage   67.52%   67.52%           
=======================================
  Files         328      329    +1     
  Lines       17246    17254    +8     
  Branches     5071     5073    +2     
=======================================
+ Hits        11645    11651    +6     
- Misses       5568     5570    +2     
  Partials       33       33           

Impacted Files	Coverage Δ
packages/jest-worker/src/workers/messageParent.ts	35.71% <0.00%> (ø)
packages/jest-worker/src/workers/utils.ts	87.50% <87.50%> (ø)
...ages/jest-worker/src/workers/ChildProcessWorker.ts	94.23% <100.00%> (ø)
...kages/jest-worker/src/workers/NodeThreadsWorker.ts	93.61% <100.00%> (ø)
packages/jest-worker/src/workers/processChild.ts	94.28% <100.00%> (ø)
packages/jest-worker/src/workers/threadChild.ts	91.54% <100.00%> (ø)
packages/expect/src/utils.ts	96.03% <0.00%> (-0.50%)	⬇️

---

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 48f68a5...a595026. Read the comment docs.

[G-Rath]

@SimenB I think this is ready for you to take a look at to advise on next steps (since I have the tests passing, but not sure if that's enough to confirm this is the whole fix or if you want to go bug hunting given the problems with this in the past).

The only test failing is the standard does not report --notify flag one.

[SimenB]

What do you mean by that? Is that what you were meaning here when you said "Running this test on its own is fine, but having 2 of them and running in test mode leads to", or is this something else?

Yep, that's what I meant (I think 😅 been a while).

[G-Rath]

Yep, that's what I meant

That'd track with what I've been seeing in tests for eslint plugins: if I run a test for just one rule I don't get a "circular error" error.

So then I guess this might not actually be complete yet since we don't have a test for doing that...

[SimenB]

@G-Rath I pushed up a commit using jest-serializer v8 serializer instead of flatted, thoughts?

This should in theory also support BigInt, fixing #12377 as well.

Note that this fails type and unit tests, but that shouldn't be too painful.

(there was #5613 which attempted a fancy version of this - using just the serializer aspect seems to have same performance)

[G-Rath]

@SimenB sounds fine to me, I like that it lets us avoid having an extra dependency.

What's required to move this forward? I'm happy to resolve the type errors, but don't think I'll be able to handle implementing a proper parallel test so might need you to do that, if that's something you want for this.

[SimenB]

When I played with this this morning, the test seems correct to me - 2 tests running in parallel

[SimenB]

Bah, just noticed this has the same issue as #10981 (comment) 🙁

I'll push a test for this

[SimenB]

OK, pushed that test to master, and merged here. It's failing 😭 We need to filter out functions somehow, but doesn't seem like the API supports it. I guess we could do some recursion, but still.

[G-Rath]

We need to filter out functions somehow, but doesn't seem like the API supports it. I guess we could do some recursion, but still.

When you say filter, are you meaning we want to pass them without serialising, or skip them all together?

I think that's probably going to get complex fast...

[SimenB]

Skip them entirely, it's impossible to actually serialize them, so we need to remove them

[G-Rath]

I think we can do this with flatted, as it supports the same API as JSON.stringify so we can have a replacer that returns undefined if typeof value === 'function'.

[G-Rath]

Actually maybe that means flatted will just handle this out of the box, because:

If you return a Function, Symbol, or undefined, the property is not included in the output.

But if it doesn't, then it sounds like we could use a replacer that is just value => value 🤔

[SimenB]

Yeah, that's how JSON.stringify works, it just strips it (which is why this is working fine atm on main). But it fails on circular, BigInt, Map, Set, Date etc

[G-Rath]

My understanding is that flatted should handle all of those - was there a reason you switched from flatted to v8 aside from being able to avoid an extra dependency? (oh right, it was a performance hit wasn't it? 🤔)

Frankly either way it sounds like flatted would be an improvement over just JSON.stringify even if it fails to handle a few of those so could be worth using that for now and we could look for another replacement as a follow-up if there are other things it can't handle.

[SimenB]

I swapped mainly as it should be faster as it's implemented in c++ and honed for years by google engineers. Benchmarking confirmed no real difference between using it and the current "raw" approach. And it passed the tests 😀

We could go for flatted, but it only fixes a subset of the issue (circular references) and not the underlying problem (inability to serialize complex objects).

But it might be better to just go with flatted for now as it's an incremental improvement, albeit a small one. Will need to benchmark it, tho

[G-Rath]

the underlying problem (inability to serialize complex objects).

I suspect the only true way to resolve that properly is going to be to have a pluggable system to let people provide their own serializer, given all the different ways an object could be structured, and the performance hits we might take if we tried to support all of them.

I think the incremental approach is the right one for now - are you happy to do the benchmarking if I re-add flatted back in (as it sounds like you might already have that setup, and will have a better idea of the numbers anyway)

[SimenB]

I wonder if we should take a step back. jest-worker inherently needs to serialize things, so if it fails (like the case is here, or with the reverted #10981) that's kinda expected, and users outside of Jest needs to adjust what data they send. What we need to fix here in Jest to fix the linked bugs is to do the same.

In the case of failing tests in Jest, we attempt to serialize JestAssertionError, which includes matcherResult, an object which can contain all sorts of nonsense people attempt to assert on: https://github.com/facebook/jest/blob/ecab294cd5c1653041289b5cf80deea11af40f3f/packages/expect/src/index.ts#L61-L63

We might need to properly serialize that object in particular so it's in some representation that's safe to transfer between processes, and then just let jest-worker do its thing. Notice how it even swaps out message function with just a string since the function isn't serializable.

Then probably bump minimum node 12 version from 12.13 to 12.16 so we can use https://nodejs.org/api/child_process.html#advanced-serialization (this is already the default in worker_threads, and what I attempt to replicate manually with using the v8 APIs)

[G-Rath]

That sounds like a good path, but doesn't it just move the underlying problem to be higher up since we still have to deal with functions and other types that can't be serialized?

(I think you're probably right though that that responsibility should be with whatever is calling jest-worker)

[SimenB]

That sounds like a good path, but doesn't it just move the underlying problem to be higher up since we still have to deal with functions and other types that can't be serialized?

Yes, but it should be up to the dependents to pass sane data to the worker. Like expect (solution might be in jest-circus or jest-jasmine, not in expect itself).

I think that by trying to work around it in jest-worker we're trying to solve something that's inherently unsolvable, although we can play whack-a-mole and solve concrete examples to get closer. But it can never be perfect, so I think a good line to draw is "v8 cannot serialize this, please clean up your data before passing it back" or some such. A clear distinction, and we can point to Node/v8 for limitations

[G-Rath]

so I think a good line to draw is "v8 cannot serialize this, please clean up your data before passing it back" or some such.

Completely agree - so then is the next step to look into serializing matcherResult better? (e.g. with flatted or v8)

[SimenB]

I think we shouldn't try to serialize the instance, but rather make sure that a complete assertionResult string is passed. I haven't dug into what that would entail, but essentially whatever happens here must result in a JSON serializable thing: https://github.com/facebook/jest/blob/ecab294cd5c1653041289b5cf80deea11af40f3f/packages/jest-circus/src/testCaseReportHandler.ts#L16-L21 (probably more specifically https://github.com/facebook/jest/blob/ecab294cd5c1653041289b5cf80deea11af40f3f/packages/jest-circus/src/utils.ts#L473-L474)

And the same for jasmine.

So we might have to also tweak the reporter since the object it'll receive will be less rich

[SimenB]

@G-Rath is what we discussed above something you're willing to work on? 🙂 (No pressure of course, I just wanna know if I should add it to my TODO-list or not 😀 )

[G-Rath]

@SimenB I'm interested, but if you're ok having it on your todo I think that'd probably be better as I've already got a fair bit on and I think you'll have a better understanding of what needs to happen anyway.

Keen to see the follow-up work though, so feel free to tag me for review and am happy to help so e.g. if there are isolated or follow-up improvements that could be done that I could help do let me know know

[MatanBobi]

@SimenB, @G-Rath I accidentally bumped into this one while investigating an issue we have in dom-testing-library for a while now: testing-library/dom-testing-library#875

Do you think this one might be related? @agmcleod was able to provide a reproduction but it still doesn't reproduce every time..

[SimenB]

Yeah, probably

[MatanBobi]

Thanks @SimenB and @G-Rath.. Anything I can do to help pushing this one forwards? :)

[SimenB]

Yeah, if you could pick up #11467 (comment) that'd be great!

If you're able to unskip

https://github.com/facebook/jest/blob/4dc9db2192b3df21c511acf8b91c86f8c6a222f7/e2e/__tests__/circularInequality.test.ts#L28

&

https://github.com/facebook/jest/blob/4dc9db2192b3df21c511acf8b91c86f8c6a222f7/e2e/__tests__/complexItemsInErrors.ts#L64

we should be good 🙂

[MatanBobi]

@SimenB I'll give it a try :) will update on any progress I make.

[SimenB]

Awesome, thanks!

[MatanBobi]

Hi @SimenB, just looping back to say it's taking me a bit longer to on-board to the project as I'm not too familiar with the codebase. Still didn't give up on this one but just wanted you to know :)

[github-actions]

This pull request has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.
Please note this issue tracker is not a help forum. We recommend using StackOverflow or our discord channel for questions.