Closed Bug 1080130 Opened 12 years ago Closed 11 years ago

Intermittent test_udpsocket.html | Test timed out

Categories

(Core :: DOM: Device Interfaces, defect)

Product:
Core
Component:
DOM: Device Interfaces
Platform:
ARM
Gonk (Firefox OS)
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla40
Tracking Flags:
Tracking Status
firefox37 --- fixed
firefox38 --- fixed
firefox39 --- fixed
firefox40 --- fixed
firefox-esr31 --- unaffected
b2g-v2.2 --- fixed
b2g-master --- fixed

People

(Reporter: RyanVM, Assigned: schien)

Details

(Keywords: intermittent-failure)

Attachments

(2 files, 1 obsolete file)

fix-gc-failure.patch
1.68 KB, patch
khuey
: review+
Details | Diff | Splinter Review
force-gc.patch
937 bytes, patch
jmaher
: review+
Details | Diff | Splinter Review
https://treeherder.mozilla.org/ui/logviewer.html#?job_id=607863&repo=b2g-inbound builder b2g_emulator_vm b2g-inbound debug test mochitest-debug-10 buildid 20141008082311 builduid edf557f913a2411393c9b0cabc908672 results warnings (1) revision b96113fcb2fc661a07d717a4b260bfd67c5d2244 slave tst-linux64-spot-1159 starttime Wed Oct 08 2014 11:40:28 GMT-0400 (Eastern Standard Time) 09:22:21 INFO - 139 INFO TEST-START | /tests/dom/network/tests/test_udpsocket.html 09:22:22 INFO - [Child 795] WARNING: Failed to retarget HTML data delivery to the parser thread.: file ../../../gecko/parser/html/nsHtml5StreamParser.cpp, line 947 09:22:24 INFO - [Child 795] WARNING: NS_ENSURE_TRUE(nsContentUtils::GetCurrentJSContext()) failed: file ../../../gecko/docshell/base/nsDocShell.cpp, line 9036 09:22:25 INFO - [Child 795] WARNING: NS_ENSURE_TRUE(globalObject && globalObject->GetGlobalJSObject()) failed: file ../../../../../gecko/content/html/document/src/nsHTMLContentSink.cpp, line 741 09:22:36 INFO - ###################################### forms.js loaded 09:22:37 INFO - ############################### browserElementPanning.js loaded 09:22:38 INFO - ######################## BrowserElementChildPreload.js loaded 09:22:43 INFO - [Child 906] WARNING: NS_ENSURE_TRUE(startupCache) failed: file ../../../gecko/dom/xbl/nsXBLDocumentInfo.cpp, line 237 09:22:44 INFO - [Child 906] WARNING: NS_ENSURE_TRUE(startupCache) failed: file ../../../gecko/dom/xbl/nsXBLDocumentInfo.cpp, line 305 09:22:45 INFO - [Child 795] WARNING: NS_ENSURE_TRUE(mListeners.Contains(aListener)) failed: file ../../../gecko/dom/mobileconnection/ipc/MobileConnectionChild.cpp, line 79 09:29:44 INFO - 140 INFO test for creating an UDP Socket 09:29:44 INFO - 141 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expect no local port before socket opened 09:29:44 INFO - 142 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expect no local address before socket opened 09:29:44 INFO - 143 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expected no default remote port 09:29:44 INFO - 144 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expected no default remote address 09:29:44 INFO - 145 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expected ready state = opening 09:29:44 INFO - 146 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expected no loopback 09:29:44 INFO - 147 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expect to reuse address 09:29:44 INFO - 148 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expect openedPromise to be resolved after successful socket binding 09:29:44 INFO - 149 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expect allocated a local port 09:29:44 INFO - 150 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expect assigned to default address 09:29:44 INFO - 151 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expected ready state = open 09:29:44 INFO - 152 INFO test for sending string data 09:29:44 INFO - 153 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expected packet from 51798 09:29:44 INFO - 154 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expected same string data 09:29:44 INFO - 155 INFO test for sending ArrayBuffer 09:29:44 INFO - 156 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expected packet from 51798 09:29:44 INFO - 157 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expected same buffer data 09:29:44 INFO - 158 INFO test for sending ArrayBufferView 09:29:44 INFO - 159 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expected packet from 51798 09:29:44 INFO - 160 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expected same buffer data 09:29:44 INFO - 161 INFO test for sending Blob 09:29:44 INFO - 162 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expected packet from 51798 09:29:44 INFO - 163 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expected same string data 09:29:44 INFO - 164 INFO test for sending Big ArrayBuffer 09:29:44 INFO - 165 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expected packet from 51798 09:29:44 INFO - 166 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expected same buffer data [0-1400] 09:29:44 INFO - 167 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expected packet from 51798 09:29:44 INFO - 168 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expected same buffer data [1400-2800] 09:29:44 INFO - 169 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expected packet from 51798 09:29:44 INFO - 170 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expected same buffer data [2800-4096] 09:29:44 INFO - 171 INFO test for sending Big Blob 09:29:44 INFO - 172 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expected packet from 51798 09:29:44 INFO - 173 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expected same buffer data [0-1400] 09:29:44 INFO - 174 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expected packet from 51798 09:29:44 INFO - 175 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expected same buffer data [1400-2800] 09:29:44 INFO - 176 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expected packet from 51798 09:29:44 INFO - 177 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expected same buffer data [2800-4096] 09:29:44 INFO - 178 INFO test for UDP init options 09:29:44 INFO - 179 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expected local address 09:29:44 INFO - 180 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expected remote address 09:29:44 INFO - 181 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expected remote port 09:29:44 INFO - 182 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expected address not reusable 09:29:44 INFO - 183 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expected loopback mode is on 09:29:44 INFO - 184 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expected packet from 56466 09:29:44 INFO - 185 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expected same string data 09:29:44 INFO - 186 INFO test for close 09:29:44 INFO - 187 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expect ready state to be "closed" 09:29:44 INFO - 188 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expected send fail after socket closed 09:29:44 INFO - 189 INFO TEST-PASS | /tests/dom/network/tests/test_udpsocket.html | expected closedPromise is resolved after socket.close() 09:29:44 INFO - 190 INFO test for multicast 09:29:44 INFO - 191 INFO TEST-UNEXPECTED-FAIL | /tests/dom/network/tests/test_udpsocket.html | Test timed out. - expected PASS 09:29:46 INFO - 192 INFO TEST-OK | /tests/dom/network/tests/test_udpsocket.html | took 445067ms Yikes, no wonder why: 09:22:45 INFO - [Child 795] WARNING: NS_ENSURE_TRUE(mListeners.Contains(aListener)) failed: file ../../../gecko/dom/mobileconnection/ipc/MobileConnectionChild.cpp, line 79 09:29:44 INFO - 140 INFO test for creating an UDP Socket
Put this into my queue.
Assignee: nobody → schien
The promise chain doesn't resolve at [1], so that SimpleTest.finish() is never called. This means socket are not opened successfully. There are multiple warning shown at UDPSocketChild.cpp line 222, so I guess these local JS variables are been GC'ed before opened. [1] https://dxr.mozilla.org/mozilla-central/source/dom/network/tests/test_udpsocket.html?from=test_udpsocket.html&case=true#321
Attached patch fix-gc-failure.patch — — Splinter Review
This might be the cure. Unreferenced socket might be GC'ed before open, which will cause the Promise.all(...) being rejected. Passed in my local machine, will submit try request when tree is reopened.
Comment on attachment 8580097 [details] [diff] [review] fix-gc-failure.patch Review of attachment 8580097 [details] [diff] [review]: ----------------------------------------------------------------- I assume this is supposed to test that a socket that is opened is closed when there are no more references to it, and that the intermittent failures are because sometimes we don't even finish opening the socket before it's GCd?
Attachment #8580097 - Flags: review?(khuey) → review+
If you're around, you should land this over the weekend.
Flags: needinfo?(schien)
Flags: needinfo?(schien)
Keywords: checkin-needed
(In reply to Kyle Huey [:khuey] (khuey@mozilla.com) from comment #51) > Comment on attachment 8580097 [details] [diff] [review] > fix-gc-failure.patch > > Review of attachment 8580097 [details] [diff] [review]: > ----------------------------------------------------------------- > > I assume this is supposed to test that a socket that is opened is closed > when there are no more references to it, and that the intermittent failures > are because sometimes we don't even finish opening the socket before it's > GCd? Yes, that's what I observed in comment #17.
https://hg.mozilla.org/mozilla-central/rev/00cab360dc10
Status: NEW → RESOLVED
Closed: 11 years ago
status-firefox39: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla39
(In reply to Treeherder Robot from comment #87) This is on mozilla-central, so it looks like we still have issues :(
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Attached patch force-gc.patch (obsolete) — — Splinter Review
All those timeout happened at testing for open without close. In this test step, we create a bunch of local UDPSocket and waiting for socket close after GC, which is not time-deterministic. Explicitly triggering GC in test case will ensure GC happened right away. try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=20146f9c66d6
Attached patch force-gc.patch — — Splinter Review
@khuey is not available for review recently. @RyanVM could you do this review for the test case modification? This patch will make the GC timing deterministic instead of waiting for GC timer.
Attachment #8587187 - Attachment is obsolete: true
Attachment #8588946 - Flags: review?(ryanvm)
Comment on attachment 8588946 [details] [diff] [review] force-gc.patch Joel, maybe you can help here?
Attachment #8588946 - Flags: review?(ryanvm) → review?(jmaher)
Comment on attachment 8588946 [details] [diff] [review] force-gc.patch Review of attachment 8588946 [details] [diff] [review]: ----------------------------------------------------------------- I assume this is the correct place in the test to call the forceGC
Attachment #8588946 - Flags: review?(jmaher) → review+
Thanks Joel :)
status-b2g-v2.2: fixed → affected
status-b2g-master: fixed → affected
status-firefox38: fixed → affected
status-firefox39: fixed → affected
status-firefox40: --- → affected
Keywords: checkin-needed
Target Milestone: mozilla39 → ---
https://hg.mozilla.org/mozilla-central/rev/61b5d6d08c8a
Status: REOPENED → RESOLVED
Closed: 11 years ago → 11 years ago
status-firefox40: affected → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla40
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: