Intermittent mozilla/tests/webdriver/bidi/network/cached_image_events/cached_image_events.py | test_page_with_cached_image - AssertionError: assert 6 == 5 | failing under a combination of manifests
Categories
(Remote Protocol :: WebDriver BiDi, defect, P5)
Tracking
(firefox-esr128 unaffected, firefox131 unaffected, firefox132 unaffected, firefox133 fixed)
Tracking | Status | |
---|---|---|
firefox-esr128 | --- | unaffected |
firefox131 | --- | unaffected |
firefox132 | --- | unaffected |
firefox133 | --- | fixed |
People
(Reporter: intermittent-bug-filer, Assigned: jdescottes)
References
(Regression)
Details
(Keywords: intermittent-failure, regression, Whiteboard: [webdriver:m13])
Attachments
(1 file)
Filed by: csabou [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=479450995&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/cAso0s52RVKS9e1z74V8-g/runs/0/artifacts/public/logs/live_backing.log
[task 2024-10-23T01:36:26.983Z] 01:36:26 INFO - STDOUT: =================================== FAILURES ===================================
[task 2024-10-23T01:36:26.986Z] 01:36:26 INFO - STDOUT: _________________________ test_page_with_cached_image __________________________
[task 2024-10-23T01:36:26.987Z] 01:36:26 INFO - STDOUT: bidi_session = <webdriver.bidi.client.BidiSession object at 0x7fd40596f6a0>
[task 2024-10-23T01:36:26.987Z] 01:36:26 INFO - STDOUT: url = <function url.<locals>.url at 0x7fd4059715e0>
[task 2024-10-23T01:36:26.989Z] 01:36:26 INFO - STDOUT: inline = <function inline.<locals>.inline at 0x7fd405971790>
[task 2024-10-23T01:36:26.989Z] 01:36:26 INFO - STDOUT: setup_network_test = <function setup_network_test.<locals>._setup_network_test at 0x7fd405971d30>
[task 2024-10-23T01:36:26.990Z] 01:36:26 INFO - STDOUT: top_context = {'children': [], 'context': '7f8ef67e-fcba-4283-9e9a-b007d9b77662', 'originalOpener': None, 'parent': None, ...}
[task 2024-10-23T01:36:26.993Z] 01:36:26 INFO - STDOUT: @pytest.mark.asyncio
[task 2024-10-23T01:36:26.993Z] 01:36:26 INFO - STDOUT: async def test_page_with_cached_image(
[task 2024-10-23T01:36:26.993Z] 01:36:26 INFO - STDOUT: bidi_session,
[task 2024-10-23T01:36:26.993Z] 01:36:26 INFO - STDOUT: url,
[task 2024-10-23T01:36:26.993Z] 01:36:26 INFO - STDOUT: inline,
[task 2024-10-23T01:36:26.993Z] 01:36:26 INFO - STDOUT: setup_network_test,
[task 2024-10-23T01:36:26.993Z] 01:36:26 INFO - STDOUT: top_context,
[task 2024-10-23T01:36:26.994Z] 01:36:26 INFO - STDOUT: ):
[task 2024-10-23T01:36:26.995Z] 01:36:26 INFO - STDOUT: network_events = await setup_network_test(
[task 2024-10-23T01:36:26.995Z] 01:36:26 INFO - STDOUT: events=[
[task 2024-10-23T01:36:26.996Z] 01:36:26 INFO - STDOUT: BEFORE_REQUEST_SENT_EVENT,
[task 2024-10-23T01:36:26.997Z] 01:36:26 INFO - STDOUT: RESPONSE_COMPLETED_EVENT,
[task 2024-10-23T01:36:26.997Z] 01:36:26 INFO - STDOUT: RESPONSE_STARTED_EVENT,
[task 2024-10-23T01:36:27.160Z] 01:36:27 INFO -
[task 2024-10-23T01:36:27.160Z] 01:36:27 INFO - TEST-UNEXPECTED-FAIL | /_mozilla/webdriver/bidi/network/cached_image_events/cached_image_events.py | test_page_with_cached_image - AssertionError: assert 6 == 5
[task 2024-10-23T01:36:27.160Z] 01:36:27 INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x7fd40596f6a0>
[task 2024-10-23T01:36:27.160Z] 01:36:27 INFO - url = <function url.<locals>.url at 0x7fd4059715e0>
[task 2024-10-23T01:36:27.160Z] 01:36:27 INFO - inline = <function inline.<locals>.inline at 0x7fd405971790>
[task 2024-10-23T01:36:27.160Z] 01:36:27 INFO - setup_network_test = <function setup_network_test.<locals>._setup_network_test at 0x7fd405971d30>
[task 2024-10-23T01:36:27.160Z] 01:36:27 INFO - top_context = {'children': [], 'context': '7f8ef67e-fcba-4283-9e9a-b007d9b77662', 'originalOpener': None, 'parent': None, ...}
[task 2024-10-23T01:36:27.160Z] 01:36:27 INFO -
[task 2024-10-23T01:36:27.161Z] 01:36:27 INFO - @pytest.mark.asyncio
[task 2024-10-23T01:36:27.161Z] 01:36:27 INFO - async def test_page_with_cached_image(
[task 2024-10-23T01:36:27.161Z] 01:36:27 INFO - bidi_session,
[task 2024-10-23T01:36:27.161Z] 01:36:27 INFO - url,
[task 2024-10-23T01:36:27.161Z] 01:36:27 INFO - inline,
[task 2024-10-23T01:36:27.161Z] 01:36:27 INFO - setup_network_test,
[task 2024-10-23T01:36:27.161Z] 01:36:27 INFO - top_context,
[task 2024-10-23T01:36:27.161Z] 01:36:27 INFO - ):
[task 2024-10-23T01:36:27.161Z] 01:36:27 INFO - network_events = await setup_network_test(
[task 2024-10-23T01:36:27.161Z] 01:36:27 INFO - events=[
[task 2024-10-23T01:36:27.161Z] 01:36:27 INFO - BEFORE_REQUEST_SENT_EVENT,
[task 2024-10-23T01:36:27.161Z] 01:36:27 INFO - RESPONSE_COMPLETED_EVENT,
[task 2024-10-23T01:36:27.162Z] 01:36:27 INFO - RESPONSE_STARTED_EVENT,
[task 2024-10-23T01:36:27.162Z] 01:36:27 INFO - ]
[task 2024-10-23T01:36:27.162Z] 01:36:27 INFO - )
[task 2024-10-23T01:36:27.162Z] 01:36:27 INFO - before_request_sent_events = network_events[BEFORE_REQUEST_SENT_EVENT]
[task 2024-10-23T01:36:27.162Z] 01:36:27 INFO - response_started_events = network_events[RESPONSE_STARTED_EVENT]
[task 2024-10-23T01:36:27.162Z] 01:36:27 INFO - response_completed_events = network_events[RESPONSE_COMPLETED_EVENT]
[task 2024-10-23T01:36:27.162Z] 01:36:27 INFO -
[task 2024-10-23T01:36:27.162Z] 01:36:27 INFO - # Small assert helper to assert events in the various event arrays
[task 2024-10-23T01:36:27.162Z] 01:36:27 INFO - def assert_events_at(index, expected_request, expected_response):
[task 2024-10-23T01:36:27.163Z] 01:36:27 INFO - assert_before_request_sent_event(
[task 2024-10-23T01:36:27.163Z] 01:36:27 INFO - before_request_sent_events[index],
[task 2024-10-23T01:36:27.163Z] 01:36:27 INFO - expected_request=expected_request,
[task 2024-10-23T01:36:27.163Z] 01:36:27 INFO - )
[task 2024-10-23T01:36:27.163Z] 01:36:27 INFO - assert_response_event(
[task 2024-10-23T01:36:27.163Z] 01:36:27 INFO - response_started_events[index],
[task 2024-10-23T01:36:27.163Z] 01:36:27 INFO - expected_request=expected_request,
[task 2024-10-23T01:36:27.163Z] 01:36:27 INFO - expected_response=expected_response,
[task 2024-10-23T01:36:27.163Z] 01:36:27 INFO - )
[task 2024-10-23T01:36:27.163Z] 01:36:27 INFO - assert_response_event(
[task 2024-10-23T01:36:27.163Z] 01:36:27 INFO - response_completed_events[index],
[task 2024-10-23T01:36:27.163Z] 01:36:27 INFO - expected_request=expected_request,
[task 2024-10-23T01:36:27.163Z] 01:36:27 INFO - expected_response=expected_response,
[task 2024-10-23T01:36:27.163Z] 01:36:27 INFO - )
[task 2024-10-23T01:36:27.163Z] 01:36:27 INFO -
[task 2024-10-23T01:36:27.163Z] 01:36:27 INFO - cached_image_url = url(get_cached_url("img/png", IMAGE_RESPONSE_BODY))
[task 2024-10-23T01:36:27.163Z] 01:36:27 INFO - page_with_cached_image = inline(
[task 2024-10-23T01:36:27.163Z] 01:36:27 INFO - f"""
[task 2024-10-23T01:36:27.163Z] 01:36:27 INFO - <body>
[task 2024-10-23T01:36:27.163Z] 01:36:27 INFO - test page with cached image
[task 2024-10-23T01:36:27.163Z] 01:36:27 INFO - <img src="{cached_image_url}">
[task 2024-10-23T01:36:27.163Z] 01:36:27 INFO - </body>
[task 2024-10-23T01:36:27.163Z] 01:36:27 INFO - """,
[task 2024-10-23T01:36:27.163Z] 01:36:27 INFO - )
[task 2024-10-23T01:36:27.163Z] 01:36:27 INFO -
[task 2024-10-23T01:36:27.163Z] 01:36:27 INFO - await bidi_session.browsing_context.navigate(
[task 2024-10-23T01:36:27.163Z] 01:36:27 INFO - context=top_context["context"],
[task 2024-10-23T01:36:27.163Z] 01:36:27 INFO - url=page_with_cached_image,
[task 2024-10-23T01:36:27.164Z] 01:36:27 INFO - wait="complete",
[task 2024-10-23T01:36:27.164Z] 01:36:27 INFO - )
[task 2024-10-23T01:36:27.164Z] 01:36:27 INFO -
[task 2024-10-23T01:36:27.164Z] 01:36:27 INFO - # Expect two events, one for the document and one for the image.
[task 2024-10-23T01:36:27.164Z] 01:36:27 INFO - wait = AsyncPoll(bidi_session, timeout=2)
[task 2024-10-23T01:36:27.164Z] 01:36:27 INFO - await wait.until(lambda _: len(response_completed_events) >= 2)
[task 2024-10-23T01:36:27.164Z] 01:36:27 INFO - assert len(before_request_sent_events) == 2
[task 2024-10-23T01:36:27.164Z] 01:36:27 INFO - assert len(response_started_events) == 2
[task 2024-10-23T01:36:27.164Z] 01:36:27 INFO - assert len(response_completed_events) == 2
[task 2024-10-23T01:36:27.164Z] 01:36:27 INFO -
[task 2024-10-23T01:36:27.164Z] 01:36:27 INFO - assert_events_at(
[task 2024-10-23T01:36:27.164Z] 01:36:27 INFO - 0,
[task 2024-10-23T01:36:27.164Z] 01:36:27 INFO - expected_request={"method": "GET", "url": page_with_cached_image},
[task 2024-10-23T01:36:27.164Z] 01:36:27 INFO - expected_response={"url": page_with_cached_image, "fromCache": False},
[task 2024-10-23T01:36:27.164Z] 01:36:27 INFO - )
[task 2024-10-23T01:36:27.165Z] 01:36:27 INFO - assert_events_at(
[task 2024-10-23T01:36:27.165Z] 01:36:27 INFO - 1,
[task 2024-10-23T01:36:27.165Z] 01:36:27 INFO - expected_request={"method": "GET", "url": cached_image_url},
[task 2024-10-23T01:36:27.165Z] 01:36:27 INFO - expected_response={"url": cached_image_url, "fromCache": False},
[task 2024-10-23T01:36:27.165Z] 01:36:27 INFO - )
[task 2024-10-23T01:36:27.165Z] 01:36:27 INFO -
[task 2024-10-23T01:36:27.165Z] 01:36:27 INFO - # Reload the page.
[task 2024-10-23T01:36:27.165Z] 01:36:27 INFO - await bidi_session.browsing_context.reload(context=top_context["context"])
[task 2024-10-23T01:36:27.166Z] 01:36:27 INFO -
[task 2024-10-23T01:36:27.166Z] 01:36:27 INFO - # Expect two events, one for the document and one for the image.
[task 2024-10-23T01:36:27.166Z] 01:36:27 INFO - wait = AsyncPoll(bidi_session, timeout=2)
[task 2024-10-23T01:36:27.166Z] 01:36:27 INFO - await wait.until(lambda _: len(response_completed_events) >= 4)
[task 2024-10-23T01:36:27.166Z] 01:36:27 INFO - assert len(before_request_sent_events) == 4
[task 2024-10-23T01:36:27.166Z] 01:36:27 INFO - assert len(response_started_events) == 4
[task 2024-10-23T01:36:27.166Z] 01:36:27 INFO - assert len(response_completed_events) == 4
[task 2024-10-23T01:36:27.166Z] 01:36:27 INFO -
[task 2024-10-23T01:36:27.166Z] 01:36:27 INFO - assert_events_at(
[task 2024-10-23T01:36:27.166Z] 01:36:27 INFO - 2,
[task 2024-10-23T01:36:27.166Z] 01:36:27 INFO - expected_request={"method": "GET", "url": page_with_cached_image},
[task 2024-10-23T01:36:27.166Z] 01:36:27 INFO - expected_response={"url": page_with_cached_image, "fromCache": False},
[task 2024-10-23T01:36:27.166Z] 01:36:27 INFO - )
[task 2024-10-23T01:36:27.166Z] 01:36:27 INFO - assert_events_at(
[task 2024-10-23T01:36:27.166Z] 01:36:27 INFO - 3,
[task 2024-10-23T01:36:27.166Z] 01:36:27 INFO - expected_request={"method": "GET", "url": cached_image_url},
[task 2024-10-23T01:36:27.166Z] 01:36:27 INFO - expected_response={"url": cached_image_url, "fromCache": True},
[task 2024-10-23T01:36:27.166Z] 01:36:27 INFO - )
[task 2024-10-23T01:36:27.166Z] 01:36:27 INFO -
[task 2024-10-23T01:36:27.166Z] 01:36:27 INFO - page_with_2_cached_images = inline(
[task 2024-10-23T01:36:27.166Z] 01:36:27 INFO - f"""
[task 2024-10-23T01:36:27.167Z] 01:36:27 INFO - <body>
[task 2024-10-23T01:36:27.167Z] 01:36:27 INFO - test page with 2 cached images
[task 2024-10-23T01:36:27.167Z] 01:36:27 INFO - <img src="{cached_image_url}">
[task 2024-10-23T01:36:27.167Z] 01:36:27 INFO - <img src="{cached_image_url}">
[task 2024-10-23T01:36:27.167Z] 01:36:27 INFO - </body>
[task 2024-10-23T01:36:27.167Z] 01:36:27 INFO - """,
[task 2024-10-23T01:36:27.168Z] 01:36:27 INFO - )
[task 2024-10-23T01:36:27.168Z] 01:36:27 INFO -
[task 2024-10-23T01:36:27.168Z] 01:36:27 INFO - await bidi_session.browsing_context.navigate(
[task 2024-10-23T01:36:27.168Z] 01:36:27 INFO - context=top_context["context"],
[task 2024-10-23T01:36:27.168Z] 01:36:27 INFO - url=page_with_2_cached_images,
[task 2024-10-23T01:36:27.168Z] 01:36:27 INFO - wait="complete",
[task 2024-10-23T01:36:27.168Z] 01:36:27 INFO - )
[task 2024-10-23T01:36:27.168Z] 01:36:27 INFO -
[task 2024-10-23T01:36:27.168Z] 01:36:27 INFO - # Only expect one event for the document here, as Firefox should reuse the
[task 2024-10-23T01:36:27.169Z] 01:36:27 INFO - # existing images from the previous document load.
[task 2024-10-23T01:36:27.169Z] 01:36:27 INFO - wait = AsyncPoll(bidi_session, timeout=2)
[task 2024-10-23T01:36:27.169Z] 01:36:27 INFO - await wait.until(lambda _: len(response_completed_events) >= 5)
[task 2024-10-23T01:36:27.169Z] 01:36:27 INFO - > assert len(before_request_sent_events) == 5
[task 2024-10-23T01:36:27.169Z] 01:36:27 INFO - E AssertionError: assert 6 == 5
[task 2024-10-23T01:36:27.169Z] 01:36:27 INFO - E + where 6 = len([{'context': '7f8ef67e-fcba-4283-9e9a-b007d9b77662', 'initiator': {'type': 'other'}, 'isBlocked': False, 'navigation': '7c7b6b1e-0582-4fcf-946c-01794e554759', ...}, {'context': '7f8ef67e-fcba-4283-9e9a-b007d9b77662', 'initiator': {'type': 'other'}, 'isBlocked': False, 'navigation': None, ...}, {'context': '7f8ef67e-fcba-4283-9e9a-b007d9b77662', 'initiator': {'type': 'other'}, 'isBlocked': False, 'navigation': '99660704-9919-4e37-ba5e-aa60323ed882', ...}, {'context': '7f8ef67e-fcba-4283-9e9a-b007d9b77662', 'initiator': {'type': 'other'}, 'isBlocked': False, 'navigation': None, ...}, {'context': '7f8ef67e-fcba-4283-9e9a-b007d9b77662', 'initiator': {'type': 'other'}, 'isBlocked': False, 'navigation': '9112547b-f018-4c72-b9bf-336c9afce867', ...}, {'context': '7f8ef67e-fcba-4283-9e9a-b007d9b77662', 'initiator': {'type': 'other'}, 'isBlocked': False, 'navigation': None, ...}])
Comment 1•3 days ago
|
||
This seems to fail under a combination of manifests as it also fails where it was initially green on a backstop push as seen here. Green run here https://treeherder.mozilla.org/logviewer?job_id=479428344&repo=autoland.
Test Groups
/_mozilla/webdriver/bidi/network/cached_image_events
/_mozilla/webdriver/cdp
/_mozilla/webdriver/classic/protocol
/webdriver/tests/bidi/browsing_context/capture_screenshot
/webdriver/tests/bidi/browsing_context/handle_user_prompt
/webdriver/tests/bidi/browsing_context/reload
/webdriver/tests/bidi/input/release_actions
/webdriver/tests/bidi/network/continue_request
/webdriver/tests/bidi/network/response_started
/webdriver/tests/bidi/script/realm_created
/webdriver/tests/bidi/storage/get_cookies
/webdriver/tests/classic/delete_session
/webdriver/tests/classic/find_element_from_element
/webdriver/tests/classic/get_alert_text
/webdriver/tests/classic/get_element_shadow_root
/webdriver/tests/classic/get_window_handles
/webdriver/tests/classic/new_session
/webdriver/tests/classic/set_timeouts
/webdriver/tests/interop
Updated•3 days ago
|
Comment 2•3 days ago
|
||
Julian could you please take a look? It seems like that at least one test, which runs before that failing one, doesn't clean-up correctly. Maybe we should move everything to using a new tab?
Assignee | ||
Comment 3•3 days ago
|
||
Thanks for the ping. It's not a cleanup issue here. The URL we use for the image is also unique to this test, and it's the only one we have in the events array.
We have an extra beforeRequestSent
event for the image which is unexpected. I was assuming the way Firefox is using the "list of available images" across document loads would be consistent, but maybe there are some heuristics which drive whether the browser will reuse a cached image or not.
I wrote the test based on the discussions over at Bug 1886518, but I didn't thoroughly check if the behavior would be consistent or not.
Hi Emilio, I added a test where the following happens:
- navigate to a page which loads
imageA
via an img tag - then reload the same page (which should load
imageA
again) - then navigate to another page which loads
imageA
twice with 2 img tags
Based on local runs for this test, I was always seeing only two requests for imageA
across the whole test. Basically one call for the initial page, and another (cached) call for the reload. The final step always seemed to bypass fetch and simply reuse the list of available images. But based on the intermittent failures above, maybe this behavior is not guaranteed and might change based on various conditions?
Do you think it's not something we can rely on for tests?
Comment 4•3 days ago
|
||
Set release status flags based on info from the regressing bug 1886518
Comment 5•3 days ago
|
||
Whether images are revalidated in the cache depends on a variety of conditions, I'd rather not hard-code them because we have some known bugs in the area that would go away if we start using the shared subresource cache. You can see what's going on on a failing run by enabling the image cache logs.
Assignee | ||
Comment 6•3 days ago
|
||
Thanks. In that case I think we should remove the mozilla-specific test.
Assignee | ||
Comment 7•3 days ago
|
||
Based on the discussion in the bug, the specific behavior tested in this file is not reliable and might also change in the future.
We have cross browser tests already asserting simpler caching scenarios also added in D224506, which should be sufficient here.
Updated•3 days ago
|
Comment hidden (Intermittent Failures Robot) |
Comment 10•1 day ago
|
||
bugherder |
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Updated•17 hours ago
|
Description
•