Open Bug 1395759 Opened 7 years ago Updated 2 years ago

Intermittent devtools/client/webconsole/new-console-output/test/mochitest/browser_webconsole_network_messages_expand.js | A promise chain failed to handle a rejection: this.webConsoleFrame is null - stack: null

Categories

(DevTools :: Console, defect, P3)

Product:
DevTools
Component:
Console
Type:
defect

Tracking

(firefox57 wontfix, firefox58 fixed)

Status:
REOPENED
Milestone:
Firefox 58
Tracking Flags:
Tracking Status
firefox57 --- wontfix
firefox58 --- fixed

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure, Whiteboard: [reserve-console-html][stockwell unknown])

Attachments

(2 files)

Bug 1395759 - Properly declare request payload as ready;
59 bytes, text/x-review-board-request
nchevobbe
: review+
Details
Bug 1395759 - Properly wait on payload ready in tests;
59 bytes, text/x-review-board-request
nchevobbe
: review+
ritu
: approval-mozilla-beta-
Details 
New test added in bug 1362036; started failing right away.

:Honza - Can you make this test more reliable?
Flags: needinfo?(odvarko)
Whiteboard: [stockwell needswork]
Assignee: nobody → odvarko
Status: NEW → ASSIGNED
Flags: needinfo?(odvarko)
Priority: P5 → P1
Whiteboard: [stockwell needswork] → [stockwell needswork][reserve-console-html]
Comment on attachment 8909661 [details]
Bug 1395759 - Properly declare request payload as ready;

https://reviewboard.mozilla.org/r/181178/#review186346

This is looking good.
One thing that came to my mind reviewing the code : do we clean this.payloadQueue ? I guess the array can get pretty big and keep unecessary data, which might waste memory ?

::: devtools/client/netmonitor/src/connector/firefox-data-provider.js:324
(Diff revision 1)
> +   * @param {string} id request id
> +   * @param {object} payload request data payload
> +   */
> +  pushRequestToQueue(id, payload) {
> +    let request = this.getRequestFromQueue(id);
> +    request.payload = Object.assign({}, request.payload, payload);

maybe we could check if request isn't falsy here
Attachment #8909661 - Flags: review?(nchevobbe) → review+
Flags: qe-verify-
(In reply to Nicolas Chevobbe [:nchevobbe] from comment #9)
> One thing that came to my mind reviewing the code : do we clean
> this.payloadQueue ? I guess the array can get pretty big and keep unecessary
> data, which might waste memory ?
This is now in the patch too.

> maybe we could check if request isn't falsy here
Also fixed.

Honza
Attachment #8909661 - Flags: review+ → review?(nchevobbe)
Comment on attachment 8909661 [details]
Bug 1395759 - Properly declare request payload as ready;

https://reviewboard.mozilla.org/r/181178/#review192226

::: devtools/client/netmonitor/src/connector/firefox-data-provider.js:425
(Diff revision 5)
> +   * It also nicely returns a promise.
> +   *
> +   * @param {string} actor actor id (used as request id)
> +   * @param {string} method identifier of the data we want to fetch
> +   *
> +   * @return {Promise} return a promise resolved when date are received.

s/date/data
Attachment #8909661 - Flags: review?(nchevobbe) → review+
(In reply to Nicolas Chevobbe [:nchevobbe] from comment #17)
> > +   * @return {Promise} return a promise resolved when date are received.
> s/date/data

Fixed, thanks!

Honza
We're sorry, Autoland could not rebase your commits for you automatically. Please manually rebase your commits and try again.

hg error in cmd: hg rebase -s d5de0f945ac6 -d d115a2114809: rebasing 424522:d5de0f945ac6 "Bug 1395759 - Properly declare request payload as ready; r=nchevobbe" (tip)
merging devtools/client/netmonitor/src/connector/firefox-data-provider.js
warning: conflicts while merging devtools/client/netmonitor/src/connector/firefox-data-provider.js! (edit, then use 'hg resolve --mark')
unresolved conflicts (see hg resolve, then hg rebase --continue)
Pushed by jodvarko@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/cde3a0751329
Properly declare request payload as ready; r=nchevobbe
Backed out for frequently failing clipboard's devtools/client/netmonitor/test/browser_net_copy_headers.js:

https://hg.mozilla.org/integration/autoland/rev/638ce81da2e381ae8c4764a585705f23327329c2

Push with failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=cde3a075132970db8ed850af08ddfa4d3c1b1603&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception&filter-resultStatus=retry&filter-resultStatus=usercancel&filter-resultStatus=runnable

Failure log clipboard: https://treeherder.mozilla.org/logviewer.html#?job_id=135479003&repo=autoland
[task 2017-10-07T06:31:49.687Z] 06:31:49     INFO - TEST-START | devtools/client/netmonitor/test/browser_net_copy_headers.js
[task 2017-10-07T06:31:51.158Z] 06:31:51     INFO - GECKO(5315) | *************************
[task 2017-10-07T06:31:51.158Z] 06:31:51     INFO - GECKO(5315) | A coding exception was thrown and uncaught in a Task.
[task 2017-10-07T06:31:51.159Z] 06:31:51     INFO - GECKO(5315) | Full message: TypeError: monitor.panelWin.parent.document.querySelector(...) is null
[task 2017-10-07T06:31:51.162Z] 06:31:51     INFO - GECKO(5315) | Full stack: setup@chrome://mochitests/content/browser/devtools/client/netmonitor/test/browser_net_copy_headers.js:69:5
[task 2017-10-07T06:31:51.163Z] 06:31:51     INFO - GECKO(5315) | SimpleTest.waitForClipboard/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1032:12
[task 2017-10-07T06:31:51.164Z] 06:31:51     INFO - GECKO(5315) | wait@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1019:13
[task 2017-10-07T06:31:51.164Z] 06:31:51     INFO - GECKO(5315) | SimpleTest.waitForClipboard@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1029:5
[task 2017-10-07T06:31:51.164Z] 06:31:51     INFO - GECKO(5315) | waitForClipboardPromise/<@chrome://mochitests/content/browser/devtools/client/framework/test/shared-head.js:542:5
[task 2017-10-07T06:31:51.165Z] 06:31:51     INFO - GECKO(5315) | waitForClipboardPromise@chrome://mochitests/content/browser/devtools/client/framework/test/shared-head.js:541:10
[task 2017-10-07T06:31:51.166Z] 06:31:51     INFO - GECKO(5315) | @chrome://mochitests/content/browser/devtools/client/netmonitor/test/browser_net_copy_headers.js:68:9
[task 2017-10-07T06:31:51.167Z] 06:31:51     INFO - GECKO(5315) | Tester_execTest@chrome://mochikit/content/browser-test.js:798:9
[task 2017-10-07T06:31:51.168Z] 06:31:51     INFO - GECKO(5315) | Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:697:9
[task 2017-10-07T06:31:51.169Z] 06:31:51     INFO - GECKO(5315) | SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:795:59
[task 2017-10-07T06:31:51.170Z] 06:31:51     INFO - GECKO(5315) | *************************
[task 2017-10-07T06:31:51.170Z] 06:31:51     INFO - TEST-INFO | started process screentopng
[task 2017-10-07T06:31:51.555Z] 06:31:51     INFO - TEST-INFO | screentopng: exit 0
[task 2017-10-07T06:31:51.556Z] 06:31:51     INFO - Buffered messages logged at 06:31:49
[task 2017-10-07T06:31:51.557Z] 06:31:51     INFO - Entering test bound 
[task 2017-10-07T06:31:51.558Z] 06:31:51     INFO - Initializing a network monitor pane.
[task 2017-10-07T06:31:51.559Z] 06:31:51     INFO - Adding a new tab with URL: http://example.com/browser/devtools/client/netmonitor/test/html_simple-test-page.html
[task 2017-10-07T06:31:51.559Z] 06:31:51     INFO - Buffered messages logged at 06:31:50
[task 2017-10-07T06:31:51.561Z] 06:31:51     INFO - Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/FileUtils.jsm" line: 174}]
[task 2017-10-07T06:31:51.562Z] 06:31:51     INFO - Tab added and finished loading
[task 2017-10-07T06:31:51.564Z] 06:31:51     INFO - Net tab added successfully: http://example.com/browser/devtools/client/netmonitor/test/html_simple-test-page.html
[task 2017-10-07T06:31:51.565Z] 06:31:51     INFO - Target remoted.
[task 2017-10-07T06:31:51.567Z] 06:31:51     INFO - Console message: [JavaScript Warning: "Expected end of value but found ‘1pxpx’.  Error in parsing value for ‘flex’.  Declaration dropped." {file: "chrome://devtools/content/netmonitor/index.html" line: 0 column: 4 source: "0 0 1pxpx"}]
[task 2017-10-07T06:31:51.569Z] 06:31:51     INFO - Network monitor pane shown successfully.
[task 2017-10-07T06:31:51.569Z] 06:31:51     INFO - Disabling cache and reloading page.
[task 2017-10-07T06:31:51.570Z] 06:31:51     INFO - Request server1.conn1.child1/netEvent27 for http://example.com/browser/devtools/client/netmonitor/test/html_simple-test-page.html not yet done, keep waiting...
[task 2017-10-07T06:31:51.570Z] 06:31:51     INFO - Request server1.conn1.child1/netEvent27 for http://example.com/browser/devtools/client/netmonitor/test/html_simple-test-page.html done
[task 2017-10-07T06:31:51.571Z] 06:31:51     INFO - All requests finished
[task 2017-10-07T06:31:51.571Z] 06:31:51     INFO - Got marker: document::DOMContentLoaded
[task 2017-10-07T06:31:51.571Z] 06:31:51     INFO - Got marker: document::Load
[task 2017-10-07T06:31:51.572Z] 06:31:51     INFO - Got two timeline markers, done waiting
[task 2017-10-07T06:31:51.572Z] 06:31:51     INFO - Cache disabled when the current and all future toolboxes are open.
[task 2017-10-07T06:31:51.573Z] 06:31:51     INFO - TEST-PASS | devtools/client/netmonitor/test/browser_net_copy_headers.js | Request to reconfigure the tab was recorded. - 
[task 2017-10-07T06:31:51.573Z] 06:31:51     INFO - Clearing requests in the console client.
[task 2017-10-07T06:31:51.574Z] 06:31:51     INFO - Clearing requests in the UI.
[task 2017-10-07T06:31:51.574Z] 06:31:51     INFO - Starting test... 
[task 2017-10-07T06:31:51.575Z] 06:31:51     INFO - > Network events progress: 1/13, 0/0, got NetMonitor:NetworkEventUpdating:RequestHeaders for server1.conn1.child1/netEvent28
[task 2017-10-07T06:31:51.575Z] 06:31:51     INFO - > Network events progress: 2/13, 0/0, got NetMonitor:NetworkEventUpdated:RequestHeaders for server1.conn1.child1/netEvent28
[task 2017-10-07T06:31:51.575Z] 06:31:51     INFO - > Network events progress: 3/13, 0/0, got NetMonitor:NetworkEventUpdating:RequestCookies for server1.conn1.child1/netEvent28
[task 2017-10-07T06:31:51.576Z] 06:31:51     INFO - > Network events progress: 4/13, 0/0, got NetMonitor:NetworkEventUpdated:RequestCookies for server1.conn1.child1/netEvent28
[task 2017-10-07T06:31:51.576Z] 06:31:51     INFO - > Network events progress: 5/13, 0/0, got NetMonitor:NetworkEventUpdating:ResponseStart for server1.conn1.child1/netEvent28
[task 2017-10-07T06:31:51.577Z] 06:31:51     INFO - > Network events progress: 6/13, 0/0, got NetMonitor:NetworkEventUpdating:ResponseHeaders for server1.conn1.child1/netEvent28
[task 2017-10-07T06:31:51.577Z] 06:31:51     INFO - > Network events progress: 7/13, 0/0, got NetMonitor:NetworkEventUpdated:ResponseHeaders for server1.conn1.child1/netEvent28
[task 2017-10-07T06:31:51.578Z] 06:31:51     INFO - > Network events progress: 8/13, 0/0, got NetMonitor:NetworkEventUpdating:ResponseCookies for server1.conn1.child1/netEvent28
[task 2017-10-07T06:31:51.579Z] 06:31:51     INFO - > Network events progress: 9/13, 0/0, got NetMonitor:NetworkEventUpdated:ResponseCookies for server1.conn1.child1/netEvent28
[task 2017-10-07T06:31:51.579Z] 06:31:51     INFO - Buffered messages logged at 06:31:51
[task 2017-10-07T06:31:51.580Z] 06:31:51     INFO - > Network events progress: 10/13, 0/0, got NetMonitor:NetworkEventUpdating:EventTimings for server1.conn1.child1/netEvent28
[task 2017-10-07T06:31:51.580Z] 06:31:51     INFO - > Network events progress: 11/13, 0/0, got NetMonitor:NetworkEventUpdated:EventTimings for server1.conn1.child1/netEvent28
[task 2017-10-07T06:31:51.581Z] 06:31:51     INFO - > Network events progress: 12/13, 0/0, got NetMonitor:NetworkEventUpdating:ResponseContent for server1.conn1.child1/netEvent28
[task 2017-10-07T06:31:51.581Z] 06:31:51     INFO - > Network events progress: 13/13, 0/0, got NetMonitor:NetworkEventUpdated:ResponseContent for server1.conn1.child1/netEvent28
[task 2017-10-07T06:31:51.582Z] 06:31:51     INFO - TEST-PASS | devtools/client/netmonitor/test/browser_net_copy_headers.js | Clipboard has the given value - 
[task 2017-10-07T06:31:51.582Z] 06:31:51     INFO - Clipboard contains the currently selected item's request headers.
[task 2017-10-07T06:31:51.583Z] 06:31:51     INFO - Buffered messages finished
[task 2017-10-07T06:31:51.583Z] 06:31:51     INFO - TEST-UNEXPECTED-FAIL | devtools/client/netmonitor/test/browser_net_copy_headers.js | Uncaught exception - at chrome://mochitests/content/browser/devtools/client/netmonitor/test/browser_net_copy_headers.js:69 - TypeError: monitor.panelWin.parent.document.querySelector(...) is null
[task 2017-10-07T06:31:51.584Z] 06:31:51     INFO - Stack trace:
[task 2017-10-07T06:31:51.584Z] 06:31:51     INFO -     setup@chrome://mochitests/content/browser/devtools/client/netmonitor/test/browser_net_copy_headers.js:69:5
[task 2017-10-07T06:31:51.584Z] 06:31:51     INFO -     SimpleTest.waitForClipboard/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1032:12
[task 2017-10-07T06:31:51.585Z] 06:31:51     INFO -     wait@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1019:13
[task 2017-10-07T06:31:51.585Z] 06:31:51     INFO -     SimpleTest.waitForClipboard@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1029:5
[task 2017-10-07T06:31:51.586Z] 06:31:51     INFO -     waitForClipboardPromise/<@chrome://mochitests/content/browser/devtools/client/framework/test/shared-head.js:542:5
[task 2017-10-07T06:31:51.586Z] 06:31:51     INFO -     waitForClipboardPromise@chrome://mochitests/content/browser/devtools/client/framework/test/shared-head.js:541:10
[task 2017-10-07T06:31:51.586Z] 06:31:51     INFO -     @chrome://mochitests/content/browser/devtools/client/netmonitor/test/browser_net_copy_headers.js:68:9
[task 2017-10-07T06:31:51.587Z] 06:31:51     INFO -     Tester_execTest@chrome://mochikit/content/browser-test.js:798:9
[task 2017-10-07T06:31:51.587Z] 06:31:51     INFO -     Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:697:9
[task 2017-10-07T06:31:51.588Z] 06:31:51     INFO -     SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:795:59
[task 2017-10-07T06:31:51.588Z] 06:31:51     INFO -     Tester_execTest@chrome://mochikit/content/browser-test.js:798:9
[task 2017-10-07T06:31:51.588Z] 06:31:51     INFO -     Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:697:9
[task 2017-10-07T06:31:51.589Z] 06:31:51     INFO -     SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:795:59
[task 2017-10-07T06:31:51.589Z] 06:31:51     INFO - Leaving test bound 
[task 2017-10-07T06:31:51.590Z] 06:31:51     INFO - Removing tab.

Failure log devtools: https://treeherder.mozilla.org/logviewer.html#?job_id=135478198&repo=autoland
23:39:23     INFO - TEST-PASS | devtools/client/netmonitor/test/browser_net_prefs-reload.js | Request to reconfigure the tab was recorded. - 
23:39:23     INFO - Clearing requests in the console client.
23:39:23     INFO - Clearing requests in the UI.
23:39:23     INFO - > Network events progress: 1/13, 0/0, got NetMonitor:NetworkEventUpdating:RequestHeaders for server1.conn70.child1/netEvent28
23:39:23     INFO - > Network events progress: 2/13, 0/0, got NetMonitor:NetworkEventUpdated:RequestHeaders for server1.conn70.child1/netEvent28
23:39:23     INFO - > Network events progress: 3/13, 0/0, got NetMonitor:NetworkEventUpdating:RequestCookies for server1.conn70.child1/netEvent28
23:39:23     INFO - > Network events progress: 4/13, 0/0, got NetMonitor:NetworkEventUpdated:RequestCookies for server1.conn70.child1/netEvent28
23:39:23     INFO - > Network events progress: 5/13, 0/0, got NetMonitor:NetworkEventUpdating:ResponseStart for server1.conn70.child1/netEvent28
23:39:23     INFO - > Network events progress: 6/13, 0/0, got NetMonitor:NetworkEventUpdating:ResponseHeaders for server1.conn70.child1/netEvent28
23:39:23     INFO - > Network events progress: 7/13, 0/0, got NetMonitor:NetworkEventUpdated:ResponseHeaders for server1.conn70.child1/netEvent28
23:39:23     INFO - > Network events progress: 8/13, 0/0, got NetMonitor:NetworkEventUpdating:ResponseCookies for server1.conn70.child1/netEvent28
23:39:23     INFO - > Network events progress: 9/13, 0/0, got NetMonitor:NetworkEventUpdated:ResponseCookies for server1.conn70.child1/netEvent28
23:39:23     INFO - > Network events progress: 10/13, 0/0, got NetMonitor:NetworkEventUpdating:EventTimings for server1.conn70.child1/netEvent28
23:39:23     INFO - > Network events progress: 11/13, 0/0, got NetMonitor:NetworkEventUpdated:EventTimings for server1.conn70.child1/netEvent28
23:39:23     INFO - > Network events progress: 12/13, 0/0, got NetMonitor:NetworkEventUpdating:ResponseContent for server1.conn70.child1/netEvent28
23:39:23     INFO - > Network events progress: 13/13, 0/0, got NetMonitor:NetworkEventUpdated:ResponseContent for server1.conn70.child1/netEvent28
23:39:23     INFO - Console message: [JavaScript Warning: "Error in parsing value for ‘transform’ after substituting variables. Generated value was ‘ scaleX(Infinity)’.  Falling back to ‘initial’." {file: "chrome://devtools/content/netmonitor/src/assets/styles/netmonitor.css" line: 717 column: 15285 source: " scaleX(Infinity)"}]
23:39:23     INFO - Buffered messages logged at 23:37:53
23:39:23     INFO - Longer timeout required, waiting longer...  Remaining timeouts: 2
23:39:23     INFO - Buffered messages logged at 23:38:38
23:39:23     INFO - Longer timeout required, waiting longer...  Remaining timeouts: 1
23:39:23     INFO - Buffered messages finished
23:39:23     INFO - TEST-UNEXPECTED-FAIL | devtools/client/netmonitor/test/browser_net_prefs-reload.js | Test timed out - 
23:39:23     INFO - Removing tab.
Flags: needinfo?(odvarko)
@Nicolas: I yet changed the way tests wait for 'all requests finished'.
(now it includes also all 'resolve long string' actions)

Honza
Flags: needinfo?(odvarko)
Comment on attachment 8916692 [details]
Bug 1395759 - Properly wait on payload ready in tests;

https://reviewboard.mozilla.org/r/187786/#review192988

::: devtools/client/netmonitor/src/connector/firefox-data-provider.js:488
(Diff revision 2)
>  
>      return promise;
>    }
>  
>    /**
> +   * Executed after all requested data are received and

Is it still true ? Looking at the code I feel like it is called each time we get an event update. Am I wrong ?
Attachment #8916692 - Flags: review?(nchevobbe) → review+
(In reply to Nicolas Chevobbe [:nchevobbe] from comment #30)
> Is it still true ? Looking at the code I feel like it is called each time we
> get an event update. Am I wrong ?
Ah, comment updated.

There is a few more small changes. Let me know if you have any comments.

I am now waiting for try and I'l try to land again if it's green.

Thanks!
Honza
Pushed by jodvarko@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/116b95159cc9
Properly declare request payload as ready; r=nchevobbe
https://hg.mozilla.org/integration/autoland/rev/be43001142a8
Properly wait on payload ready in tests; r=nchevobbe
https://hg.mozilla.org/mozilla-central/rev/116b95159cc9
https://hg.mozilla.org/mozilla-central/rev/be43001142a8
Status: ASSIGNED → RESOLVED
Closed: 7 years ago
status-firefox58: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 58
This is a pretty regular occurrence on Beta. Please request approval when you get a chance.
Flags: needinfo?(odvarko)
Comment on attachment 8916692 [details]
Bug 1395759 - Properly wait on payload ready in tests;

Approval Request Comment
[Feature/Bug causing the regression]: n/a
[User impact if declined]: No user impact
[Is this code covered by automated tests?]: yes
[Has the fix been verified in Nightly?]: yes
[Needs manual test from QE? If yes, steps to reproduce]:  no
[List of other uplifts needed for the feature/fix]: n/a
[Is the change risky?]: low risk
[Why is the change risky/not risky?]: it's covered by tests and the patch is for fixing a test failure, there is no change visible for the user
[String changes made/needed]: n/a
Flags: needinfo?(odvarko)
Attachment #8916692 - Flags: approval-mozilla-beta?
Comment on attachment 8916692 [details]
Bug 1395759 - Properly wait on payload ready in tests;

As much as I'd like to take this uplift since it fixes an intermittent, the amount of code change is not trivial and makes me anxious to uplift this, it has no real end user benefit/impact. I'd suggest we live with this for a few more weeks on beta :( and let it ride the 58 train.
Attachment #8916692 - Flags: approval-mozilla-beta? → approval-mozilla-beta-
Product: Firefox → DevTools
Moving to p3 because no activity for at least 24 weeks.
See https://github.com/mozilla/bug-handling/blob/master/policy/triage-bugzilla.md#how-do-you-triage for more information
Priority: P1 → P3
Assignee: odvarko → nobody
Severity: normal → S3
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: