Closed Bug 872379 Opened 7 years ago Closed 6 years ago

Intermittent browser_net_sort-01.js,browser_net_sort-02.js,browser_net_sort-03.js | Test timed out, Found a tab

Categories

(DevTools :: Netmonitor, defect)

Product:
DevTools
Component:
Netmonitor
Platform:
x86
Windows XP
Type:
defect
Priority:
Not set

Tracking

(firefox31 fixed, firefox32 fixed, firefox33 fixed, firefox-esr24 unaffected)

Status:
RESOLVED FIXED
Milestone:
Firefox 33
Tracking Flags:
Tracking Status
firefox31 --- fixed
firefox32 --- fixed
firefox33 --- fixed
firefox-esr24 --- unaffected

People

(Reporter: philor, Assigned: sjakthol)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file, 1 obsolete file)

netmonitor-fix-intermittent-timeouts.patch
3.64 KB, patch
vporof
: review+
Details | Diff | Splinter Review 
https://tbpl.mozilla.org/php/getParsedLog.php?id=22963735&tree=Mozilla-Inbound
Rev3 WINNT 5.1 mozilla-inbound debug test mochitest-browser-chrome on 2013-05-14 16:08:50 PDT for push b880a068345e
slave: talos-r3-xp-106

16:58:32     INFO -  TEST-INFO | chrome://mochitests/content/browser/browser/devtools/netmonitor/test/browser_net_sort-02.js | > Network events progress: 17/65, 0/0
16:58:34     INFO -  1368575914674	Services.DataReporting.Policy	DEBUG	Deletion request is scheduled for the future: Wed May 15 2013 16:22:25 GMT-0700 (Pacific Standard Time)
16:58:41     INFO -  --DOMWINDOW == 115 (219F8020) [serial = 10651] [outer = 00000000] [url = chrome://browser/content/devtools/netmonitor.xul]
16:58:41     INFO -  --DOMWINDOW == 114 (1801BEB8) [serial = 10668] [outer = 00000000] [url = http://example.com/browser/browser/devtools/netmonitor/test/html_status-codes-test-page.html]
16:58:41     INFO -  --DOMWINDOW == 113 (18A98058) [serial = 10674] [outer = 00000000] [url = chrome://browser/content/devtools/netmonitor.xul]
16:58:41     INFO -  --DOMWINDOW == 112 (17FBF3F0) [serial = 10670] [outer = 00000000] [url = chrome://browser/content/devtools/framework/toolbox.xul]
16:58:41     INFO -  --DOMWINDOW == 111 (20E5DE30) [serial = 10665] [outer = 00000000] [url = chrome://browser/content/devtools/netmonitor.xul]
16:58:41     INFO -  --DOMWINDOW == 110 (248AB1F0) [serial = 10661] [outer = 00000000] [url = chrome://browser/content/devtools/framework/toolbox.xul]
16:58:41     INFO -  --DOMWINDOW == 109 (22791AE0) [serial = 10647] [outer = 00000000] [url = chrome://browser/content/devtools/framework/toolbox.xul]
16:58:41     INFO -  --DOMWINDOW == 108 (24B449A0) [serial = 10656] [outer = 00000000] [url = about:blank]
16:58:41     INFO -  --DOMWINDOW == 107 (250EAC38) [serial = 10654] [outer = 00000000] [url = data:text/html;charset=utf8,<!DOCTYPE%20html><html%20style='height:100%'%20dir='ltr'><head><link%20rel='stylesheet'%20href='chrome://browser/skin/devtools/orion-container.css'></head><body%20style='height:100%;margin:0;overflow:hidden'><div%20id='editor'%20style='height:100%'></div></body></html>]
16:58:41     INFO -  --DOMWINDOW == 106 (22765868) [serial = 10626] [outer = 00000000] [url = about:blank]
16:58:48     INFO -  --DOMWINDOW == 105 (0BF3D4F8) [serial = 10666] [outer = 00000000] [url = about:blank]
16:58:48     INFO -  --DOMWINDOW == 104 (20946820) [serial = 10664] [outer = 00000000] [url = chrome://browser/content/devtools/framework/toolbox.xul]
16:58:48     INFO -  --DOMWINDOW == 103 (181C11B0) [serial = 10662] [outer = 00000000] [url = about:blank]
16:58:48     INFO -  --DOMWINDOW == 102 (19428E30) [serial = 10658] [outer = 00000000] [url = about:blank]
16:58:48     INFO -  --DOMWINDOW == 101 (17DBF068) [serial = 10657] [outer = 00000000] [url = about:blank]
16:58:48     INFO -  --DOMWINDOW == 100 (19364C20) [serial = 10655] [outer = 00000000] [url = data:text/html;charset=utf8,<!DOCTYPE%20html><html%20style='height:100%'%20dir='ltr'><head><link%20rel='stylesheet'%20href='chrome://browser/skin/devtools/orion-container.css'></head><body%20style='height:100%;margin:0;overflow:hidden'><div%20id='editor'%20style='height:100%'></div></body></html>]
16:58:48     INFO -  --DOMWINDOW == 99 (16E23C88) [serial = 10652] [outer = 00000000] [url = about:blank]
16:58:48     INFO -  --DOMWINDOW == 98 (207087E8) [serial = 10650] [outer = 00000000] [url = chrome://browser/content/devtools/framework/toolbox.xul]
16:58:48     INFO -  --DOMWINDOW == 97 (20D2AF48) [serial = 10679] [outer = 00000000] [url = about:blank]
16:58:48     INFO -  --DOMWINDOW == 96 (17513278) [serial = 10675] [outer = 00000000] [url = about:blank]
16:58:48     INFO -  --DOMWINDOW == 95 (219D9098) [serial = 10673] [outer = 00000000] [url = chrome://browser/content/devtools/framework/toolbox.xul]
16:58:48     INFO -  --DOMWINDOW == 94 (23CA61A8) [serial = 10671] [outer = 00000000] [url = about:blank]
16:58:48     INFO -  --DOMWINDOW == 93 (16F84260) [serial = 10627] [outer = 00000000] [url = about:blank]
16:58:48     INFO -  --DOMWINDOW == 92 (206D3098) [serial = 10672] [outer = 00000000] [url = http://example.com/browser/browser/devtools/netmonitor/test/html_status-codes-test-page.html]
16:58:58  WARNING -  TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/devtools/netmonitor/test/browser_net_sort-02.js | Test timed out
(screenshot)
16:59:00     INFO -  TEST-INFO | chrome://mochitests/content/browser/browser/devtools/netmonitor/test/browser_net_sort-02.js | finish() was called, cleaning up...
16:59:00     INFO -  INFO TEST-END | chrome://mochitests/content/browser/browser/devtools/netmonitor/test/browser_net_sort-02.js | finished in 30108ms
16:59:00  WARNING -  TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/devtools/netmonitor/test/browser_net_sort-02.js | Found a tab after previous test timed out: http://example.com/browser/browser/devtools/netmonitor/test/html_sorting-test-page.html

https://tbpl.mozilla.org/php/getParsedLog.php?id=22966251&tree=Mozilla-Inbound
Rev3 WINNT 5.1 mozilla-inbound debug test mochitest-browser-chrome on 2013-05-14 17:43:00 PDT for push e1290fb9b72e
slave: talos-r3-xp-079

18:34:13     INFO -  TEST-INFO | chrome://mochitests/content/browser/browser/devtools/netmonitor/test/browser_net_sort-03.js | > Network events progress: 17/65, 0/0
18:34:14     INFO -  --DOMWINDOW == 121 (09BD1438) [serial = 10682] [outer = 00000000] [url = chrome://browser/content/devtools/netmonitor.xul]
18:34:14     INFO -  --DOMWINDOW == 120 (32494238) [serial = 10686] [outer = 00000000] [url = about:blank]
18:34:14     INFO -  --DOMWINDOW == 119 (0CAC6888) [serial = 10684] [outer = 00000000] [url = data:text/html;charset=utf8,<!DOCTYPE%20html><html%20style='height:100%'%20dir='ltr'><head><link%20rel='stylesheet'%20href='chrome://browser/skin/devtools/orion-container.css'></head><body%20style='height:100%;margin:0;overflow:hidden'><div%20id='editor'%20style='height:100%'></div></body></html>]
18:34:14     INFO -  --DOMWINDOW == 118 (178C5FD8) [serial = 10676] [outer = 00000000] [url = http://example.com/browser/browser/devtools/netmonitor/test/html_sorting-test-page.html]
18:34:14     INFO -  --DOMWINDOW == 117 (20B16470) [serial = 10678] [outer = 00000000] [url = chrome://browser/content/devtools/framework/toolbox.xul]
18:34:14     INFO -  1368581654664	Services.DataReporting.Policy	DEBUG	Deletion request is scheduled for the future: Wed May 15 2013 17:56:47 GMT-0700 (Pacific Standard Time)
18:34:21     INFO -  --DOMWINDOW == 116 (214403F8) [serial = 10692] [outer = 00000000] [url = about:blank]
18:34:21     INFO -  --DOMWINDOW == 115 (16A492B8) [serial = 10683] [outer = 00000000] [url = about:blank]
18:34:21     INFO -  --DOMWINDOW == 114 (262FBD38) [serial = 10681] [outer = 00000000] [url = chrome://browser/content/devtools/framework/toolbox.xul]
18:34:21     INFO -  --DOMWINDOW == 113 (242CBE30) [serial = 10688] [outer = 00000000] [url = about:blank]
18:34:21     INFO -  --DOMWINDOW == 112 (2525AE30) [serial = 10687] [outer = 00000000] [url = about:blank]
18:34:21     INFO -  --DOMWINDOW == 111 (17122C48) [serial = 10685] [outer = 00000000] [url = data:text/html;charset=utf8,<!DOCTYPE%20html><html%20style='height:100%'%20dir='ltr'><head><link%20rel='stylesheet'%20href='chrome://browser/skin/devtools/orion-container.css'></head><body%20style='height:100%;margin:0;overflow:hidden'><div%20id='editor'%20style='height:100%'></div></body></html>]
18:34:21     INFO -  --DOMWINDOW == 110 (271F52E0) [serial = 10680] [outer = 00000000] [url = http://example.com/browser/browser/devtools/netmonitor/test/html_sorting-test-page.html]
18:34:23     INFO -  --DOMWINDOW == 109 (2226C080) [serial = 10540] [outer = 00000000] [url = chrome://browser/content/devtools/netmonitor.xul]
18:34:23     INFO -  --DOMWINDOW == 108 (19231E30) [serial = 10543] [outer = 00000000] [url = data:text/html;charset=utf8,<!DOCTYPE%20html><html%20style='height:100%'%20dir='ltr'><head><link%20rel='stylesheet'%20href='chrome://browser/skin/devtools/orion-container.css'></head><body%20style='height:100%;margin:0;overflow:hidden'><div%20id='editor'%20style='height:100%'></div></body></html>]
18:34:23     INFO -  --DOMWINDOW == 107 (21F79528) [serial = 10542] [outer = 00000000] [url = data:text/html;charset=utf8,<!DOCTYPE%20html><html%20style='height:100%'%20dir='ltr'><head><link%20rel='stylesheet'%20href='chrome://browser/skin/devtools/orion-container.css'></head><body%20style='height:100%;margin:0;overflow:hidden'><div%20id='editor'%20style='height:100%'></div></body></html>]
18:34:23     INFO -  --DOMWINDOW == 106 (1968B9D8) [serial = 10547] [outer = 00000000] [url = about:blank]
18:34:23     INFO -  --DOMWINDOW == 105 (183C8D00) [serial = 10546] [outer = 00000000] [url = about:blank]
18:34:30     INFO -  --DOMWINDOW == 104 (19F0D388) [serial = 10551] [outer = 00000000] [url = about:blank]
18:34:30     INFO -  --DOMWINDOW == 103 (26ABE108) [serial = 10550] [outer = 00000000] [url = about:blank]
18:34:30     INFO -  --DOMWINDOW == 102 (227D7598) [serial = 10545] [outer = 00000000] [url = data:text/html;charset=utf8,<!DOCTYPE%20html><html%20style='height:100%'%20dir='ltr'><head><link%20rel='stylesheet'%20href='chrome://browser/skin/devtools/orion-container.css'></head><body%20style='height:100%;margin:0;overflow:hidden'><div%20id='editor'%20style='height:100%'></div></body></html>]
18:34:30     INFO -  --DOMWINDOW == 101 (205B8700) [serial = 10544] [outer = 00000000] [url = data:text/html;charset=utf8,<!DOCTYPE%20html><html%20style='height:100%'%20dir='ltr'><head><link%20rel='stylesheet'%20href='chrome://browser/skin/devtools/orion-container.css'></head><body%20style='height:100%;margin:0;overflow:hidden'><div%20id='editor'%20style='height:100%'></div></body></html>]
18:34:30     INFO -  --DOMWINDOW == 100 (214A3FD0) [serial = 10541] [outer = 00000000] [url = about:blank]
18:34:39  WARNING -  TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/devtools/netmonitor/test/browser_net_sort-03.js | Test timed out
(screenshot)
18:34:40     INFO -  TEST-INFO | chrome://mochitests/content/browser/browser/devtools/netmonitor/test/browser_net_sort-03.js | finish() was called, cleaning up...
18:34:40     INFO -  INFO TEST-END | chrome://mochitests/content/browser/browser/devtools/netmonitor/test/browser_net_sort-03.js | finished in 30123ms
18:34:40  WARNING -  TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/devtools/netmonitor/test/browser_net_sort-03.js | Found a tab after previous test timed out: http://example.com/browser/browser/devtools/netmonitor/test/html_sorting-test-page.html
Attached patch v1 (obsolete) — — Splinter Review 
Either some unexpected caching is going on which confuses waitForNetworkEvents(), or this test just needs a bit more time.
Assignee: nobody → vporof
Status: NEW → ASSIGNED
Attachment #749730 - Flags: review?(dcamp)
Attachment #749730 - Flags: review?(dcamp) → review+
https://hg.mozilla.org/mozilla-central/rev/04da0fd6380b
Status: ASSIGNED → RESOLVED
Closed: 7 years ago
Flags: in-testsuite+
Resolution: --- → FIXED
Target Milestone: --- → Firefox 24
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Assignee: vporof → nobody
Comment on attachment 749730 [details] [diff] [review]
v1

I don't know what's going on here.
Attachment #749730 - Attachment is obsolete: true
https://tbpl.mozilla.org/php/getParsedLog.php?id=24937146&tree=Mozilla-Inbound
Summary: Intermittent browser_net_sort-02.js,browser_net_sort-03.js | Test timed out, Found a tab → Intermittent browser_net_sort-01.js,browser_net_sort-02.js,browser_net_sort-03.js | Test timed out, Found a tab
It seems that "http://example.com/browser/browser/devtools/netmonitor/test/sjs_sorting-test-server.sjs?index=5" isn't fully loading, but just *sometimes*, based on the following log: 

20:05:45     INFO -    "http://example.com/browser/browser/devtools/netmonitor/test/sjs_sorting-test-server.sjs?index=5&0.02198164902577282": {
20:05:45     INFO -      "UPDATING_REQUEST_HEADERS": 1,
20:05:45     INFO -      "RECEIVED_REQUEST_HEADERS": 1,
20:05:45     INFO -      "UPDATING_REQUEST_COOKIES": 1,
20:05:45     INFO -      "RECEIVED_REQUEST_COOKIES": 1,
20:05:45     INFO -      "UPDATING_REQUEST_POST_DATA": 0,
20:05:45     INFO -      "RECEIVED_REQUEST_POST_DATA": 0,
20:05:45     INFO -      "UPDATING_RESPONSE_HEADERS": 0,
20:05:45     INFO -      "RECEIVED_RESPONSE_HEADERS": 0,
20:05:45     INFO -      "UPDATING_RESPONSE_COOKIES": 0,
20:05:45     INFO -      "RECEIVED_RESPONSE_COOKIES": 0,
20:05:45     INFO -      "STARTED_RECEIVING_RESPONSE": 0,
20:05:45     INFO -      "UPDATING_RESPONSE_CONTENT": 0,
20:05:45     INFO -      "RECEIVED_RESPONSE_CONTENT": 0,
20:05:45     INFO -      "UPDATING_EVENT_TIMINGS": 0,
20:05:45     INFO -      "RECEIVED_EVENT_TIMINGS": 0
20:05:45     INFO -    }

Everything except UPDATING_REQUEST_POST_DATA and RECEIVED_REQUEST_POST_DATA should be 1.
Here's a patch that might fix this and bunch of other netmonitor timeouts.

For asynchronous server-js the response timer might be garbage collected before it has a chance to fire. If that happens, no response is sent and thus tests timeout waiting for the missing responses. This patch keeps a reference of the timer around long enough for the timer to fire.

With this patch I was able to run netmonitor tests locally 20 times without any timeouts that might relate to this patch.

By looking at files that use sjs containing timers timeouts in following tests could be caused by this problem:
browser_net_content-type.js
browser_net_copy_image_as_data_uri.js
browser_net_cyrillic-01.js
browser_net_cyrillic-02.js
browser_net_filter-01.js
browser_net_filter-02.js
browser_net_filter-03.js
browser_net_filter-04.js
browser_net_footer-summary.js
browser_net_html-preview.js
browser_net_icon-preview.js
browser_net_image-tooltip.js
browser_net_json_custom_mime.js
browser_net_json-long.js
browser_net_json-malformed.js
browser_net_jsonp.js
browser_net_json_text_mime.js
browser_net_req-resp-bodies.js
browser_net_sort-01.js
browser_net_sort-02.js
browser_net_sort-03.js
browser_net_statistics-01.js
browser_net_statistics-02.js
browser_net_statistics-03.js
browser_net_status-codes.js

By comparing the open timeout bugs with the list above this patch could fix following bugs (some of them did not contain logs anymore so I can't say for sure they are all related):
bug 872379  (timeout of browser_net_sort-01.js)
bug 872379  (timeout of browser_net_sort-02.js)
bug 872379  (timeout of browser_net_sort-03.js)
bug 891053  (timeout of browser_net_status-codes.js)
bug 926669  (timeout of browser_net_filter-03.js)
bug 968218  (timeout of browser_net_req-resp-bodies.js)
bug 969607  (timeout of browser_net_content-type.js)
bug 989186  (timeout of browser_net_filter-02.js)
bug 996459  (timeout of browser_net_icon-preview.js)
bug 998300  (timeout of browser_net_copy_image_as_data_uri.js)
bug 998300  (timeout of browser_net_copy_image_as_data_uri.js)
bug 1000734 (timeout of browser_net_image-tooltip.js)
bug 1002812 (timeout of browser_net_large-response.js)
bug 1004097 (timeout of browser_net_json_custom_mime.js)
bug 1006902 (timeout of browser_net_json-malformed.js)
bug 1015151 (timeout of browser_net_filter-04.js)
bug 1016967 (timeout of browser_net_jsonp.js)
bug 1018940 (timeout of browser_net_html-preview.js)
Attachment #8447892 - Flags: review?(vporof)
Comment on attachment 8447892 [details] [diff] [review]
netmonitor-fix-intermittent-timeouts.patch

Review of attachment 8447892 [details] [diff] [review]:
-----------------------------------------------------------------

This is very interesting! I had a hunch that the fact that we're using nsITimer in the server files might somehow be related to all of this, so I'm loving to see this patch. Thank you so much Sami!
Attachment #8447892 - Flags: review?(vporof) → review+
Assignee: nobody → sjakthol
Target Milestone: Firefox 24 → ---
https://hg.mozilla.org/mozilla-central/rev/73fa8431273d
Status: REOPENED → RESOLVED
Closed: 7 years ago → 6 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 33
Duplicate of this bug: 891053
Duplicate of this bug: 926669
Duplicate of this bug: 968218
Duplicate of this bug: 969607
Duplicate of this bug: 989186
Duplicate of this bug: 996459
Duplicate of this bug: 998300
Duplicate of this bug: 1000734
Duplicate of this bug: 1002812
Duplicate of this bug: 1004097
Duplicate of this bug: 1006902
Duplicate of this bug: 1015151
Duplicate of this bug: 1016967
Duplicate of this bug: 1018940
Product: Firefox → DevTools
You need to log in before you can comment on or make changes to this bug.