1921712 - Intermittent [Tier 2] Wd | test_request_timing_info - AssertionError (assert start <= actual <= end)

Status: NEW

(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=476210780&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/KBi5kZsoSt2W_lcajpjBAg/runs/0/artifacts/public/logs/live_backing.log

---

TEST-PASS | /webdriver/tests/bidi/network/response_completed/response_completed.py | test_load_page_twice 
[task 2024-09-30T05:02:50.116Z] 05:02:50     INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/bidi/network/response_completed/response_completed.py | test_request_timing_info - AssertionError
[task 2024-09-30T05:02:50.116Z] 05:02:50     INFO - url = <function url.<locals>.url at 0x000002CD41D7EDE0>
[task 2024-09-30T05:02:50.116Z] 05:02:50     INFO - wait_for_event = <function wait_for_event.<locals>.wait_for_event at 0x000002CD41D7FCE0>
[task 2024-09-30T05:02:50.116Z] 05:02:50     INFO - wait_for_future_safe = <function wait_for_future_safe.<locals>.wait_for_future_safe at 0x000002CD41DE0D60>
[task 2024-09-30T05:02:50.117Z] 05:02:50     INFO - fetch = <function fetch.<locals>.fetch at 0x000002CD41DE0900>
[task 2024-09-30T05:02:50.117Z] 05:02:50     INFO - setup_network_test = <function setup_network_test.<locals>._setup_network_test at 0x000002CD41DE1080>
[task 2024-09-30T05:02:50.117Z] 05:02:50     INFO - current_time = <function current_time.<locals>.current_time at 0x000002CD41DE1580>
[task 2024-09-30T05:02:50.117Z] 05:02:50     INFO - 
[task 2024-09-30T05:02:50.117Z] 05:02:50     INFO -     @pytest.mark.asyncio
[task 2024-09-30T05:02:50.117Z] 05:02:50     INFO -     async def test_request_timing_info(
[task 2024-09-30T05:02:50.117Z] 05:02:50     INFO -         url, wait_for_event, wait_for_future_safe, fetch, setup_network_test,
[task 2024-09-30T05:02:50.117Z] 05:02:50     INFO -         current_time,
[task 2024-09-30T05:02:50.117Z] 05:02:50     INFO -     ):
[task 2024-09-30T05:02:50.117Z] 05:02:50     INFO -         network_events = await setup_network_test(events=[RESPONSE_COMPLETED_EVENT])
[task 2024-09-30T05:02:50.117Z] 05:02:50     INFO -         events = network_events[RESPONSE_COMPLETED_EVENT]
[task 2024-09-30T05:02:50.117Z] 05:02:50     INFO -     
[task 2024-09-30T05:02:50.117Z] 05:02:50     INFO -         # Record the time range for the request to assert the timing info.
[task 2024-09-30T05:02:50.117Z] 05:02:50     INFO -         time_start = await current_time()
[task 2024-09-30T05:02:50.117Z] 05:02:50     INFO -     
[task 2024-09-30T05:02:50.117Z] 05:02:50     INFO -         on_response_completed = wait_for_event(RESPONSE_COMPLETED_EVENT)
[task 2024-09-30T05:02:50.117Z] 05:02:50     INFO -         await fetch(url(PAGE_EMPTY_HTML), method="GET")
[task 2024-09-30T05:02:50.117Z] 05:02:50     INFO -         await wait_for_future_safe(on_response_completed)
[task 2024-09-30T05:02:50.117Z] 05:02:50     INFO -     
[task 2024-09-30T05:02:50.117Z] 05:02:50     INFO -         time_end = await current_time()
[task 2024-09-30T05:02:50.117Z] 05:02:50     INFO -         time_range = number_interval(time_start, time_end)
[task 2024-09-30T05:02:50.118Z] 05:02:50     INFO -     
[task 2024-09-30T05:02:50.118Z] 05:02:50     INFO -         assert len(events) == 1
[task 2024-09-30T05:02:50.118Z] 05:02:50     INFO -     
[task 2024-09-30T05:02:50.118Z] 05:02:50     INFO -         expected_request = {
[task 2024-09-30T05:02:50.118Z] 05:02:50     INFO -             "method": "GET",
[task 2024-09-30T05:02:50.118Z] 05:02:50     INFO -             "url": url(PAGE_EMPTY_HTML),
[task 2024-09-30T05:02:50.118Z] 05:02:50     INFO -         }
[task 2024-09-30T05:02:50.118Z] 05:02:50     INFO -         expected_response = {"url": url(PAGE_EMPTY_HTML)}
[task 2024-09-30T05:02:50.118Z] 05:02:50     INFO - >       assert_response_event(
[task 2024-09-30T05:02:50.118Z] 05:02:50     INFO -             events[0],
[task 2024-09-30T05:02:50.118Z] 05:02:50     INFO -             expected_request=expected_request,
[task 2024-09-30T05:02:50.118Z] 05:02:50     INFO -             expected_response=expected_response,
[task 2024-09-30T05:02:50.118Z] 05:02:50     INFO -             expected_time_range=time_range,
[task 2024-09-30T05:02:50.118Z] 05:02:50     INFO -             redirect_count=0,
[task 2024-09-30T05:02:50.118Z] 05:02:50     INFO -         )
[task 2024-09-30T05:02:50.118Z] 05:02:50     INFO - 
[task 2024-09-30T05:02:50.118Z] 05:02:50     INFO - current_time = <function current_time.<locals>.current_time at 0x000002CD41DE1580>
[task 2024-09-30T05:02:50.118Z] 05:02:50     INFO - events     = [{'context': 'dafb58f5-2180-4571-a32e-d0f2afa37684',
[task 2024-09-30T05:02:50.118Z] 05:02:50     INFO -   'isBlocked': False,
[task 2024-09-30T05:02:50.118Z] 05:02:50     INFO -   'navigation': None,
[task 2024-09-30T05:02:50.118Z] 05:02:50     INFO -   'redirectCount': 0,
[task 2024-09-30T05:02:50.118Z] 05:02:50     INFO -   'request': {'bodySize': 0,
[task 2024-09-30T05:02:50.119Z] 05:02:50     INFO -               'cookies': [],
[task 2024-09-30T05:02:50.119Z] 05:02:50     INFO -               'headers': [{'name': 'Host',
[task 2024-09-30T05:02:50.119Z] 05:02:50     INFO -                            'value': {'type': 'string',
[task 2024-09-30T05:02:50.119Z] 05:02:50     INFO -                                      'value': 'web-platform.test:8443'}},
[task 2024-09-30T05:02:50.119Z] 05:02:50     INFO -                           {'name': 'User-Agent',
[task 2024-09-30T05:02:50.119Z] 05:02:50     INFO -                            'value': {'type': 'string',
[task 2024-09-30T05:02:50.119Z] 05:02:50     INFO -                                      'value': 'Mozilla/5.0 (Windows NT 10.0; '
[task 2024-09-30T05:02:50.119Z] 05:02:50     INFO -                                               'Win64; x64; rv:132.0) '
[task 2024-09-30T05:02:50.119Z] 05:02:50     INFO -                                               'Gecko/20100101 Firefox/132.0'}},
[task 2024-09-30T05:02:50.119Z] 05:02:50     INFO -                           {'name': 'Accept',
[task 2024-09-30T05:02:50.119Z] 05:02:50     INFO -                            'value': {'type': 'string', 'value': '*/*'}},
[task 2024-09-30T05:02:50.119Z] 05:02:50     INFO -                           {'name': 'Accept-Language',
[task 2024-09-30T05:02:50.119Z] 05:02:50     INFO -                            'value': {'type': 'string',
[task 2024-09-30T05:02:50.119Z] 05:02:50     INFO -                                      'value': 'en-US,en;q=0.5'}},
[task 2024-09-30T05:02:50.119Z] 05:02:50     INFO -                           {'name': 'Accept-Encoding',
[task 2024-09-30T05:02:50.119Z] 05:02:50     INFO -                            'value': {'type': 'string',
[task 2024-09-30T05:02:50.119Z] 05:02:50     INFO -                                      'value': 'gzip, deflate, br, zstd'}},
[task 2024-09-30T05:02:50.120Z] 05:02:50     INFO -                           {'name': 'Referer',
[task 2024-09-30T05:02:50.120Z] 05:02:50     INFO -                            'value': {'type': 'string',
[task 2024-09-30T05:02:50.120Z] 05:02:50     INFO -                                      'value': 'https://web-platform.test:8443/webdriver/tests/bidi/network/support/empty.html'}},
[task 2024-09-30T05:02:50.120Z] 05:02:50     INFO -                           {'name': 'Connection',
[task 2024-09-30T05:02:50.120Z] 05:02:50     INFO -                            'value': {'type': 'string', 'value': 'keep-alive'}},
[task 2024-09-30T05:02:50.120Z] 05:02:50     INFO -                           {'name': 'Sec-Fetch-Dest',
[task 2024-09-30T05:02:50.120Z] 05:02:50     INFO -                            'value': {'type': 'string', 'value': 'empty'}},
[task 2024-09-30T05:02:50.120Z] 05:02:50     INFO -                           {'name': 'Sec-Fetch-Mode',
[task 2024-09-30T05:02:50.120Z] 05:02:50     INFO -                            'value': {'type': 'string', 'value': 'cors'}},
[task 2024-09-30T05:02:50.120Z] 05:02:50     INFO -                           {'name': 'Sec-Fetch-Site',
[task 2024-09-30T05:02:50.120Z] 05:02:50     INFO -                            'value': {'type': 'string', 'value': 'same-origin'}},
[task 2024-09-30T05:02:50.120Z] 05:02:50     INFO -                           {'name': 'Priority',
[task 2024-09-30T05:02:50.120Z] 05:02:50     INFO -                            'value': {'type': 'string', 'value': 'u=4'}}],
[task 2024-09-30T05:02:50.120Z] 05:02:50     INFO -               'headersSize': 479,
[task 2024-09-30T05:02:50.120Z] 05:02:50     INFO -               'method': 'GET',
[task 2024-09-30T05:02:50.120Z] 05:02:50     INFO -               'request': '12',
[task 2024-09-30T05:02:50.120Z] 05:02:50     INFO -               'timings': {'connectEnd': 1727672562017.43,
[task 2024-09-30T05:02:50.120Z] 05:02:50     INFO -                           'connectStart': 1727672562013.541,
[task 2024-09-30T05:02:50.120Z] 05:02:50     INFO -                           'dnsEnd': 1727672562012.858,
[task 2024-09-30T05:02:50.121Z] 05:02:50     INFO -                           'dnsStart': 1727672562011.568,
[task 2024-09-30T05:02:50.121Z] 05:02:50     INFO -                           'fetchStart': 1727672562011.568,
[task 2024-09-30T05:02:50.121Z] 05:02:50     INFO -                           'redirectEnd': 0,
[task 2024-09-30T05:02:50.121Z] 05:02:50     INFO -                           'redirectStart': 0,
[task 2024-09-30T05:02:50.121Z] 05:02:50     INFO -                           'requestStart': 1727672562017.51,
[task 2024-09-30T05:02:50.121Z] 05:02:50     INFO -                           'requestTime': 1727672562011,
[task 2024-09-30T05:02:50.121Z] 05:02:50     INFO -                           'responseEnd': 1727672562019.181,
 INFO -                           'responseStart': 1727672562017.548,
[task 2024-09-30T05:02:50.121Z] 05:02:50     INFO -                           'timeOrigin': 0,
[task 2024-09-30T05:02:50.121Z] 05:02:50     INFO -                           'tlsEnd': 1727672562017.43,
[task 2024-09-30T05:02:50.121Z] 05:02:50     INFO -                           'tlsStart': 1727672562013.912},
[task 2024-09-30T05:02:50.121Z] 05:02:50     INFO -               'url': 'https://web-platform.test:8443/webdriver/tests/bidi/network/support/empty.html'},
[task 2024-09-30T05:02:50.121Z] 05:02:50     INFO -   'response': {'bodySize': 30,
[task 2024-09-30T05:02:50.121Z] 05:02:50     INFO -                'bytesReceived': 147,
[task 2024-09-30T05:02:50.121Z] 05:02:50     INFO -                'content': {'size': 0},
[task 2024-09-30T05:02:50.121Z] 05:02:50     INFO -                'fromCache': False,
[task 2024-09-30T05:02:50.122Z] 05:02:50     INFO -                'headers': [{'name': 'Content-Type',
[task 2024-09-30T05:02:50.122Z] 05:02:50     INFO -                             'value': {'type': 'string', 'value': 'text/html'}},
[task 2024-09-30T05:02:50.122Z] 05:02:50     INFO -                            {'name': 'Server',
[task 2024-09-30T05:02:50.122Z] 05:02:50     INFO -                             'value': {'type': 'string',
[task 2024-09-30T05:02:50.122Z] 05:02:50     INFO -                                       'value': 'BaseHTTP/0.6 Python/3.11.7'}},
[task 2024-09-30T05:02:50.122Z] 05:02:50     INFO -                            {'name': 'Date',
[task 2024-09-30T05:02:50.122Z] 05:02:50     INFO -                             'value': {'type': 'string',
[task 2024-09-30T05:02:50.122Z] 05:02:50     INFO -                                       'value': 'Mon, 30 Sep 2024 05:02:42 '
[task 2024-09-30T05:02:50.122Z] 05:02:50     INFO -                                                'GMT'}}],
[task 2024-09-30T05:02:50.122Z] 05:02:50     INFO -                'headersSize': 117,
[task 2024-09-30T05:02:50.122Z] 05:02:50     INFO -                'mimeType': 'text/html',
[task 2024-09-30T05:02:50.122Z] 05:02:50     INFO -                'protocol': 'http/1.1',
[task 2024-09-30T05:02:50.122Z] 05:02:50     INFO -                'status': 200,
[task 2024-09-30T05:02:50.122Z] 05:02:50     INFO -                'statusText': 'OK',
[task 2024-09-30T05:02:50.122Z] 05:02:50     INFO -                'url': 'https://web-platform.test:8443/webdriver/tests/bidi/network/support/empty.html'},
[task 2024-09-30T05:02:50.122Z] 05:02:50     INFO -   'timestamp': 1727672562043}]
[task 2024-09-30T05:02:50.122Z] 05:02:50     INFO - expected_request = {'method': 'GET',
[task 2024-09-30T05:02:50.123Z] 05:02:50     INFO -  'url': 'https://web-platform.test:8443/webdriver/tests/bidi/network/support/empty.html'}
[task 2024-09-30T05:02:50.123Z] 05:02:50     INFO - expected_response = {'url': 'https://web-platform.test:8443/webdriver/tests/bidi/network/support/empty.html'}
[task 2024-09-30T05:02:50.123Z] 05:02:50     INFO - fetch      = <function fetch.<locals>.fetch at 0x000002CD41DE0900>
[task 2024-09-30T05:02:50.123Z] 05:02:50     INFO - network_events = {'network.responseCompleted': [{'context': 'dafb58f5-2180-4571-a32e-d0f2afa37684',
[task 2024-09-30T05:02:50.123Z] 05:02:50     INFO -                                 'isBlocked': False,
[task 2024-09-30T05:02:50.123Z] 05:02:50     INFO -                                 'navigation': None,
[task 2024-09-30T05:02:50.123Z] 05:02:50     INFO -                                 'redirectCount': 0,
[task 2024-09-30T05:02:50.123Z] 05:02:50     INFO -                                 'request': {'bodySize': 0,
[task 2024-09-30T05:02:50.123Z] 05:02:50     INFO -                                             'cookies': [],
[task 2024-09-30T05:02:50.123Z] 05:02:50     INFO -                                             'headers': [{'name': 'Host',
[task 2024-09-30T05:02:50.123Z] 05:02:50     INFO -                                                          'value': {'type': 'string',
[task 2024-09-30T05:02:50.123Z] 05:02:50     INFO -                                                                    'value': 'web-platform.test:8443'}},
[task 2024-09-30T05:02:50.123Z] 05:02:50     INFO -                                                         {'name': 'User-Agent',
[task 2024-09-30T05:02:50.123Z] 05:02:50     INFO -                                                          'value': {'type': 'string',
[task 2024-09-30T05:02:50.123Z] 05:02:50     INFO -                                                                    'value': 'Mozilla/5.0 '
[task 2024-09-30T05:02:50.123Z] 05:02:50     INFO -                                                                             '(Windows '
[task 2024-09-30T05:02:50.124Z] 05:02:50     INFO -                                                                             'NT '
[task 2024-09-30T05:02:50.124Z] 05:02:50     INFO -                                                                             '10.0; '
[task 2024-09-30T05:02:50.124Z] 05:02:50     INFO -                                                                             'Win64; '
[task 2024-09-30T05:02:50.124Z] 05:02:50     INFO -                                                                             'x64; '
[task 2024-09-30T05:02:50.124Z] 05:02:50     INFO -                                                                             'rv:132.0) '
[task 2024-09-30T05:02:50.124Z] 05:02:50     INFO -                                                                             'Gecko/20100101 '
[task 2024-09-30T05:02:50.124Z] 05:02:50     INFO -                                                                             'Firefox/132.0'}},
[task 2024-09-30T05:02:50.124Z] 05:02:50     INFO -                                                         {'name': 'Accept',
[task 2024-09-30T05:02:50.124Z] 05:02:50     INFO -                                                          'value': {'type': 'string',
[task 2024-09-30T05:02:50.124Z] 05:02:50     INFO -                                                                    'value': '*/*'}},
[task 2024-09-30T05:02:50.124Z] 05:02:50     INFO -                                                         {'name': 'Accept-Language',
[task 2024-09-30T05:02:50.124Z] 05:02:50     INFO -                                                          'value': {'type': 'string',
[task 2024-09-30T05:02:50.124Z] 05:02:50     INFO -                                                                    'value': 'en-US,en;q=0.5'}},
[task 2024-09-30T05:02:50.124Z] 05:02:50     INFO -                                                         {'name': 'Accept-Encoding',
[task 2024-09-30T05:02:50.124Z] 05:02:50     INFO -                                                          'value': {'type': 'string',
[task 2024-09-30T05:02:50.124Z] 05:02:50     INFO -                                                                    'value': 'gzip, '
[task 2024-09-30T05:02:50.125Z] 05:02:50     INFO -                                                                             'deflate, '
[task 2024-09-30T05:02:50.125Z] 05:02:50     INFO -                                                                             'br, '
[task 2024-09-30T05:02:50.125Z] 05:02:50     INFO -                                                                             'zstd'}},
[task 2024-09-30T05:02:50.125Z] 05:02:50     INFO -                                                         {'name': 'Referer',
[task 2024-09-30T05:02:50.125Z] 05:02:50     INFO -                                                          'value': {'type': 'string',
[task 2024-09-30T05:02:50.125Z] 05:02:50     INFO -                                                                    'value': 'https://web-platform.test:8443/webdriver/tests/bidi/network/support/empty.html'}},
[task 2024-09-30T05:02:50.125Z] 05:02:50     INFO -                                                         {'name': 'Connection',
[task 2024-09-30T05:02:50.125Z] 05:02:50     INFO -                                                          'value': {'type': 'string',
[task 2024-09-30T05:02:50.126Z] 05:02:50     INFO -                                                                    'value': 'keep-alive'}},
[task 2024-09-30T05:02:50.126Z] 05:02:50     INFO -                                                         {'name': 'Sec-Fetch-Dest',
[task 2024-09-30T05:02:50.126Z] 05:02:50     INFO -                                                          'value': {'type': 'string',
[task 2024-09-30T05:02:50.126Z] 05:02:50     INFO -                                                                    'value': 'empty'}},
[task 2024-09-30T05:02:50.126Z] 05:02:50     INFO -                                                         {'name': 'Sec-Fetch-Mode',
[task 2024-09-30T05:02:50.126Z] 05:02:50     INFO -                                                          'value': {'type': 'string',
[task 2024-09-30T05:02:50.126Z] 05:02:50     INFO -                                                                    'value': 'cors'}},
[task 2024-09-30T05:02:50.126Z] 05:02:50     INFO -                                                         {'name': 'Sec-Fetch-Site',
[task 2024-09-30T05:02:50.126Z] 05:02:50     INFO -                                                          'value': {'type': 'string',
[task 2024-09-30T05:02:50.126Z] 05:02:50     INFO -                                                                    'value': 'same-origin'}},
[task 2024-09-30T05:02:50.126Z] 05:02:50     INFO -                                                         {'name': 'Priority',
[task 2024-09-30T05:02:50.126Z] 05:02:50     INFO -                                                          'value': {'type': 'string',
[task 2024-09-30T05:02:50.126Z] 05:02:50     INFO -                                                                    'value': 'u=4'}}],
[task 2024-09-30T05:02:50.126Z] 05:02:50     INFO -                                             'headersSize': 479,
[task 2024-09-30T05:02:50.126Z] 05:02:50     INFO -                                             'method': 'GET',
<...>

Comment 1

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

This is a timing issue again:

[task 2024-09-30T05:02:50.146Z] 05:02:50     INFO -         any_number(actual)
[task 2024-09-30T05:02:50.146Z] 05:02:50     INFO - >       assert start <= actual <= end
[task 2024-09-30T05:02:50.146Z] 05:02:50     INFO - E       AssertionError
[task 2024-09-30T05:02:50.146Z] 05:02:50     INFO - 
[task 2024-09-30T05:02:50.146Z] 05:02:50     INFO - actual     = 1727672562011
[task 2024-09-30T05:02:50.146Z] 05:02:50     INFO - end        = 1727672562049
[task 2024-09-30T05:02:50.146Z] 05:02:50     INFO - start      = 1727672562012

Julian, it looks like the other follow-up commit that was downstreamed end of last week doesn't solve this issue. But it failed only once on Windows 11 headless so far, so it's not that important right now.

Comment 3

[Julian Descottes [:jdescottes]]

The fact that it's windows only is also interesting, windows timings are often a bit odd compared to other platforms.

Comment 4

[Intermittent Failures Robot]

2 failures in 3574 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 1
• autoland: 1

Platform and build breakdown:

• windows11-64-2009-devedition-qr: 1
  • opt: 1
• windows11-32-2009-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1921712&startday=2024-09-30&endday=2024-10-06&tree=all

Comment 5

[Julian Descottes [:jdescottes]]

Should be fixed by Bug 1922390

Comment 6

[Intermittent Failures Robot]

5 failures in 4679 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 5

Platform and build breakdown:

• windows11-32-2009-qr: 3
  • opt: 3
• windows11-64-2009-qr: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1921712&startday=2024-10-07&endday=2024-10-13&tree=all

Comment 8

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

(In reply to Julian Descottes [:jdescottes] from comment #5)

Should be fixed by Bug 1922390

There was no further failure afterward but now we have bug 1924120. Maybe we should close this bug and handle the other one separately? Or is it still the same?

Comment 10

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

I think that we have to keep this bug open. The underlying issue isn't fixed yet.

Comment 11

[Intermittent Failures Robot]

11 failures in 4579 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-beta: 6
• mozilla-central: 1
• autoland: 1
• try: 3

Platform and build breakdown:

• windows11-64-2009-devedition-qr: 3
  • opt: 3
• windows11-32-2009-shippable-qr: 6
  • opt: 6
• windows11-64-2009-shippable-qr: 1
  • opt: 1
• windows11-64-2009-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1921712&startday=2024-10-14&endday=2024-10-20&tree=all