Closed Bug 982816 Opened 10 years ago Closed 10 years ago

Intermittent test_hawkrequest.js | test failed (with xpcshell return code: 0) | (Sometimes: [Exception... "NS_ERROR_ABORT" nsresult: "0x80004004 (NS_ERROR_ABORT)") | 200 == null

Categories

(Firefox :: Sync, defect)

Product:
Firefox
Component:
Sync
Platform:
x86_64
macOS
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla33
Tracking Flags:
Tracking Status
firefox31 --- fixed
firefox32 --- fixed
firefox33 --- fixed
firefox-esr24 --- unaffected
b2g-v1.4 --- fixed
b2g-v2.0 --- fixed
b2g-v2.1 --- fixed

People

(Reporter: RyanVM, Assigned: sworkman)

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

v1.0 Remove extra calls to nextTest in test_hawkrequest.js
2.51 KB, patch
ckarlof
: review+
Details | Diff | Splinter Review 
https://tbpl.mozilla.org/php/getParsedLog.php?id=36006530&tree=Mozilla-Inbound

Rev4 MacOSX Snow Leopard 10.6 mozilla-inbound opt test xpcshell on 2014-03-12 09:40:15 PDT for push 35e1bf061284
slave: talos-r4-snow-039

09:53:36     INFO -  TEST-INFO | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/services/common/tests/unit/test_hawkrequest.js | running test ...
09:53:36  WARNING -  TEST-UNEXPECTED-FAIL | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/services/common/tests/unit/test_hawkrequest.js | test failed (with xpcshell return code: 0), see following log:
09:53:36     INFO -  >>>>>>>
09:53:36     INFO -  TEST-INFO | (xpcshell/head.js) | test MAIN run_test pending (1)
09:53:36     INFO -  TEST-INFO | (xpcshell/head.js) | test run_next_test 0 pending (2)
09:53:36     INFO -  TEST-INFO | (xpcshell/head.js) | test MAIN run_test finished (2)
09:53:36     INFO -  TEST-INFO | (xpcshell/head.js) | running event loop
09:53:36     INFO -  TEST-INFO | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/services/common/tests/unit/test_hawkrequest.js | Starting test_intl_accept_language
09:53:36     INFO -  TEST-INFO | (xpcshell/head.js) | test test_intl_accept_language pending (2)
09:53:36     INFO -  Services.Common.RESTRequest	TRACE	local time, offset: 1394643216461, 0
09:53:36     INFO -  TEST-INFO | (xpcshell/head.js) | test run_next_test 0 finished (2)
09:53:36     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/services/common/tests/unit/test_hawkrequest.js | [test_intl_accept_language/nextTest/< : 50] "zu-NP;vo" == "zu-NP;vo"
09:53:36     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/services/common/tests/unit/test_hawkrequest.js | [test_intl_accept_language/nextTest/< : 50] "fa-CG;ik" == "fa-CG;ik"
09:53:36     INFO -  TEST-INFO | (xpcshell/head.js) | test run_next_test 1 pending (2)
09:53:36     INFO -  TEST-INFO | (xpcshell/head.js) | test test_intl_accept_language finished (2)
09:53:36     INFO -  TEST-INFO | (xpcshell/head.js) | test run_next_test 1 pending (2)
09:53:36     INFO -  TEST-INFO | (xpcshell/head.js) | test test_intl_accept_language finished (2)
09:53:36     INFO -  TEST-INFO | (xpcshell/head.js) | test run_next_test 1 pending (2)
09:53:36     INFO -  TEST-INFO | (xpcshell/head.js) | test test_intl_accept_language finished (2)
09:53:36     INFO -  TEST-INFO | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/services/common/tests/unit/test_hawkrequest.js | Starting test_hawk_authenticated_request
09:53:36     INFO -  TEST-INFO | (xpcshell/head.js) | test test_hawk_authenticated_request pending (2)
09:53:36     INFO -  Services.Common.RESTRequest	TRACE	local time, offset: 34329720000, -120000
09:53:36     INFO -  TEST-INFO | (xpcshell/head.js) | test run_next_test 1 finished (2)
09:53:36     INFO -  TEST-INFO | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/services/common/tests/unit/test_hawkrequest.js | Starting test_hawk_language_pref_changed
09:53:36     INFO -  TEST-INFO | (xpcshell/head.js) | test test_hawk_language_pref_changed pending (2)
09:53:36     INFO -  Services.Common.RESTRequest	TRACE	local time, offset: 1394643216467, 0
09:53:36     INFO -  TEST-INFO | (xpcshell/head.js) | test run_next_test 1 finished (2)
09:53:36     INFO -  TEST-INFO | (xpcshell/head.js) | test run_next_test 1 finished (1)
09:53:36     INFO -  TEST-INFO | (xpcshell/head.js) | exiting test
09:53:36     INFO -  Services.Common.RESTRequest	TRACE	hawk auth header: Hawk id="eyJleHBpcmVzIjogMTM2NTAxMDg5OC4x", ts="34329600", nonce="xAprKjlQJDE=", hash="DVbZ29jR3iih+4JrtiZ1O6j9P7s0o5GosyGfeodPJ3M=", mac="t94Z1wFKN1R56GtCVQht3v5JwQdzMab+MXKOCqzFqVI="
09:53:36     INFO -  Services.Common.RESTRequest	TRACE	HTTP Header authorization: ***** (suppressed)
09:53:36     INFO -  Services.Common.RESTRequest	TRACE	HTTP Header content-type: application/json
09:53:36     INFO -  Services.Common.RESTRequest	TRACE	HTTP Header accept-language: zu-NP
09:53:36     INFO -  Services.Common.RESTRequest	DEBUG	POST Length: 15
09:53:36     INFO -  Services.Common.RESTRequest	TRACE	POST Body: {"your":"data"}
09:53:36     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/services/common/tests/unit/test_hawkrequest.js | [testFirstLanguage : 182] "zu-NP" == "zu-NP"
09:53:36     INFO -  Services.Common.RESTRequest	TRACE	local time, offset: 1394643216490, 0
09:53:36     INFO -  Services.Common.RESTRequest	TRACE	hawk auth header: Hawk id="eyJleHBpcmVzIjogMTM2NTAxMDg5OC4x", ts="1394643216", nonce="FMa9YXxhboI=", hash="vNZvU+y3rJKqH4hu1yxrNuaijNPgIJ2Rgj/sHzsQhXY=", mac="ocgmJrpFFkAFXDgJaWWJu95sfF8KKM15yMWelwwG8QY="
09:53:36     INFO -  Services.Common.RESTRequest	TRACE	HTTP Header authorization: ***** (suppressed)
09:53:36     INFO -  Services.Common.RESTRequest	TRACE	HTTP Header content-type: application/json
09:53:36     INFO -  Services.Common.RESTRequest	TRACE	HTTP Header accept-language: fa-CG
09:53:36     INFO -  Services.Common.RESTRequest	DEBUG	POST Length: 2
09:53:36     INFO -  Services.Common.RESTRequest	TRACE	POST Body: {}
09:53:36     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/services/common/tests/unit/test_hawkrequest.js | [test_hawk_authenticated_request/server<["/elysium"] : 90] true == true
09:53:36     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/services/common/tests/unit/test_hawkrequest.js | [test_hawk_authenticated_request/server<["/elysium"] : 97] 34329600000 == 34329600000
09:53:36     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/services/common/tests/unit/test_hawkrequest.js | [test_hawk_authenticated_request/server<["/elysium"] : 105] "zu-NP" == zu-NP
09:53:36     INFO -  Services.Common.RESTRequest	TRACE	onStartRequest: POST http://localhost:54280/foo
09:53:36     INFO -  Services.Common.RESTRequest	TRACE	Channel for POST http://localhost:54280/foo returned status code 2147500036
09:53:36  WARNING -  TEST-UNEXPECTED-FAIL | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/services/common/tests/unit/test_hawkrequest.js | [Exception... "NS_ERROR_ABORT"  nsresult: "0x80004004 (NS_ERROR_ABORT)"  location: "JS frame :: resource://services-common/rest.js :: onStopRequest :: line 443"  data: no] == null - See following stack:
09:53:36     INFO -  JS frame :: /builds/slave/talos-slave/test/build/tests/xpcshell/tests/services/common/tests/unit/test_hawkrequest.js :: test_hawk_language_pref_changed/testRequest/< :: line 194
09:53:36     INFO -  JS frame :: resource://services-common/rest.js :: onStopRequest :: line 444
09:53:36     INFO -  JS frame :: /builds/slave/talos-slave/test/build/tests/xpcshell/head.js :: do_get_profile/< :: line 1149
09:53:36     INFO -  JS frame :: /builds/slave/talos-slave/test/build/tests/xpcshell/head.js :: _execute_test :: line 411
09:53:36     INFO -  JS frame :: -e :: <TOP_LEVEL> :: line 1
09:53:36     INFO -  native frame :: <unknown filename> :: <TOP_LEVEL> :: line 0
09:53:36     INFO -  TEST-INFO | (xpcshell/head.js) | exiting test
09:53:36     INFO -  Services.Common.RESTRequest	TRACE	onStartRequest: POST http://localhost:54279/elysium
09:53:36     INFO -  Services.Common.RESTRequest	TRACE	Channel for POST http://localhost:54279/elysium returned status code 2147500036
09:53:36     INFO -  Sync.RESTResponse	DEBUG	Caught exception fetching HTTP status code:Component returned failure code: 0x80040111 (NS_ERROR_NOT_AVAILABLE) [nsIHttpChannel.responseStatus] Stack trace: RESTResponse.prototype.status()@resource://services-common/rest.js:620 < onComplete()@/builds/slave/talos-slave/test/build/tests/xpcshell/tests/services/common/tests/unit/test_hawkrequest.js:118 < onStopRequest()@resource://services-common/rest.js:444 < do_get_profile/<()@/builds/slave/talos-slave/test/build/tests/xpcshell/head.js:1149 < _execute_test()@/builds/slave/talos-slave/test/build/tests/xpcshell/head.js:411 < -e:1 < <file:unknown>
09:53:36  WARNING -  TEST-UNEXPECTED-FAIL | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/services/common/tests/unit/test_hawkrequest.js | 200 == null - See following stack:
09:53:36     INFO -  JS frame :: /builds/slave/talos-slave/test/build/tests/xpcshell/tests/services/common/tests/unit/test_hawkrequest.js :: onComplete :: line 118
09:53:36     INFO -  JS frame :: resource://services-common/rest.js :: onStopRequest :: line 444
09:53:36     INFO -  JS frame :: /builds/slave/talos-slave/test/build/tests/xpcshell/head.js :: do_get_profile/< :: line 1149
09:53:36     INFO -  JS frame :: /builds/slave/talos-slave/test/build/tests/xpcshell/head.js :: _execute_test :: line 411
09:53:36     INFO -  JS frame :: -e :: <TOP_LEVEL> :: line 1
09:53:36     INFO -  native frame :: <unknown filename> :: <TOP_LEVEL> :: line 0
09:53:36     INFO -  TEST-INFO | (xpcshell/head.js) | exiting test
09:53:36     INFO -  TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/services/common/tests/unit/test_hawkrequest.js | [test_hawk_language_pref_changed/server<["/foo"] : 164] "fa-CG" == "fa-CG"
09:53:36     INFO -  !!! error running onStopped callback: TypeError: callback is not a function
09:53:36     INFO -  !!! error running onStopped callback: TypeError: callback is not a function
09:53:36     INFO -  <<<<<<<
Summary: Intermittent test_hawkrequest.js | test failed (with xpcshell return code: 0) | [Exception... "NS_ERROR_ABORT" nsresult: "0x80004004 (NS_ERROR_ABORT)" | 200 == null → Intermittent test_hawkrequest.js | test failed (with xpcshell return code: 0) | (Sometimes: [Exception... "NS_ERROR_ABORT" nsresult: "0x80004004 (NS_ERROR_ABORT)") | 200 == null
Chris, can you take a look at this please? I looked into test_hawkrequest.js because it was consistently failing on WinXP (dbg and opt) with patches from bug 354493 (as per the email thread from last week).

Not sure why my patches exposed anything here - no real changes to timing. But anyway, they did :)

After looking at the test script, I can see some extra calls to nextTest. It's added as a pref observer, so it should be called when the pref changes and the next sub-test checking the next language should be run. However, nextTest is also called by itself resulting in extra calls - I can see 3 of them locally on my mac. And this results in 3 extra calls to run_next_test. So, it's possible that sometimes do_test_finished is called by head.js before the tests are actually complete. Seems plausible, right?

Without the patch, consistent failures like the ones mentioned in this bug: https://tbpl.mozilla.org/?rev=69c3e2088a9f&tree=Try

With the patch, all gone: https://tbpl.mozilla.org/?tree=Try&rev=78cfc7a6fc86
Attachment #8452123 - Flags: review?(ckarlof)
Comment on attachment 8452123 [details] [diff] [review]
v1.0 Remove extra calls to nextTest in test_hawkrequest.js

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

Thanks for spotting that, as well as the overall cleanup! We owe you a beverage of your choice.

::: services/common/tests/unit/test_hawkrequest.js
@@ -63,4 @@
>  
> -        testCount += 1;
> -        setLanguage(languages[testCount]);
> -        nextTest();

This sure looks suspect. :)
Attachment #8452123 - Flags: review?(ckarlof) → review+
https://hg.mozilla.org/mozilla-central/rev/5be37f43c77b
Assignee: nobody → sworkman
Status: NEW → RESOLVED
Closed: 10 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla33
Component: Firefox Sync: Backend → Sync
Product: Cloud Services → Firefox
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: