1749104 - Intermittent /webdriver/tests/send_alert_text/send.py | test_unexpected_alert - webdriver.error.TimeoutException: timeout (500): Timed out after 5.1 seconds with message: No user prompt with text 'Hello' detected

Status: RESOLVED FIXED

(Remote Protocol :: Marionette, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2022-01-08T04:37:31.668Z] 04:37:31     INFO - TEST-PASS | /webdriver/tests/send_alert_text/send.py | test_send_alert_text[ Fed erer ] 
[task 2022-01-08T04:37:31.668Z] 04:37:31     INFO - TEST-PASS | /webdriver/tests/send_alert_text/send.py | test_send_alert_text[Fed\terer] 
[task 2022-01-08T04:37:31.668Z] 04:37:31     INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/send_alert_text/send.py | test_unexpected_alert - webdriver.error.TimeoutException: timeout (500): Timed out after 5.1 seconds with message: No user prompt with text 'Hello' detected
[task 2022-01-08T04:37:31.668Z] 04:37:31     INFO - session = <Session a0dd2ea5-8fda-4ac3-9c73-a33ef46a89e0>
[task 2022-01-08T04:37:31.668Z] 04:37:31     INFO - 
[task 2022-01-08T04:37:31.668Z] 04:37:31     INFO -     def test_unexpected_alert(session):
[task 2022-01-08T04:37:31.669Z] 04:37:31     INFO -         session.execute_script("setTimeout(function() { prompt('Hello'); }, 100);")
[task 2022-01-08T04:37:31.669Z] 04:37:31     INFO -         wait = Poll(
[task 2022-01-08T04:37:31.669Z] 04:37:31     INFO -             session,
[task 2022-01-08T04:37:31.669Z] 04:37:31     INFO -             timeout=5,
[task 2022-01-08T04:37:31.669Z] 04:37:31     INFO -             ignored_exceptions=NoSuchAlertException,
[task 2022-01-08T04:37:31.669Z] 04:37:31     INFO -             message="No user prompt with text 'Hello' detected")
[task 2022-01-08T04:37:31.669Z] 04:37:31     INFO - >       wait.until(lambda s: s.alert.text == "Hello")
[task 2022-01-08T04:37:31.669Z] 04:37:31     INFO - 
[task 2022-01-08T04:37:31.669Z] 04:37:31     INFO - session    = <Session a0dd2ea5-8fda-4ac3-9c73-a33ef46a89e0>
[task 2022-01-08T04:37:31.669Z] 04:37:31     INFO - wait       = <tests.support.sync.Poll object at 0x0000024675D005B0>
[task 2022-01-08T04:37:31.669Z] 04:37:31     INFO - 
[task 2022-01-08T04:37:31.669Z] 04:37:31     INFO - tests\web-platform\tests\webdriver\tests\send_alert_text\send.py:91: 
[task 2022-01-08T04:37:31.669Z] 04:37:31     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[task 2022-01-08T04:37:31.669Z] 04:37:31     INFO - tests\web-platform\tests\webdriver\tests\support\sync.py:141: in until
[task 2022-01-08T04:37:31.669Z] 04:37:31     INFO -     raise self.exc_cls(message=message).with_traceback(tb)
[task 2022-01-08T04:37:31.670Z] 04:37:31     INFO -         _          = <NoSuchAlertException http_status=404>
[task 2022-01-08T04:37:31.670Z] 04:37:31     INFO -         condition  = <function test_unexpected_alert.<locals>.<lambda> at 0x0000024675D2C3A0>
[task 2022-01-08T04:37:31.670Z] 04:37:31     INFO -         elapsed    = 5.1
[task 2022-01-08T04:37:31.670Z] 04:37:31     INFO -         end        = 1641616651.3073595
[task 2022-01-08T04:37:31.670Z] 04:37:31     INFO -         interval_new = 0.09766554832458496
[task 2022-01-08T04:37:31.670Z] 04:37:31     INFO -         message    = ("Timed out after 5.1 seconds with message: No user prompt with text 'Hello' "
[task 2022-01-08T04:37:31.670Z] 04:37:31     INFO -  'detected')
[task 2022-01-08T04:37:31.670Z] 04:37:31     INFO -         next       = 1641616651.3817894
[task 2022-01-08T04:37:31.670Z] 04:37:31     INFO -         rv         = None
[task 2022-01-08T04:37:31.670Z] 04:37:31     INFO -         self       = <tests.support.sync.Poll object at 0x0000024675D005B0>
[task 2022-01-08T04:37:31.670Z] 04:37:31     INFO -         start      = 1641616646.3073595
[task 2022-01-08T04:37:31.670Z] 04:37:31     INFO -         tb         = <traceback object at 0x0000024675DB2900>
[task 2022-01-08T04:37:31.670Z] 04:37:31     INFO - tests\web-platform\tests\webdriver\tests\support\sync.py:117: in until
[task 2022-01-08T04:37:31.670Z] 04:37:31     INFO -     rv = condition(self.session)
[task 2022-01-08T04:37:31.670Z] 04:37:31     INFO -         _          = <NoSuchAlertException http_status=404>
[task 2022-01-08T04:37:31.670Z] 04:37:31     INFO -         condition  = <function test_unexpected_alert.<locals>.<lambda> at 0x0000024675D2C3A0>
[task 2022-01-08T04:37:31.670Z] 04:37:31     INFO -         elapsed    = 5.1
[task 2022-01-08T04:37:31.670Z] 04:37:31     INFO -         end        = 1641616651.3073595
[task 2022-01-08T04:37:31.671Z] 04:37:31     INFO -         interval_new = 0.09766554832458496
[task 2022-01-08T04:37:31.671Z] 04:37:31     INFO -         message    = ("Timed out after 5.1 seconds with message: No user prompt with text 'Hello' "
[task 2022-01-08T04:37:31.671Z] 04:37:31     INFO -  'detected')
[task 2022-01-08T04:37:31.671Z] 04:37:31     INFO -         next       = 1641616651.3817894
[task 2022-01-08T04:37:31.671Z] 04:37:31     INFO -         rv         = None
[task 2022-01-08T04:37:31.671Z] 04:37:31     INFO -         self       = <tests.support.sync.Poll object at 0x0000024675D005B0>
[task 2022-01-08T04:37:31.671Z] 04:37:31     INFO -         start      = 1641616646.3073595
[task 2022-01-08T04:37:31.671Z] 04:37:31     INFO -         tb         = <traceback object at 0x0000024675DB2900>
[task 2022-01-08T04:37:31.671Z] 04:37:31     INFO - tests\web-platform\tests\webdriver\tests\send_alert_text\send.py:91: in <lambda>
[task 2022-01-08T04:37:31.671Z] 04:37:31     INFO -     wait.until(lambda s: s.alert.text == "Hello")
[task 2022-01-08T04:37:31.671Z] 04:37:31     INFO -         s          = <Session a0dd2ea5-8fda-4ac3-9c73-a33ef46a89e0>
[task 2022-01-08T04:37:31.671Z] 04:37:31     INFO - tests\web-platform\tests\tools\webdriver\webdriver\client.py:20: in inner
[task 2022-01-08T04:37:31.671Z] 04:37:31     INFO -     return func(self, *args, **kwargs)
[task 2022-01-08T04:37:31.671Z] 04:37:31     INFO -         args       = ()
[task 2022-01-08T04:37:31.671Z] 04:37:31     INFO -         func       = <function UserPrompt.text at 0x0000024675C84C10>
[task 2022-01-08T04:37:31.671Z] 04:37:31     INFO -         kwargs     = {}
[task 2022-01-08T04:37:31.671Z] 04:37:31     INFO -         self       = <webdriver.client.UserPrompt object at 0x0000024675CFFBB0>
[task 2022-01-08T04:37:31.671Z] 04:37:31     INFO -         session    = <Session a0dd2ea5-8fda-4ac3-9c73-a33ef46a89e0>
[task 2022-01-08T04:37:31.671Z] 04:37:31     INFO - tests\web-platform\tests\tools\webdriver\webdriver\client.py:479: in text
[task 2022-01-08T04:37:31.671Z] 04:37:31     INFO -     return self.session.send_session_command("GET", "alert/text")
[task 2022-01-08T04:37:31.671Z] 04:37:31     INFO -         self       = <webdriver.client.UserPrompt object at 0x0000024675CFFBB0>
[task 2022-01-08T04:37:31.672Z] 04:37:31     INFO - tests\web-platform\tests\tools\webdriver\webdriver\client.py:659: in send_session_command
[task 2022-01-08T04:37:31.672Z] 04:37:31     INFO -     return self.send_command(method, url, body, timeout)
[task 2022-01-08T04:37:31.672Z] 04:37:31     INFO -         body       = None
[task 2022-01-08T04:37:31.672Z] 04:37:31     INFO -         method     = 'GET'
[task 2022-01-08T04:37:31.672Z] 04:37:31     INFO -         self       = <Session a0dd2ea5-8fda-4ac3-9c73-a33ef46a89e0>
[task 2022-01-08T04:37:31.672Z] 04:37:31     INFO -         timeout    = None
[task 2022-01-08T04:37:31.672Z] 04:37:31     INFO -         uri        = 'alert/text'
[task 2022-01-08T04:37:31.672Z] 04:37:31     INFO -         url        = 'session/a0dd2ea5-8fda-4ac3-9c73-a33ef46a89e0/alert/text'
[task 2022-01-08T04:37:31.672Z] 04:37:31     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[task 2022-01-08T04:37:31.672Z] 04:37:31     INFO - 
[task 2022-01-08T04:37:31.672Z] 04:37:31     INFO - self = <Session a0dd2ea5-8fda-4ac3-9c73-a33ef46a89e0>, method = 'GET'
[task 2022-01-08T04:37:31.673Z] 04:37:31     INFO - url = 'session/a0dd2ea5-8fda-4ac3-9c73-a33ef46a89e0/alert/text', body = None
[task 2022-01-08T04:37:31.673Z] 04:37:31     INFO - timeout = None
[task 2022-01-08T04:37:31.673Z] 04:37:31     INFO - 
[task 2022-01-08T04:37:31.673Z] 04:37:31     INFO -     def send_command(self, method, url, body=None, timeout=None):
[task 2022-01-08T04:37:31.673Z] 04:37:31     INFO -         """
[task 2022-01-08T04:37:31.673Z] 04:37:31     INFO -         Send a command to the remote end and validate its success.
[task 2022-01-08T04:37:31.673Z] 04:37:31     INFO -     
[task 2022-01-08T04:37:31.673Z] 04:37:31     INFO -         :param method: HTTP method to use in request.
[task 2022-01-08T04:37:31.673Z] 04:37:31     INFO -         :param uri: "Command part" of the HTTP request URL,
[task 2022-01-08T04:37:31.673Z] 04:37:31     INFO -             e.g. `window/rect`.
[task 2022-01-08T04:37:31.673Z] 04:37:31     INFO -         :param body: Optional body of the HTTP request.
[task 2022-01-08T04:37:31.673Z] 04:37:31     INFO -     
[task 2022-01-08T04:37:31.673Z] 04:37:31     INFO -         :return: `None` if the HTTP response body was empty, otherwise
[task 2022-01-08T04:37:31.673Z] 04:37:31     INFO -             the `value` field returned after parsing the response
[task 2022-01-08T04:37:31.674Z] 04:37:31     INFO -             body as JSON.
[task 2022-01-08T04:37:31.674Z] 04:37:31     INFO -     
[task 2022-01-08T04:37:31.674Z] 04:37:31     INFO -         :raises error.WebDriverException: If the remote end returns
[task 2022-01-08T04:37:31.674Z] 04:37:31     INFO -             an error.
[task 2022-01-08T04:37:31.674Z] 04:37:31     INFO -         :raises ValueError: If the response body does not contain a
[task 2022-01-08T04:37:31.674Z] 04:37:31     INFO -             `value` key.
[task 2022-01-08T04:37:31.674Z] 04:37:31     INFO -         """
[task 2022-01-08T04:37:31.674Z] 04:37:31     INFO -     
[task 2022-01-08T04:37:31.674Z] 04:37:31     INFO -         response = self.transport.send(
[task 2022-01-08T04:37:31.674Z] 04:37:31     INFO -             method, url, body,
[task 2022-01-08T04:37:31.674Z] 04:37:31     INFO -             encoder=protocol.Encoder, decoder=protocol.Decoder,
[task 2022-01-08T04:37:31.674Z] 04:37:31     INFO -             session=self, timeout=timeout)
[task 2022-01-08T04:37:31.674Z] 04:37:31     INFO -     
[task 2022-01-08T04:37:31.674Z] 04:37:31     INFO -         if response.status != 200:
[task 2022-01-08T04:37:31.675Z] 04:37:31     INFO -             err = error.from_response(response)
[task 2022-01-08T04:37:31.675Z] 04:37:31     INFO -     
[task 2022-01-08T04:37:31.675Z] 04:37:31     INFO -             if isinstance(err, error.InvalidSessionIdException):
[task 2022-01-08T04:37:31.675Z] 04:37:31     INFO -                 # The driver could have already been deleted the session.
[task 2022-01-08T04:37:31.675Z] 04:37:31     INFO -                 self.session_id = None
[task 2022-01-08T04:37:31.675Z] 04:37:31     INFO -     
[task 2022-01-08T04:37:31.675Z] 04:37:31     INFO - >           raise err
[task 2022-01-08T04:37:31.675Z] 04:37:31     INFO - E           webdriver.error.TimeoutException: timeout (500): Timed out after 5.1 seconds with message: No user prompt with text 'Hello' detected
[task 2022-01-08T04:37:31.675Z] 04:37:31     INFO - 
[task 2022-01-08T04:37:31.675Z] 04:37:31     INFO - body       = None
[task 2022-01-08T04:37:31.675Z] 04:37:31     INFO - err        = <NoSuchAlertException http_status=404>
[task 2022-01-08T04:37:31.675Z] 04:37:31     INFO - method     = 'GET'
[task 2022-01-08T04:37:31.675Z] 04:37:31     INFO - response   = <Response status=404 error=<NoSuchAlertException http_status=404>>
[task 2022-01-08T04:37:31.675Z] 04:37:31     INFO - self       = <Session a0dd2ea5-8fda-4ac3-9c73-a33ef46a89e0>
[task 2022-01-08T04:37:31.675Z] 04:37:31     INFO - timeout    = None
[task 2022-01-08T04:37:31.675Z] 04:37:31     INFO - url        = 'session/a0dd2ea5-8fda-4ac3-9c73-a33ef46a89e0/alert/text'
[task 2022-01-08T04:37:31.675Z] 04:37:31     INFO - 
[task 2022-01-08T04:37:31.675Z] 04:37:31     INFO - tests\web-platform\tests\tools\webdriver\webdriver\client.py:623: TimeoutException
[task 2022-01-08T04:37:31.676Z] 04:37:31     INFO - TEST-OK | /webdriver/tests/send_alert_text/send.py | took 16052ms

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 4
• mozilla-central: 1

Platform and build breakdown:

• windows10-64-2004-qr: 5
  • debug: 5

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

Comment 2

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

Probably a regression from bug 1739369. I'll check back later today for results from over the weekend.

Comment 3

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

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

Comment 4

[Intermittent Failures Robot]

14 failures in 3060 pushes (0.005 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 2
• autoland: 11
• mozilla-central: 1

Platform and build breakdown:

• windows10-64-2004-qr: 5
  • debug: 5
• macosx1015-64-qr: 3
  • debug: 3
• windows10-32-2004-qr: 4
  • debug: 4
• linux1804-64-qr: 2
  • opt: 1
  • debug: 1

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

Comment 5

[Intermittent Failures Robot]

1 failures in 3444 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
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1749104&startday=2022-01-17&endday=2022-01-23&tree=all

Comment 6

[BMO Automation]

Moving bug to Remote Protocol::Marionette component per bug 1815831.