Closed Bug 1671783 Opened 1 year ago Closed 5 months ago

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

Categories

(Testing :: geckodriver, defect, P5)

defect

Tracking

(Not tracked)

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Depends on 1 open bug)

Details

(Keywords: intermittent-failure)

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

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.

Depends on: 1664165

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

Status: NEW → RESOLVED
Closed: 1 year ago
Resolution: --- → INCOMPLETE
Status: REOPENED → RESOLVED
Closed: 1 year ago5 months ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.