web-test-runner: DynamicTerminal can swallow errors

[devversion]

I've been trying to use Web Test Runner with our Bazel build system. This means Web Test Runner may be invoked multiple times, executing multiple tests concurrently, with isolated instances of WTR.

This worked great overall, but we've noticed some instability/flakiness with the Puppeteer/web/test-runner-chome launcher and it was extremely hard to debug and required lots of patching of @web/test-runner-core to actually see what is going on. The problem is that, even in non TTY mode, with static logging option enabled, the dynamic terminal logic was swallowing the errors— likely due to the regular clears() or dynamic logging that is still happening even with staticLogging: true.

It would be great to improve the logic around logging here, to make it more CI/non TTY friendly.

[bashmish]

I didn't encounter such issues myself. Can you make some screenshots showing what you expected to see in the console and what was missing? A link to a repository with this particular test setup can also help a lot.

[devversion]

It's a little difficult to reproduce, unless you build our whole repository with Bazel involved 😄 — I could potentially try to work on a simpler reproduction.

The error I've fixed with #2928, was basically swallowed because it was an uncaught error due to the incorrect exposeFunction call from the browser (hence patches removed now). We were investigating quite some time, and couldn't figure out why the test runner exited without any output.

I've then enabled Puppeteer debug logging and traced back that TestRunner#stop was being called. Even adding console.trace() or console.log('a') messages for debugging didn't work because the output never got printed (I believe that is where the dynamic terminal was interferring!) — Ultimately I've patched test runner to not do the dynamic terminal and was able to see the actual "uncaught exception" triggering the TestRunner#stop.

Uncaught exception. Stopping...
 ProtocolError: Protocol error (script.callFunction): no such handle Unable to find an object reference for "handle" 3d8b8175-1008-45e2-aa17-9a0662f70b7b RemoteError@chrome://remote/content/shared/RemoteError.sys.mjs:8:8
WebDriverError@chrome://remote/content/shared/webdriver/Errors.sys.mjs:199:5
NoSuchHandleError@chrome://remote/content/shared/webdriver/Errors.sys.mjs:633:5
deserialize@chrome://remote/content/webdriver-bidi/RemoteValue.sys.mjs:287:13
deserialize@chrome://remote/content/webdriver-bidi/modules/WindowGlobalBiDiModule.sys.mjs:42:17
callFunctionDeclaration/deserializedArguments<@chrome://remote/content/webdriver-bidi/modules/windowglobal/script.sys.mjs:357:18
callFunctionDeclaration@chrome://remote/content/webdriver-bidi/modules/windowglobal/script.sys.mjs:356:28
handleCommand@chrome://remote/content/shared/messagehandler/MessageHandler.sys.mjs:260:33
receiveMessage@chrome://remote/content/shared/messagehandler/transports/js-window-actors/MessageHandlerFrameChild.sys.mjs:78:37

    at <instance_members_initializer> (/usr/local/google/home/pgschwendtner/.cache/bazel/_bazel_pgschwendtner/b3e2b6cb76f4b71f1143108e3588676f/execroot/angular_material/bazel-out/k8-fastbuild/bin/src/material/sidenav/testing/unit_tests_firefox_/unit_tests_firefox.runfiles/rules_browsers/node_modules/.aspect_rules_js/puppeteer-core@24.6.0/node_modules/puppeteer-core/lib/cjs/puppeteer/common/CallbackRegistry.js:101:14)
    at new Callback (/usr/local/google/home/pgschwendtner/.cache/bazel/_bazel_pgschwendtner/b3e2b6cb76f4b71f1143108e3588676f/execroot/angular_material/bazel-out/k8-fastbuild/bin/src/material/sidenav/testing/unit_tests_firefox_/unit_tests_firefox.runfiles/rules_browsers/node_modules/.aspect_rules_js/puppeteer-core@24.6.0/node_modules/puppeteer-core/lib/cjs/puppeteer/common/CallbackRegistry.js:105:16)
    at CallbackRegistry.create (/usr/local/google/home/pgschwendtner/.cache/bazel/_bazel_pgschwendtner/b3e2b6cb76f4b71f1143108e3588676f/execroot/angular_material/bazel-out/k8-fastbuild/bin/src/material/sidenav/testing/unit_tests_firefox_/unit_tests_firefox.runfiles/rules_browsers/node_modules/.aspect_rules_js/puppeteer-core@24.6.0/node_modules/puppeteer-core/lib/cjs/puppeteer/common/CallbackRegistry.js:23:26)
    at BidiConnection.send (/usr/local/google/home/pgschwendtner/.cache/bazel/_bazel_pgschwendtner/b3e2b6cb76f4b71f1143108e3588676f/execroot/angular_material/bazel-out/k8-fastbuild/bin/src/material/sidenav/testing/unit_tests_firefox_/unit_tests_firefox.runfiles/rules_browsers/node_modules/.aspect_rules_js/puppeteer-core@24.6.0/node_modules/puppeteer-core/lib/cjs/puppeteer/bidi/Connection.js:54:32)
    at Session.send (/usr/local/google/home/pgschwendtner/.cache/bazel/_bazel_pgschwendtner/b3e2b6cb76f4b71f1143108e3588676f/execroot/angular_material/bazel-out/k8-fastbuild/bin/src/material/sidenav/testing/unit_tests_firefox_/unit_tests_firefox.runfiles/rules_browsers/node_modules/.aspect_rules_js/puppeteer-core@24.6.0/node_modules/puppeteer-core/lib/cjs/puppeteer/bidi/core/Session.js:137:42)
    at Session.<anonymous> (/usr/local/google/home/pgschwendtner/.cache/bazel/_bazel_pgschwendtner/b3e2b6cb76f4b71f1143108e3588676f/execroot/angular_material/bazel-out/k8-fastbuild/bin/src/material/sidenav/testing/unit_tests_firefox_/unit_tests_firefox.runfiles/rules_browsers/node_modules/.aspect_rules_js/puppeteer-core@24.6.0/node_modules/puppeteer-core/lib/cjs/puppeteer/util/decorators.js:109:27)
    at WindowRealm.callFunction (/usr/local/google/home/pgschwendtner/.cache/bazel/_bazel_pgschwendtner/b3e2b6cb76f4b71f1143108e3588676f/execroot/angular_material/bazel-out/k8-fastbuild/bin/src/material/sidenav/testing/unit_tests_firefox_/unit_tests_firefox.runfiles/rules_browsers/node_modules/.aspect_rules_js/puppeteer-core@24.6.0/node_modules/puppeteer-core/lib/cjs/puppeteer/bidi/core/Realm.js:95:51)
    at WindowRealm.<anonymous> (/usr/local/google/home/pgschwendtner/.cache/bazel/_bazel_pgschwendtner/b3e2b6cb76f4b71f1143108e3588676f/execroot/angular_material/bazel-out/k8-fastbuild/bin/src/material/sidenav/testing/unit_tests_firefox_/unit_tests_firefox.runfiles/rules_browsers/node_modules/.aspect_rules_js/puppeteer-core@24.6.0/node_modules/puppeteer-core/lib/cjs/puppeteer/util/decorators.js:109:27)
    at #evaluate (/usr/local/google/home/pgschwendtner/.cache/bazel/_bazel_pgschwendtner/b3e2b6cb76f4b71f1143108e3588676f/execroot/angular_material/bazel-out/k8-fastbuild/bin/src/material/sidenav/testing/unit_tests_firefox_/unit_tests_firefox.runfiles/rules_browsers/node_modules/.aspect_rules_js/puppeteer-core@24.6.0/node_modules/puppeteer-core/lib/cjs/puppeteer/bidi/Realm.js:137:42)
    at BidiFrameRealm.evaluateHandle (/usr/local/google/home/pgschwendtner/.cache/bazel/_bazel_pgschwendtner/b3e2b6cb76f4b71f1143108e3588676f/execroot/angular_material/bazel-out/k8-fastbuild/bin/src/material/sidenav/testing/unit_tests_firefox_/unit_tests_firefox.runfiles/rules_browsers/node_modules/.aspect_rules_js/puppeteer-core@24.6.0/node_modules/puppeteer-core/lib/cjs/puppeteer/bidi/Realm.js:104:36)
    at BidiJSHandle.evaluateHandle (/usr/local/google/home/pgschwendtner/.cache/bazel/_bazel_pgschwendtner/b3e2b6cb76f4b71f1143108e3588676f/execroot/angular_material/bazel-out/k8-fastbuild/bin/src/material/sidenav/testing/unit_tests_firefox_/unit_tests_firefox.runfiles/rules_browsers/node_modules/.aspect_rules_js/puppeteer-core@24.6.0/node_modules/puppeteer-core/lib/cjs/puppeteer/api/JSHandle.js:157:37)
    at BidiJSHandle.getProperty (/usr/local/google/home/pgschwendtner/.cache/bazel/_bazel_pgschwendtner/b3e2b6cb76f4b71f1143108e3588676f/execroot/angular_material/bazel-out/k8-fastbuild/bin/src/material/sidenav/testing/unit_tests_firefox_/unit_tests_firefox.runfiles/rules_browsers/node_modules/.aspect_rules_js/puppeteer-core@24.6.0/node_modules/puppeteer-core/lib/cjs/puppeteer/api/JSHandle.js:163:31)
    at BidiJSHandle.<anonymous> (/usr/local/google/home/pgschwendtner/.cache/bazel/_bazel_pgschwendtner/b3e2b6cb76f4b71f1143108e3588676f/execroot/angular_material/bazel-out/k8-fastbuild/bin/src/material/sidenav/testing/unit_tests_firefox_/unit_tests_firefox.runfiles/rules_browsers/node_modules/.aspect_rules_js/puppeteer-core@24.6.0/node_modules/puppeteer-core/lib/cjs/puppeteer/util/decorators.js:109:27)
    at /usr/local/google/home/pgschwendtner/.cache/bazel/_bazel_pgschwendtner/b3e2b6cb76f4b71f1143108e3588676f/execroot/angular_material/bazel-out/k8-fastbuild/bin/src/material/sidenav/testing/unit_tests_firefox_/unit_tests_firefox.runfiles/rules_browsers/node_modules/.aspect_rules_js/puppeteer-core@24.6.0/node_modules/puppeteer-core/lib/cjs/puppeteer/api/JSHandle.js:198:29
    at Array.map (<anonymous>)
    at BidiJSHandle.getProperties (/usr/local/google/home/pgschwendtner/.cache/bazel/_bazel_pgschwendtner/b3e2b6cb76f4b71f1143108e3588676f/execroot/angular_material/bazel-out/k8-fastbuild/bin/src/material/sidenav/testing/unit_tests_firefox_/unit_tests_firefox.runfiles/rules_browsers/node_modules/.aspect_rules_js/puppeteer-core@24.6.0/node_modules/puppeteer-core/lib/cjs/puppeteer/api/JSHandle.js:197:61)
    at async #handleMessage (/usr/local/google/home/pgschwendtner/.cache/bazel/_bazel_pgschwendtner/b3e2b6cb76f4b71f1143108e3588676f/execroot/angular_material/bazel-out/k8-fastbuild/bin/src/material/sidenav/testing/unit_tests_firefox_/unit_tests_firefox.runfiles/rules_browsers/node_modules/.aspect_rules_js/puppeteer-core@24.6.0/node_modules/puppeteer-core/lib/cjs/puppeteer/bidi/ExposedFunction.js:189:43)

Based on this experience, I feel like the DynamicTerminal is great for TTY's but there should be a whole new implementation for static logging that never involves clearing, patching of console.X. Does that sound somewhat reasonable?

[bashmish]

I'm afraid I don't know the context well enough to imagine this behavior based on provided description.
The code that implements the logging, including the clearing of it, was not written by me, maybe that's why I don't get what this means. I might try to read it and even understand how it might theoretically happen, but with a practical reproduction it would be so much easier.
Bazel is open source, so should be possible to make a small repro? I'd really appreciate if you can make one.