1835369 - Intermittent Wd | <random> - assert 0 == 1 (InvalidStateError: JSWindowActorChild.sendAsyncMessage: JSWindowActorChild cannot send at the moment)

Status: RESOLVED WORKSFORME

(Remote Protocol :: WebDriver BiDi, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: smolnar [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=417208952&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/dvsLBkRERauvX4FtwdcNJQ/runs/0/artifacts/public/logs/live_backing.log

---

INFO - TEST-PASS | /webdriver/tests/bidi/session/subscribe/contexts.py | test_subscribe_to_one_context_twice 
[task 2023-05-26T17:09:47.780Z] 17:09:47     INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/bidi/session/subscribe/contexts.py | test_subscribe_to_one_context_and_then_to_all - assert 0 == 1
[task 2023-05-26T17:09:47.780Z] 17:09:47     INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x000002459277B040>
[task 2023-05-26T17:09:47.780Z] 17:09:47     INFO - subscribe_events = <function subscribe_events.<locals>.subscribe_events at 0x0000024592785430>
[task 2023-05-26T17:09:47.780Z] 17:09:47     INFO - top_context = {'children': [], 'context': '245b7e95-a2a1-4551-94f6-98b12929f48f', 'parent': None, 'url': 'about:blank'}
[task 2023-05-26T17:09:47.780Z] 17:09:47     INFO - new_tab = {'context': '14132071-cb73-4057-b01d-06120849a2c5'}
[task 2023-05-26T17:09:47.780Z] 17:09:47     INFO - wait_for_event = <function wait_for_event.<locals>.wait_for_event at 0x0000024592785940>
[task 2023-05-26T17:09:47.780Z] 17:09:47     INFO - 
[task 2023-05-26T17:09:47.780Z] 17:09:47     INFO -     @pytest.mark.asyncio
[task 2023-05-26T17:09:47.780Z] 17:09:47     INFO -     async def test_subscribe_to_one_context_and_then_to_all(
[task 2023-05-26T17:09:47.780Z] 17:09:47     INFO -         bidi_session, subscribe_events, top_context, new_tab, wait_for_event
[task 2023-05-26T17:09:47.780Z] 17:09:47     INFO -     ):
[task 2023-05-26T17:09:47.780Z] 17:09:47     INFO -         # Subscribe for log events to a specific context
[task 2023-05-26T17:09:47.780Z] 17:09:47     INFO -         await subscribe_events(events=["log.entryAdded"], contexts=[top_context["context"]])
[task 2023-05-26T17:09:47.780Z] 17:09:47     INFO -     
[task 2023-05-26T17:09:47.780Z] 17:09:47     INFO -         # Track all received log.entryAdded events in the events array
[task 2023-05-26T17:09:47.780Z] 17:09:47     INFO -         events = []
[task 2023-05-26T17:09:47.780Z] 17:09:47     INFO -     
[task 2023-05-26T17:09:47.780Z] 17:09:47     INFO -         async def on_event(method, data):
[task 2023-05-26T17:09:47.780Z] 17:09:47     INFO -             events.append(data)
[task 2023-05-26T17:09:47.781Z] 17:09:47     INFO -     
[task 2023-05-26T17:09:47.781Z] 17:09:47     INFO -         remove_listener = bidi_session.add_event_listener("log.entryAdded", on_event)
[task 2023-05-26T17:09:47.781Z] 17:09:47     INFO -     
[task 2023-05-26T17:09:47.781Z] 17:09:47     INFO -         # Trigger console event in the another context
[task 2023-05-26T17:09:47.781Z] 17:09:47     INFO -         buffered_event_expected_text = await create_console_api_message(
[task 2023-05-26T17:09:47.781Z] 17:09:47     INFO -             bidi_session, new_tab, "text1"
[task 2023-05-26T17:09:47.781Z] 17:09:47     INFO -         )
[task 2023-05-26T17:09:47.781Z] 17:09:47     INFO -     
[task 2023-05-26T17:09:47.781Z] 17:09:47     INFO -         assert len(events) == 0
[task 2023-05-26T17:09:47.781Z] 17:09:47     INFO -     
[task 2023-05-26T17:09:47.781Z] 17:09:47     INFO -         # Trigger another console event in the observed context
[task 2023-05-26T17:09:47.781Z] 17:09:47     INFO -         on_entry_added = wait_for_event("log.entryAdded")
[task 2023-05-26T17:09:47.782Z] 17:09:47     INFO -         expected_text = await create_console_api_message(bidi_session, top_context, "text2")
[task 2023-05-26T17:09:47.782Z] 17:09:47     INFO -         await on_entry_added
INFO -     
[task 2023-05-26T17:09:47.782Z] 17:09:47     INFO -         assert len(events) == 1
[task 2023-05-26T17:09:47.782Z] 17:09:47     INFO -         recursive_compare(
[task 2023-05-26T17:09:47.782Z] 17:09:47     INFO -             {
[task 2023-05-26T17:09:47.782Z] 17:09:47     INFO -                 "text": expected_text,
[task 2023-05-26T17:09:47.782Z] 17:09:47     INFO -             },
[task 2023-05-26T17:09:47.782Z] 17:09:47     INFO -             events[0],
[task 2023-05-26T17:09:47.782Z] 17:09:47     INFO -         )
[task 2023-05-26T17:09:47.782Z] 17:09:47     INFO -     
[task 2023-05-26T17:09:47.782Z] 17:09:47     INFO -         events = []
[task 2023-05-26T17:09:47.782Z] 17:09:47     INFO -     
[task 2023-05-26T17:09:47.782Z] 17:09:47     INFO -         # Subscribe to all contexts
[task 2023-05-26T17:09:47.782Z] 17:09:47     INFO -         await subscribe_events(events=["log.entryAdded"])
[task 2023-05-26T17:09:47.782Z] 17:09:47     INFO -     
[task 2023-05-26T17:09:47.782Z] 17:09:47     INFO -         # Check that we received the buffered event
[task 2023-05-26T17:09:47.782Z] 17:09:47     INFO - >       assert len(events) == 1
[task 2023-05-26T17:09:47.782Z] 17:09:47     INFO - E       assert 0 == 1
[task 2023-05-26T17:09:47.782Z] 17:09:47     INFO - E         +0
[task 2023-05-26T17:09:47.782Z] 17:09:47     INFO - E         -1
[task 2023-05-26T17:09:47.782Z] 17:09:47     INFO - 
[task 2023-05-26T17:09:47.783Z] 17:09:47     INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x000002459277B040>
[task 2023-05-26T17:09:47.783Z] 17:09:47     INFO - buffered_event_expected_text = 'text1'
[task 2023-05-26T17:09:47.783Z] 17:09:47     INFO - events     = []
[task 2023-05-26T17:09:47.783Z] 17:09:47     INFO - expected_text = 'text2'
[task 2023-05-26T17:09:47.783Z] 17:09:47     INFO - new_tab    = {'context': '14132071-cb73-4057-b01d-06120849a2c5'}
[task 2023-05-26T17:09:47.783Z] 17:09:47     INFO - on_entry_added = <Future finished result={'args': [{'type': 'string', 'value': 'text2'}], 'level': 'info', 'method': 'log', 'source': {'context': '245b7e95-a2a...-98b12929f48f', 'realm': '303510f6-55f...-e4a02fb1db5d'}, ...}>
[task 2023-05-26T17:09:47.783Z] 17:09:47     INFO - on_event   = <function test_subscribe_to_one_context_and_then_to_all.<locals>.on_event at 0x000002459278A700>
[task 2023-05-26T17:09:47.783Z] 17:09:47     INFO - remove_listener = <function BidiSession.add_event_listener.<locals>.<lambda> at 0x000002459278A820>
[task 2023-05-26T17:09:47.783Z] 17:09:47     INFO - subscribe_events = <function subscribe_events.<locals>.subscribe_events at 0x0000024592785430>
[task 2023-05-26T17:09:47.783Z] 17:09:47     INFO - top_context = {'children': [],
INFO -  'context': '245b7e95-a2a1-4551-94f6-98b12929f48f',
[task 2023-05-26T17:09:47.783Z] 17:09:47     INFO -  'parent': None,
[task 2023-05-26T17:09:47.783Z] 17:09:47     INFO -  'url': 'about:blank'}
[task 2023-05-26T17:09:47.783Z] 17:09:47     INFO - wait_for_event = <function wait_for_event.<locals>.wait_for_event at 0x0000024592785940>
[task 2023-05-26T17:09:47.783Z] 17:09:47     INFO - 
[task 2023-05-26T17:09:47.783Z] 17:09:47     INFO - tests\web-platform\tests\webdriver\tests\bidi\session\subscribe\contexts.py:122: AssertionError
[task 2023-05-26T17:09:47.786Z] 17:09:47     INFO - ...
[task 2023-05-26T17:09:47.786Z] 17:09:47     INFO - TEST-OK | /webdriver/tests/bidi/session/subscribe/contexts.py | took 13028ms

Comment 1

[Intermittent Failures Robot]

1 failures in 3946 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• windows11-64-2009-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1835369&startday=2023-05-22&endday=2023-05-28&tree=all

Comment 2

[Henrik Skupin [:whimboo][⌚️UTC+2]]

The failure happened around those lines:
https://treeherder.mozilla.org/logviewer?job_id=417208952&repo=mozilla-central&lineNumber=62462-62504

[task 2023-05-26T17:09:45.468Z] 17:09:45     INFO - PID 6788 | console.error: "Failed to broadcast a command to browsingContext 12" (new AbortError("Actor 'MessageHandlerFrame' destroyed before query 'MessageHandlerFrameParent:sendCommand' was resolved", (void 0)))
[task 2023-05-26T17:09:45.469Z] 17:09:45     INFO - PID 6788 | 1685120985459	RemoteAgent	DEBUG	WebDriverBiDiConnection 54f3f7fd-7548-4024-bf6d-f724fd31daf3 <- {"id":19,"result":{}}
[task 2023-05-26T17:09:45.470Z] 17:09:45     INFO - PID 6788 | 1685120985460	RemoteAgent	TRACE	Created MessageHandler WINDOW_GLOBAL for session cb93eae3-3972-4387-a656-9d991a07b0e7
[task 2023-05-26T17:09:45.471Z] 17:09:45     INFO - PID 6788 | 1685120985469	RemoteAgent	TRACE	Received command log._applySessionData for destination WINDOW_GLOBAL
[task 2023-05-26T17:09:45.472Z] 17:09:45     INFO - PID 6788 | 1685120985471	RemoteAgent	TRACE	Module windowglobal/log.jsm found for WINDOW_GLOBAL
[task 2023-05-26T17:09:45.472Z] 17:09:45     INFO - PID 6788 | 1685120985472	RemoteAgent	TRACE	Module windowglobal/log.jsm found for WINDOW_GLOBAL
[task 2023-05-26T17:09:45.477Z] 17:09:45     INFO - PID 6788 | [Child 3936, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (MessageHandlerFrame, MessageHandlerFrameChild:messageHandlerEvent) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:61
[task 2023-05-26T17:09:45.479Z] 17:09:45     INFO - PID 6788 | console.error:
[task 2023-05-26T17:09:45.482Z] 17:09:45     INFO - PID 6788 |   InvalidStateError: JSWindowActorChild.sendAsyncMessage: JSWindowActorChild cannot send at the moment: _onRegistryEvent@chrome://remote/content/shared/messagehandler/transports/js-window-actors/MessageHandlerFrameChild.sys.mjs:101:10
[task 2023-05-26T17:09:45.486Z] 17:09:45     INFO - PID 6788 | emit@resource://gre/modules/EventEmitter.sys.mjs:154:20
[task 2023-05-26T17:09:45.486Z] 17:09:45     INFO - PID 6788 | _onMessageHandlerEvent@chrome://remote/content/shared/messagehandler/MessageHandlerRegistry.sys.mjs:236:10
[task 2023-05-26T17:09:45.487Z] 17:09:45     INFO - PID 6788 | emit@resource://gre/modules/EventEmitter.sys.mjs:154:20
[task 2023-05-26T17:09:45.488Z] 17:09:45     INFO - PID 6788 | emitEvent@chrome://remote/content/shared/messagehandler/MessageHandler.sys.mjs:180:10
[..]

As it looks like the underlying JSWindowActor pair died and we no longer can send messages.

Comment 3

[Julian Descottes [:jdescottes]]

And as usual, a missed navigation right before https://treeherder.mozilla.org/logviewer?job_id=417208952&repo=mozilla-central&lineNumber=62406-62412

[task 2023-05-26T17:09:43.571Z] 17:09:43 INFO - PID 6788 | 1685120983568 RemoteAgent TRACE [12] ProgressListener Start: expectNavigation=false resolveWhenStarted=false unloadTimeout=1600 waitForExplicitStart=false
[task 2023-05-26T17:09:43.572Z] 17:09:43 INFO - PID 6788 | 1685120983568 RemoteAgent TRACE [12] ProgressListener Setting unload timer (1600ms)
[task 2023-05-26T17:09:45.138Z] 17:09:45 INFO - PID 6788 | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to C:\Users\task_168511707535855\AppData\Local\Temp\tmpuk1uw7p_.mozrunner\runtests_leaks_8148_tab_pid7964.log
[task 2023-05-26T17:09:45.141Z] 17:09:45 INFO - PID 6788 | [7964, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp:345
[task 2023-05-26T17:09:45.154Z] 17:09:45 INFO - PID 6788 | [Child 7964, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/toolkit/xre/nsXREDirProvider.cpp:475
[task 2023-05-26T17:09:45.171Z] 17:09:45 INFO - PID 6788 | 1685120985171 RemoteAgent TRACE [12] ProgressListener No navigation detected: about:blank
[task 2023-05-26T17:09:45.173Z] 17:09:45 INFO - PID 6788 | 1685120985171 RemoteAgent TRACE [12] ProgressListener Stop: has error=false

Comment 4

[Henrik Skupin [:whimboo][⌚️UTC+2]]

There was only a single failure. Lets call it WFM.

Comment 5

[Henrik Skupin [:whimboo][⌚️UTC+2]]

As it looks like failures are wrongly classified. Here one more case:
https://treeherder.mozilla.org/logviewer?job_id=418844117&repo=autoland&lineNumber=20902

Comment 6

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Haven't seen this failure again when checking log details. Closing for now.