1534732 - Intermittent TEST-UNEXPECTED-FAIL | application timed out after 370 seconds with no output -- in Android x86 7.0 tests

Status: RESOLVED DUPLICATE of bug 1556058

(Firefox for Android Graveyard :: Testing, defect, P1)

Description

[Geoff Brown [:gbrown]]

+++ This bug was initially created as a clone of Bug #1500977 +++

Bug 1500977 has several instances of this error in Android x86 7.0 mochitests. It looks like there is a hang on harness startup: No tests are run, but screenshots show mochitest loaded.

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=232967124&repo=autoland&lineNumber=4571
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=232904155&repo=try&lineNumber=3139
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=232881498&repo=mozilla-central&lineNumber=1819

Comment 1

[Geoff Brown [:gbrown]]

Logcats sometimes contain:

03-09 10:39:53.680 4508 4523 W Web Content: [JavaScript Warning: "Loading failed for the <script> with source “http://mochi.test:8888/tests/SimpleTest/StructuredLog.jsmâ€." {file: "http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&logFile=%2Fsdcard%2Ftests%2Flogs%2Fmochitest.log&fileLevel=INFO&consoleLevel=INFO&hideResultsTable=1&manifestFile=tests.json&dumpOutputDirectory=%2Fsdcard%2Ftests" line: 3}]
03-09 10:40:29.800 4508 4523 E Web Content: [JavaScript Error: "ReferenceError: StructuredFormatter is not defined" {file: "http://mochi.test:8888/tests/SimpleTest/TestRunner.js" line: 103}]
03-09 10:40:29.800 4508 4523 E Web Content: @http://mochi.test:8888/tests/SimpleTest/TestRunner.js:103:1
03-09 10:40:29.850 4508 4523 W Web Content: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://specialpowers/MozillaLogger.js" line: 91}]
03-09 10:40:29.850 4508 4523 D GeckoViewNavigation[C]: shouldLoadURI about:blank
03-09 10:40:29.860 4508 4523 D GeckoViewContent[C]: handleEvent: DOMTitleChanged
03-09 10:40:29.860 4508 4523 D GeckoViewContent[C]: handleEvent: pageshow
03-09 10:40:29.860 4508 4523 D GeckoViewContent[C]: handleEvent: pageshow
03-09 10:40:29.880 4508 4523 I GeckoDump: TEST-UNEXPECTED-FAIL: manifestLibrary.js | error parsing http://mochi.test:8888/tests.json (TypeError: TestRunner.setParameterInfo is not a function)

Comment 2

[Geoff Brown [:gbrown]]

A variation:

03-13 23:04:40.420  3711  3726 D GeckoViewNavigation[C]: shouldLoadURI http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&logFile=%2Fsdcard%2Ftests%2Flogs%2Fmochitest.log&fileLevel=INFO&consoleLevel=INFO&hideResultsTable=1&manifestFile=tests.json&dumpOutputDirectory=%2Fsdcard%2Ftests
03-13 23:04:40.470  3711  3726 D GeckoViewSelectionAction[C]: handleEvent: visibilitychange
03-13 23:04:40.470  3711  3726 D GeckoViewContent[C]: handleEvent: pagehide
03-13 23:04:40.470  3711  3726 D GeckoViewAutoFill: Clearing auto-fill
03-13 23:04:40.470  3652  3667 D GeckoViewNavigation: onLocationChange
03-13 23:04:40.510  3711  3726 D GeckoViewContent[C]: handleEvent: DOMTitleChanged
03-13 23:04:54.560  3711  3726 W Web Content: [JavaScript Warning: "Loading failed for the <script> with source “http://mochi.test:8888/tests/SimpleTest/TestRunner.js”." {file: "http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&logFile=%2Fsdcard%2Ftests%2Flogs%2Fmochitest.log&fileLevel=INFO&consoleLevel=INFO&hideResultsTable=1&manifestFile=tests.json&dumpOutputDirectory=%2Fsdcard%2Ftests" line: 6}]
03-13 23:04:54.560  3711  3726 W Web Content: [JavaScript Warning: "Loading failed for the <script> with source “http://mochi.test:8888/tests/SimpleTest/MozillaLogger.js”." {file: "http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&logFile=%2Fsdcard%2Ftests%2Flogs%2Fmochitest.log&fileLevel=INFO&consoleLevel=INFO&hideResultsTable=1&manifestFile=tests.json&dumpOutputDirectory=%2Fsdcard%2Ftests" line: 7}]
03-13 23:04:54.560  3711  3726 W Web Content: [JavaScript Warning: "Loading failed for the <script> with source “http://mochi.test:8888/chunkifyTests.js”." {file: "http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&logFile=%2Fsdcard%2Ftests%2Flogs%2Fmochitest.log&fileLevel=INFO&consoleLevel=INFO&hideResultsTable=1&manifestFile=tests.json&dumpOutputDirectory=%2Fsdcard%2Ftests" line: 8}]
03-13 23:05:04.840  3711  3726 W Web Content: [JavaScript Warning: "Loading failed for the <script> with source “http://mochi.test:8888/tests/SimpleTest/setup.js”." {file: "http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&logFile=%2Fsdcard%2Ftests%2Flogs%2Fmochitest.log&fileLevel=INFO&consoleLevel=INFO&hideResultsTable=1&manifestFile=tests.json&dumpOutputDirectory=%2Fsdcard%2Ftests" line: 10}]
03-13 23:05:04.840  3711  3726 E Web Content: [JavaScript Error: "ReferenceError: hookup is not defined" {file: "http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&logFile=%2Fsdcard%2Ftests%2Flogs%2Fmochitest.log&fileLevel=INFO&consoleLevel=INFO&hideResultsTable=1&manifestFile=tests.json&dumpOutputDirectory=%2Fsdcard%2Ftests" line: 11}]
03-13 23:05:04.840  3711  3726 E Web Content: @http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&logFile=%2Fsdcard%2Ftests%2Flogs%2Fmochitest.log&fileLevel=INFO&consoleLevel=INFO&hideResultsTable=1&manifestFile=tests.json&dumpOutputDirectory=%2Fsdcard%2Ftests:11:1
03-13 23:05:04.840  3711  3726 D GeckoViewNavigation[C]: shouldLoadURI about:blank
03-13 23:05:04.850  3711  3726 D GeckoViewContent[C]: handleEvent: DOMTitleChanged
03-13 23:05:04.850  3711  3726 D GeckoViewContent[C]: handleEvent: pageshow
03-13 23:05:04.850  3711  3726 D GeckoViewContent[C]: handleEvent: pageshow
03-13 23:05:39.950  3652  3667 E GeckoConsole: [JavaScript Error: "Polling for changes failed: Unexpected content-type "text/html;charset=utf-8"." {file: "resource://services-settings/remote-settings.js" line: 203}]
03-13 23:05:39.950  3652  3667 E GeckoConsole: remoteSettingsFunction/remoteSettings.pollChanges@resource://services-settings/remote-settings.js:203:13

Comment 3

[Geoff Brown [:gbrown]]

03-15 19:18:30.100  8422  8437 D GeckoViewNavigation[C]: shouldLoadURI http://mochi.test:8888/tests/editor/libeditor/tests/test_abs_positioner_appearance.html
03-15 19:18:30.110  8422  8437 D GeckoViewSelectionAction[C]: handleEvent: visibilitychange
03-15 19:18:30.120  8422  8437 D GeckoViewContent[C]: handleEvent: pagehide
03-15 19:18:30.120  8363  8378 D GeckoViewNavigation: onLocationChange
03-15 19:18:30.130  8422  8437 D GeckoViewContent[C]: handleEvent: DOMTitleChanged
03-15 19:18:44.150  8422  8437 W Web Content: [JavaScript Warning: "Loading failed for the <script> with source “http://mochi.test:8888/tests/SimpleTest/SimpleTest.js”." {file: "http://mochi.test:8888/tests/editor/libeditor/tests/test_abs_positioner_appearance.html" line: 5}]
03-15 19:18:44.160  8422  8437 W Web Content: [JavaScript Warning: "Loading failed for the <script> with source “http://mochi.test:8888/tests/SimpleTest/EventUtils.js”." {file: "http://mochi.test:8888/tests/editor/libeditor/tests/test_abs_positioner_appearance.html" line: 6}]
03-15 19:18:44.160  8422  8437 E Web Content: [JavaScript Error: "ReferenceError: SimpleTest is not defined" {file: "http://mochi.test:8888/tests/editor/libeditor/tests/test_abs_positioner_appearance.html" line: 23}]
03-15 19:18:44.160  8422  8437 E Web Content: @http://mochi.test:8888/tests/editor/libeditor/tests/test_abs_positioner_appearance.html:23:1
03-15 19:18:44.160  8422  8437 W Web Content: [JavaScript Warning: "The character encoding of a framed document was not declared. The document may appear different if viewed without the document framing it." {file: "http://mochi.test:8888/tests/editor/libeditor/tests/test_abs_positioner_appearance.html" line: 0}]
03-15 19:18:54.430  8422  8437 D GeckoViewContent[C]: handleEvent: pageshow
03-15 19:19:33.510  8363  8378 E GeckoConsole: [JavaScript Error: "Polling for changes failed: Unexpected content-type "text/html;charset=utf-8"." {file: "resource://services-settings/remote-settings.js" line: 203}]
03-15 19:19:33.510  8363  8378 E GeckoConsole: remoteSettingsFunction/remoteSettings.pollChanges@resource://services-settings/remote-settings.js:203:13
03-15 19:24:55.010  1323  1336 I UsageStatsService: User[0] Flushing usage stats to disk
03-15 19:25:00.070  8363  8369 I art     : Thread[3,tid=8369,WaitingInMainSignalCatcherLoop,Thread*=0x720970594e00,peer=0x12c50a60,"Signal Catcher"]: reacting to signal 3
03-15 19:25:00.070  8363  8369 I art     : 
03-15 19:25:00.100  8363  8369 E art     : Unable to open stack trace file '/data/anr/traces.txt': Permission denied
03-15 19:25:08.360  8363  8363 W google-breakpad: ExceptionHandler::GenerateDump cloned child 

Comment 4

[Geoff Brown [:gbrown]]

In comment 1 and comment 2, the "Loading failed for the <script> with source..." failures seem to originate here:

https://searchfox.org/mozilla-central/rev/7abb9117c8500ed20833746c9f8e800fce3a4688/testing/mochitest/server.js#664-681

Why would those fail, intermittently? How can I get more information about the load failure?

Comment 5

[Geoff Brown [:gbrown]]

It looks like the same sort of failure can occur during the first test (previous examples were before any tests start to run):

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=235012446&repo=try&lineNumber=4513

https://taskcluster-artifacts.net/PFDOennwTKKUuOw-Ale_Yg/0/public/test_info//logcat-emulator-5554.log

03-20 17:01:04.850  7835  7850 D GeckoViewNavigation[C]: loadURI: uri=http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&logFile=%2Fsdcard%2Ftests%2Flogs%2Fmochitest.log&fileLevel=INFO&consoleLevel=INFO&hideResultsTable=1&manifestFile=tests.json&dumpOutputDirectory=%2Fsdcard%2Ftests where=1 flags=0 tp=moz-nullprincipal:{20d83209-bb37-4229-8442-0a56202c7e8a}
03-20 17:01:04.850  7835  7850 D GeckoViewSettings[C]: onSettingsUpdate {"useMultiprocess":true,"chromeUri":null,"screenId":0,"userAgentOverride":null,"allowJavascript":true,"userAgentMode":0,"viewportMode":0,"useTrackingProtection":false,"suspendMediaWhenInactive":false,"usePrivateMode":false,"displayMode":0,"fullAccessibilityTree":false}
03-20 17:01:04.850  7835  7850 D GeckoViewContent[C]: handleEvent: DOMTitleChanged
03-20 17:01:04.850  7835  7850 D GeckoViewContent[C]: handleEvent: pageshow
03-20 17:01:04.860  7835  7850 D GeckoViewNavigation[C]: shouldLoadURI http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&logFile=%2Fsdcard%2Ftests%2Flogs%2Fmochitest.log&fileLevel=INFO&consoleLevel=INFO&hideResultsTable=1&manifestFile=tests.json&dumpOutputDirectory=%2Fsdcard%2Ftests
03-20 17:01:04.870  7835  7835 D GeckoNetworkManager: New network state: UP, CELLULAR, CELL_4G
03-20 17:01:04.910  7835  7850 D GeckoViewSelectionAction[C]: handleEvent: visibilitychange
03-20 17:01:04.910  7835  7850 D GeckoViewContent[C]: handleEvent: pagehide
03-20 17:01:04.910  7835  7850 D GeckoViewAutoFill: Clearing auto-fill
03-20 17:01:04.920  7835  7850 D GeckoViewContent[C]: handleEvent: DOMTitleChanged
03-20 17:01:04.940  7775  7790 D GeckoViewNavigation: onLocationChange
03-20 17:01:05.020  7835  7850 W Web Content: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://specialpowers/MozillaLogger.js" line: 91}]
03-20 17:01:05.030  7835  7850 D GeckoViewNavigation[C]: shouldLoadURI about:blank
03-20 17:01:05.040  7835  7850 D GeckoViewContent[C]: handleEvent: DOMTitleChanged
03-20 17:01:05.040  7835  7850 D GeckoViewContent[C]: handleEvent: pageshow
03-20 17:01:05.040  7835  7850 D GeckoViewContent[C]: handleEvent: pageshow
03-20 17:01:05.060  7835  7850 I GeckoDump: ⰲ겿{"action":"log","time":1553101265060,"thread":null,"pid":null,"source":"mochitest","level":"INFO","message":"SimpleTest START","js_source":"TestRunner.js"}ⰲ겿
03-20 17:01:05.060  7835  7850 D GeckoViewNavigation[C]: shouldLoadURI about:blank
03-20 17:01:05.060  7835  7850 I GeckoDump: ⰲ겿{"action":"test_start","time":1553101265060,"thread":null,"pid":null,"source":"mochitest","test":"/tests/dom/crypto/test/test_WebCrypto.html","js_source":"TestRunner.js"}ⰲ겿
03-20 17:01:05.070  7835  7850 D GeckoViewSelectionAction[C]: handleEvent: visibilitychange
03-20 17:01:05.070  7835  7850 D GeckoViewContent[C]: handleEvent: pagehide
03-20 17:01:05.080  7835  7850 D GeckoViewContent[C]: handleEvent: DOMTitleChanged
03-20 17:01:05.080  7835  7850 D GeckoViewContent[C]: handleEvent: pageshow
03-20 17:01:06.080  7835  7850 D GeckoViewNavigation[C]: shouldLoadURI http://mochi.test:8888/tests/dom/crypto/test/test_WebCrypto.html
03-20 17:01:06.090  7835  7850 D GeckoViewSelectionAction[C]: handleEvent: visibilitychange
03-20 17:01:06.090  7835  7850 D GeckoViewContent[C]: handleEvent: pagehide
03-20 17:01:06.100  7775  7790 D GeckoViewNavigation: onLocationChange
03-20 17:01:06.100  7835  7850 D GeckoViewContent[C]: handleEvent: DOMTitleChanged
03-20 17:01:20.140  7835  7850 W Web Content: [JavaScript Warning: "Loading failed for the <script> with source “http://mochi.test:8888/tests/SimpleTest/SimpleTest.js”." {file: "http://mochi.test:8888/tests/dom/crypto/test/test_WebCrypto.html" line: 8}]
03-20 17:01:30.430  7835  7850 W Web Content: [JavaScript Warning: "Loading failed for the <script> with source “http://mochi.test:8888/tests/dom/crypto/test/simpledb.js”." {file: "http://mochi.test:8888/tests/dom/crypto/test/test_WebCrypto.html" line: 14}]
03-20 17:02:00.050  7835  7850 D GeckoViewNavigation[C]: shouldLoadURI about:blank
03-20 17:02:00.070  7835  7850 D GeckoViewContent[C]: handleEvent: DOMTitleChanged
03-20 17:02:00.070  7835  7850 D GeckoViewContent[C]: handleEvent: pageshow
03-20 17:02:00.090  7835  7850 D GeckoViewContent[C]: handleEvent: pageshow
03-20 17:02:04.330  7775  7790 E GeckoConsole: [JavaScript Error: "Polling for changes failed: Unexpected content-type "text/html;charset=utf-8"." {file: "resource://services-settings/remote-settings.js" line: 203}]
03-20 17:02:04.330  7775  7790 E GeckoConsole: remoteSettingsFunction/remoteSettings.pollChanges@resource://services-settings/remote-settings.js:203:13
03-20 17:07:42.470  1314  1328 I UsageStatsService: User[0] Flushing usage stats to disk

Comment 6

[Geoff Brown [:gbrown]]

(In reply to Geoff Brown [:gbrown] from comment #4)

How can I get more information about the load failure?

With the help of bug 1536640 I am trying to collect a MOZ_LOG with ScriptLoader. In preliminary results, I think I am seeing a correlation with "Using preload request" in the ScriptLoader log, for scripts that failed to load.

Comment 7

[Geoff Brown [:gbrown]]

Try run with ScriptLoader MOZ_LOGs:

https://treeherder.mozilla.org/#/jobs?repo=try&tier=1%2C2%2C3&revision=e25b1c68a1acc156e9d0937ad2cafe7176cf30bf

Example:

https://treeherder.mozilla.org/logviewer.html#?job_id=235292498&repo=try

[task 2019-03-21T22:39:30.745Z] 22:39:30     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_UPLOAD_DIR=/sdcard/tests/mozlog --es env8 R_LOG_DESTINATION=stderr --es args "-no-remote -profile /sdcard/tests/profile//" --es env3 MOZ_LOG=ScriptLoader:5,sync,timestamp --es env2 R_LOG_VERBOSE=1 --es env1 XPCOM_DEBUG_BREAK=stack --es env0 MOZ_CRASHREPORTER=1 --es env7 MOZ_LOG_FILE=/sdcard/tests/mozlog/moz-pid=%PID-uid=947d7a28-501f-4700-9ddb-493fe374fb03.log --es env6 MOZ_CRASHREPORTER_SHUTDOWN=1 --es env5 MOZ_IN_AUTOMATION=1 --es env4 MOZ_DISABLE_NONLOCAL_CONNECTIONS=1 --ez use_multiprocess True --es env13 DISABLE_UNSAFE_CPOW_WARNINGS=1 --es env12 R_LOG_LEVEL=6 --es env11 MOZ_HIDE_RESULTS_TABLE=1 --es env10 MOZ_CRASHREPORTER_NO_REPORT=1 -d "http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&logFile=%2Fsdcard%2Ftests%2Flogs%2Fmochitest.log&fileLevel=INFO&consoleLevel=INFO&hideResultsTable=1&manifestFile=tests.json&dumpOutputDirectory=%2Fsdcard%2Ftests"
[task 2019-03-21T22:39:31.754Z] 22:39:31     INFO -  remoteautomation.py | Application pid: 9063
[task 2019-03-21T22:46:00.089Z] 22:46:00     INFO -  wait for org.mozilla.geckoview.test complete; top activity=org.mozilla.geckoview.test
[task 2019-03-21T22:46:00.199Z] 22:46:00     INFO -  org.mozilla.geckoview.test unexpectedly found running. Killing...
[task 2019-03-21T22:46:00.200Z] 22:46:00     INFO -  TEST-INFO | started process screentopng
[task 2019-03-21T22:46:00.640Z] 22:46:00     INFO -  TEST-INFO | screentopng: exit 0
[task 2019-03-21T22:46:15.001Z] 22:46:15  WARNING -  TEST-UNEXPECTED-FAIL | remoteautomation.py | application timed out after 370 seconds with no output

Logcat for that:

https://taskcluster-artifacts.net/Eg6NcrlZRaKrbW4hWqvFXg/0/public/test_info//logcat-emulator-5554.log

03-21 22:39:19.520  9123  9138 D GeckoViewNavigation[C]: shouldLoadURI http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&logFile=%2Fsdcard%2Ftests%2Flogs%2Fmochitest.log&fileLevel=INFO&consoleLevel=INFO&hideResultsTable=1&manifestFile=tests.json&dumpOutputDirectory=%2Fsdcard%2Ftests
03-21 22:39:19.560  9123  9138 D GeckoViewSelectionAction[C]: handleEvent: visibilitychange
03-21 22:39:19.560  9123  9138 D GeckoViewContent[C]: handleEvent: pagehide
03-21 22:39:19.560  9123  9138 D GeckoViewAutoFill: Clearing auto-fill
03-21 22:39:19.560  9063  9079 D GeckoViewNavigation: onLocationChange
03-21 22:39:19.560  9123  9138 D GeckoViewContent[C]: handleEvent: DOMTitleChanged
03-21 22:39:33.660  9123  9138 W Web Content: [JavaScript Warning: "Loading failed for the <script> with source “http://mochi.test:8888/tests/SimpleTest/LogController.js”." {file: "http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&logFile=%2Fsdcard%2Ftests%2Flogs%2Fmochitest.log&fileLevel=INFO&consoleLevel=INFO&hideResultsTable=1&manifestFile=tests.json&dumpOutputDirectory=%2Fsdcard%2Ftests" line: 4}]
03-21 22:39:33.670  9123  9138 W Web Content: [JavaScript Warning: "Loading failed for the <script> with source “http://mochi.test:8888/tests/SimpleTest/MemoryStats.js”." {file: "http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&logFile=%2Fsdcard%2Ftests%2Flogs%2Fmochitest.log&fileLevel=INFO&consoleLevel=INFO&hideResultsTable=1&manifestFile=tests.json&dumpOutputDirectory=%2Fsdcard%2Ftests" line: 5}]
03-21 22:39:43.950  9123  9138 W Web Content: [JavaScript Warning: "Loading failed for the <script> with source “http://mochi.test:8888/tests/SimpleTest/TestRunner.js”." {file: "http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&logFile=%2Fsdcard%2Ftests%2Flogs%2Fmochitest.log&fileLevel=INFO&consoleLevel=INFO&hideResultsTable=1&manifestFile=tests.json&dumpOutputDirectory=%2Fsdcard%2Ftests" line: 6}]
03-21 22:40:13.610  9123  9138 E Web Content: [JavaScript Error: "ReferenceError: TestRunner is not defined" {file: "http://mochi.test:8888/tests/SimpleTest/setup.js" line: 9}]
03-21 22:40:13.610  9123  9138 E Web Content: @http://mochi.test:8888/tests/SimpleTest/setup.js:9:1
03-21 22:40:13.620  9123  9138 D GeckoViewNavigation[C]: shouldLoadURI about:blank

MOZ_LOG:

https://queue.taskcluster.net/v1/task/Eg6NcrlZRaKrbW4hWqvFXg/runs/0/artifacts/public/test_info//mozLogs.zip

For PID 9123:

...
2019-03-21 22:39:19.570000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d765834c100): Created preload request for http://mochi.test:8888/tests/SimpleTest/LogController.js
2019-03-21 22:39:19.570000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d765834c100): Start Load (url = http://mochi.test:8888/tests/SimpleTest/LogController.js)
2019-03-21 22:39:19.570000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d765834c100): Maybe request bytecode
2019-03-21 22:39:19.570000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d765834c100): mode=0 tracking=0
2019-03-21 22:39:19.570000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d765834c400): Created preload request for http://mochi.test:8888/tests/SimpleTest/MemoryStats.js
2019-03-21 22:39:19.570000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d765834c400): Start Load (url = http://mochi.test:8888/tests/SimpleTest/MemoryStats.js)
2019-03-21 22:39:19.570000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d765834c400): Maybe request bytecode
2019-03-21 22:39:19.570000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d765834c400): mode=0 tracking=0
2019-03-21 22:39:19.570000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d765834c700): Created preload request for http://mochi.test:8888/tests/SimpleTest/TestRunner.js
2019-03-21 22:39:19.570000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d765834c700): Start Load (url = http://mochi.test:8888/tests/SimpleTest/TestRunner.js)
2019-03-21 22:39:19.570000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d765834c700): Maybe request bytecode
2019-03-21 22:39:19.570000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d765834c700): mode=0 tracking=0
2019-03-21 22:39:19.570000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d765834ca00): Created preload request for http://mochi.test:8888/tests/SimpleTest/MozillaLogger.js
2019-03-21 22:39:19.570000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d765834ca00): Start Load (url = http://mochi.test:8888/tests/SimpleTest/MozillaLogger.js)
2019-03-21 22:39:19.570000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d765834ca00): Maybe request bytecode
2019-03-21 22:39:19.570000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d765834ca00): mode=0 tracking=0
2019-03-21 22:39:19.570000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d765834cd00): Created preload request for http://mochi.test:8888/chunkifyTests.js
2019-03-21 22:39:19.570000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d765834cd00): Start Load (url = http://mochi.test:8888/chunkifyTests.js)
2019-03-21 22:39:19.570000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d765834cd00): Maybe request bytecode
2019-03-21 22:39:19.570000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d765834cd00): mode=0 tracking=0
2019-03-21 22:39:19.570000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d7658353080): Created preload request for http://mochi.test:8888/manifestLibrary.js
2019-03-21 22:39:19.570000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d7658353080): Start Load (url = http://mochi.test:8888/manifestLibrary.js)
2019-03-21 22:39:19.570000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d7658353080): Maybe request bytecode
2019-03-21 22:39:19.570000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d7658353080): mode=0 tracking=0
2019-03-21 22:39:19.570000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d7658353380): Created preload request for http://mochi.test:8888/tests/SimpleTest/setup.js
2019-03-21 22:39:19.570000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d7658353380): Start Load (url = http://mochi.test:8888/tests/SimpleTest/setup.js)
2019-03-21 22:39:19.570000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d7658353380): Maybe request bytecode
2019-03-21 22:39:19.570000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d7658353380): mode=0 tracking=0
2019-03-21 22:39:19.640000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d7658335200): Stream complete (url = http://mochi.test:8888/tests/SimpleTest/StructuredLog.jsm)
2019-03-21 22:39:19.640000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d7658335200): Source length = 6418
2019-03-21 22:39:19.640000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d7658335200): nsICacheInfoChannel = 0x7d765830bdc0
2019-03-21 22:39:19.640000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d7658335200): Process request
2019-03-21 22:39:19.640000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d7658335200): Bytecode-cache: strategy = 0.
2019-03-21 22:39:19.640000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d7658335200): Bytecode-cache: fetchCount = 1.
2019-03-21 22:39:19.640000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d7658335200): Compile And Exec
2019-03-21 22:39:19.640000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d7658335200): Bytecode-cache: disabled (rv = 0, script = 0x2e23c9608040)
2019-03-21 22:39:19.640000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d7658335200): ScriptLoader = 0x7d7658602d60
2019-03-21 22:39:19.640000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoader (0x7d7658602d60): Wait for the load-end event to fire.
2019-03-21 22:39:19.640000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoader (0x7d7658602d60): Process external script for element 0x7d7658337a80
2019-03-21 22:39:19.640000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d765834c100): Using preload request
2019-03-21 22:39:19.670000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d765834cd00): Stream complete (url = http://mochi.test:8888/chunkifyTests.js)
2019-03-21 22:39:19.670000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d765834cd00): Source length = 873
2019-03-21 22:39:19.670000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d765834cd00): nsICacheInfoChannel = 0x7d765830e5c0
2019-03-21 22:39:33.660000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d765834c100): Stream complete (url = http://mochi.test:8888/tests/SimpleTest/LogController.js)
2019-03-21 22:39:33.660000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d765834c100): Source length = 0
2019-03-21 22:39:33.660000 UTC - [Child 9123: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7d765834c100): nsICacheInfoChannel = 0x7d765830c5c0
...

"Source length = 0" seems odd to me, but otherwise, nothing is jumping out at me.

:baku -- We are trying to run mochitests in geckoview on the new-ish Android x86_64 7.0 test platform (a fast android emulator). Tests are mostly passing, but this sort of intermittent failure is too easily reproducible. We see the test harness (or sometimes the code for a test) failing, typically with a ReferenceError, following "Loading failed for the <script> with source ...", typically for one of these <script> elements:

https://searchfox.org/mozilla-central/rev/486b64e4bff86b7988af8c8b80845404ad197533/testing/mochitest/server.js#664-681

I have reproduced the error with ScriptLoader MOZ_LOG (links above) but I'm unfamiliar with this code and nothing is jumping out at me. Can you tell what's going wrong? Suggest next steps?

Comment 16

[Geoff Brown [:gbrown]]

More examples at https://treeherder.mozilla.org/#/jobs?repo=try&tier=1%2C2%2C3&selectedJob=236964973&revision=b57f76faffa3d02ec03ab8a9728b718f8e649ba4.

(In reply to Geoff Brown [:gbrown] from comment #7)

"Source length = 0" seems odd to me, but otherwise, nothing is jumping out at me.

Additional failures confirm: the "Source length" reported at

https://searchfox.org/mozilla-central/rev/532e4b94b9e807d157ba8e55034aef05c1196dc9/dom/script/ScriptLoadHandler.cpp#362

is incorrect in the failure cases. Sometimes it is 0; 8192 seems common also.

Comment 17

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1
• mozilla-beta: 2

Platform breakdown:

• android-em-7-0-x86_64: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1534732&startday=2019-03-25&endday=2019-03-31&tree=all

Comment 18

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform breakdown:

• android-em-7-0-x86_64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1534732&startday=2019-04-01&endday=2019-04-07&tree=all

Comment 19

[Geoff Brown [:gbrown]]

Another example, with http moz_logs:

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=238541684&repo=try&lineNumber=1547

[task 2019-04-06T00:45:55.964Z] 00:45:55     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_UPLOAD_DIR=/sdcard/tests/mozlog --es env8 R_LOG_DESTINATION=stderr --es args "-no-remote -profile /sdcard/tests/profile//" --es env3 MOZ_LOG=nsHttp:4,ScriptLoader:5 --es env2 R_LOG_VERBOSE=1 --es env1 XPCOM_DEBUG_BREAK=stack --es env0 MOZ_CRASHREPORTER=1 --es env7 MOZ_LOG_FILE=/sdcard/tests/mozlog/moz-pid=%PID-uid=cdcc190e-e307-430a-b561-a350da040283.log --es env6 MOZ_CRASHREPORTER_SHUTDOWN=1 --es env5 MOZ_IN_AUTOMATION=1 --es env4 MOZ_DISABLE_NONLOCAL_CONNECTIONS=1 --ez use_multiprocess True --es env13 DISABLE_UNSAFE_CPOW_WARNINGS=1 --es env12 R_LOG_LEVEL=6 --es env11 MOZ_HIDE_RESULTS_TABLE=1 --es env10 MOZ_CRASHREPORTER_NO_REPORT=1 -d "http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&logFile=%2Fsdcard%2Ftests%2Flogs%2Fmochitest.log&fileLevel=INFO&consoleLevel=INFO&hideResultsTable=1&manifestFile=tests.json&dumpOutputDirectory=%2Fsdcard%2Ftests"
[task 2019-04-06T00:45:56.971Z] 00:45:56     INFO -  remoteautomation.py | Application pid: 2465
[task 2019-04-06T00:52:25.333Z] 00:52:25     INFO -  wait for org.mozilla.geckoview.test complete; top activity=org.mozilla.geckoview.test
[task 2019-04-06T00:52:25.438Z] 00:52:25     INFO -  org.mozilla.geckoview.test unexpectedly found running. Killing...
[task 2019-04-06T00:52:25.439Z] 00:52:25     INFO -  TEST-INFO | started process screentopng
[task 2019-04-06T00:52:25.738Z] 00:52:25     INFO -  TEST-INFO | screentopng: exit 0
[task 2019-04-06T00:52:40.127Z] 00:52:40  WARNING -  TEST-UNEXPECTED-FAIL | remoteautomation.py | application timed out after 370 seconds with no output

https://taskcluster-artifacts.net/PZ8o_-ohS6eaczbKHQWv2Q/0/public/test_info//logcat-emulator-5554.log

04-06 01:46:11.400  2526  2541 W Web Content: [JavaScript Warning: "Loading failed for the <script> with source http://mochi.test:8888/tests/SimpleTest/TestRunner.js." {file: "http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&logFile=%2Fsdcard%2Ftests%2Flogs%2Fmochitest.log&fileLevel=INFO&consoleLevel=INFO&hideResultsTable=1&manifestFile=tests.json&dumpOutputDirectory=%2Fsdcard%2Ftests" line: 6}]

https://queue.taskcluster.net/v1/task/PZ8o_-ohS6eaczbKHQWv2Q/runs/0/artifacts/public/test_info//mozLogs.zip

[Child 2526: Main Thread]: D/nsHttp HttpChannelChild::RecvOnStartRequest [this=0x7cc8e000e800]
[Child 2526: Main Thread]: D/nsHttp StartRequestEvent [this=0x7cc8e000e800]
[Child 2526: Main Thread]: D/nsHttp HttpChannelChild::OnStartRequest [this=0x7cc8e000e800]
[Child 2526: Main Thread]: D/nsHttp HttpBaseChannel::SetApplyConversion [this=0x7cc8e000e828 value=1]
[Child 2526: Main Thread]: D/nsHttp HttpChannelChild::DoOnStartRequest [this=0x7cc8e000e800]
[Child 2526: Main Thread]: D/nsHttp HttpBaseChannel::DoApplyContentConversions [this=0x7cc8e000e828]
[Child 2526: Unnamed thread 0x7cc8eb12b460]: D/nsHttp HttpBackgroundChannelChild::OnStartRequestReceived [this=0x7cc8e005b1a0]
[Child 2526: Unnamed thread 0x7cc8eb12b460]: D/nsHttp HttpBackgroundChannelChild::RecvOnTransportAndData [this=0x7cc8e005b1a0]
[Child 2526: Unnamed thread 0x7cc8eb12b460]: D/nsHttp HttpChannelChild::ProcessOnTransportAndData [this=0x7cc8e000e800]
...
[Child 2526: Main Thread]: D/nsHttp HttpChannelChild::OnTransportAndData [this=0x7cc8e000e800]
[Child 2526: Main Thread]: D/nsHttp HttpChannelChild::DoOnStatus [this=0x7cc8e000e800]
[Child 2526: Main Thread]: D/nsHttp HttpChannelChild::DoOnProgress [this=0x7cc8e000e800]
[Child 2526: Main Thread]: D/nsHttp HttpChannelChild::DoOnDataAvailable [this=0x7cc8e000e800]
[Child 2526: Main Thread]: D/ScriptLoader OnIncrementalData aDataLength=8192
...
[Child 2526: Unnamed thread 0x7cc8eb12b460]: D/nsHttp HttpChannelChild::ProcessOnStopRequest [this=0x7cc8e000e800]
...
Child 2526: Main Thread]: D/nsHttp HttpChannelChild::OnStopRequest [this=0x7cc8e000e800 status=804b000e]
[Child 2526: Main Thread]: D/nsHttp HttpChannelChild::DoPreOnStopRequest [this=0x7cc8e000e800 status=804b000e]
[Child 2526: Main Thread]: D/nsHttp HttpChannelChild::DoOnStopRequest [this=0x7cc8e000e800]
[Child 2526: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7cc8e004aa00): Stream complete (url = http://mochi.test:8888/tests/SimpleTest/TestRunner.js), aDataLength=0
[Child 2526: Main Thread]: D/ScriptLoader DecodeRawData sees scriptText.length=8192
[Child 2526: Main Thread]: D/ScriptLoader DecodeRawData sets length=8192
[Child 2526: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7cc8e004aa00): Source length = 8192
[Child 2526: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7cc8e004aa00): nsICacheInfoChannel = 0x7cc8e000edc0
[Child 2526: Main Thread]: D/ScriptLoader <script> load failed
[Child 2526: Main Thread]: D/ScriptLoader ScriptLoadRequest (0x7cc8e004aa00): ScriptLoadHandler::OnStreamComplete OK
[Child 2526: Main Thread]: D/nsHttp nsHttpHandler::NotifyObservers [chan=0x7cc8e000e868 event="http-on-stop-request"]
[Child 2526: Main Thread]: D/nsHttp HttpChannelChild::CleanupBackgroundChannel [this=0x7cc8e000e800 bgChild=0x7cc8e005b1a0]

Comment 20

[Geoff Brown [:gbrown]]

:edenchuang - In the logs from comment 19, it seems to me that OnStopRequest is seen too early, before all content has been received, but I don't notice HttpChannelChild::Cancel(NS_BINDING_ABORTED), as you reported in https://bugzilla.mozilla.org/show_bug.cgi?id=1427396#c56. Would I see the Cancel in the http moz_log? Does this case look different?

Comment 21

[Eden Chuang[:edenchuang]]

According to the above log messages, this is another timeout issue for android platform.
The root cause of bug 1427396 is the ServiceWorker is terminated before the intercepted channel transaction finish. ServiceWorker termination cancels the channel, so loading fail is reported by ScriptLoader.
In this bug, the script loading is not related to ServiceWorker, so it is not the same situation with bug 1427396.

Comment 23

[Geoff Brown [:gbrown]]

:hsinyi - This defect is causing frequent intermittent test failures across all geckoview mochitests. We see "Loading failed for the <script> with source ... (some mochitest test file or some mochitest test harness script)", and it looks like the script has not been fully loaded. Can you find someone to investigate?

Comment 19 has detailed logs.

Comment 24

[Hsin-Yi Tsai (she/her) [:hsinyi]]

(In reply to Geoff Brown [:gbrown] from comment #23)

:hsinyi - This defect is causing frequent intermittent test failures across all geckoview mochitests. We see "Loading failed for the <script> with source ... (some mochitest test file or some mochitest test harness script)", and it looks like the script has not been fully loaded. Can you find someone to investigate?

Comment 19 has detailed logs.

As it seems an issue with <script>, Jon, are you the right person to help Geoff investigate here?

Comment 25

[Intermittent Failures Robot]

10 failures in 3025 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 7
• mozilla-central: 1
• mozilla-inbound: 2

Platform breakdown:

• android-em-7-0-x86_64: 9
• android-em-4-3-armv7-api16: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1534732&startday=2019-04-08&endday=2019-04-14&tree=all

Comment 26

[Jon Coppeard (:jonco)]

The status code in this message:

Child 2526: Main Thread]: D/nsHttp HttpChannelChild::OnStopRequest [this=0x7cc8e000e800 status=804b000e]

Is:

nsresult(0x0x804b000e) NS_ERROR_NET_TIMEOUT "The connection has timed out" from the NETWORK module, commented as:
The connection was lost due to a timeout error.

So it looks like a network issue to me.

Comment 27

[Chris Peterson [:cpeterson]]

gbrown says this bug is a blocker for upgrading GeckoView mochitests to tier 1.

Comment 28

[Geoff Brown [:gbrown]]

Thanks :jonco!

I reproduced this failure two more times here:

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=241161412&repo=try&lineNumber=6807
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=241181563&repo=try&lineNumber=3861

and verified that both of those also show HttpChannelChild::OnStopRequest with NS_ERROR_NET_TIMEOUT.

Let's see if Necko folks can help...

Comment 29

[Geoff Brown [:gbrown]]

:mayhemer -- This intermittent test failure is seen on our new Android x86 7.0 test platform. mochitests sometimes fail when a mochitest harness script fails to load. Comment 19 and comment 28 capture instances of this with http MOZ_LOGging; in all 3 cases I see HttpChannelChild::OnStopRequest with NS_ERROR_NET_TIMEOUT. Requests are between the browser running in an android emulator to an httpd.js server running in xpcshell on the Ubuntu host that is running the emulator. Can you provide any insight into the error, or suggest next steps for debugging?

Comment 30

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform breakdown:

• android-em-7-0-x86_64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1534732&startday=2019-04-15&endday=2019-04-21&tree=all

Comment 31

[Honza Bambas (:mayhemer)]

Please provide the logs from comment 19.

Comment 32

[Honza Bambas (:mayhemer)]

OK, found logs in comment 28. Please use at least these modules: timestamp,nsSocketTransport:5,nsHttp:5. Only thing I can see is that the server simply stops sending the response back after we received 8192 bytes of data. the log seems kinda broken, some pretty much expected lines are missing, specifically from constructors.

Comment 33

[Geoff Brown [:gbrown]]

(In reply to Honza Bambas (:mayhemer) from comment #31)

Please provide the logs from comment 19.

Sorry, looks like those artifacts have expired / are no longer available.

Comment 34

[Geoff Brown [:gbrown]]

Here's a new run with timestamp,nsSocketTransport:5,nsHttp:5:

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=242147253&repo=try&lineNumber=4391

https://taskcluster-artifacts.net/EHdEawjqTaWLr-85tkCcmw/0/public/test_info//logcat-emulator-5554.log

04-23 22:31:07.990  8944  8959 W Web Content: [JavaScript Warning: "Loading failed for the <script> with source http://mochi.test:8888/tests/SimpleTest/TestRunner.js." {file: "http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&logFile=%2Fsdcard%2Ftests%2Flogs%2Fmochitest.log&fileLevel=INFO&consoleLevel=INFO&hideResultsTable=1&manifestFile=tests.json&dumpOutputDirectory=%2Fsdcard%2Ftests" line: 6}]

So it looks like pid 8944 is of interest. mozlogs at:

https://queue.taskcluster.net/v1/task/EHdEawjqTaWLr-85tkCcmw/runs/0/artifacts/public/test_info//mozLogs.zip

Comment 35

[Honza Bambas (:mayhemer)]

Thanks! Now it's complete I can make a conclusion. This is a server problem or a problem between the browser and the server. I see the following in the log analyzes:

2019-04-23 21:31:07.990724 UTC - [Parent 8885: Unnamed thread 0x712a96422570]: E/nsSocketTransport nsSocketTransport::OnSocketReady [this=0x712a88d65c00 outFlags=41]
2019-04-23 21:31:07.990724 UTC - [Parent 8885: Unnamed thread 0x712a96422570]: D/nsSocketTransport nsSocketInputStream::OnSocketReady [this=0x712a88d65e78 cond=0]
2019-04-23 21:31:07.990724 UTC - [Parent 8885: Unnamed thread 0x712a96422570]: V/nsHttp nsHttpConnection::OnSocketReadable [this=0x712a88d61c00]
nsSocketTransport @712a88d65c00
2019-04-23 21:31:07.990724 UTC - [Parent 8885: Unnamed thread 0x712a96422570]: V/nsHttp nsHttpTransaction::WriteSegments 0x712a88d69400
2019-04-23 21:31:07.990724 UTC - [Parent 8885: Unnamed thread 0x712a96422570]: V/nsHttp nsHttpConnectionMgr::ShouldThrottle trans=0x712a88d69400
2019-04-23 21:31:07.990724 UTC - [Parent 8885: Unnamed thread 0x712a96422570]: D/nsSocketTransport nsSocketInputStream::Read [this=0x712a88d65e78 count=16384]
2019-04-23 21:31:07.990724 UTC - [Parent 8885: Unnamed thread 0x712a96422570]: D/nsSocketTransport   calling PR_Read [count=16384]
2019-04-23 21:31:07.990724 UTC - [Parent 8885: Unnamed thread 0x712a96422570]: D/nsSocketTransport   PR_Read returned [n=-1]
2019-04-23 21:31:07.990724 UTC - [Parent 8885: Unnamed thread 0x712a96422570]: D/nsSocketTransport ErrorAccordingToNSPR [in=-5990 out=804b000e]
2019-04-23 21:31:07.990724 UTC - [Parent 8885: Unnamed thread 0x712a96422570]: D/nsSocketTransport nsSocketTransport::OnMsgInputClosed [this=0x712a88d65c00 reason=804b000e]

outFlags=41 means:
POLL_READ | POLL_ERR | POLL_HUP

reading the socket returns PR error -5990 which is net-timeout, kinda surprisingly.

It means the server or NAT (if there is) killed the connection. It happened after 13 seconds we received 202 bytes from the server - which is exactly the size of the response head+headers, see the log.

There are 4 channels with 804b000e status that are all opened at the same moment and killed at the same moment (after 13 seconds), all of them received just the response head.

So, could just the server be killed by some external event or crash?

Comment 36

[Bobby Holley (:bholley)]

Seems like the next step is to add/audit logging on the xpcshell instance.

Comment 37

[Geoff Brown [:gbrown]]

I'm having trouble reproducing the failure with all this logging.

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=242496752&repo=try&lineNumber=75185

might be an example, now with httpd.js debugging enabled. It looks a little different in that it is the test script itself that fails to load (rather than part of the mochitest harness):

https://taskcluster-artifacts.net/ILUYy0oQTKeqpOg5OdWEKw/0/public/test_info//logcat-emulator-5554.log

04-25 04:02:41.180  3833  3848 W Web Content: [JavaScript Warning: "Loading failed for the <script> with source https://example.com/tests/SimpleTest/SimpleTest.js." {file: "https://example.com/tests/dom/indexedDB/test/test_storage_manager_estimate.html" line: 9}]

moz_logs at https://queue.taskcluster.net/v1/task/ILUYy0oQTKeqpOg5OdWEKw/runs/0/artifacts/public/test_info//mozLogs.zip

I notice the httpd debug output includes:

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=242496752&repo=try&lineNumber=74964

[task 2019-04-25T03:03:06.920Z] 03:03:06     INFO -  HTTPD-INFO | *** WARNING: unexpected error when reading from socket; will be treated as if the input stream had been closed
[task 2019-04-25T03:03:06.920Z] 03:03:06     INFO -  HTTPD-INFO | *** WARNING: actual error was: [Exception... "Component returned failure code: 0x80470002 (NS_BASE_STREAM_CLOSED) [nsIInputStream.available]"  nsresult: "0x80470002 (NS_BASE_STREAM_CLOSED)"  location: "JS frame :: /builds/worker/workspace/build/hostutils/host-utils-68.0a1.en-US.linux-x86_64/components/httpd.js :: onInputStreamReady :: line 1273"  data: no]

Significant?

Comment 38

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 3
• autoland: 1

Platform breakdown:

• android-em-7-0-x86_64: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1534732&startday=2019-04-22&endday=2019-04-28&tree=all

Comment 39

[Geoff Brown [:gbrown]]

:snorp - Have you had a chance to look at this?

Comment 40

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform breakdown:

• android-em-7-0-x86_64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1534732&startday=2019-04-29&endday=2019-05-05&tree=all

Comment 41

[James Willcox (:snorp) ([e-mail]) (he/him)]

I have not...

Comment 42

[Geoff Brown [:gbrown]]

Since this was becoming difficult to reproduce with all the logging, I tried turning off all the moz_logs, but kept the httpd.js logging enabled -- failures reproduced easily.

https://treeherder.mozilla.org/#/jobs?repo=try&tier=1%2C2%2C3&revision=62bfc6fa859c6749030d7aefa660397231e691f6

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=244957586&repo=try&lineNumber=7744
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=244957585&repo=try&lineNumber=404917
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=244957615&repo=try&lineNumber=44498

I haven't examined the logs closely -- just verified script loading errors in each.

Comment 43

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 3
• mozilla-beta: 1

Platform breakdown:

• android-em-7-0-x86_64: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1534732&startday=2019-05-06&endday=2019-05-12&tree=all

Comment 44

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-inbound: 1

Platform breakdown:

• android-em-7-0-x86_64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1534732&startday=2019-05-13&endday=2019-05-19&tree=all

Comment 45

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1
• mozilla-inbound: 2

Platform breakdown:

• android-em-7-0-x86_64: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1534732&startday=2019-05-20&endday=2019-05-26&tree=all

Comment 46

[Geoff Brown [:gbrown]]

Failures continue and are generally reported in bug 1500977. This is a serious concern for geckoview mochitests.

Ideas:

• There has been speculation that the emulator's networking support might be flaky. Can I reproduce the issue on a real device (locally, or on bitbar perhaps)?
• Revisit the logs in comment 42, or generate new ones to understand what is happening from the httpd.js perspective.
• Run one httpd.js server per task (rather than per manifest) to determine if httpd.js functions well after a timeout. (In progress -- unexpectedly difficult!).

Comment 47

[Geoff Brown [:gbrown]]

(In reply to Geoff Brown [:gbrown] from comment #46)

• There has been speculation that the emulator's networking support might be flaky. Can I reproduce the issue on a real device (locally, or on bitbar perhaps)?

I tried that on bitbar, but encountered several issues: Since we don't normally run mochitest-plain on bitbar, there are many normal test failures; Test failures include 370 second timeouts for other reasons; An arm build is required for real devices, so now there are multiple factors at play.

Comment 48

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform breakdown:

• android-em-7-0-x86_64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1534732&startday=2019-05-27&endday=2019-06-02&tree=all

Comment 49

[Geoff Brown [:gbrown]]

It's too difficult to classify these correctly, so I'd prefer all failures reported against bug 1500977.

Comment 50

[Geoff Brown [:gbrown]]

I cannot reproduce these failures with an update to the latest android emulator (however, there are other problems with that version of the emulator -- updating is non-trivial).

Comment 51

[Geoff Brown [:gbrown]]

afaik, we only see the networking problems with mochitests, which does not fit with the idea that the emulator's networking is flaky (comment 50). One of the characteristics of mochitest-plain is that the tasks run for longer than many of the other test suites. I tried reducing run-time dramatically by tripling the number of chunks, but network timeouts persisted:

https://treeherder.mozilla.org/#/jobs?repo=try&tier=1%2C2%2C3&revision=fdccf1fac66999974d2f63b46bdbe76f5207ce43

Comment 52

[Geoff Brown [:gbrown]]

An idea for working around this another way: Run httpd.js on the emulator. This network setup would be more like the desktop mochitest configuration. netwerk/ xpcshell tests run httpd.js with good success and we know today's emulator has lots of storage, memory, and cpu, so I think it is possible...but this would be a big change, with no guarantee of success.

Comment 53

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform breakdown:

• android-em-7-0-x86_64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1534732&startday=2019-06-03&endday=2019-06-09&tree=all

Comment 54

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 4
• mozilla-release: 1

Platform breakdown:

• android-em-7-0-x86_64: 5

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1534732&startday=2019-06-10&endday=2019-06-16&tree=all

Comment 55

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 2
• autoland: 1

Platform breakdown:

• android-em-7-0-x86_64: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1534732&startday=2019-06-17&endday=2019-06-23&tree=all

Comment 57

[Geoff Brown [:gbrown]]

(In reply to Geoff Brown [:gbrown] from comment #50)

I cannot reproduce these failures with an update to the latest android emulator (however, there are other problems with that version of the emulator -- updating is non-trivial).

I have solutions for some of the new problems introduced by the emulator upgrade. I'm going to push ahead with bug 1556058, at least for mochitests, to resolve this bug.

Comment 58

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform breakdown:

• android-em-7-0-x86_64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1534732&startday=2019-06-24&endday=2019-06-30&tree=all

Comment 59

[Geoff Brown [:gbrown]]

With the emulator updated for mochitests, no more network-based no-output timeouts are seen.

Comment 60

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-esr68: 1
• autoland: 3

Platform breakdown:

• android-em-7-0-x86_64: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1534732&startday=2019-07-01&endday=2019-07-07&tree=all