Closed Bug 951146 Opened 11 years ago Closed 10 years ago

Intermittent browser_webconsole_console_logging_api.js | Timed out while waiting for: 1 message shown for exception (logging turned on)

Categories

(DevTools :: Console, defect)

Product:
DevTools
Component:
Console
Platform:
x86
Linux
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(firefox27 unaffected, firefox28 wontfix, firefox29 fixed, firefox-esr24 unaffected)

Status:
RESOLVED FIXED
Milestone:
Firefox 29
Tracking Flags:
Tracking Status
firefox27 --- unaffected
firefox28 --- wontfix
firefox29 --- fixed
firefox-esr24 --- unaffected

People

(Reporter: RyanVM, Assigned: msucan)

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

bug951146-1.diff
6.59 KB, patch
Details | Diff | Splinter Review 
https://tbpl.mozilla.org/php/getParsedLog.php?id=32067192&tree=Mozilla-Inbound

Rev3 Fedora 12 mozilla-inbound debug test mochitest-browser-chrome on 2013-12-16 18:57:01 PST for push 97822855e969
slave: talos-r3-fed-046

20:43:37     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/devtools/webconsole/test/browser_webconsole_console_logging_api.js | 1 message shown for log (logging turned on)
20:43:37     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/devtools/webconsole/test/browser_webconsole_console_logging_api.js | matched rule: "foo" "bar"
20:43:37     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/devtools/webconsole/test/browser_webconsole_console_logging_api.js | 1 hidden info node via string filtering
20:43:37     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/devtools/webconsole/test/browser_webconsole_console_logging_api.js | 1 message hidden for info (logging turned off)
20:43:37     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/devtools/webconsole/test/browser_webconsole_console_logging_api.js | 1 message shown for info (logging turned on)
20:43:37     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/devtools/webconsole/test/browser_webconsole_console_logging_api.js | matched rule: "foo" "bar"
20:43:38     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/devtools/webconsole/test/browser_webconsole_console_logging_api.js | 1 hidden warn node via string filtering
20:43:38     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/devtools/webconsole/test/browser_webconsole_console_logging_api.js | 1 message hidden for warn (logging turned off)
20:43:38     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/devtools/webconsole/test/browser_webconsole_console_logging_api.js | 1 message shown for warn (logging turned on)
20:43:38     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/devtools/webconsole/test/browser_webconsole_console_logging_api.js | matched rule: "foo" "bar"
20:43:38     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/devtools/webconsole/test/browser_webconsole_console_logging_api.js | 1 hidden error node via string filtering
20:43:38     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/devtools/webconsole/test/browser_webconsole_console_logging_api.js | 1 message hidden for error (logging turned off)
20:43:38     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/devtools/webconsole/test/browser_webconsole_console_logging_api.js | 1 message shown for error (logging turned on)
20:43:38     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/devtools/webconsole/test/browser_webconsole_console_logging_api.js | matched rule: "foo" "bar"
20:43:38     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/devtools/webconsole/test/browser_webconsole_console_logging_api.js | 1 hidden exception node via string filtering
20:43:39     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/devtools/webconsole/test/browser_webconsole_console_logging_api.js | 1 message hidden for exception (logging turned off)
20:43:45     INFO -  --DOCSHELL 0x1025cd48 == 69 [pid = 2197] [id = 6522]
20:43:45     INFO -  --DOCSHELL 0x13423cd8 == 68 [pid = 2197] [id = 6521]
20:43:45     INFO -  --DOCSHELL 0xe83d998 == 67 [pid = 2197] [id = 6520]
20:43:45     INFO -  --DOCSHELL 0x17a9f5e8 == 66 [pid = 2197] [id = 6517]
20:43:45     INFO -  --DOCSHELL 0xd1f15a8 == 65 [pid = 2197] [id = 6516]
20:43:45     INFO -  --DOCSHELL 0x159245e0 == 64 [pid = 2197] [id = 6515]
20:43:45     INFO -  --DOCSHELL 0x14bb1990 == 63 [pid = 2197] [id = 6514]
20:43:45     INFO -  --DOCSHELL 0x15cb0300 == 62 [pid = 2197] [id = 6138]
20:43:45     INFO -  --DOCSHELL 0x17772ca0 == 61 [pid = 2197] [id = 6512]
20:43:45     INFO -  --DOCSHELL 0x17a1d678 == 60 [pid = 2197] [id = 6511]
20:43:45     INFO -  --DOCSHELL 0x17d5e0d8 == 59 [pid = 2197] [id = 6510]
20:43:45     INFO -  --DOCSHELL 0x18bd8408 == 58 [pid = 2197] [id = 6509]
20:43:45     INFO -  --DOCSHELL 0x190713a0 == 57 [pid = 2197] [id = 6508]
20:43:45     INFO -  --DOCSHELL 0x189cc070 == 56 [pid = 2197] [id = 6507]
20:43:45     INFO -  --DOCSHELL 0x17ebac00 == 55 [pid = 2197] [id = 6506]
20:43:45     INFO -  --DOCSHELL 0x11a07c70 == 54 [pid = 2197] [id = 6505]
20:43:45     INFO -  --DOCSHELL 0x11b7edc0 == 53 [pid = 2197] [id = 6503]
20:43:45     INFO -  --DOCSHELL 0x16369f50 == 52 [pid = 2197] [id = 6502]
20:43:45     INFO -  --DOCSHELL 0x192c23e8 == 51 [pid = 2197] [id = 6501]
20:43:45     INFO -  [Parent 2197] WARNING: Detected really long delay between samples, continuing from previous sample: file ../../../content/smil/nsSMILAnimationController.cpp, line 144
20:43:45     INFO -  --DOMWINDOW == 856 (0x1673a7ac) [pid = 2197] [serial = 16236] [outer = (nil)] [url = about:blank]
20:43:45     INFO -  --DOMWINDOW == 855 (0x174600f4) [pid = 2197] [serial = 16195] [outer = (nil)] [url = about:blank]
20:43:45     INFO -  --DOMWINDOW == 854 (0x182edd4c) [pid = 2197] [serial = 16208] [outer = (nil)] [url = chrome://browser/content/devtools/framework/toolbox.xul]
20:43:45     INFO -  --DOMWINDOW == 853 (0x1932b1a4) [pid = 2197] [serial = 16224] [outer = (nil)] [url = about:blank]
20:43:45  WARNING -  TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/devtools/webconsole/test/browser_webconsole_console_logging_api.js | Timed out while waiting for: 1 message shown for exception (logging turned on)
20:43:45     INFO -  Stack trace:
20:43:45     INFO -      JS frame :: chrome://mochitests/content/browser/browser/devtools/webconsole/test/head.js :: wait :: line 361
20:43:45     INFO -      JS frame :: chrome://mochitests/content/browser/browser/devtools/webconsole/test/head.js :: <TOP_LEVEL> :: line 371
20:43:45     INFO -      native frame :: <unknown filename> :: <TOP_LEVEL> :: line 0
20:43:45     INFO -  --DOMWINDOW == 852 (0x194934d4) [pid = 2197] [serial = 16332] [outer = 0x1793e5c4] [url = about:blank]
20:43:45     INFO -  --DOMWINDOW == 851 (0x177ed9f4) [pid = 2197] [serial = 16317] [outer = 0xbb78e34] [url = about:blank]
20:43:45     INFO -  --DOMWINDOW == 850 (0x17bfc1cc) [pid = 2197] [serial = 16315] [outer = 0x17c196ec] [url = about:blank]
20:43:45     INFO -  --DOMWINDOW == 849 (0x16f4bcac) [pid = 2197] [serial = 16307] [outer = 0xfded064] [url = about:blank]
20:43:45     INFO -  --DOMWINDOW == 848 (0xc07ddec) [pid = 2197] [serial = 16337] [outer = 0x170f3ad4] [url = about:blank]
20:43:45     INFO -  --DOMWINDOW == 847 (0x177ee80c) [pid = 2197] [serial = 16345] [outer = 0xf010c34] [url = about:blank]
20:43:45     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/devtools/webconsole/test/browser_webconsole_console_logging_api.js | matched rule: "foo" "bar"
20:43:45     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/devtools/webconsole/test/browser_webconsole_console_logging_api.js | 1 hidden debug node via string filtering
20:43:45     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/devtools/webconsole/test/browser_webconsole_console_logging_api.js | 1 message hidden for debug (logging turned off)
20:43:45     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/devtools/webconsole/test/browser_webconsole_console_logging_api.js | 1 message shown for debug (logging turned on)
20:43:45     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/devtools/webconsole/test/browser_webconsole_console_logging_api.js | matched rule: "foo" "bar"
20:43:46     INFO -  TEST-INFO | MEMORY STAT vsize after test: 1295003648
20:43:46     INFO -  TEST-INFO | MEMORY STAT residentFast after test: 679628800
20:43:46     INFO -  INFO TEST-END | chrome://mochitests/content/browser/browser/devtools/webconsole/test/browser_webconsole_console_logging_api.js | finished in 10846ms
Disabling test on Linux for too many intermittent failures.
Whiteboard: [test disabled on linux] [leave open]
Made a patch, waiting for try results: https://tbpl.mozilla.org/?tree=Try&rev=7567047c4588

If this is green, I will attach the patch here and I will land it in fx-team.
Assignee: nobody → mihai.sucan
Status: NEW → ASSIGNED
(In reply to Mihai Sucan [:msucan] from comment #77)
> Made a patch, waiting for try results:
> https://tbpl.mozilla.org/?tree=Try&rev=7567047c4588
> 
> If this is green, I will attach the patch here and I will land it in fx-team.

Have requested some retriggers; thank you for taking a look at this! :-)
(In reply to Ed Morley [:edmorley UTC+0] from comment #78)
> (In reply to Mihai Sucan [:msucan] from comment #77)
> > Made a patch, waiting for try results:
> > https://tbpl.mozilla.org/?tree=Try&rev=7567047c4588
> > 
> > If this is green, I will attach the patch here and I will land it in fx-team.
> 
> Have requested some retriggers; thank you for taking a look at this! :-)

Thanks for the retriggers. Sorry I got to fix these tests so late - holidays then high-priority work. Please always feel free to disable misbehaving tests.
Attached patch bug951146-1.diff — — Splinter Review 
Try push seems green. There's a different console intermittent test failure that shows up in the retriggers. I'll investigate that, separately.

Again, here we had waitForSuccess() problems with slow machines.

r=me

Landed: https://hg.mozilla.org/integration/fx-team/rev/f5651e975e71
Whiteboard: [test disabled on linux] [leave open] → [fixed-in-fx-team]
Big thank you! :-)
I don't suppose at some point (no rush) you could take a glance at https://developer.mozilla.org/en-US/docs/Mozilla/QA/Avoiding_intermittent_oranges and see if any of the patterns you've seen whilst fixing various oranges recently aren't documented? :-)

(We're going to start advertising that page more to both new hires & reviewers, in the hope that we can stop a proportion of our intermittents before they even reach the tree).
(In reply to Ed Morley [:edmorley UTC+0] from comment #82)
> I don't suppose at some point (no rush) you could take a glance at
> https://developer.mozilla.org/en-US/docs/Mozilla/QA/
> Avoiding_intermittent_oranges and see if any of the patterns you've seen
> whilst fixing various oranges recently aren't documented? :-)

The article already covers the problems we've had with various devtools tests. In the specific case of the webconsole, back when I made it async, I underestimated how slow test machines can be and I considered that waiting for a condition 5 seconds "should be enough". The hardest rule, to live and die with, is really never-ever touch anything like timeouts -- always use event listeners. Being newer to the codebase it's quite hard to know which events to use and when. My mistake was to let myself inspired by the waitForClipboard() function I found in some older tests...
Great - thank you for checking :-)
https://hg.mozilla.org/mozilla-central/rev/f5651e975e71
Status: ASSIGNED → RESOLVED
Closed: 10 years ago
Flags: in-testsuite+
Resolution: --- → FIXED
Whiteboard: [fixed-in-fx-team]
Target Milestone: --- → Firefox 29
Product: Firefox → DevTools
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: