Intermittent test_udpsocket.html | Test timed out

RESOLVED FIXED in Firefox 37

Status

()

defect
RESOLVED FIXED
5 years ago
4 years ago

People

(Reporter: RyanVM, Assigned: schien)

Tracking

({intermittent-failure})

Trunk
mozilla40
ARM
Gonk (Firefox OS)
Points:
---
Bug Flags:
in-testsuite +

Firefox Tracking Flags

(firefox37 fixed, firefox38 fixed, firefox39 fixed, firefox40 fixed, firefox-esr31 unaffected, b2g-v2.2 fixed, b2g-master fixed)

Details

Attachments

(2 attachments, 1 obsolete attachment)

Reporter

Description

5 years ago
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
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Put this into my queue.
Assignee: nobody → schien
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
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
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
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 hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
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+
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
If you're around, you should land this over the weekend.
Flags: needinfo?(schien)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
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.
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
https://hg.mozilla.org/mozilla-central/rev/00cab360dc10
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla39
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Reporter

Comment 88

4 years ago
(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 → ---
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Posted 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
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
@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 hidden (Legacy TBPL/Treeherder Robot)
Reporter

Comment 144

4 years ago
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+
Reporter

Comment 146

4 years ago
Thanks Joel :)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Reporter

Comment 151

4 years ago
https://hg.mozilla.org/mozilla-central/rev/61b5d6d08c8a
Status: REOPENED → RESOLVED
Closed: 4 years ago4 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla40
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
You need to log in before you can comment on or make changes to this bug.