Closed Bug 1862600 Opened 1 year ago Closed 2 days ago

Intermittent ASAN /webdriver/tests/bidi/network/add_intercept/url_patterns.py | single tracking bug

Categories

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

defect

Tracking

(firefox-esr128 unaffected, firefox135 unaffected, firefox136 unaffected, firefox137 fixed)

RESOLVED FIXED
137 Branch
Tracking Status
firefox-esr128 --- unaffected
firefox135 --- unaffected
firefox136 --- unaffected
firefox137 --- fixed

People

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

References

(Regression)

Details

(4 keywords)

Attachments

(1 file, 2 obsolete files)

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


[task 2023-11-02T07:18:14.661Z] 07:18:14     INFO - TEST-PASS | /webdriver/tests/bidi/network/add_intercept/url_patterns.py | test_string_patterns_not_matching[https://{wpt_host}/?a=b&c=d-https://{wpt_host}/?c=d&a=b] 
[task 2023-11-02T07:18:14.661Z] 07:18:14     INFO - TEST-UNEXPECTED-ERROR | /webdriver/tests/bidi/network/add_intercept/url_patterns.py | test_string_patterns_not_matching[https://{wpt_host}/??-https://{wpt_host}/?] - teardown error: OSError: [WinError 10048] Only one usage of each socket address (protocol/network address/port) is normally permitted
[task 2023-11-02T07:18:14.661Z] 07:18:14     INFO - def finalizer() -> None:
[task 2023-11-02T07:18:14.661Z] 07:18:14     INFO -         """Yield again, to finalize."""
[task 2023-11-02T07:18:14.661Z] 07:18:14     INFO -     
[task 2023-11-02T07:18:14.661Z] 07:18:14     INFO -         async def async_finalizer() -> None:
[task 2023-11-02T07:18:14.661Z] 07:18:14     INFO -             try:
[task 2023-11-02T07:18:14.661Z] 07:18:14     INFO -                 await gen_obj.__anext__()
[task 2023-11-02T07:18:14.661Z] 07:18:14     INFO -             except StopAsyncIteration:
[task 2023-11-02T07:18:14.661Z] 07:18:14     INFO -                 pass
[task 2023-11-02T07:18:14.661Z] 07:18:14     INFO -             else:
[task 2023-11-02T07:18:14.661Z] 07:18:14     INFO -                 msg = "Async generator fixture didn't stop."
[task 2023-11-02T07:18:14.661Z] 07:18:14     INFO -                 msg += "Yield only once."
[task 2023-11-02T07:18:14.661Z] 07:18:14     INFO -                 raise ValueError(msg)
[task 2023-11-02T07:18:14.661Z] 07:18:14     INFO -     
[task 2023-11-02T07:18:14.661Z] 07:18:14     INFO - >       event_loop.run_until_complete(async_finalizer())
[task 2023-11-02T07:18:14.661Z] 07:18:14     INFO - 
[task 2023-11-02T07:18:14.661Z] 07:18:14     INFO - async_finalizer = <function _wrap_asyncgen.<locals>._asyncgen_fixture_wrapper.<locals>.finalizer.<locals>.async_finalizer at 0x000001D71B4B1C10>
[task 2023-11-02T07:18:14.661Z] 07:18:14     INFO - event_loop = <ProactorEventLoop running=False closed=True debug=False>
[task 2023-11-02T07:18:14.661Z] 07:18:14     INFO - gen_obj    = <async_generator object bidi_session at 0x000001D71B4B1820>
[task 2023-11-02T07:18:14.661Z] 07:18:14     INFO - 

This is an error during teardown:

OSError: [WinError 10048] Only one usage of each socket address (protocol/network address/port) is normally permitted

Maybe available ports are exhausted? Might be a badly behaving machine. Lets observe.

The failures here come from the following assertion:

https://treeherder.mozilla.org/logviewer?job_id=446641494&repo=mozilla-beta&lineNumber=129134-129196

[task 2024-02-09T11:04:32.963Z] 11:04:32     INFO -         if is_blocked is not None:
[task 2024-02-09T11:04:32.963Z] 11:04:32     INFO - >           assert event["isBlocked"] == is_blocked
[task 2024-02-09T11:04:32.963Z] 11:04:32     INFO - E           AssertionError
[task 2024-02-09T11:04:32.963Z] 11:04:32     INFO - 
[task 2024-02-09T11:04:32.963Z] 11:04:32     INFO - context    = None
[task 2024-02-09T11:04:32.963Z] 11:04:32     INFO - event      = {'context': '3246b459-9ed3-4b45-ace2-368aaacec804',
[task 2024-02-09T11:04:32.963Z] 11:04:32     INFO -  'initiator': {'type': 'other'},
[task 2024-02-09T11:04:32.964Z] 11:04:32     INFO -  'intercepts': ['1fcb741f-44f2-4a22-9f5d-db2ab0800ff2'],
[task 2024-02-09T11:04:32.964Z] 11:04:32     INFO -  'isBlocked': True,
[task 2024-02-09T11:04:32.964Z] 11:04:32     INFO -  'navigation': None,
[task 2024-02-09T11:04:32.964Z] 11:04:32     INFO -  'redirectCount': 0,
[task 2024-02-09T11:04:32.964Z] 11:04:32     INFO -  'request': {'bodySize': None,
[task 2024-02-09T11:04:32.964Z] 11:04:32     INFO -              'cookies': [],
[task 2024-02-09T11:04:32.964Z] 11:04:32     INFO -              'headers': [{'name': 'Host',
[task 2024-02-09T11:04:32.964Z] 11:04:32     INFO -                           'value': {'type': 'string',
[task 2024-02-09T11:04:32.964Z] 11:04:32     INFO -                                     'value': 'web-platform.test'}},
[task 2024-02-09T11:04:32.964Z] 11:04:32     INFO -                          {'name': 'User-Agent',
[task 2024-02-09T11:04:32.964Z] 11:04:32     INFO -                           'value': {'type': 'string',
[task 2024-02-09T11:04:32.964Z] 11:04:32     INFO -                                     'value': 'Mozilla/5.0 (Windows NT 10.0; '
[task 2024-02-09T11:04:32.964Z] 11:04:32     INFO -                                              'Win64; x64; rv:123.0) '
[task 2024-02-09T11:04:32.964Z] 11:04:32     INFO -                                              'Gecko/20100101 Firefox/123.0'}},
[task 2024-02-09T11:04:32.964Z] 11:04:32     INFO -                          {'name': 'Accept',
[task 2024-02-09T11:04:32.964Z] 11:04:32     INFO -                           'value': {'type': 'string', 'value': '*/*'}},
[task 2024-02-09T11:04:32.964Z] 11:04:32     INFO -                          {'name': 'Accept-Language',
[task 2024-02-09T11:04:32.965Z] 11:04:32     INFO -                           'value': {'type': 'string',
[task 2024-02-09T11:04:32.965Z] 11:04:32     INFO -                                     'value': 'en-US,en;q=0.5'}},
[task 2024-02-09T11:04:32.965Z] 11:04:32     INFO -                          {'name': 'Accept-Encoding',
[task 2024-02-09T11:04:32.965Z] 11:04:32     INFO -                           'value': {'type': 'string',
[task 2024-02-09T11:04:32.965Z] 11:04:32     INFO -                                     'value': 'gzip, deflate, br'}},
[task 2024-02-09T11:04:32.965Z] 11:04:32     INFO -                          {'name': 'Origin',
[task 2024-02-09T11:04:32.965Z] 11:04:32     INFO -                           'value': {'type': 'string', 'value': 'null'}},
[task 2024-02-09T11:04:32.965Z] 11:04:32     INFO -                          {'name': 'Connection',
[task 2024-02-09T11:04:32.965Z] 11:04:32     INFO -                           'value': {'type': 'string', 'value': 'keep-alive'}},
[task 2024-02-09T11:04:32.965Z] 11:04:32     INFO -                          {'name': 'Sec-Fetch-Dest',
[task 2024-02-09T11:04:32.966Z] 11:04:32     INFO -                           'value': {'type': 'string', 'value': 'empty'}},
[task 2024-02-09T11:04:32.966Z] 11:04:32     INFO -                          {'name': 'Sec-Fetch-Mode',
[task 2024-02-09T11:04:32.966Z] 11:04:32     INFO -                           'value': {'type': 'string', 'value': 'cors'}},
[task 2024-02-09T11:04:32.966Z] 11:04:32     INFO -                          {'name': 'Sec-Fetch-Site',
[task 2024-02-09T11:04:32.966Z] 11:04:32     INFO -                           'value': {'type': 'string', 'value': 'cross-site'}}],
[task 2024-02-09T11:04:32.966Z] 11:04:32     INFO -              'headersSize': 0,
[task 2024-02-09T11:04:32.966Z] 11:04:32     INFO -              'method': 'GET',
[task 2024-02-09T11:04:32.966Z] 11:04:32     INFO -              'request': '34',
[task 2024-02-09T11:04:32.966Z] 11:04:32     INFO -              'timings': {'connectEnd': 0,
[task 2024-02-09T11:04:32.966Z] 11:04:32     INFO -                          'connectStart': 1707476669865526,
[task 2024-02-09T11:04:32.966Z] 11:04:32     INFO -                          'dnsEnd': 1707476667828944,
[task 2024-02-09T11:04:32.967Z] 11:04:32     INFO -                          'dnsStart': 1707476667828814,
[task 2024-02-09T11:04:32.967Z] 11:04:32     INFO -                          'fetchStart': 1707476667828814,
[task 2024-02-09T11:04:32.967Z] 11:04:32     INFO -                          'redirectEnd': 0,
[task 2024-02-09T11:04:32.967Z] 11:04:32     INFO -                          'redirectStart': 0,
[task 2024-02-09T11:04:32.967Z] 11:04:32     INFO -                          'requestStart': 0,
[task 2024-02-09T11:04:32.967Z] 11:04:32     INFO -                          'requestTime': 1707476667827000,
[task 2024-02-09T11:04:32.967Z] 11:04:32     INFO -                          'responseEnd': 0,
[task 2024-02-09T11:04:32.967Z] 11:04:32     INFO -                          'responseStart': 0,
[task 2024-02-09T11:04:32.968Z] 11:04:32     INFO -                          'timeOrigin': 0,
[task 2024-02-09T11:04:32.968Z] 11:04:32     INFO -                          'tlsEnd': 0,
[task 2024-02-09T11:04:32.968Z] 11:04:32     INFO -                          'tlsStart': 0},
[task 2024-02-09T11:04:32.968Z] 11:04:32     INFO -              'url': 'https://web-platform.test/'},
[task 2024-02-09T11:04:32.968Z] 11:04:32     INFO -  'timestamp': 1707476670118}
[task 2024-02-09T11:04:32.968Z] 11:04:32     INFO - expected_request = None
[task 2024-02-09T11:04:32.968Z] 11:04:32     INFO - intercepts = None
[task 2024-02-09T11:04:32.968Z] 11:04:32     INFO - is_blocked = False
[task 2024-02-09T11:04:32.968Z] 11:04:32     INFO - navigation = None
[task 2024-02-09T11:04:32.968Z] 11:04:32     INFO - redirect_count = None

Julian, could you please have a quick look?

Flags: needinfo?(jdescottes)

It seems that we are randomly getting a beforeRequestSent event for a request which was already emitted for a previous test. Most likely this is because we receive the response for that request and re-create a beforeRequestSent event for it.

The network observer gets stopped and started dynamically as the tests are running, and if a new instance of the network observer catches a response for which it did not catch the request, it will emit a beforeRequestSent event for consistency.

To fix this, we could either isolate the browsing contexts used for the tests by using the new_tab fixture (so that we only capture network events for that specific context) or try to ignore those "fake" beforeRequestSent notifications.

Flags: needinfo?(jdescottes)
Depends on: 1880859
Attachment #9386405 - Attachment is obsolete: true
Status: NEW → RESOLVED
Closed: 10 months ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 10 months ago6 months ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 6 months ago3 months ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Duplicate of this bug: 1946218

There's been a recent spike in failures as you can see here , all failing on linux1804-64-asan-qr
Failure log: https://treeherder.mozilla.org/logviewer?job_id=493449971&repo=autoland&lineNumber=104330

Could you please take a look? Thanks.

Flags: needinfo?(aborovova)
Keywords: regression
Regressed by: 1945706

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

We used to OK, TIMEOUT on asan but the bot removed it with https://hg.mozilla.org/integration/autoland/rev/8cfaeb03aace407860088b65a2fb66ad39a81b13#l5.7

We can either fix it early here or wait for Bug 1938604 to land.

Assignee: nobody → aborovova
Flags: needinfo?(aborovova)
Attachment #9464714 - Attachment is obsolete: true
Attachment #9464714 - Attachment is obsolete: false
Pushed by aborovova@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/36d5e330a6ad Return back test metadata for webdriver/tests/bidi/network/add_intercept/url_patterns.py removed by the bot. r=webdriver-reviewers,jdescottes

Sasha, as Joel mentioned to me recently we should keep separate entries for different variations, so the entries as done by the bot were fine. Also the OK, TIMEOUT multiple status we probably should not set as a default. Maybe we should backout this recently landed patch?

Flags: needinfo?(aborovova)

(In reply to Henrik Skupin [:whimboo][⌚️UTC+2] from comment #48)

Sasha, as Joel mentioned to me recently we should keep separate entries for different variations, so the entries as done by the bot were fine. Also the OK, TIMEOUT multiple status we probably should not set as a default. Maybe we should backout this recently landed patch?

Ok, I've requested the backout

Flags: needinfo?(aborovova)
Attachment #9464714 - Attachment is obsolete: true
Assignee: aborovova → nobody
Status: REOPENED → NEW
Keywords: test-disabled
Summary: Intermittent /webdriver/tests/bidi/network/add_intercept/url_patterns.py | single tracking bug → Intermittent ASAN /webdriver/tests/bidi/network/add_intercept/url_patterns.py | single tracking bug

push enabling the tests on ASAN with rebuild 10: https://treeherder.mozilla.org/jobs?repo=try&revision=83e4d7cf7b0479d5ab3c1a55a425c4a085e4dc70

Compared to comment 18, it seems we already moved the test to use the new_tab fixture so this is most likely a different issue.
The recent failures are however a bit tricky to investigate because they hit a temporary regression in the EventsDispatcher which was recently fixed by Sasha. It's also possible that the recent spike was due to this regression?

Let's see if we can get a failure on try.

No failure on try, reenable to monitor.

Assignee: nobody → jdescottes
Status: NEW → ASSIGNED
Pushed by jdescottes@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/7badd961c012 [wdspec] Enable url patterns test on ASAN r=webdriver-reviewers,whimboo
Status: ASSIGNED → RESOLVED
Closed: 3 months ago2 days ago
Resolution: --- → FIXED
Target Milestone: --- → 137 Branch
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: