Closed Bug 1253816 Opened 8 years ago Closed 7 years ago

Intermittent browser_web_channel.js | This test exceeded the timeout threshold. It should be rewritten or split up.

Categories

(Firefox :: General, defect, P3)

Product:
Firefox
Component:
General
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
Firefox 53
Tracking Flags:
Tracking Status
firefox51 --- fixed
firefox52 --- fixed
firefox53 --- fixed

People

(Reporter: philor, Assigned: markh)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

Bug 1253816 - requestLongerTimeout due to timeouts in debug builds.
59 bytes, text/x-review-board-request
jmaher
: review+
Details 
Bulk assigning P3 to all open intermittent bugs without a priority set in Firefox components per bug 1298978.
Priority: -- → P3
See Also: → 1253815
this test is one of our most frequent failure.  It is linux debug only but not restricted to e10s or non-e10s.

I see a normal run on linux32 debug e10s showing:
TEST-OK | browser/base/content/test/general/browser_web_channel.js | took 34878ms


when it fails, I see a lot of errors in the log file [0], specifically like this:
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | undefined assertion name - 
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | undefined assertion name - 
01:54:43     INFO - Running: WebChannel generic message in a private window.
01:54:43     INFO - Buffered messages logged at 01:54:02
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | undefined assertion name - 
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | undefined assertion name - 
01:54:43     INFO - Buffered messages logged at 01:54:03
01:54:43     INFO - Running: WebChannel two way communication
01:54:43     INFO - Buffered messages logged at 01:54:04
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | bad id - 
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | command not ok - 
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | bad id - 
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | command not ok - 
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | undefined assertion name - 
01:54:43     INFO - Running: WebChannel two way communication in an iframe
01:54:43     INFO - Buffered messages logged at 01:54:08
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | bad id (2) - 
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | command not ok (2) - 
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | bad id (2) - 
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | command not ok (2) - 
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | undefined assertion name - 
01:54:43     INFO - Running: WebChannel response to a redirected iframe
01:54:43     INFO - Buffered messages logged at 01:54:16
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | undefined assertion name - 
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | undefined assertion name - 
01:54:43     INFO - Buffered messages logged at 01:54:17
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | undefined assertion name - 
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | undefined assertion name - 
01:54:43     INFO - Console message: [JavaScript Error: "WebChannel message failed. Principal mismatch." {file: "chrome://global/content/browser-content.js" line: 946}]
01:54:43     INFO - Running: WebChannel multichannel
01:54:43     INFO - Buffered messages logged at 01:54:18
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | undefined assertion name - 
01:54:43     INFO - Console message: [JavaScript Error: "wrongchannel error message. No Such Channel" {file: "resource://gre/modules/WebChannel.jsm" line: 148}]
01:54:43     INFO - _sendErrorEventToContent@resource://gre/modules/WebChannel.jsm:148:5
01:54:43     INFO - _listener@resource://gre/modules/WebChannel.jsm:103:11
01:54:43     INFO - 
01:54:43     INFO - Running: WebChannel unsolicited send, using system principal
01:54:43     INFO - Buffered messages logged at 01:54:20
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | undefined assertion name - 
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | undefined assertion name - 
01:54:43     INFO - Buffered messages logged at 01:54:21
01:54:43     INFO - Running: WebChannel unsolicited send, using target origin's principal
01:54:43     INFO - Buffered messages logged at 01:54:22
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | undefined assertion name - 
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | undefined assertion name - 
01:54:43     INFO - Running: WebChannel unsolicited send with principal mismatch
01:54:43     INFO - Buffered messages logged at 01:54:24
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | undefined assertion name - 
01:54:43     INFO - Console message: [JavaScript Error: "WebChannel message failed. Principal mismatch." {file: "chrome://global/content/browser-content.js" line: 946}]
01:54:43     INFO - Running: WebChannel non-window target
01:54:43     INFO - Buffered messages logged at 01:54:26
01:54:43     INFO - Running: WebChannel disallows non-string message from non-whitelisted origin
01:54:43     INFO - Buffered messages logged at 01:54:27
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | undefined assertion name - 
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | undefined assertion name - 
01:54:43     INFO - Buffered messages logged at 01:54:28
01:54:43     INFO - Console message: [JavaScript Error: "WebChannelMessageToChrome sent with an object from a non-whitelisted principal" {file: "chrome://global/content/browser-content.js" line: 908}]
01:54:43     INFO - Running: WebChannel allows both string and non-string message from whitelisted origin
01:54:43     INFO - Buffered messages logged at 01:54:30
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | undefined assertion name - 
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | undefined assertion name - 
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | undefined assertion name - 
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | undefined assertion name - 
01:54:43     INFO - Buffered messages logged at 01:54:36
01:54:43     INFO - Running: WebChannel errors handling the message are delivered back to content
01:54:43     INFO - Buffered messages logged at 01:54:37
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | undefined assertion name - 
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | undefined assertion name - 
01:54:43     INFO - Console message: [JavaScript Error: "Failed to execute WebChannel callback:" {file: "resource://gre/modules/WebChannel.jsm" line: 330}]
01:54:43     INFO - deliver@resource://gre/modules/WebChannel.jsm:330:9
01:54:43     INFO - _listener@resource://gre/modules/WebChannel.jsm:97:13
01:54:43     INFO - 
01:54:43     INFO - Console message: [JavaScript Error: "oh no" {file: "chrome://mochitests/content/browser/browser/base/content/test/general/browser_web_channel.js" line: 443}]
01:54:43     INFO - run/testDonePromise</<@chrome://mochitests/content/browser/browser/base/content/test/general/browser_web_channel.js:443:17
01:54:43     INFO - deliver@resource://gre/modules/WebChannel.jsm:324:9
01:54:43     INFO - _listener@resource://gre/modules/WebChannel.jsm:97:13
01:54:43     INFO - 
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | undefined assertion name - 
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | undefined assertion name - 
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | undefined assertion name - 
01:54:43     INFO - Running: WebChannel errors due to an invalid channel are delivered back to content
01:54:43     INFO - Buffered messages logged at 01:54:39
01:54:43     INFO - Console message: [JavaScript Error: "invalid-channel error message. No Such Channel" {file: "resource://gre/modules/WebChannel.jsm" line: 148}]
01:54:43     INFO - _sendErrorEventToContent@resource://gre/modules/WebChannel.jsm:148:5
01:54:43     INFO - _listener@resource://gre/modules/WebChannel.jsm:103:11
01:54:43     INFO - 
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | undefined assertion name - 
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | undefined assertion name - 
01:54:43     INFO - TEST-PASS | browser/base/content/test/general/browser_web_channel.js | undefined assertion name - 
01:54:43     INFO - Buffered messages finished
01:54:43     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/general/browser_web_channel.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. - 
01:54:43     INFO - MEMORY STAT | vsize 1214MB | residentFast 308MB | heapAllocated 116MB
01:54:43     INFO - TEST-OK | browser/base/content/test/general/browser_web_channel.js | took 46036ms


[0] - https://archive.mozilla.org/pub/firefox/tinderbox-builds/mozilla-inbound-linux-debug/1482914258/mozilla-inbound_ubuntu32_vm-debug_test-mochitest-e10s-browser-chrome-5-bm04-tests1-linux32-build63.txt.gz


:rfkelly, I see you modified this test most recently- can you help fix this or find someone who could?
Flags: needinfo?(rfkelly)
> this test is one of our most frequent failure.  It is linux debug only 

I wonder what makes the **debug** build act differently...  
 Mark, any ideas?

I'm going to try running that locally.
Flags: needinfo?(rfkelly) → needinfo?(markh)
Here's a summary of recent test times, in case that helps:

Test durations for browser/base/content/test/general/browser_web_channel.js on mozilla-central,mozilla-inbound,autoland between Dec 22 and Dec 29:
linux32/debug:                  35.17 s (23.27 s - 54.43 s over 15 runs)
linux32/debug-e10s:             38.90 s (32.08 s - 44.90 s over 35 runs)
linux32/opt:                     9.05 s (7.74 s - 10.58 s over 32 runs)
linux32/opt-e10s:               13.47 s (9.50 s - 45.17 s over 28 runs)
linux32/pgo:                     7.59 s (6.12 s - 9.01 s over 16 runs)
linux32/pgo-e10s:               10.25 s (9.40 s - 12.07 s over 11 runs)
linux64/asan-chunked:           22.14 s (16.02 s - 30.23 s over 64 runs)
linux64/asan-e10s:              25.38 s (22.61 s - 30.23 s over 35 runs)
linux64/debug-chunked:          32.12 s (22.87 s - 49.02 s over 64 runs)
linux64/debug-e10s:             35.02 s (29.97 s - 41.98 s over 29 runs)
linux64/opt:                     8.96 s (7.68 s - 10.29 s over 22 runs)
linux64/opt-chunked:            11.12 s (8.21 s - 14.04 s over 26 runs)
linux64/opt-e10s:               13.24 s (10.73 s - 45.16 s over 47 runs)
linux64/pgo:                     7.73 s (7.12 s - 8.75 s over 17 runs)
linux64/pgo-chunked:             8.88 s (7.45 s - 11.05 s over 23 runs)
linux64/pgo-e10s:               10.15 s (9.13 s - 11.27 s over 24 runs)
macosx64/debug:                 12.45 s (9.80 s - 16.30 s over 33 runs)
macosx64/debug-e10s:            10.83 s (9.68 s - 13.49 s over 33 runs)
macosx64/opt:                    4.30 s (3.87 s - 4.98 s over 25 runs)
macosx64/opt-e10s:               5.30 s (5.02 s - 5.70 s over 51 runs)
win32/debug:                    17.53 s (15.55 s - 20.03 s over 15 runs)
win32/debug-e10s:               12.83 s (11.86 s - 14.32 s over 15 runs)
win32/opt:                       3.83 s (3.35 s - 4.26 s over 26 runs)
win32/opt-e10s:                  5.02 s (4.78 s - 5.24 s over 22 runs)
win32/pgo:                       2.84 s (1.64 s - 3.83 s over 18 runs)
win32/pgo-e10s:                  4.37 s (3.01 s - 5.11 s over 19 runs)
win64/debug:                    17.17 s (13.83 s - 20.16 s over 17 runs)
win64/debug-e10s:               12.73 s (11.42 s - 16.53 s over 17 runs)
win64/opt:                       3.56 s (3.18 s - 3.88 s over 24 runs)
win64/opt-e10s:                  4.93 s (4.77 s - 5.11 s over 20 runs)
win64/pgo:                       2.98 s (2.73 s - 3.14 s over 11 runs)
win64/pgo-e10s:                  4.55 s (4.44 s - 4.69 s over 17 runs)

I notice:
 - long average run times on linux/linux64 debug/asan
 - significant variation in run time for linux/linux64 debug and opt-e10s
(In reply to Geoff Brown [:gbrown] from comment #21)
> I notice:
>  - long average run times on linux/linux64 debug/asan
>  - significant variation in run time for linux/linux64 debug and opt-e10s

Isn't the above true for almost all tests? I regularly see debug builds take ~5x as long to run certain tests as the same tests run on opt builds. Indeed, IMO it is a failing of our test infrastructure that it doesn't take this into account when timing out tests, which IME is the most common reason for requestLongerTimeout (eg, [1] - and I suspect that the vast majority of uncommented |requestLongerTimeout(2)| calls are for exactly this issue.)

So I think the most recent change to this file, which added new tests, pushed it over the limit for debug builds and a simple solution would the standard response in this case - a |requestLongerTimeout(2);| call.

[1] Just some examples where a developer actually commented why requestLongerTimeout was added and "debug builds" was the answer
https://dxr.mozilla.org/mozilla-central/source/browser/base/content/test/general/browser_bug590206.js#22
https://dxr.mozilla.org/mozilla-central/source/browser/base/content/test/general/browser_newWindowDrop.js#9
https://dxr.mozilla.org/mozilla-central/source/browser/base/content/test/general/browser_parsable_script.js#89
https://dxr.mozilla.org/mozilla-central/source/browser/base/content/test/tabcrashed/browser_autoSubmitRequest.js#9
https://dxr.mozilla.org/mozilla-central/source/devtools/client/debugger/test/mochitest/browser_dbg_conditional-breakpoints-01.js#13
https://dxr.mozilla.org/mozilla-central/source/devtools/client/framework/test/browser_browser_toolbox.js#5

etc.
Flags: needinfo?(markh)
Comment on attachment 8823150 [details]
Bug 1253816 - requestLongerTimeout due to timeouts in debug builds.

https://reviewboard.mozilla.org/r/101728/#review102246

should we leave this bug open to split it up?
Attachment #8823150 - Flags: review?(jmaher) → review+
Thanks for the review!

(In reply to Joel Maher ( :jmaher) from comment #25)
> should we leave this bug open to split it up?

I don't think it's worthwhile - the test completes in ~10 seconds for opt builds, so I see splitting the test as unnecessary work that will cause either code duplication or complexity (ie, the helpers in that test, either duplicating them or moving them to a different file, far away from where they are used) for what is IMO a test infrastructure issue. I'd much rather see the default timeout for debug builds increased, which would have avoid this bug and others like it being opened in the first place and will avoid many more like it in the future.
Assignee: nobody → markh
Pushed by mhammond@skippinet.com.au:
https://hg.mozilla.org/integration/autoland/rev/85dce4906832
requestLongerTimeout due to timeouts in debug builds. r=jmaher
:gbrown- what do you think about making a longer timeout for debug vs opt?  maybe even asan?  Possibly some analysis of opt vs debug runtimes and we could have a more reliable runtime?
Flags: needinfo?(gbrown)
https://hg.mozilla.org/mozilla-central/rev/85dce4906832
Status: NEW → RESOLVED
Closed: 7 years ago
status-firefox53: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 53
Thanks Joel and Mark - I think increasing some default timeouts certainly deserves consideration. I filed bug 1329034.
Flags: needinfo?(gbrown)
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: