1671783 - Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/forward/user_prompts.py | expected OK

Status: RESOLVED INCOMPLETE

(Remote Protocol :: Marionette, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2020-10-17T16:32:48.058Z] 16:32:48     INFO - PID 512 | DEBUG: Adding blocker ContentParent: id=1f617126800 for phase xpcom-will-shutdown
[task 2020-10-17T16:32:48.058Z] 16:32:48     INFO - PID 512 | DEBUG: Adding blocker ContentParent: id=1f617126800 for phase profile-before-change
[task 2020-10-17T16:32:48.170Z] 16:32:48     INFO - PID 512 | 1602952368153	Marionette	TRACE	[41] Frame script loaded
[task 2020-10-17T16:32:48.174Z] 16:32:48     INFO - PID 512 | 1602952368159	Marionette	TRACE	Detected remoteness change. New browsing context: 41
[task 2020-10-17T16:32:48.176Z] 16:32:48     INFO - PID 512 | DEBUG: Adding blocker ContentParent: id=1f61712d800 for phase xpcom-will-shutdown
[task 2020-10-17T16:32:48.177Z] 16:32:48     INFO - PID 512 | DEBUG: Adding blocker ContentParent: id=1f61712d800 for phase profile-before-change
[task 2020-10-17T16:32:48.177Z] 16:32:48     INFO - PID 512 | 1602952368171	Marionette	TRACE	[41] Frame script unloaded
[task 2020-10-17T16:32:48.177Z] 16:32:48     INFO - PID 512 | 1602952368173	Marionette	TRACE	Received message beforeunload for about:blank
[task 2020-10-17T16:32:48.203Z] 16:32:48     INFO - PID 512 | 1602952368189	Marionette	TRACE	Received message pagehide for about:blank
[task 2020-10-17T16:32:48.232Z] 16:32:48     INFO - PID 512 | 1602952368223	Marionette	TRACE	Received message DOMContentLoaded for http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cp+id%3D1%3E&charset=UTF-8&mime=text%2Fhtml
[task 2020-10-17T16:32:48.232Z] 16:32:48     INFO - PID 512 | 1602952368224	Marionette	TRACE	Received message beforeunload for about:blank
[task 2020-10-17T16:32:48.233Z] 16:32:48     INFO - PID 512 | 1602952368227	Marionette	TRACE	Received message pageshow for http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cp+id%3D1%3E&charset=UTF-8&mime=text%2Fhtml
[task 2020-10-17T16:32:48.238Z] 16:32:48     INFO - PID 512 | 1602952368233	Marionette	TRACE	Received message pagehide for about:blank
[task 2020-10-17T16:32:49.122Z] 16:32:49     INFO - PID 512 | DEBUG: Adding blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2020-10-17T16:32:49.122Z] 16:32:49     INFO - PID 512 | DEBUG: Completed blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2020-10-17T16:33:04.132Z] 16:33:04     INFO - PID 512 | DEBUG: Adding blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2020-10-17T16:33:04.132Z] 16:33:04     INFO - PID 512 | DEBUG: Completed blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2020-10-17T16:35:31.715Z] 16:35:31     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/forward/user_prompts.py | expected OK
[task 2020-10-17T16:35:31.715Z] 16:35:31     INFO - TEST-INFO took 185014ms
[task 2020-10-17T16:35:31.716Z] 16:35:31     INFO - No more tests
[task 2020-10-17T16:35:31.796Z] 16:35:31     INFO - Closing logging queue
[task 2020-10-17T16:35:31.796Z] 16:35:31     INFO - queue closed
[task 2020-10-17T16:35:31.797Z] 16:35:31     INFO - Got 1 unexpected results
[task 2020-10-17T16:35:31.797Z] 16:35:31     INFO - SUITE-END | took 902s
[task 2020-10-17T16:35:31.836Z] 16:35:31     INFO - Removed font: Ahem.ttf
[task 2020-10-17T16:35:31.845Z] 16:35:31     INFO - Closing logging queue
[task 2020-10-17T16:35:31.845Z] 16:35:31     INFO - queue closed
[task 2020-10-17T16:35:31.998Z] 16:35:31    ERROR - Return code: 1
[task 2020-10-17T16:35:31.998Z] 16:35:31    ERROR - Got 1 unexpected statuses
[task 2020-10-17T16:35:31.999Z] 16:35:31  WARNING - # TBPL WARNING #
[task 2020-10-17T16:35:31.999Z] 16:35:31  WARNING - setting return code to 1```

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform breakdown:

• windows10-64-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1671783&startday=2020-10-12&endday=2020-10-18&tree=all

Comment 2

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

Here the failure details:

[task 2020-10-17T16:32:48.035Z] 16:32:48     INFO - PID 512 | 1602952368017	Marionette	DEBUG	0 -> [0,37,"WebDriver:Navigate",{"url":"http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cp+id%3D1%3E&charset=UTF-8&mime=text%2Fhtml"}]
[task 2020-10-17T16:32:48.058Z] 16:32:48     INFO - PID 512 | DEBUG: Adding blocker ContentParent: id=1f617126800 for phase xpcom-will-shutdown
[task 2020-10-17T16:32:48.058Z] 16:32:48     INFO - PID 512 | DEBUG: Adding blocker ContentParent: id=1f617126800 for phase profile-before-change
[task 2020-10-17T16:32:48.170Z] 16:32:48     INFO - PID 512 | 1602952368153	Marionette	TRACE	[41] Frame script loaded
[task 2020-10-17T16:32:48.174Z] 16:32:48     INFO - PID 512 | 1602952368159	Marionette	TRACE	Detected remoteness change. New browsing context: 41
[task 2020-10-17T16:32:48.176Z] 16:32:48     INFO - PID 512 | DEBUG: Adding blocker ContentParent: id=1f61712d800 for phase xpcom-will-shutdown
[task 2020-10-17T16:32:48.177Z] 16:32:48     INFO - PID 512 | DEBUG: Adding blocker ContentParent: id=1f61712d800 for phase profile-before-change
[task 2020-10-17T16:32:48.177Z] 16:32:48     INFO - PID 512 | 1602952368171	Marionette	TRACE	[41] Frame script unloaded
[task 2020-10-17T16:32:48.177Z] 16:32:48     INFO - PID 512 | 1602952368173	Marionette	TRACE	Received message beforeunload for about:blank
[task 2020-10-17T16:32:48.203Z] 16:32:48     INFO - PID 512 | 1602952368189	Marionette	TRACE	Received message pagehide for about:blank
[task 2020-10-17T16:32:48.232Z] 16:32:48     INFO - PID 512 | 1602952368223	Marionette	TRACE	Received message DOMContentLoaded for http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cp+id%3D1%3E&charset=UTF-8&mime=text%2Fhtml
[task 2020-10-17T16:32:48.232Z] 16:32:48     INFO - PID 512 | 1602952368224	Marionette	TRACE	Received message beforeunload for about:blank
[task 2020-10-17T16:32:48.233Z] 16:32:48     INFO - PID 512 | 1602952368227	Marionette	TRACE	Received message pageshow for http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cp+id%3D1%3E&charset=UTF-8&mime=text%2Fhtml
[task 2020-10-17T16:32:48.238Z] 16:32:48     INFO - PID 512 | 1602952368233	Marionette	TRACE	Received message pagehide for about:blank
[task 2020-10-17T16:32:49.122Z] 16:32:49     INFO - PID 512 | DEBUG: Adding blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2020-10-17T16:32:49.122Z] 16:32:49     INFO - PID 512 | DEBUG: Completed blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2020-10-17T16:33:04.132Z] 16:33:04     INFO - PID 512 | DEBUG: Adding blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2020-10-17T16:33:04.132Z] 16:33:04     INFO - PID 512 | DEBUG: Completed blocker SessionFile: Finish writing Session Restore data for phase profile-before-change

Probably due to the remoteness change during a navigation the command didn't return. The mixed page load events are still questionable. By using a webprogress listener (bug 1664165) it should become easier.

Comment 3

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform breakdown:

• windows10-64-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1671783&startday=2020-10-19&endday=2020-10-25&tree=all

Comment 4

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

Only two failures so far. As such lets close this bug as incomplete.

Comment 5

[Natalia Csoregi [:nataliaCs]]

https://treeherder.mozilla.org/logviewer?job_id=342310631&repo=autoland&lineNumber=37116

Comment 6

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 5

Platform and build breakdown:

• linux1804-64-shippable-qr: 3
  • opt: 3
• linux1804-64-qr: 1
  • opt: 1
• windows10-64: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1671783&startday=2021-06-07&endday=2021-06-13&tree=all

Comment 7

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows10-64: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1671783&startday=2021-06-14&endday=2021-06-20&tree=all

Comment 8

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

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Comment 9

[BMO Automation]

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