1794066 - Intermittent [tier 2] /webdriver/tests/bidi/browsing_context/load/load.py | test_iframe - asyncio.exceptions.CancelledError

Status: RESOLVED FIXED

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

Description

[Treeherder Bug Filer]

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

---

[task 2022-10-07T00:14:10.417Z] 00:14:10     INFO - TEST-PASS | /webdriver/tests/bidi/browsing_context/load/load.py | test_subscribe 
[task 2022-10-07T00:14:10.417Z] 00:14:10     INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/bidi/browsing_context/load/load.py | test_iframe - asyncio.exceptions.CancelledError
[task 2022-10-07T00:14:10.417Z] 00:14:10     INFO - async def poll():
[task 2022-10-07T00:14:10.417Z] 00:14:10     INFO -         result = None
[task 2022-10-07T00:14:10.417Z] 00:14:10     INFO -     
[task 2022-10-07T00:14:10.417Z] 00:14:10     INFO -         while True:
[task 2022-10-07T00:14:10.417Z] 00:14:10     INFO -             next = self.clock.time() + self.interval
[task 2022-10-07T00:14:10.417Z] 00:14:10     INFO -     
[task 2022-10-07T00:14:10.417Z] 00:14:10     INFO -             try:
[task 2022-10-07T00:14:10.417Z] 00:14:10     INFO -                 result = condition(self.session)
[task 2022-10-07T00:14:10.417Z] 00:14:10     INFO -             except self.exceptions:
[task 2022-10-07T00:14:10.417Z] 00:14:10     INFO -                 _, _, traceback = sys.exc_info()
[task 2022-10-07T00:14:10.417Z] 00:14:10     INFO -     
[task 2022-10-07T00:14:10.417Z] 00:14:10     INFO -             # re-adjust the interval depending on how long
[task 2022-10-07T00:14:10.417Z] 00:14:10     INFO -             # the callback took to evaluate the condition
[task 2022-10-07T00:14:10.417Z] 00:14:10     INFO -             interval_new = max(next - self.clock.time(), 0)
[task 2022-10-07T00:14:10.417Z] 00:14:10     INFO -     
[task 2022-10-07T00:14:10.417Z] 00:14:10     INFO -             if result:
[task 2022-10-07T00:14:10.418Z] 00:14:10     INFO -                 return result
[task 2022-10-07T00:14:10.418Z] 00:14:10     INFO -     
[task 2022-10-07T00:14:10.418Z] 00:14:10     INFO - >           await asyncio.sleep(interval_new)
[task 2022-10-07T00:14:10.418Z] 00:14:10     INFO - 
[task 2022-10-07T00:14:10.418Z] 00:14:10     INFO - condition  = <function test_iframe.<locals>.<lambda> at 0x00000208AEB47B80>
[task 2022-10-07T00:14:10.418Z] 00:14:10     INFO - interval_new = 0.10000000000002274
[task 2022-10-07T00:14:10.418Z] 00:14:10     INFO - next       = 563.3340000000001
[task 2022-10-07T00:14:10.418Z] 00:14:10     INFO - result     = False
[task 2022-10-07T00:14:10.418Z] 00:14:10     INFO - self       = <tests.support.sync.AsyncPoll object at 0x00000208AEB54370>
[task 2022-10-07T00:14:10.418Z] 00:14:10     INFO - 
[task 2022-10-07T00:14:10.418Z] 00:14:10     INFO - tests\web-platform\tests\webdriver\tests\support\sync.py:263: 

Comment 1

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

So this comes from the usage of AsyncPoll in waiting for the browsingContext.load event to be received. As it can be seen it took 5s until the browsing context actually got created, and that is the default timeout for the AsyncPoll.until() call:

https://treeherder.mozilla.org/logviewer?job_id=392522430&repo=autoland&lineNumber=7787-7794

The problem is actually in these lines:

https://searchfox.org/mozilla-central/rev/d416a7b827c2d76b12848e355a4e03dde49ece25/testing/web-platform/tests/webdriver/tests/support/sync.py#265-267

Because of the timeout the method runs into asyncio.wait_for() raises an asyncio.TimeoutError but at the same time also cancels the task. That is what we do not catch here or handle correctly. We might want to catch this exception as well or canceling the task ourselves by passing a shielded coroutine into asyncio.wait_for().

Comment 2

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

Our AsyncPoll implementation is actually kinda busted. I'll have a patch shortly which fixes it and doesn't require us to use asyncio.wait_for().

Comment 3

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

Attachment: Bug 1794066 - [wdspec] Fix internal polling mechanism for AsyncPoll.

The internal async poll helper should raise the timeout error
on its own. This doesn't require us to use asyncio.wait_for
which itself would force a cancellation which would fail anyway
due to the infinite while loop.

Comment 4

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/72d94d7acaa6
[wdspec] Fix internal polling mechanism for AsyncPoll. r=webdriver-reviewers,jgraham

Comment 5

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

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

Comment 6

[Cristian Tuns]

https://hg.mozilla.org/mozilla-central/rev/72d94d7acaa6

Comment 7

[Intermittent Failures Robot]

1 failures in 2449 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows10-32-2004-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1794066&startday=2022-10-03&endday=2022-10-09&tree=all

Comment 8

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

Upstream PR merged by jgraham