Closed Bug 1513451 Opened 5 years ago Closed 5 years ago

Intermittent TEST-UNEXPECTED-TIMEOUT | /html/browsers/browsing-the-web/read-media/pageload-image.html | expected OK (various Android 7.0 x86 wpt timeouts in /html/browsers)

Categories

(Testing :: Marionette Client and Harness, defect, P5)

Product:
Testing
Component:
Marionette Client and Harness
Type:
defect

Tracking

(firefox-esr60 unaffected, firefox64 unaffected, firefox65 fixed, firefox66 fixed)

Status:
RESOLVED FIXED
Milestone:
mozilla66
Tracking Flags:
Tracking Status
firefox-esr60 --- unaffected
firefox64 --- unaffected
firefox65 --- fixed
firefox66 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: whimboo)

References

Details

(Keywords: intermittent-failure, regression) 

Filed by: rmaries [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=216543546&repo=mozilla-central

https://queue.taskcluster.net/v1/task/IpztRvYOQO-uz3J0kZNHYA/runs/0/artifacts/public/logs/live_backing.log

[task 2018-12-12T06:21:39.359Z] 06:21:39     INFO - TEST-START | /html/browsers/browsing-the-web/read-media/pageload-image.html
[task 2018-12-12T06:21:39.374Z] 06:21:39     INFO - Closing window 24
[task 2018-12-12T06:22:24.407Z] 06:22:24     INFO - TEST-UNEXPECTED-TIMEOUT | /html/browsers/browsing-the-web/read-media/pageload-image.html | expected OK
[task 2018-12-12T06:22:24.407Z] 06:22:24     INFO - TEST-INFO took 45041ms
[task 2018-12-12T06:22:25.202Z] 06:22:25     INFO - Closing logging queue
[task 2018-12-12T06:22:25.202Z] 06:22:25     INFO - queue closed
[task 2018-12-12T06:22:25.225Z] 06:22:25     INFO - Setting up ssl
[task 2018-12-12T06:22:25.253Z] 06:22:25     INFO - certutil | 
[task 2018-12-12T06:22:25.290Z] 06:22:25     INFO - certutil | 
[task 2018-12-12T06:22:25.306Z] 06:22:25     INFO - certutil | 
[task 2018-12-12T06:22:25.307Z] 06:22:25     INFO - Certificate Nickname                                         Trust Attributes
[task 2018-12-12T06:22:25.307Z] 06:22:25     INFO -                                                              SSL,S/MIME,JAR/XPI
[task 2018-12-12T06:22:25.307Z] 06:22:25     INFO - 
[task 2018-12-12T06:22:25.307Z] 06:22:25     INFO - web-platform-tests                                           CT,, 
[task 2018-12-12T06:22:25.308Z] 06:22:25     INFO - 
[task 2018-12-12T06:22:27.225Z] 06:22:27     INFO - adb Granting important runtime permissions to org.mozilla.fennec_aurora
[task 2018-12-12T06:22:29.128Z] 06:22:29     INFO - adb launch_application: am start -W -n org.mozilla.fennec_aurora/org.mozilla.gecko.BrowserApp -a android.intent.action.VIEW --es env9 MOZ_PROCESS_LOG=/tmp/tmptfWf0opidlog --es env8 MOZ_CRASHREPORTER_NO_REPORT=1 --es args "-no-remote -profile /sdcard/tests/profile --marionette about:blank" --es env3 STYLO_THREADS=4 --es env2 MOZ_HIDE_RESULTS_TABLE=1 --es env1 R_LOG_VERBOSE=1 --es env0 MOZ_CRASHREPORTER=1 --es env7 MOZ_DISABLE_NONLOCAL_CONNECTIONS=1 --es env6 R_LOG_DESTINATION=stderr --es env5 MOZ_CRASHREPORTER_SHUTDOWN=1 --es env4 MOZ_LOG=signaling:3,mtransport:4,DataChannel:4,jsep:4,MediaPipelineFactory:4 --es env10 R_LOG_LEVEL=6
[task 2018-12-12T06:22:31.091Z] 06:22:31     INFO - Starting runner
[task 2018-12-12T06:22:32.580Z] 06:22:32     INFO - TEST-START | /html/browsers/browsing-the-web/read-media/pageload-video.html
[task 2018-12-12T06:22:33.515Z] 06:22:33     INFO - .
[task 2018-12-12T06:22:33.515Z] 06:22:33     INFO - TEST-OK | /html/browsers/browsing-the-web/read-media/pageload-video.html | took 929ms
[task 2018-12-12T06:22:34.880Z] 06:22:34     INFO - Closing logging queue
[task 2018-12-12T06:22:34.881Z] 06:22:34     INFO - queue closed
[task 2018-12-12T06:22:34.898Z] 06:22:34     INFO - Setting up ssl
[task 2018-12-12T06:22:34.943Z] 06:22:34     INFO - certutil | 
[task 2018-12-12T06:22:34.981Z] 06:22:34     INFO - certutil | 
[task 2018-12-12T06:22:35.011Z] 06:22:35     INFO - certutil | 
[task 2018-12-12T06:22:35.011Z] 06:22:35     INFO - Certificate Nickname                                         Trust Attributes
[task 2018-12-12T06:22:35.011Z] 06:22:35     INFO -                                                              SSL,S/MIME,JAR/XPI
[task 2018-12-12T06:22:35.011Z] 06:22:35     INFO - 
[task 2018-12-12T06:22:35.011Z] 06:22:35     INFO - web-platform-tests                                           CT,, 
[task 2018-12-12T06:22:35.012Z] 06:22:35     INFO - 
[task 2018-12-12T06:22:36.931Z] 06:22:36     INFO - adb Granting important runtime permissions to org.mozilla.fennec_aurora
[task 2018-12-12T06:22:38.837Z] 06:22:38     INFO - adb launch_application: am start -W -n org.mozilla.fennec_aurora/org.mozilla.gecko.BrowserApp -a android.intent.action.VIEW --es env9 MOZ_PROCESS_LOG=/tmp/tmpJFczuupidlog --es env8 MOZ_CRASHREPORTER_NO_REPORT=1 --es args "-no-remote -profile /sdcard/tests/profile --marionette about:blank" --es env3 STYLO_THREADS=4 --es env2 MOZ_HIDE_RESULTS_TABLE=1 --es env1 R_LOG_VERBOSE=1 --es env0 MOZ_CRASHREPORTER=1 --es env7 MOZ_DISABLE_NONLOCAL_CONNECTIONS=1 --es env6 R_LOG_DESTINATION=stderr --es env5 MOZ_CRASHREPORTER_SHUTDOWN=1 --es env4 MOZ_LOG=signaling:3,mtransport:4,DataChannel:4,jsep:4,MediaPipelineFactory:4 --es env10 R_LOG_LEVEL=6
See Also: → 1181229
Component: web-platform-tests → DOM
Product: Testing → Core
Version: Version 3 → unspecified
Shall the timeout for all those html/ or html/browsers/ tests get increased because they frequently time out on Android 7.0 x86?
Flags: needinfo?(gbrown)
A successful run only takes a few hundred ms, while the failure happens after 45000 ms, so I think the timeout is plenty!

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=216543630&repo=mozilla-central&lineNumber=1984-1987

[task 2018-12-12T06:33:12.530Z] 06:33:12     INFO - TEST-START | /html/browsers/browsing-the-web/read-media/pageload-image.html
[task 2018-12-12T06:33:12.586Z] 06:33:12     INFO - Closing window 24
[task 2018-12-12T06:33:12.915Z] 06:33:12     INFO - .
[task 2018-12-12T06:33:12.915Z] 06:33:12     INFO - TEST-OK | /html/browsers/browsing-the-web/read-media/pageload-image.html | took 385ms


There is only one failure reported here. Are there related bugs?
Flags: needinfo?(gbrown)
(In reply to Treeherder Bug Filer from comment #0)
> Filed by: rmaries [at] mozilla.com
> 
> https://treeherder.mozilla.org/logviewer.html#?job_id=216543546&repo=mozilla-
> central
> 
> https://queue.taskcluster.net/v1/task/IpztRvYOQO-uz3J0kZNHYA/runs/0/
> artifacts/public/logs/live_backing.log
> 
> [task 2018-12-12T06:21:39.359Z] 06:21:39     INFO - TEST-START |
> /html/browsers/browsing-the-web/read-media/pageload-image.html
> [task 2018-12-12T06:21:39.374Z] 06:21:39     INFO - Closing window 24
> [task 2018-12-12T06:22:24.407Z] 06:22:24     INFO - TEST-UNEXPECTED-TIMEOUT
> | /html/browsers/browsing-the-web/read-media/pageload-image.html | expected
> OK
> [task 2018-12-12T06:22:24.407Z] 06:22:24     INFO - TEST-INFO took 45041ms

The corresponding logcat has some errors:

12-12 06:21:32.450  4772  4772 D GeckoMediaControlAgent: HandleAction, action = action_tab_state_stopped, mediaState = STOPPED
12-12 06:21:32.450  4772  4772 D GeckoMediaControlAgent: onStateChanged, state = STOPPED
12-12 06:21:32.450  4772  4772 D GeckoMediaControlAgent: release
12-12 06:21:32.490  4772  4790 D GeckoViewAutoFill: Clearing auto-fill
12-12 06:21:32.500  4772  4772 D GeckoToolbar: onTabChanged: SELECTED
12-12 06:21:32.500  4772  4772 D GeckoBrowserApp: BrowserApp.onTabChanged: 0: SELECTED
12-12 06:21:32.500  4772  4772 D GeckoToolbar: onTabChanged: UNSELECTED
12-12 06:21:32.500  4772  4772 D GeckoBrowserApp: BrowserApp.onTabChanged: 1: UNSELECTED
12-12 06:21:32.500  4772  4772 D GeckoToolbar: onTabChanged: CLOSED
12-12 06:21:32.500  4772  4772 D GeckoBrowserApp: BrowserApp.onTabChanged: 1: CLOSED
12-12 06:21:32.500  4772  4772 D MediaControlService: onStartCommand
12-12 06:21:32.500  1325  1341 V ActivityManager: Attempted to start a foreground service (ComponentInfo{org.mozilla.fennec_aurora/org.mozilla.gecko.media.MediaControlService}) with a broken notification (no icon: Notification(pri=0 contentView=null vibrate=null sound=null defaults=0x0 flags=0x40 color=0x00000000 vis=PRIVATE))
12-12 06:21:32.530  4772  4790 W GeckoEventDispatcher: No listener for Website:AppLeft
12-12 06:21:32.560  4772  4790 D GeckoScreenOrientation: unlocking
12-12 06:21:32.560  4772  4790 D GeckoViewAutoFill: Clearing auto-fill
12-12 06:21:32.570  4772  4790 E GeckoConsole: [JavaScript Error: "TypeError: this.browser.webProgress is undefined" {file: "chrome://geckoview/content/ext-utils.js" line: 547}]
12-12 06:21:32.650  4772  4772 D GeckoToolbar: onTabChanged: THUMBNAIL
12-12 06:21:32.650  4772  4772 D GeckoBrowserApp: BrowserApp.onTabChanged: 0: THUMBNAIL
12-12 06:21:40.620  4772  4790 W GeckoEventDispatcher: No listener for Session:DataWritten
12-12 06:22:12.490  4772  4790 E GeckoConsole: [JavaScript Error: "TypeError: window.win.timeout is not a function" {file: "tests/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py" line: 77}]
Oh, that does look annoying.

I think these started on Dec 5 on mozilla-central:

https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&searchStr=android%2Cwpt8&tochange=d932537fec3ba7fbfb70ff79568f759d6faefd56&fromchange=89fd36f5fbe5e90bf16563342819fa6700431ccb

:aryx - Can you find someone to narrow the regression window on integration branches? Android wpt does not run on mozilla-inbound or autoland, but can be added with treeherder 'Add new jobs'.
Flags: needinfo?(aryx.bugmail)
Sorry but none of those failing jobs show this test failure. So why do you think that bug 1504756 is the causing one here? Or do I miss something?
Flags: needinfo?(aryx.bugmail)
See comment 2 and comment 4. Bug 1504756 has 7 wpt failures, the previous push 0/18 (and e.g. /html/browsers/the-window-object/apis-for-creating-and-navigating-browsing-contexts-by-name/open-features-tokenization-innerheight-innerwidth.html is part of them).
Flags: needinfo?(aryx.bugmail)
Only a single failure in the last 7 days, so it's not a priority to look at for me.
Don't forget comment 4: This bug is really about intermittent timeouts in Android 7.0 x86 wpt tests, especially in /html/browsers. They are starred against many bugs and collectively are quite frequent, especially when you consider that that android wpt only runs on mozilla-central currently. We'll need to skip all of /html/browsers on android if we don't figure this out.
Summary: Intermittent TEST-UNEXPECTED-TIMEOUT | /html/browsers/browsing-the-web/read-media/pageload-image.html | expected OK → Intermittent TEST-UNEXPECTED-TIMEOUT | /html/browsers/browsing-the-web/read-media/pageload-image.html | expected OK (various Android 7.0 x86 wpt timeouts in /html/browsers)
I pushed a try build with Marionette trace logging enabled. This might help and give some insights what's going on when closing a window/tab.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=9559cf94d6048932f93193edb64f1567825cdfef
Artifact builds seem to be busted on Android 7.0. See bug 1515621. Here a new try push:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=5bfcde4a3e217803edb4ffe2b57875a6fd292a77
Closing the tab/window seems to work fine. But the problem is the call to execute async script:

> 12-20 12:46:29.170  4103  4121 I Gecko   : 1545309989170	Marionette	DEBUG	2 -> [0,90,"WebDriver:SwitchToWindow",{"focus":true,"name":"95"}]
> 12-20 12:46:29.180  4103  4121 I Gecko   : 1545309989180	Marionette	DEBUG	2 <- [1,90,null,{"value":null}]
> 12-20 12:46:29.180  4103  4121 I Gecko   : 1545309989180	Marionette	DEBUG	2 -> [0,91,"WebDriver:CloseWindow",{}]
> 12-20 12:46:29.190  4103  4103 D GeckoToolbar: onTabChanged: LOADED
> 12-20 12:46:29.190  4103  4103 D GeckoBrowserApp: BrowserApp.onTabChanged: 19: LOADED
> 12-20 12:46:29.190  4103  4103 D GeckoToolbar: onTabChanged: PAGE_SHOW
> 12-20 12:46:29.190  4103  4103 D GeckoBrowserApp: BrowserApp.onTabChanged: 19: PAGE_SHOW
> 12-20 12:46:29.190  4103  4103 I GeckoTabs: zerdatime 601700 - page load stop
> 12-20 12:46:29.190  4103  4103 D GeckoToolbar: onTabChanged: STOP
> 12-20 12:46:29.190  4103  4103 D GeckoBrowserApp: BrowserApp.onTabChanged: 19: STOP
> 12-20 12:46:29.190  4103  4103 D GeckoToolbar: onTabChanged: CLOSED
> 12-20 12:46:29.190  4103  4103 D GeckoBrowserApp: BrowserApp.onTabChanged: 19: CLOSED
> 12-20 12:46:29.190  4103  4103 D GeckoToolbar: onTabChanged: MENU_UPDATED
> 12-20 12:46:29.190  4103  4103 D GeckoBrowserApp: BrowserApp.onTabChanged: 19: MENU_UPDATED
> 12-20 12:46:29.200  4103  4121 I Gecko   : 1545309989200	Marionette	TRACE	Received DOM event TabClose for [object XULFrameElement]
> 12-20 12:46:29.200  4103  4121 I Gecko   : 1545309989200	Marionette	TRACE	Received observer notification message-manager-disconnect
> 12-20 12:46:29.220  4103  4121 I Gecko   : 1545309989220	Marionette	DEBUG	2 <- [1,91,null,["16","95"]]
> 12-20 12:46:29.220  4103  4121 I Gecko   : 1545309989220	Marionette	DEBUG	2 -> [0,92,"WebDriver:SwitchToWindow",{"focus":true,"name":"98"}]
> 12-20 12:46:29.220  4103  4121 I Gecko   : 1545309989220	Marionette	DEBUG	2 <- [1,92,{"error":"no such window","message":"Unable to locate window: 98","stacktrace":"WebDriverError@chrome://marionette/cont ... et@chrome://marionette/content/server.js:235:8\n_onJSONObjectReady/<@chrome://marionette/content/transport.js:493:9\n"},null]
> 12-20 12:46:29.220  4103  4121 I Gecko   : 1545309989220	Marionette	DEBUG	2 -> [0,93,"WebDriver:SwitchToWindow",{"focus":true,"name":"16"}]
> 12-20 12:46:29.220  4103  4121 I Gecko   : 1545309989220	Marionette	DEBUG	2 <- [1,93,null,{"value":null}]
> 12-20 12:46:29.230  4103  4121 I Gecko   : 1545309989230	Marionette	DEBUG	2 -> [0,94,"WebDriver:ExecuteAsyncScript",{"scriptTimeout":null,"newSandbox":false,"args":[],"filename":"tests/web-platform/tests/ ...  != null) {\n  window.timer = setTimeout(function() {\n    window.win.timeout();\n  }, 40000);\n}","sandbox":null,"line":60}]
> 1
[..]
> 12-20 12:47:14.240  4103  4121 I Gecko   : 1545310034240	Marionette	DEBUG	2 <- [1,94,{"error":"script timeout","message":"Timed out after 45000 ms","stacktrace":"WebDriverError@chrome://marionette/content ... :419:5\ntimeoutHandler@chrome://marionette/content/evaluate.js:100:35\nnotify@resource://gre/modules/Timer.jsm:42:7\n"},null]

The executor in this case should be Marionette. So I'm not sure which kind of script is getting run here. I only found a reference for the webdriver executor:

https://searchfox.org/mozilla-central/source/testing/web-platform/tests/tools/wptrunner/wptrunner/executors/testharness_webdriver.js#16

James, can you help?
Flags: needinfo?(james)
Backing out each of my commits from bug 1504756 seem to have fixed it. Here a try build:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=671ce978ffee415288adc8480cc1a4b9af8a2398&selectedJob=218124091

I will request a backout of my patch on bug 1504756 given that I won't have the time in the next 2 weeks to figure that out.
With the backout all the failures should be gone now. Sebastian, can you please verify?
Flags: needinfo?(aryx.bugmail)
I actually checked again and all the failures are gone on mozilla-central.
Assignee: nobody → hskupin
Status: NEW → RESOLVED
Closed: 5 years ago
status-firefox65: --- → fixed
status-firefox66: --- → fixed
Component: DOM → Marionette
Flags: needinfo?(james)
Flags: needinfo?(aryx.bugmail)
Keywords: regression
Product: Core → Testing
Resolution: --- → FIXED
(In reply to Sebastian Hengst [PTO-ish; back 2019-01-02] [:aryx] (needinfo on intermittent or backout) from comment #4)
> From
> https://bugzilla.mozilla.org/buglist.
> cgi?short_desc_type=allwordssubstr&chfieldto=Now&chfield=%5BBug%20creation%5D
> &short_desc=timeout%20%2Fhtml%2Fbrowsers%2F&list_id=14469667&chfieldfrom=90d&
> query_format=advanced 6/6 I checked were for Android 7.0 x86.

Can someone from the sheriffs go through this list and check which of the bugs we can also close? At least some seem to have filed already before my patch landed.
Flags: needinfo?(sheriffs)
Found and closed as duplicate 22 bugs from the list that were for Android 7.0 x86
Flags: needinfo?(sheriffs)
Thanks!

Recent failure https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&resultStatus=testfailed%2Cbusted%2Cexception&selectedJob=250238986&searchStr=android%2C7.0%2Cx86-64%2Copt%2Cweb%2Cplatform%2Ctests%2Ctest-android-em-7.0-x86_64%2Fopt-web-platform-tests-e10s-7%2Cw%28wpt7%29&revision=d5226e5dc522af70e16172029e8c8286e2a8674c

Failure log https://treeherder.mozilla.org/logviewer.html#?job_id=250238986&repo=mozilla-central

Part of that log
[task 2019-06-05T21:59:58.340Z] 21:59:58 INFO - TEST-START | /html/browsers/browsing-the-web/unloading-documents/002.html
[task 2019-06-05T21:59:58.343Z] 21:59:58 INFO - Closing window 2147483664
[task 2019-06-05T21:59:58.359Z] 21:59:58 INFO - Closing window 2147483667
[task 2019-06-05T22:05:58.454Z] 22:05:58 INFO - IOError on command, setting status to CRASH
[task 2019-06-05T22:05:58.678Z] 22:05:58 INFO - TEST-UNEXPECTED-CRASH | /html/browsers/browsing-the-web/unloading-documents/002.html | expected OK
[task 2019-06-05T22:05:58.678Z] 22:05:58 INFO - TEST-INFO took 360338ms
[task 2019-06-05T22:05:59.340Z] 22:05:59 INFO - Closing logging queue
[task 2019-06-05T22:05:59.340Z] 22:05:59 INFO - queue closed
[task 2019-06-05T22:05:59.348Z] 22:05:59 INFO - Setting up ssl
[task 2019-06-05T22:05:59.368Z] 22:05:59 INFO - certutil |
[task 2019-06-05T22:05:59.383Z] 22:05:59 INFO - certutil |
[task 2019-06-05T22:05:59.399Z] 22:05:59 INFO - certutil |
[task 2019-06-05T22:05:59.399Z] 22:05:59 INFO - Certificate Nickname Trust Attributes
[task 2019-06-05T22:05:59.399Z] 22:05:59 INFO - SSL,S/MIME,JAR/XPI
[task 2019-06-05T22:05:59.399Z] 22:05:59 INFO -
[task 2019-06-05T22:05:59.399Z] 22:05:59 INFO - web-platform-tests CT,,
[task 2019-06-05T22:05:59.399Z] 22:05:59 INFO -
[task 2019-06-05T22:06:01.202Z] 22:06:01 INFO - adb Granting important runtime permissions to org.mozilla.geckoview.test
[task 2019-06-05T22:06:03.098Z] 22:06:03 INFO - adb launch_application: am start -W -n org.mozilla.geckoview.test/org.mozilla.geckoview.test.TestRunnerActivity -a android.intent.action.MAIN --es env9 MOZ_PROCESS_LOG=/tmp/tmpAzsbzppidlog --es env8 MOZ_CRASHREPORTER_NO_REPORT=1 --es args "-no-remote -profile /sdcard/tests/profile --marionette about:blank" --es env3 STYLO_THREADS=4 --es env2 MOZ_HIDE_RESULTS_TABLE=1 --es env1 R_LOG_VERBOSE=1 --es env0 MOZ_CRASHREPORTER=1 --es env7 MOZ_DISABLE_NONLOCAL_CONNECTIONS=1 --es env6 R_LOG_DESTINATION=stderr --es env5 MOZ_CRASHREPORTER_SHUTDOWN=1 --es env4 MOZ_LOG=signaling:3,mtransport:4,DataChannel:4,jsep:4 --ez use_multiprocess True --es env10 R_LOG_LEVEL=6
[task 2019-06-05T22:06:05.160Z] 22:06:05 INFO - Starting runner
[task 2019-06-05T22:06:05.621Z] 22:06:05 INFO - TEST-START | /html/browsers/browsing-the-web/unloading-documents/003.html

Status: RESOLVED → REOPENED
Resolution: FIXED → ---

This was a test failure caused by a bad commit which then was backed-out. So please do not reopen such a fixed bug, but instead file a new one. Thanks.

Status: REOPENED → RESOLVED
Closed: 5 years ago → 5 years ago
Flags: needinfo?(aiakab)
Resolution: --- → FIXED
Target Milestone: --- → mozilla66

Thank you for the info. Next time will create a new bug.

Flags: needinfo?(aiakab)
Product: Testing → Remote Protocol
Moving bug to Testing::Marionette Client and Harness component per bug 1815831.
Component: Marionette → Marionette Client and Harness
Product: Remote Protocol → Testing
You need to log in before you can comment on or make changes to this bug.