Bug 322171 – [Glib][WebDriver] Step webdriver-test has been running for more than 12 hours

• Status: RESOLVED
• Resolution: FIXED
• Component: Tools / Tests

[Carlos Alberto Lopez Perez]

See: https://build.webkit.org/#/builders/37/builds/32314

I entered into the machine and I see this:

buildbot-worker@gtk-linux-64-bit-release-webdriver-tests-gtk-linux-bot-14:~/GTK-Linux-64-bit-Release-WebDriver-Tests/build$ date
Thu Aug 20 03:11:31 PDT 2026
buildbot-worker@gtk-linux-64-bit-release-webdriver-tests-gtk-linux-bot-14:~/GTK-Linux-64-bit-Release-WebDriver-Tests/build$ tail -50 logs.txt 
websockets.client: [DEBUG] < PONG 27 d3 38 18 [binary, 4 bytes]
websockets.client: [DEBUG] % received keepalive pong
websockets.client: [DEBUG] % sending keepalive ping
websockets.client: [DEBUG] > PING 11 73 8e 20 [binary, 4 bytes]
websockets.client: [DEBUG] < PONG 11 73 8e 20 [binary, 4 bytes]
websockets.client: [DEBUG] % received keepalive pong
websockets.client: [DEBUG] % sending keepalive ping
websockets.client: [DEBUG] > PING 84 94 55 36 [binary, 4 bytes]
websockets.client: [DEBUG] < PONG 84 94 55 36 [binary, 4 bytes]
websockets.client: [DEBUG] % received keepalive pong
websockets.client: [DEBUG] % sending keepalive ping
websockets.client: [DEBUG] > PING c5 2c 1e a1 [binary, 4 bytes]
websockets.client: [DEBUG] < PONG c5 2c 1e a1 [binary, 4 bytes]
websockets.client: [DEBUG] % received keepalive pong
websockets.client: [DEBUG] % sending keepalive ping
websockets.client: [DEBUG] > PING f4 06 ed 02 [binary, 4 bytes]
websockets.client: [DEBUG] < PONG f4 06 ed 02 [binary, 4 bytes]
websockets.client: [DEBUG] % received keepalive pong
websockets.client: [DEBUG] % sending keepalive ping
websockets.client: [DEBUG] > PING 30 6c 01 c7 [binary, 4 bytes]
websockets.client: [DEBUG] < PONG 30 6c 01 c7 [binary, 4 bytes]
websockets.client: [DEBUG] % received keepalive pong
websockets.client: [DEBUG] % sending keepalive ping
websockets.client: [DEBUG] > PING 3f 52 eb 46 [binary, 4 bytes]
websockets.client: [DEBUG] < PONG 3f 52 eb 46 [binary, 4 bytes]
websockets.client: [DEBUG] % received keepalive pong
websockets.client: [DEBUG] % sending keepalive ping
websockets.client: [DEBUG] > PING 3c c9 2c da [binary, 4 bytes]
websockets.client: [DEBUG] < PONG 3c c9 2c da [binary, 4 bytes]
websockets.client: [DEBUG] % received keepalive pong
websockets.client: [DEBUG] % sending keepalive ping
websockets.client: [DEBUG] > PING c5 0b f1 dc [binary, 4 bytes]
websockets.client: [DEBUG] < PONG c5 0b f1 dc [binary, 4 bytes]
websockets.client: [DEBUG] % received keepalive pong
websockets.client: [DEBUG] % sending keepalive ping
websockets.client: [DEBUG] > PING 64 e7 58 98 [binary, 4 bytes]
websockets.client: [DEBUG] < PONG 64 e7 58 98 [binary, 4 bytes]
websockets.client: [DEBUG] % received keepalive pong
websockets.client: [DEBUG] % sending keepalive ping
websockets.client: [DEBUG] > PING 7e cb fd 6f [binary, 4 bytes]
websockets.client: [DEBUG] < PONG 7e cb fd 6f [binary, 4 bytes]
websockets.client: [DEBUG] % received keepalive pong
websockets.client: [DEBUG] % sending keepalive ping
websockets.client: [DEBUG] > PING 3d 2e 99 05 [binary, 4 bytes]
websockets.client: [DEBUG] < PONG 3d 2e 99 05 [binary, 4 bytes]
websockets.client: [DEBUG] % received keepalive pong
websockets.client: [DEBUG] % sending keepalive ping
websockets.client: [DEBUG] > PING 60 c0 cb 1a [binary, 4 bytes]
websockets.client: [DEBUG] < PONG 60 c0 cb 1a [binary, 4 bytes]
websockets.client: [DEBUG] % received keepalive pong




That continues ping-pong from the debug connection causes the step to never be killed by buildbot because it is always printing something.

I think we need to implement into the webdriver test runner some kind of timeout to prevent this.

[Carlos Alberto Lopez Perez]

I have uploaded the logs to https://people.igalia.com/clopez/wkbug/322171/logs.txt (17M)

And then proceeded to manually kit the WebDriver process to see if that way the test run can continue

$ pidof WebKitWebDriver
3980648
$ kill -TERM 3980648

then on the logs.txt this was printed:

websockets.client: [DEBUG] ! failing connection with code 1006
websockets.client: [DEBUG] = connection is CLOSED


And then I can see that the process has become zombie:

$ ps aux|grep 3980648
buildbo+ 3980648  0.0  0.0      0     0 ?        Z    Aug19   0:00 [WebKitWebDriver] <defunct>


That is another bug, the runner should reap it back.


Instead the runner is stuck waiting for nothing.


Nothing is printed anymore in logs.txt, neither the runner is doing anything.
It it simply hasn't noticed that the only process it should be waiting for has become a zombie.

I tried to send

$ kill -KILL 3980648

but nothing new happens, the process was already death, is just a zombie waiting for the runner to reap it.

 pstree -pa 3508065
python3,3508065 /sdk/webkit/Tools/Scripts/run-webdriver-tests --verbose --json-output=webdriver_tests.json --release --gtk
  |-(WebKitWebDriver,3980648)
  |-Xvfb,3508149 -displayfd 4 -nolisten tcp -ac -screen 0 1024x768x24
  |-python3,3738588 /sdk/webkit/LayoutTests/imported/w3c/web-platform-tests/wpt.py serve --config /sdk/webkit/LayoutTests/imported/w3c/web-platform-tests/config.json
  |   |-python3,3738612 -c from multiprocessing.resource_tracker import main;main(5)
  |   |-python3,3738613 -c from multiprocessing.spawn import spawn_main; spawn_main(tracker_fd=6, pipe_handle=8) --multiprocessing-fork
  |   |   `-{python3},3738614
  |   |-python3,3738615 -c from multiprocessing.spawn import spawn_main; spawn_main(tracker_fd=6, pipe_handle=7) --multiprocessing-fork
  |   |   `-{python3},3738626
  |   |-python3,3738616 -c from multiprocessing.spawn import spawn_main; spawn_main(tracker_fd=6, pipe_handle=10) --multiprocessing-fork
  |   |   `-{python3},3738623
  |   |-python3,3738617 -c from multiprocessing.spawn import spawn_main; spawn_main(tracker_fd=6, pipe_handle=12) --multiprocessing-fork
  |   |   `-{python3},3738628
  |   |-python3,3738618 -c from multiprocessing.spawn import spawn_main; spawn_main(tracker_fd=6, pipe_handle=14) --multiprocessing-fork
  |   |   `-{python3},3738622
  |   |-python3,3738619 -c from multiprocessing.spawn import spawn_main; spawn_main(tracker_fd=6, pipe_handle=16) --multiprocessing-fork
  |   |   `-{python3},3738627
  |   |-python3,3738620 -c from multiprocessing.spawn import spawn_main; spawn_main(tracker_fd=6, pipe_handle=18) --multiprocessing-fork
  |   |   `-{python3},3738624
  |   `-python3,3738621 -c from multiprocessing.spawn import spawn_main; spawn_main(tracker_fd=6, pipe_handle=20) --multiprocessing-fork
  |       `-{python3},3738625
  |-python3,3980652 /sdk/webkit/Tools/Scripts/run-webdriver-tests --verbose --json-output=webdriver_tests.json --release --gtk
  |-{python3},3738636
  |-{python3},3980649
  `-{python3},3980650


I'm going to leave it here, buildbot should now kill it after 20 minutes because nothing is printed anymore. That will be also another probe that the runner has really hanged here and that it has another bug in how it manages subprocess.

[Claudio Saavedra]

What happened

The run died on the first of 3 tests collected from
WebDriverTests/imported/w3c/webdriver/tests/bidi/browsing_context/navigation_committed/navigation_interrupted.py::test_multiple_events_for_interrupted_navigation[Interrupted immediately], started 20:46:47.41.

pytest-timeout was set to 10 s with timeout method: signal (SIGALRM). At 20:46:57.43 — exactly 10 s in — the alarm fired while the event loop was mid-way through this chain:

futures._set_result_unless_cancelled  →  fut.set_result(result)
  → base_events.call_soon → _call_soon → events.Handle.__init__   ← SIGALRM landed here
      → pytest_timeout.handler → pytest.fail → raise Failed

That's the whole bug. set_result() had already marked the future done, but the call_soon() that would reschedule the coroutine awaiting it was aborted while constructing its Handle. So the future is resolved and nothing is ever woken — the test coroutine is parked permanently. asyncio logged the escape as "Exception in callback" and kept the loop running, so pytest never received the failure: the timeout destroyed its own delivery path.

The loop's surviving websockets keepalive task then pinged every 20 s → 4 log lines → 12 lines/min → filter-test-logs' heartbeat → buildbot's inactivity timer reset forever. Three days.

The fix

Root cause is one line. Tools/Scripts/webkitpy/webdriver_tests/pytest_runner.py:209 passes --timeout with no --timeout-method, so pytest-timeout defaults to signal, which is documented as unsafe against code that isn't signal-safe — and asyncio internals are exactly that:

cmd = ['-vv',
       '--capture', 'no',
       '--basetemp', cache_directory,
       '--showlocals',
       '--timeout', str(timeout),
       '--timeout-method', 'thread',   # signal method corrupts asyncio; see below
       '-p', 'no:cacheprovider']

The thread method uses a timer thread that dumps stacks and hard-exits instead of raising inside arbitrary frames. Noisier on timeout, but it cannot wedge.

Then the maxTime in steps.py as defense in depth — that's what turned a hung test into a three-day outage, and it protects against the next unrelated hang too.

Third, milder item: the two orphaned MiniBrowser processes reparented to podman-init date from ~20:24 PDT, about 22 min before the hang, so they're an independent session-teardown leak during normal operation, not fallout from this. Worth a separate look sometime; correcting what I said earlier, they weren't part of this failure.

[Claudio Saavedra]

Pull request: https://github.com/WebKit/WebKit/pull/73413

[EWS]

Committed 320815@main (92641830324a): <https://commits.webkit.org/320815@main>

Reviewed commits have been landed. Closing PR #73413 and removing active labels.

[Adrian Perez]

Re-opening for pull request https://github.com/WebKit/WebKit/pull/73677

[EWS]

Committed 305877.1176@webkitglib/2.52 (9106ada8d005): <https://commits.webkit.org/305877.1176@webkitglib/2.52>

Reviewed commits have been landed. Closing PR #73677 and removing active labels.