Closed Bug 1109238 Opened 5 years ago Closed 5 years ago

Intermittent test_dns_cancel_wrap.js | xpcshell return code: 0 | listener2.onLookupComplete - [listener2.onLookupComplete : 49] 2152398878 == 2147500036

Categories

(Core :: Networking: DNS, defect)

x86
Windows XP
defect
Not set

Tracking

()

RESOLVED FIXED
mozilla38
Tracking Status
firefox36 --- unaffected
firefox37 --- fixed
firefox38 --- fixed
firefox-esr31 --- unaffected

People

(Reporter: RyanVM, Assigned: dragana)

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

07:41:33 INFO - TEST-START | C:/slave/test/build/tests/xpcshell/tests/netwerk/test/unit_ipc/test_dns_cancel_wrap.js
07:41:34 WARNING - TEST-UNEXPECTED-FAIL | C:/slave/test/build/tests/xpcshell/tests/netwerk/test/unit_ipc/test_dns_cancel_wrap.js | xpcshell return code: 0
07:41:34 INFO - TEST-INFO took 1047ms
07:41:34 INFO - >>>>>>>
07:41:34 INFO - PROCESS | 4356 | [4356] WARNING: Couldn't get the user appdata directory. Crash events may not be produced.: file c:\\builds\\moz2_slave\\m-aurora-w32-d-000000000000000\\build\\toolkit\\crashreporter\\nsExceptionHandler.cpp, line 2310
07:41:34 INFO - (xpcshell/head.js) | test MAIN run_test pending (1)
07:41:34 INFO - PROCESS | 4356 | JavaScript strict warning: C:\\slave\\test\\build\\tests\\xpcshell\\head.js, line 1067: ReferenceError: assignment to undeclared variable _XPCSHELL_PROCESS
07:41:34 INFO - PROCESS | 4356 | [Parent 4356] WARNING: Couldn't get the user appdata directory, crash dumps will go in an unusual location: file c:\\builds\\moz2_slave\\m-aurora-w32-d-000000000000000\\build\\toolkit\\crashreporter\\nsExceptionHandler.cpp, line 2349
07:41:34 INFO - PROCESS | 4356 | [Parent 4356] WARNING: Couldn't get the user appdata directory. Crash events may not be produced.: file c:\\builds\\moz2_slave\\m-aurora-w32-d-000000000000000\\build\\toolkit\\crashreporter\\nsExceptionHandler.cpp, line 2310
07:41:34 INFO - (xpcshell/head.js) | test run in child pending (2)
07:41:34 INFO - (xpcshell/head.js) | test MAIN run_test finished (2)
07:41:34 INFO - running event loop
07:41:34 INFO - PROCESS | 4356 | [2836] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file c:\\builds\\moz2_slave\\m-aurora-w32-d-000000000000000\\build\\xpcom\\base\\nsTraceRefcnt.cpp, line 143
07:41:34 INFO - PROCESS | 4356 | [2836] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file c:\\builds\\moz2_slave\\m-aurora-w32-d-000000000000000\\build\\xpcom\\base\\nsTraceRefcnt.cpp, line 143
07:41:34 INFO - PROCESS | 4356 | [2836] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file c:\\builds\\moz2_slave\\m-aurora-w32-d-000000000000000\\build\\xpcom\\base\\nsTraceRefcnt.cpp, line 143
07:41:34 INFO - PROCESS | 4356 | [2836] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file c:\\builds\\moz2_slave\\m-aurora-w32-d-000000000000000\\build\\xpcom\\base\\nsTraceRefcnt.cpp, line 143
07:41:34 INFO - PROCESS | 4356 | [2836] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file c:\\builds\\moz2_slave\\m-aurora-w32-d-000000000000000\\build\\xpcom\\base\\nsTraceRefcnt.cpp, line 143
07:41:34 INFO - PROCESS | 4356 | [Child 2836] WARNING: '!compMgr', file c:/builds/moz2_slave/m-aurora-w32-d-000000000000000/build/xpcom/glue/nsComponentManagerUtils.cpp, line 63
07:41:34 INFO - PROCESS | 4356 | [Child 2836] WARNING: NS_ENSURE_TRUE(svc) failed: file c:\\builds\\moz2_slave\\m-aurora-w32-d-000000000000000\\build\\dom\\ipc\\nsIContentChild.cpp, line 32
07:41:34 INFO - PROCESS | 4356 | [Child 2836] WARNING: Error constructing actor PJavaScriptChild: file c:\\builds\\moz2_slave\\m-aurora-w32-d-000000000000000\\build\\obj-firefox\\ipc\\ipdl\\PContentChild.cpp, line 932
07:41:34 INFO - PROCESS | 4356 | [Parent 4356] WARNING: 'NS_FAILED(rv)', file c:/builds/moz2_slave/m-aurora-w32-d-000000000000000/build/extensions/spellcheck/src/mozPersonalDictionary.cpp, line 135
07:41:34 INFO - CHILD-TEST-STARTED
07:41:34 INFO - (xpcshell/head.js) | test MAIN run_test pending (1)
07:41:34 INFO - (xpcshell/head.js) | test pending (2)
07:41:34 INFO - (xpcshell/head.js) | test pending (3)
07:41:34 INFO - (xpcshell/head.js) | test pending (4)
07:41:34 INFO - (xpcshell/head.js) | test pending (5)
07:41:34 INFO - (xpcshell/head.js) | test pending (6)
07:41:34 INFO - (xpcshell/head.js) | test MAIN run_test finished (6)
07:41:34 INFO - running event loop
07:41:34 INFO - TEST-PASS | C:/slave/test/build/tests/xpcshell/tests/netwerk/test/unit_ipc/test_dns_cancel_wrap.js | listener1.onLookupComplete - [listener1.onLookupComplete : 25] 2147500036 == 2147500036
07:41:34 INFO - (xpcshell/head.js) | test finished (5)
07:41:34 INFO - TEST-PASS | C:/slave/test/build/tests/xpcshell/tests/netwerk/test/unit_ipc/test_dns_cancel_wrap.js | listener1.onLookupComplete - [listener1.onLookupComplete : 25] 2147500036 == 2147500036
07:41:34 INFO - (xpcshell/head.js) | test finished (4)
07:41:34 WARNING - TEST-UNEXPECTED-FAIL | C:/slave/test/build/tests/xpcshell/tests/netwerk/test/unit_ipc/test_dns_cancel_wrap.js | listener2.onLookupComplete - [listener2.onLookupComplete : 49] 2152398878 == 2147500036
07:41:34 INFO - C:/slave/test/build/tests/xpcshell/tests/netwerk/test/unit/test_dns_cancel.js:listener2.onLookupComplete:49
07:41:34 INFO - C:/slave/test/build/tests/xpcshell/head.js:_do_main:184
07:41:34 INFO - C:/slave/test/build/tests/xpcshell/head.js:_execute_test:372
07:41:34 INFO - typein:null:0
07:41:34 INFO - null:null:0
07:41:34 INFO - exiting test
07:41:34 INFO - PROCESS | 4356 | JavaScript error: , line 0: uncaught exception: 2147500036
07:41:34 INFO - TEST-PASS | C:/slave/test/build/tests/xpcshell/tests/netwerk/test/unit_ipc/test_dns_cancel_wrap.js | listener1.onLookupComplete - [listener1.onLookupComplete : 30] 2152398878 != 2147500036
07:41:34 INFO - (xpcshell/head.js) | test finished (3)
07:41:34 INFO - TEST-PASS | C:/slave/test/build/tests/xpcshell/tests/netwerk/test/unit_ipc/test_dns_cancel_wrap.js | listener2.onLookupComplete - [listener2.onLookupComplete : 54] 2152398878 != 2147500036
07:41:34 INFO - (xpcshell/head.js) | test finished (2)
07:41:34 INFO - CHILD-TEST-COMPLETED
07:41:34 INFO - (xpcshell/head.js) | test finished (1)
07:41:34 INFO - exiting test
07:41:34 INFO - PROCESS | 4356 | [Parent 4356] WARNING: RemoveObserver() called for unregistered observer: file c:/builds/moz2_slave/m-aurora-w32-d-000000000000000/build/hal/Hal.cpp, line 205
07:41:34 INFO - PROCESS | 4356 | [Parent 4356] WARNING: RemoveObserver() called for unregistered observer: file c:/builds/moz2_slave/m-aurora-w32-d-000000000000000/build/hal/Hal.cpp, line 205
07:41:34 INFO - PROCESS | 4356 | [Parent 4356] WARNING: RemoveObserver() called for unregistered observer: file c:/builds/moz2_slave/m-aurora-w32-d-000000000000000/build/hal/Hal.cpp, line 205
07:41:34 INFO - PROCESS | 4356 | [Parent 4356] WARNING: RemoveObserver() called for unregistered observer: file c:/builds/moz2_slave/m-aurora-w32-d-000000000000000/build/hal/Hal.cpp, line 205
07:41:34 INFO - PROCESS | 4356 | [Child 2836] WARNING: Exiting child process early!: file c:\\builds\\moz2_slave\\m-aurora-w32-d-000000000000000\\build\\xpcom\\build\\XPCOMInit.cpp, line 966
07:41:34 INFO - PROCESS | 4356 | nsStringStats
07:41:34 INFO - PROCESS | 4356 | => mAllocCount: 4489
07:41:34 INFO - PROCESS | 4356 | => mReallocCount: 222
07:41:34 INFO - PROCESS | 4356 | => mFreeCount: 3150 -- LEAKED 1339 !!!
07:41:34 INFO - PROCESS | 4356 | => mShareCount: 3742
07:41:34 INFO - PROCESS | 4356 | => mAdoptCount: 120
07:41:34 INFO - PROCESS | 4356 | => mAdoptFreeCount: 119 -- LEAKED 1 !!!
07:41:34 INFO - PROCESS | 4356 | => Process ID: 2836, Thread ID: 5708
07:41:34 INFO - PROCESS | 4356 | [Parent 4356] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file c:\\builds\\moz2_slave\\m-aurora-w32-d-000000000000000\\build\\xpcom\\base\\nsTraceRefcnt.cpp, line 143
07:41:34 INFO - PROCESS | 4356 | [Parent 4356] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file c:\\builds\\moz2_slave\\m-aurora-w32-d-000000000000000\\build\\xpcom\\base\\nsTraceRefcnt.cpp, line 143
07:41:34 INFO - PROCESS | 4356 | nsStringStats
07:41:34 INFO - PROCESS | 4356 | => mAllocCount: 4566
07:41:34 INFO - PROCESS | 4356 | => mReallocCount: 221
07:41:34 INFO - PROCESS | 4356 | => mFreeCount: 4566
07:41:34 INFO - PROCESS | 4356 | => mShareCount: 3905
07:41:34 INFO - PROCESS | 4356 | => mAdoptCount: 157
07:41:34 INFO - PROCESS | 4356 | => mAdoptFreeCount: 157
07:41:34 INFO - PROCESS | 4356 | => Process ID: 4356, Thread ID: 5592
07:41:34 INFO - <<<<<<<

I have expected that this could happened. It is a racy test, but that is the only way to test it.
The test start async dns requests and cancel them. 

If this start happening often the only solution is to disable the test. 
I will take a look if some change has caused this, but honestly I do not believe.
Seems to have gotten a lot worse recently.
Flags: needinfo?(dd.mozilla)
Can we change the onLookupComplete methods to count the number of canceled and NS_OK responses it receives? That should provide some test coverage and be reliable.

if we can't think of a way to improve the test we should disable it. It doesn't have a lot of value right now.
(In reply to Ryan VanderMeulen [:RyanVM UTC-5] from comment #28)
> Seems to have gotten a lot worse recently.

I feel like a lot of sparse-orange has gotten a lot worse recently. hmmm.

I just looked at this test and, while its definitely racy, I can't think of anything in gecko that has changed lately that should change its failure rate.
I will look at it.
Flags: needinfo?(dd.mozilla)
This is only happening on MacOSX 10.6 and the code that is tested is not platform specific. I suggest disabling this test for mac on e10s
(In reply to Dragana Damjanovic from comment #36)
> This is only happening on MacOSX 10.6 and the code that is tested is not
> platform specific. I suggest disabling this test for mac on e10s

sometimes we end up disabling on just one platform - but that's usually because we don't understand the failure scenario. That's not really true here.

I'm really not sure what value the test provides as designed on any platform. obviously nobody looks at it if it fails because we assume that its failing for the usual reason.

What about counting the number of cancels and OKs? would that provide something useful?
(In reply to Patrick McManus [:mcmanus] from comment #38)
> (In reply to Dragana Damjanovic from comment #36)
> > This is only happening on MacOSX 10.6 and the code that is tested is not
> > platform specific. I suggest disabling this test for mac on e10s
> 
> sometimes we end up disabling on just one platform - but that's usually
> because we don't understand the failure scenario. That's not really true
> here.
> 
> I'm really not sure what value the test provides as designed on any
> platform. obviously nobody looks at it if it fails because we assume that
> its failing for the usual reason.
> 
> What about counting the number of cancels and OKs? would that provide
> something useful?


The test was implemented when CancelAcyncResolver for e10s was implemented. The test starts a couple of dns queries, different combination of listener, hostname,and flags and cancels some of them. So the test checks if the right request are canceled (with the right combination of listener, flags and host name) and not some other.

Counting number of cancels and oks will not help, because the error here is that some request that should have been canceled got resolved before they were canceled.
If I change the test and run queries and cancel them couple of times we are going to miss some real errors.

I do not see any other way to test CancelAcyncResolver that is not going to be racy.
ok - then lets just disable the test entirely for the moment.
Sorry, once again.

I will turn the logic around:

So I will check only for the requests that should not get canceled. These requests should never get canceled and it this happens we have a problem. If canceled request do not get canceled that is not much of a problem.

so we have a bit of the testing for CancelAcyncResolver.
Attached patch test fixSplinter Review
Assignee: nobody → dd.mozilla
Status: NEW → ASSIGNED
Attachment #8553193 - Flags: review?(mcmanus)
Comment on attachment 8553193 [details] [diff] [review]
test fix

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

that's something!
Attachment #8553193 - Flags: review?(mcmanus) → review+
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/bc72d105c829
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla38
You need to log in before you can comment on or make changes to this bug.