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

Shall the timeout for all those html/ or html/browsers/ tests get increased because they frequently time out on Android 7.0 x86?

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?

(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}]

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.

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'.

Our backfills point to bug 1504756: https://treeherder.mozilla.org/#/jobs?repo=autoland&resultStatus=pending%2Crunning%2Csuccess%2Ctestfailed%2Cbusted%2Cexception&searchStr=android%2C7.0%2Cx86&tochange=d7d78e79f0b34d84ba17ebd5311989cee49b5b6c&fromchange=795d02901ad0a295b7f741ccf8a726f184a2799d Please take a look when you are a back.

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?

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).

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.

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?

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?

I actually checked again and all the failures are gone on mozilla-central.

(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.

Found and closed as duplicate 22 bugs from the list that were for Android 7.0 x86

Thanks!

Moving bug to Testing::Marionette Client and Harness component per bug 1815831.