1926482 - 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

Status: RESOLVED FIXED

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

Description

[Treeherder Bug Filer]

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

[Cosmin Sabou [:CosminS]]

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

Comment 2

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

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?

Comment 3

[Julian Descottes [:jdescottes]]

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

[BugBot [:suhaib / :marco/ :calixte]]

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

Comment 5

[Emilio Cobos Álvarez (:emilio)]

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.

Comment 6

[Julian Descottes [:jdescottes]]

Thanks. In that case I think we should remove the mozilla-specific test.

Comment 7

[Julian Descottes [:jdescottes]]

Attachment: Bug 1926482 - [wdspec] Remove flaky test for BiDi network events with cached images

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.

Comment 8

[Intermittent Failures Robot]

29 failures in 918 pushes (0.032 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 15
• mozilla-central: 12
• try: 2

Platform and build breakdown:

• linux1804-64-tsan-qr: 21
  • opt: 21
• linux1804-64-ccov-qr: 4
  • opt: 4
• windows11-64-2009-ccov-qr: 4
  • opt: 4

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

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/084a45f6eb4f
[wdspec] Remove flaky test for BiDi network events with cached images r=webdriver-reviewers,Sasha

Comment 10

[Cristian Tuns]

https://hg.mozilla.org/mozilla-central/rev/084a45f6eb4f

Comment 11

[Intermittent Failures Robot]

21 failures in 885 pushes (0.024 failures/push) were associated with this bug yesterday.

Repository breakdown:

• mozilla-central: 12
• autoland: 4
• try: 5

Platform and build breakdown:

• linux1804-64-tsan-qr: 11
  • opt: 11
• windows11-64-2009-ccov-qr: 4
  • opt: 4
• linux1804-64-ccov-qr: 6
  • opt: 6

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