2016842 - Intermittent TV /webdriver/tests/bidi/script/realm_created/realm_created.py | test_service_worker - webdriver.error.TimeoutException: timeout (500): Timed out after 2.0 seconds with message: Did not receive at least 1 BiDi event(s) | single tracking bug

Reporter

Description

•

5 days ago

treeherder

Filed by: imoraru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=548737975&repo=autoland&task=UCzQWqSMRpCm2MKkPwNHvg.0
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/UCzQWqSMRpCm2MKkPwNHvg/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/default/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/UCzQWqSMRpCm2MKkPwNHvg/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO - TEST-PASS | /webdriver/tests/bidi/script/realm_created/realm_created.py | test_shared_worker
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/bidi/script/realm_created/realm_created.py | test_service_worker - webdriver.error.TimeoutException: timeout (500): Timed out after 2.0 seconds with message: Did not receive at least 1 BiDi event(s)
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x7f05e795a240>
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO - subscribe_events = <function subscribe_events.<locals>.subscribe_events at 0x7f05e7a0ad40>
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO - top_context = {'children': [], 'clientWindow': '03bd628d-cc27-4a05-beb9-4a5c90fa0869', 'context': 'f84bcfe2-df25-46d9-993f-157a9b242a2a', 'originalOpener': None, ...}
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO - inline = <function inline.<locals>.inline at 0x7f05e7a09260>
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO - 
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO -     async def test_service_worker(
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO -         bidi_session,
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO -         subscribe_events,
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO -         top_context,
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO -         inline,
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO -     ):
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO -         await subscribe_events(events=[REALM_CREATED_EVENT])
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO -     
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO -         events = []
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO -     
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO -         async def on_event(method, data):
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO -             if data["type"] == "service-worker":
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO -                 events.append(data)
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO -     
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO -         remove_listener = bidi_session.add_event_listener(
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO -             REALM_CREATED_EVENT, on_event)
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO -     
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO -         worker_url = inline("console.log('service worker')", doctype="js")
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO -         url = inline(
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO -             f"""<script>
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO -             navigator.serviceWorker.register('{worker_url}');
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO -             navigator.serviceWorker.startMessages();
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO -         </script>"""
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO -         )
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO -         await bidi_session.browsing_context.navigate(
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO -             url=url, context=top_context["context"], wait="complete"
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO -         )
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO -     
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO - >       await wait_for_bidi_events(bidi_session, events, 1)
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO - 
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x7f05e795a240>
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO - events     = []
[task 2026-02-13T20:42:42.272+00:00] 20:42:42     INFO - inline     = <function inline.<locals>.inline at 0x7f05e7a09260>
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO - on_event   = <function test_service_worker.<locals>.on_event at 0x7f05e7a0ae80>
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO - remove_listener = <function BidiSession.add_event_listener.<locals>.<lambda> at 0x7f05e7a0b920>
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO - subscribe_events = <function subscribe_events.<locals>.subscribe_events at 0x7f05e7a0ad40>
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO - top_context = {'children': [],
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -  'clientWindow': '03bd628d-cc27-4a05-beb9-4a5c90fa0869',
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -  'context': 'f84bcfe2-df25-46d9-993f-157a9b242a2a',
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -  'originalOpener': None,
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -  'parent': None,
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -  'url': 'https://web-platform.test:8443/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cscript%3E%0A++++++++const+worker+%3D+new+SharedWorker%28%27https%3A%2F%2Fweb-platform.test%3A8443%2Fwebdriver%2Ftests%2Fsupport%2Finline.py%3Fdoc%3Dconsole.log%2528%2527shared%2Bworker%2527%2529%26mime%3Dtext%252Fjavascript%26charset%3DUTF-8%27%29%3B%0A++++%3C%2Fscript%3E&mime=text%2Fhtml&charset=UTF-8',
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -  'userContext': 'default'}
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO - url        = 'https://web-platform.test:8443/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cscript%3E%0A++++++++navigator.serviceWorker.register%28%27https%3A%2F%2Fweb-platform.test%3A8443%2Fwebdriver%2Ftests%2Fsupport%2Finline.py%3Fdoc%3Dconsole.log%2528%2527service%2Bworker%2527%2529%26mime%3Dtext%252Fjavascript%26charset%3DUTF-8%27%29%3B%0A++++++++navigator.serviceWorker.startMessages%28%29%3B%0A++++%3C%2Fscript%3E&mime=text%2Fhtml&charset=UTF-8'
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO - worker_url = 'https://web-platform.test:8443/webdriver/tests/support/inline.py?doc=console.log%28%27service+worker%27%29&mime=text%2Fjavascript&charset=UTF-8'
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO - 
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO - tests/web-platform/tests/webdriver/tests/bidi/script/realm_created/realm_created.py:346: 
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO - tests/web-platform/tests/webdriver/tests/bidi/__init__.py:288: in wait_for_bidi_events
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -     await wait.until(check_bidi_events, events, count)
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -         bidi_session = <webdriver.bidi.client.BidiSession object at 0x7f05e795a240>
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -         check_bidi_events = <function wait_for_bidi_events.<locals>.check_bidi_events at 0x7f05e7a0b600>
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -         count      = 1
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -         equal_check = True
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -         events     = []
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -         timeout    = 2
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -         wait       = <tests.support.sync.AsyncPoll object at 0x7f05e7aa3ec0>
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO - tests/web-platform/tests/webdriver/tests/support/sync.py:293: in until
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -     return await poll()
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -         args       = ([], 1)
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -         condition  = <function wait_for_bidi_events.<locals>.check_bidi_events at 0x7f05e7a0b600>
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -         kwargs     = {}
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -         poll       = <function AsyncPoll.until.<locals>.poll at 0x7f05e7a0b4c0>
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -         self       = <tests.support.sync.AsyncPoll object at 0x7f05e7aa3ec0>
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO - tests/web-platform/tests/webdriver/tests/support/sync.py:289: in poll
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -     raise self.exc_cls(message=message).with_traceback(traceback)
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -         _          = <class 'AssertionError'>
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -         args       = ([], 1)
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -         condition  = <function wait_for_bidi_events.<locals>.check_bidi_events at 0x7f05e7a0b600>
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -         condition_msg = AssertionError('Did not receive at least 1 BiDi event(s)')
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -         elapsed    = 2.0
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -         end        = 239.578344369
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -         interval_new = 0.09998914999997055
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -         kwargs     = {}
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -         message    = ('Timed out after 2.0 seconds with message: Did not receive at least 1 BiDi '
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -  'event(s)')
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -         next       = 239.58275167899998
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -         result     = None
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -         self       = <tests.support.sync.AsyncPoll object at 0x7f05e7aa3ec0>
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -         start      = 237.578344369
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -         traceback  = <traceback object at 0x7f05e79ba400>
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO - tests/web-platform/tests/webdriver/tests/support/sync.py:264: in poll
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -     _result = condition(self.session, *args, **kwargs)
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -         _          = <class 'AssertionError'>
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -         args       = ([], 1)
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -         condition  = <function wait_for_bidi_events.<locals>.check_bidi_events at 0x7f05e7a0b600>
[task 2026-02-13T20:42:42.273+00:00] 20:42:42     INFO -         condition_msg = AssertionError('Did not receive at least 1 BiDi event(s)')
[task 2026-02-13T20:42:42.274+00:00] 20:42:42     INFO -         elapsed    = 2.0
[task 2026-02-13T20:42:42.274+00:00] 20:42:42     INFO -         end        = 239.578344369
[task 2026-02-13T20:42:42.274+00:00] 20:42:42     INFO -         interval_new = 0.09998914999997055
[task 2026-02-13T20:42:42.274+00:00] 20:42:42     INFO -         kwargs     = {}
[task 2026-02-13T20:42:42.274+00:00] 20:42:42     INFO -         message    = ('Timed out after 2.0 seconds with message: Did not receive at least 1 BiDi '
[task 2026-02-13T20:42:42.274+00:00] 20:42:42     INFO -  'event(s)')
[task 2026-02-13T20:42:42.274+00:00] 20:42:42     INFO -         next       = 239.58275167899998
[task 2026-02-13T20:42:42.274+00:00] 20:42:42     INFO -         result     = None
[task 2026-02-13T20:42:42.274+00:00] 20:42:42     INFO -         self       = <tests.support.sync.AsyncPoll object at 0x7f05e7aa3ec0>
[task 2026-02-13T20:42:42.274+00:00] 20:42:42     INFO -         start      = 237.578344369
[task 2026-02-13T20:42:42.274+00:00] 20:42:42     INFO -         traceback  = <traceback object at 0x7f05e79ba400>
[task 2026-02-13T20:42:42.274+00:00] 20:42:42     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
[task 2026-02-13T20:42:42.274+00:00] 20:42:42     INFO - 
[task 2026-02-13T20:42:42.274+00:00] 20:42:42     INFO - _ = <webdriver.bidi.client.BidiSession object at 0x7f05e795a240>, events = []
[task 2026-02-13T20:42:42.274+00:00] 20:42:42     INFO - count = 1
[task 2026-02-13T20:42:42.274+00:00] 20:42:42     INFO - 
[task 2026-02-13T20:42:42.274+00:00] 20:42:42     INFO -     def check_bidi_events(_, events, count):
[task 2026-02-13T20:42:42.274+00:00] 20:42:42     INFO - >       assert len(
[task 2026-02-13T20:42:42.274+00:00] 20:42:42     INFO -             events) >= count, f"Did not receive at least {count} BiDi event(s)"
[task 2026-02-13T20:42:42.274+00:00] 20:42:42     INFO - E       webdriver.error.TimeoutException: timeout (500): Timed out after 2.0 seconds with message: Did not receive at least 1 BiDi event(s)
[task 2026-02-13T20:42:42.274+00:00] 20:42:42     INFO - 
[task 2026-02-13T20:42:42.274+00:00] 20:42:42     INFO - _          = <webdriver.bidi.client.BidiSession object at 0x7f05e795a240>
[task 2026-02-13T20:42:42.274+00:00] 20:42:42     INFO - count      = 1
[task 2026-02-13T20:42:42.274+00:00] 20:42:42     INFO - events     = []
[task 2026-02-13T20:42:42.274+00:00] 20:42:42     INFO - 
[task 2026-02-13T20:42:42.274+00:00] 20:42:42     INFO - tests/web-platform/tests/webdriver/tests/bidi/__init__.py:284: TimeoutException
[task 2026-02-13T20:42:42.364+00:00] 20:42:42     INFO - ....
[task 2026-02-13T20:42:42.364+00:00] 20:42:42     INFO - TEST-OK | /webdriver/tests/bidi/script/realm_created/realm_created.py | took 13953ms

BugBot [:suhaib / :marco/ :calixte]

Comment 1

•

5 days ago

:jdescottes, since you are the author of the regressor, bug 1936770, could you take a look?

For more information, please visit BugBot documentation.

Flags: needinfo?(jdescottes)

Julian Descottes [:jdescottes]

Assignee

Comment 2

•

5 days ago

Attached file Bug 2016842 - [wdspec] Unregister service worker at the end of the realmCreated service worker test — Details

Phabricator Automation

Updated

•

5 days ago

Assignee: nobody → jdescottes

Status: NEW → ASSIGNED

BugBot [:suhaib / :marco/ :calixte]

Comment 3

•

5 days ago

Set release status flags based on info from the regressing bug 1936770

status-firefox147: --- → unaffected

status-firefox148: --- → unaffected

status-firefox149: --- → affected

status-firefox-esr140: --- → unaffected

Comment hidden (Intermittent Failures Robot)

Pulsebot

Comment 5

•

3 days ago

Pushed by jdescottes@mozilla.com: https://github.com/mozilla-firefox/firefox/commit/2394eedce329 https://hg.mozilla.org/integration/autoland/rev/7fd5b688c38a [wdspec] Unregister service worker at the end of the realmCreated service worker test r=Sasha

Web Platform Test Sync Bot [:wpt-sync] (Matrix: #interop:mozilla.org)

Comment 6

•

3 days ago

Created web-platform-tests PR https://github.com/web-platform-tests/wpt/pull/57811 for changes under testing/web-platform/tests

Julian Descottes [:jdescottes]

Assignee

Comment 7

•

3 days ago

Reproduced locally, service worker should be unregistered at the end of the test.

Points: --- → 1

Flags: needinfo?(jdescottes)

Whiteboard: [webdriver:m19]

Julian Descottes [:jdescottes]

Assignee

Updated

•

3 days ago

Severity: S4 → S3

Priority: P5 → P3

Iulian Moraru

Comment 8

•

3 days ago

bugherder

https://hg.mozilla.org/mozilla-central/rev/7fd5b688c38a

Status: ASSIGNED → RESOLVED

Closed: 3 days ago

status-firefox149: affected → fixed

Resolution: --- → FIXED

Target Milestone: --- → 149 Branch

Web Platform Test Sync Bot [:wpt-sync] (Matrix: #interop:mozilla.org)

Comment 9

•

2 days ago

Upstream PR merged by moz-wptsync-bot

Web Platform Test Sync Bot [:wpt-sync] (Matrix: #interop:mozilla.org)

Updated

•

2 days ago

Whiteboard: [webdriver:m19] → [webdriver:m19], [wptsync upstream]

Web Platform Test Sync Bot [:wpt-sync] (Matrix: #interop:mozilla.org)

Comment 10

•

2 days ago

Upstream PR merged

	no_variant
linux2404-x86_64/debug	2
linux2404-x86_64/opt	2
linux2404-x86_64/tsan	1
macosx1470-x86_64/debug	1
macosx1470-x86_64/opt	1
windows11-x86/debug	1
windows11-x86/opt	1
windows11-x86_64/debug	1
windows11-x86_64/opt	1

Bugzilla

Intermittent TV /webdriver/tests/bidi/script/realm_created/realm_created.py | test_service_worker - webdriver.error.TimeoutException: timeout (500): Timed out after 2.0 seconds with message: Did not receive at least 1 BiDi event(s) | single tracking bug

Categories

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

Tracking

(firefox-esr140 unaffected, firefox147 unaffected, firefox148 unaffected, firefox149 fixed)

People

(Reporter: intermittent-bug-filer, Assigned: jdescottes)

References

(Regression)

Details

(Keywords: intermittent-failure, regression, test-verify-fail, Whiteboard: [webdriver:m19], [wptsync upstream])

Crash Data

Security

(public)

User Story

Attachments

(1 file)

Description

Comment 1

Comment 2

Updated

Comment 3

Comment 4

Repository breakdown:

Table

For more details, see:

Comment 5

Comment 6

Comment 7

Updated

Comment 8

Comment 9

Updated

Comment 10

Attachment

General

Description

File Name

Content Type