Skip to content

Playwright: logs causes timeouts across parallel tests and across browsers #9941

@nstepien

Description

@nstepien

Describe the bug

While debugging an issue in a React lib, React started spamming the console with logs like this one:

Example log
Encountered two children with the same key, `0`. Keys should be unique so that components maintain their identity across updates. Non-unique keys may cause children to be duplicated and/or omitted — the behavior is unsupported and could change in a future version.
 ❯ console.error test/failOnConsole.ts:13:12
 ❯ require_react_dom_client_development</createChildReconciler/warnOnInvalidKey/< .cache/vite/vitest/ef98362b8a6b0c8cd804b0d227aa1ffeaba89786/deps/client-CrdCuA0L.js?v=ac8402a5:3713:15
 ❯ runWithFiberInDEV .cache/vite/vitest/ef98362b8a6b0c8cd804b0d227aa1ffeaba89786/deps/client-CrdCuA0L.js?v=ac8402a5:851:122
 ❯ warnOnInvalidKey .cache/vite/vitest/ef98362b8a6b0c8cd804b0d227aa1ffeaba89786/deps/client-CrdCuA0L.js?v=ac8402a5:3712:24
 ❯ reconcileChildrenArray .cache/vite/vitest/ef98362b8a6b0c8cd804b0d227aa1ffeaba89786/deps/client-CrdCuA0L.js?v=ac8402a5:3737:150
 ❯ reconcileChildFibersImpl .cache/vite/vitest/ef98362b8a6b0c8cd804b0d227aa1ffeaba89786/deps/client-CrdCuA0L.js?v=ac8402a5:3842:105
 ❯ require_react_dom_client_development</createChildReconciler/< .cache/vite/vitest/ef98362b8a6b0c8cd804b0d227aa1ffeaba89786/deps/client-CrdCuA0L.js?v=ac8402a5:3869:52
 ❯ reconcileChildren .cache/vite/vitest/ef98362b8a6b0c8cd804b0d227aa1ffeaba89786/deps/client-CrdCuA0L.js?v=ac8402a5:5386:45
 ❯ beginWork .cache/vite/vitest/ef98362b8a6b0c8cd804b0d227aa1ffeaba89786/deps/client-CrdCuA0L.js?v=ac8402a5:6200:1568
 ❯ runWithFiberInDEV .cache/vite/vitest/ef98362b8a6b0c8cd804b0d227aa1ffeaba89786/deps/client-CrdCuA0L.js?v=ac8402a5:851:122
 ❯ performUnitOfWork .cache/vite/vitest/ef98362b8a6b0c8cd804b0d227aa1ffeaba89786/deps/client-CrdCuA0L.js?v=ac8402a5:8429:91
 ❯ workLoopSync .cache/vite/vitest/ef98362b8a6b0c8cd804b0d227aa1ffeaba89786/deps/client-CrdCuA0L.js?v=ac8402a5:8325:54
 ❯ renderRootSync .cache/vite/vitest/ef98362b8a6b0c8cd804b0d227aa1ffeaba89786/deps/client-CrdCuA0L.js?v=ac8402a5:8309:5
 ❯ performWorkOnRoot .cache/vite/vitest/ef98362b8a6b0c8cd804b0d227aa1ffeaba89786/deps/client-CrdCuA0L.js?v=ac8402a5:7957:180
 ❯ performWorkOnRootViaSchedulerTask .cache/vite/vitest/ef98362b8a6b0c8cd804b0d227aa1ffeaba89786/deps/client-CrdCuA0L.js?v=ac8402a5:9059:21
 ❯ flushActQueue .cache/vite/vitest/ef98362b8a6b0c8cd804b0d227aa1ffeaba89786/deps/react.js?v=ac8402a5:347:35
 ❯ require_react_development</exports.act/then/< .cache/vite/vitest/ef98362b8a6b0c8cd804b0d227aa1ffeaba89786/deps/react.js?v=ac8402a5:503:22
 ❯ promise callback*then .cache/vite/vitest/ef98362b8a6b0c8cd804b0d227aa1ffeaba89786/deps/react.js?v=ac8402a5:499:14
 ❯ promise callback*act< .cache/vite/vitest/ef98362b8a6b0c8cd804b0d227aa1ffeaba89786/deps/pure-DZz-eKGg-s7G_EF11.js?v=ac8402a5:30:8
 ❯ render .cache/vite/vitest/ef98362b8a6b0c8cd804b0d227aa1ffeaba89786/deps/pure-DZz-eKGg-s7G_EF11.js?v=ac8402a5:59:7
 ❯ setup test/browser/utils.tsx:7:14
 ❯ setupGrid test/browser/virtualization.test.ts:34:9
 ❯ test/browser/virtualization.test.ts:232:8

That in itself is not an issue with Vitest whatsoever.

What is an issue on the other hand, is that the one test that triggered the logs made unrelated tests running in parallel time out, for example:

TimeoutError: locator.click: Timeout 2000ms exceeded.
Call log:
  - waiting for locator('[data-vitest="true"]').contentFrame().getByTestId('__vitest_0__')
    - locator resolved to <body data-testid="__vitest_0__">↵  ↵↵</body>
  - attempting click action
    - waiting for element to be visible, enabled and stable

 ❯ test/setupBrowser.ts:87:18
     85|   // 1. reset cursor position to avoid hover issues
     86|   // 2. force focus to be on the page
     87|   await userEvent.click(document.body, { position: { x: 0, y: 0 } });
       |                  ^
     88| });
     89|

If I .skip the test causing the logs, then the other tests pass as expected.

It seems like the test runner/nodejs process/orchestrator can become too busy to execute browser interactions in a timely manner.
I wonder if tasks other than console logs can overwork the nodejs process.
Should the nodejs process yield to higher-priority tasks?
Should there be 1 nodejs worker per test suite?
Either way, interaction latency is definitely affected by low-priority tasks.

Reproduction

https://github.com/nstepien/vitest-bug

  1. npm ci
  2. npx playwright install
  3. Run tests
    • npm test - all browsers spamming the console while running all the tests
    • npm run test:across - one browser spamming the console, other browsers run the tests
  4. Comment out the console.log(); line in test/spam.test.ts and run the tests again:
    • Actions do not timeout anymore

With npm run test:across:

  • chromium runs a test that spams console logs
  • firefox and webkit run interaction tests
  • the chromium logs cause firefox and webkit tests to time out!

Example logs:
Image

Image Image

System Info

System:
    OS: Windows 11 10.0.26200
    CPU: (32) x64 AMD Ryzen 9 9950X3D 16-Core Processor
    Memory: 34.28 GB / 63.58 GB
  Binaries:
    Node: 25.8.1 - C:\Program Files\nodejs\node.EXE
    npm: 11.11.1 - C:\Program Files\nodejs\npm.CMD
    pnpm: 10.30.3 - C:\Users\Stepi\AppData\Roaming\npm\pnpm.CMD
  Browsers:
    Chrome: 146.0.7680.154
    Edge: Chromium (146.0.3856.59)
    Firefox: 148.0.2 - C:\Program Files\Mozilla Firefox\firefox.exe
  npmPackages:
    @vitest/browser-playwright: ^4.1.0 => 4.1.0
    playwright: ^1.58.2 => 1.58.2
    vitest: ^4.1.0 => 4.1.0

Used Package Manager

npm

Validations

Metadata

Metadata

Assignees

No one assigned

    Labels

    Type

    Projects

    Status

    P2 - 2

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions