https://treeherder.mozilla.org/logviewer.html#?job_id=34758742&repo=mozilla-inbound 04:26:06 INFO - 369 INFO Leaving test bound testXhrPost 04:26:06 INFO - 370 INFO Entering test bound testFormSubmission 04:26:06 INFO - 371 INFO TEST-PASS | devtools/client/webconsole/test/browser_webconsole_netlogging.js | Console was opened - 04:26:06 INFO - 372 INFO Waiting for messages... 04:26:06 INFO - 373 INFO TEST-PASS | devtools/client/webconsole/test/browser_webconsole_netlogging.js | matched rule: http://example.com/browser/devtools/client/webconsole/test/test-network-request.html - 04:26:06 INFO - 374 INFO Waiting for the page load to be finished. 04:26:06 INFO - 375 INFO Longer timeout required, waiting longer... Remaining timeouts: 1 04:26:06 INFO - 376 INFO TEST-UNEXPECTED-FAIL | devtools/client/webconsole/test/browser_webconsole_netlogging.js | Test timed out -

The failures here have exceeded our limit of 30 failures for a given week, so we are taking a look at this and trying to find more information or push for a fix. this failure is interesting, here is a clip from a log [0]: 12:31:07 INFO - TEST-START | devtools/client/webconsole/test/browser_webconsole_netlogging.js 12:32:37 INFO - TEST-INFO | started process screenshot 12:32:38 INFO - TEST-INFO | screenshot: exit 0 12:32:38 INFO - Buffered messages logged at 12:31:07 12:32:38 INFO - Entering test bound testPageLoad 12:32:38 INFO - Buffered messages logged at 12:31:08 12:32:38 INFO - TEST-PASS | devtools/client/webconsole/test/browser_webconsole_netlogging.js | Console was opened - 12:32:38 INFO - Waiting for messages... 12:32:38 INFO - TEST-PASS | devtools/client/webconsole/test/browser_webconsole_netlogging.js | matched rule: http://example.com/browser/devtools/client/webconsole/test/test-network-request.html - 12:32:38 INFO - TEST-PASS | devtools/client/webconsole/test/browser_webconsole_netlogging.js | Page load was logged - 12:32:38 INFO - TEST-PASS | devtools/client/webconsole/test/browser_webconsole_netlogging.js | Logged network entry is page load - 12:32:38 INFO - TEST-PASS | devtools/client/webconsole/test/browser_webconsole_netlogging.js | Method is correct - 12:32:38 INFO - TEST-PASS | devtools/client/webconsole/test/browser_webconsole_netlogging.js | No request body was stored - 12:32:38 INFO - TEST-PASS | devtools/client/webconsole/test/browser_webconsole_netlogging.js | Request body was not discarded - 12:32:38 INFO - TEST-PASS | devtools/client/webconsole/test/browser_webconsole_netlogging.js | Response body's beginning is okay - 12:32:38 INFO - Buffered messages logged at 12:31:09 12:32:38 INFO - Removing tab. 12:32:38 INFO - Waiting for event: 'TabClose' on [object XULElement]. 12:32:38 INFO - Got event: 'TabClose' on [object XULElement]. 12:32:38 INFO - Tab removed and finished closing 12:32:38 INFO - Leaving test bound testPageLoad 12:32:38 INFO - Entering test bound testXhrGet 12:32:38 INFO - Buffered messages logged at 12:31:10 12:32:38 INFO - TEST-PASS | devtools/client/webconsole/test/browser_webconsole_netlogging.js | Console was opened - 12:32:38 INFO - Waiting for messages... 12:32:38 INFO - TEST-PASS | devtools/client/webconsole/test/browser_webconsole_netlogging.js | matched rule: http://example.com/browser/devtools/client/webconsole/test/test-network-request.html - 12:32:38 INFO - TEST-PASS | devtools/client/webconsole/test/browser_webconsole_netlogging.js | testXhrGet() was logged - 12:32:38 INFO - TEST-PASS | devtools/client/webconsole/test/browser_webconsole_netlogging.js | Method is correct - 12:32:38 INFO - TEST-PASS | devtools/client/webconsole/test/browser_webconsole_netlogging.js | No request body was sent - 12:32:38 INFO - TEST-PASS | devtools/client/webconsole/test/browser_webconsole_netlogging.js | Request body was not discarded - 12:32:38 INFO - TEST-PASS | devtools/client/webconsole/test/browser_webconsole_netlogging.js | Response is correct - 12:32:38 INFO - Buffered messages logged at 12:31:11 12:32:38 INFO - Removing tab. 12:32:38 INFO - Waiting for event: 'TabClose' on [object XULElement]. 12:32:38 INFO - Got event: 'TabClose' on [object XULElement]. 12:32:38 INFO - Tab removed and finished closing 12:32:38 INFO - Leaving test bound testXhrGet 12:32:38 INFO - Entering test bound testXhrPost 12:32:38 INFO - Buffered messages logged at 12:31:12 12:32:38 INFO - TEST-PASS | devtools/client/webconsole/test/browser_webconsole_netlogging.js | Console was opened - 12:32:38 INFO - Waiting for messages... 12:32:38 INFO - TEST-PASS | devtools/client/webconsole/test/browser_webconsole_netlogging.js | matched rule: http://example.com/browser/devtools/client/webconsole/test/test-network-request.html - 12:32:38 INFO - TEST-PASS | devtools/client/webconsole/test/browser_webconsole_netlogging.js | testXhrPost() was logged - 12:32:38 INFO - TEST-PASS | devtools/client/webconsole/test/browser_webconsole_netlogging.js | Method is correct - 12:32:38 INFO - TEST-PASS | devtools/client/webconsole/test/browser_webconsole_netlogging.js | Request body was logged - 12:32:38 INFO - TEST-PASS | devtools/client/webconsole/test/browser_webconsole_netlogging.js | Response is correct - 12:32:38 INFO - Buffered messages logged at 12:31:13 12:32:38 INFO - Removing tab. 12:32:38 INFO - Waiting for event: 'TabClose' on [object XULElement]. 12:32:38 INFO - Got event: 'TabClose' on [object XULElement]. 12:32:38 INFO - Tab removed and finished closing 12:32:38 INFO - Leaving test bound testXhrPost 12:32:38 INFO - Entering test bound testFormSubmission 12:32:38 INFO - Buffered messages logged at 12:31:14 12:32:38 INFO - TEST-PASS | devtools/client/webconsole/test/browser_webconsole_netlogging.js | Console was opened - 12:32:38 INFO - Waiting for messages... 12:32:38 INFO - TEST-PASS | devtools/client/webconsole/test/browser_webconsole_netlogging.js | matched rule: http://example.com/browser/devtools/client/webconsole/test/test-network-request.html - 12:32:38 INFO - Waiting for the page load to be finished. 12:32:38 INFO - Buffered messages logged at 12:31:31 12:32:38 INFO - Console message: [JavaScript Error: "1484425891623 Browser.Experiments.Experiments ERROR Experiments #0::httpGetRequest::onLoad() - Request to http://127.0.0.1:8888/experiments-dummy/manifest returned status 404" {file: "resource://gre/modules/Log.jsm" line: 748}] 12:32:38 INFO - App_append@resource://gre/modules/Log.jsm:748:9 12:32:38 INFO - log@resource://gre/modules/Log.jsm:386:7 12:32:38 INFO - getLoggerWithMessagePrefix/proxy.log@resource://gre/modules/Log.jsm:501:44 12:32:38 INFO - Experiments.Experiments/this._log.log@resource://app/modules/experiments/Experiments.jsm:322:5 12:32:38 INFO - error@resource://gre/modules/Log.jsm:394:5 12:32:38 INFO - _httpGetRequest/xhr.onload@resource://app/modules/experiments/Experiments.jsm:953:9 12:32:38 INFO - EventHandlerNonNull*_httpGetRequest@resource://app/modules/experiments/Experiments.jsm:951:5 12:32:38 INFO - _loadManifest@resource://app/modules/experiments/Experiments.jsm:815:32 12:32:38 INFO - TaskImpl_run@resource://gre/modules/Task.jsm:319:42 12:32:38 INFO - TaskImpl@resource://gre/modules/Task.jsm:277:3 12:32:38 INFO - asyncFunction@resource://gre/modules/Task.jsm:252:14 12:32:38 INFO - Task_spawn@resource://gre/modules/Task.jsm:166:12 12:32:38 INFO - TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:389:16 12:32:38 INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15 12:32:38 INFO - TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:401:7 12:32:38 INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15 12:32:38 INFO - TaskImpl@resource://gre/modules/Task.jsm:277:3 12:32:38 INFO - asyncFunction@resource://gre/modules/Task.jsm:252:14 12:32:38 INFO - Task_spawn@resource://gre/modules/Task.jsm:166:12 12:32:38 INFO - TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:389:16 12:32:38 INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15 12:32:38 INFO - TaskImpl@resource://gre/modules/Task.jsm:277:3 12:32:38 INFO - asyncFunction@resource://gre/modules/Task.jsm:252:14 12:32:38 INFO - Task_spawn@resource://gre/modules/Task.jsm:166:12 12:32:38 INFO - _run@resource://app/modules/experiments/Experiments.jsm:760:24 12:32:38 INFO - updateManifest@resource://app/modules/experiments/Experiments.jsm:848:12 12:32:38 INFO - notify@resource://app/components/ExperimentsService.js:66:7 12:32:38 INFO - TM_notify/<@resource://gre/components/nsUpdateTimerManager.js:218:11 12:32:38 INFO - TM_notify@resource://gre/components/nsUpdateTimerManager.js:263:7 12:32:38 INFO - 12:32:38 INFO - Console message: [JavaScript Error: "1484425891624 Browser.Experiments.Experiments ERROR Experiments #0::_loadManifest - failure to fetch/parse manifest (continuing anyway): Error: Experiments - XHR status for http://127.0.0.1:8888/experiments-dummy/manifest is 404" {file: "resource://gre/modules/Log.jsm" line: 748}] 12:32:38 INFO - App_append@resource://gre/modules/Log.jsm:748:9 12:32:38 INFO - log@resource://gre/modules/Log.jsm:386:7 12:32:38 INFO - getLoggerWithMessagePrefix/proxy.log@resource://gre/modules/Log.jsm:501:44 12:32:38 INFO - Experiments.Experiments/this._log.log@resource://app/modules/experiments/Experiments.jsm:322:5 12:32:38 INFO - error@resource://gre/modules/Log.jsm:394:5 12:32:38 INFO - _loadManifest@resource://app/modules/experiments/Experiments.jsm:825:7 12:32:38 INFO - TaskImpl_run@resource://gre/modules/Task.jsm:320:42 12:32:38 INFO - process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:920:21 12:32:38 INFO - walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:801:7 12:32:38 INFO - Promise*scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:734:11 12:32:38 INFO - schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:765:7 12:32:38 INFO - completePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:702:7 12:32:38 INFO - _httpGetRequest/xhr.onload@resource://app/modules/experiments/Experiments.jsm:954:9 12:32:38 INFO - EventHandlerNonNull*_httpGetRequest@resource://app/modules/experiments/Experiments.jsm:951:5 12:32:38 INFO - _loadManifest@resource://app/modules/experiments/Experiments.jsm:815:32 12:32:38 INFO - TaskImpl_run@resource://gre/modules/Task.jsm:319:42 12:32:38 INFO - TaskImpl@resource://gre/modules/Task.jsm:277:3 12:32:38 INFO - asyncFunction@resource://gre/modules/Task.jsm:252:14 12:32:38 INFO - Task_spawn@resource://gre/modules/Task.jsm:166:12 12:32:38 INFO - TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:389:16 12:32:38 INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15 12:32:38 INFO - TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:401:7 12:32:38 INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15 12:32:38 INFO - TaskImpl@resource://gre/modules/Task.jsm:277:3 12:32:38 INFO - asyncFunction@resource://gre/modules/Task.jsm:252:14 12:32:38 INFO - Task_spawn@resource://gre/modules/Task.jsm:166:12 12:32:38 INFO - TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:389:16 12:32:38 INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15 12:32:38 INFO - TaskImpl@resource://gre/modules/Task.jsm:277:3 12:32:38 INFO - asyncFunction@resource://gre/modules/Task.jsm:252:14 12:32:38 INFO - Task_spawn@resource://gre/modules/Task.jsm:166:12 12:32:38 INFO - _run@resource://app/modules/experiments/Experiments.jsm:760:24 12:32:38 INFO - updateManifest@resource://app/modules/experiments/Experiments.jsm:848:12 12:32:38 INFO - notify@resource://app/components/ExperimentsService.js:66:7 12:32:38 INFO - TM_notify/<@resource://gre/components/nsUpdateTimerManager.js:218:11 12:32:38 INFO - TM_notify@resource://gre/components/nsUpdateTimerManager.js:263:7 12:32:38 INFO - 12:32:38 INFO - Buffered messages logged at 12:31:52 12:32:38 INFO - Longer timeout required, waiting longer... Remaining timeouts: 1 12:32:38 INFO - Buffered messages finished 12:32:38 INFO - TEST-UNEXPECTED-FAIL | devtools/client/webconsole/test/browser_webconsole_netlogging.js | Test timed out - 12:32:38 INFO - Removing tab. 12:32:38 INFO - Waiting for event: 'TabClose' on [object XULElement]. 12:32:38 INFO - Got event: 'TabClose' on [object XULElement]. 12:32:38 INFO - Tab removed and finished closing 12:32:38 INFO - Handler function threw an exception: TypeError: this.transport is null 12:32:38 INFO - Stack: send@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/main.js:1498:5 12:32:38 INFO - NEA_addSecurityInfo@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/webconsole.js:2229:5 12:32:38 INFO - NetworkResponseListener.prototype._getSecurityInfo<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/webconsole/network-monitor.js:495:5 12:32:38 INFO - exports.makeInfallible/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/ThreadSafeDevToolsUtils.js:101:14 12:32:38 INFO - onStartRequest@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/webconsole/network-monitor.js:436:5 12:32:38 INFO - Line: 1498, column: 5 12:32:38 INFO - console.error: 12:32:38 INFO - Handler function threw an exception: TypeError: this.transport is null 12:32:38 INFO - Stack: send@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/main.js:1498:5 12:32:38 INFO - NEA_addSecurityInfo@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/webconsole.js:2229:5 12:32:38 INFO - NetworkResponseListener.prototype._getSecurityInfo<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/webconsole/network-monitor.js:495:5 12:32:38 INFO - exports.makeInfallible/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/ThreadSafeDevToolsUtils.js:101:14 12:32:38 INFO - onStartRequest@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/webconsole/network-monitor.js:436:5 12:32:38 INFO - Line: 1498, column: 5 12:32:38 INFO - JavaScript error: resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/main.js, line 1498: TypeError: this.transport is null 12:32:38 INFO - Console message: [JavaScript Error: "TypeError: this.transport is null" {file: "resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/main.js" line: 1498}] 12:32:38 INFO - MEMORY STAT | vsize 758MB | vsizeMaxContiguous 507MB | residentFast 240MB | heapAllocated 100MB 12:32:38 INFO - TEST-OK | devtools/client/webconsole/test/browser_webconsole_netlogging.js | took 90233ms I do wonder if this error is causing us to fail: 12:32:38 INFO - Console message: [JavaScript Error: "1484425891624 Browser.Experiments.Experiments ERROR Experiments #0::_loadManifest - failure to fetch/parse manifest (continuing anyway): Error: Experiments - XHR status for http://127.0.0.1:8888/experiments-dummy/manifest is 404" {file: "resource://gre/modules/Log.jsm" line: 748}] it could be possible that this is on a timer and we happen to hit this whilst logging netrequests and then we end up failing? We define the url as experiments-dummy/manifest so we do not hit the network. I wonder if we could be smarter about the error here from the browser.experiments so it isn't a javascript error. Then again, this could be a red herring and the problem is elsewhere. :jryans, I would typically ping :bgrins here, but he is out for the rest of the quarter- could you help find someone to look at this? [0] https://archive.mozilla.org/pub/firefox/tinderbox-builds/mozilla-inbound-win32/1484416103/mozilla-inbound_win7_vm_test-mochitest-devtools-chrome-2-bm138-tests1-windows-build793.txt.gz

:jdescottes can you investigate or redirect as needed? The transport errors suggest the RDP connection is being terminated before all request data has been sent.

Looking at the screenshot we can see two interesting things: - the tab is still loading - the tab is still on http://example.com/browser/devtools/[...] but the form submit should have triggered a navigation to https So it looks like for some reason the page load never actually finishes when the test fails. Doing a try run: - with more logs: https://treeherder.mozilla.org/#/jobs?repo=try&revision=5a438957358b0e7e13182f71626b95bc6e5661c8 - with a delay before submitting the form: https://treeherder.mozilla.org/#/jobs?repo=try&revision=90d5843774dc09713c287021d450ee3c2ce05bb5

:jdescottes, any progress with your try pushes? This is still happening at a very frequent rate.

Joel: I can't reproduce this failure locally or on try (see https://treeherder.mozilla.org/#/jobs?repo=try&revision=4c2be0bd15128b446decf953355bbf01dda4ee8a for instance, dozens of retriggers without a failure). So my try runs with logging or delays are a bit useless for now, if I can't even get it to fail once. Is there anything that could increase the failure frequency on inbound/autoland compared to try?

Here are some stats for this failure, broken down by platform: Test results for devtools/client/webconsole/test/browser_webconsole_netlogging.js on mozilla-central,mozilla-inbound,autoland between 2017-01-30 and 2017-02-06 linux32/opt-chunked: 2 failures in 631 runs linux32/opt-e10s: 2 failures in 325 runs linux64/asan-chunked: 2 failures in 624 runs linux64/asan-e10s: 2 failures in 312 runs linux64/debug-chunked: 1 failures in 613 runs linux64/debug-e10s: 1 failures in 307 runs linux64/opt-chunked: 1 failures in 638 runs linux64/opt-e10s: 0 failures in 319 runs linux64/pgo-chunked: 0 failures in 634 runs linux64/pgo-e10s: 0 failures in 323 runs macosx64/debug-e10s: 4 failures in 126 runs macosx64/debug: 0 failures in 114 runs macosx64/opt-e10s: 0 failures in 142 runs macosx64/opt: 1 failures in 147 runs win32/debug-e10s: 0 failures in 125 runs win32/debug: 0 failures in 124 runs win32/opt-e10s: 0 failures in 128 runs win32/opt: 2 failures in 126 runs win32/pgo-e10s: 1 failures in 73 runs win32/pgo: 0 failures in 75 runs win64/debug-e10s: 6 failures in 132 runs win64/debug: 0 failures in 124 runs win64/opt-e10s: 1 failures in 114 runs win64/opt: 1 failures in 113 runs win64/pgo-e10s: 0 failures in 76 runs win64/pgo: 1 failures in 71 runs If that predicts future failures, a try push for win64/debug-e10s stands the best chance of reproducing the failure.

It's true that last week the failures seemed to increase on windows compared to other platforms. But before that Linux64 seemed to be the top failing platform in the comments added by the OrangeFactor Robot. This doesn't take into account the number of runs you added here. I don't know how to get this data? Thanks for the info anyway, I will try to use Windows to reproduce the issue.

It's an inexact science, to be sure. Data comes from ActiveData; I'm trying to make it more accessible in bug 1324470.

orange factor report shows failures from all branches, so I think what gbrown said as win8-debug is best. it is odd how this changed from linux64 -> win8 as primary failure mode :(

any luck reproducing this here, the failure rate is growing :(

This test indirectly uses the webconsole tests' loadTab() function, which is being investigated in bug 1307347.

This appears to still be failing on trunk since the second patch in bug 1307347 landed. Disabling on Beta as it's too late in the 52 cycle to keep fighting with it. https://hg.mozilla.org/releases/mozilla-beta/rev/982fb7a8b3a446125b151e7ae2a3b61200536a39

this has been high_frequency for 7 weeks, :gbrown, should we disable or hack a bit more on tab context?

Let's skip it. Hopefully jdescottes can get it running again.

Pushed by gbrown@mozilla.com: https://hg.mozilla.org/integration/mozilla-inbound/rev/5ea440f7b688 Skip browser_webconsole_netlogging.js for frequent failures. r=jmaher

jdescottes, any chance you have more to do here? there is a pending ni for you.

this picked up around March 13th: https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1298364&startday=2017-03-10&endday=2017-03-17&tree=all I am confused because this test is marked |skip-if = true| as in skip in ALL cases. Looking at the failures there is a lot of mis-stars in here, but also some real failures: https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=84163281&lineNumber=4689 https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=84075488&lineNumber=2776 https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-central&job_id=84000553&lineNumber=3044 this bug is for browser_webconsole_netlogging.js and we skipped browser_console_netlogging.js: https://dxr.mozilla.org/mozilla-central/source/devtools/client/webconsole/test/browser.ini?q=devtools%2Fclient%2Fwebconsole%2Ftest%2Fbrowser.ini&redirect_type=direct#340 should we enable browser_console_netlogging.js and then disable browser_webconsole_netlogging.js?

(In reply to Joel Maher ( :jmaher) from comment #49) > should we enable browser_console_netlogging.js and then disable > browser_webconsole_netlogging.js? I think so (I think I accidentally skipped the wrong test).

Yikes! Sorry for the confusion. https://treeherder.mozilla.org/#/jobs?repo=try&revision=4b5d7778df66e4dc21b8cdb4beea743cdcce160b

Comment on attachment 8849137 [details] [diff] [review] skip browser_webconsole_netlogging.js, enable browser_console_netlogging.js Review of attachment 8849137 [details] [diff] [review]: ----------------------------------------------------------------- excellent.

Pushed by gbrown@mozilla.com: https://hg.mozilla.org/integration/mozilla-inbound/rev/e874590bad2a Actually skip browser_webconsole_netlogging.js; r=jmaher

Test was moved to devtools/client/webconsole/old folder, and will be deleted in Bug 381834

Wrong blocker id

Test removed in Bug 1381834