Intermittent test_unregister_invalid_json.js | xpcshell return code: 0

RESOLVED FIXED in Firefox 41

Status

()

Core
DOM: Push Notifications
RESOLVED FIXED
3 years ago
3 years ago

People

(Reporter: KWierso, Assigned: dragana)

Tracking

({intermittent-failure})

40 Branch
mozilla41
intermittent-failure
Points:
---

Firefox Tracking Flags

(firefox39 unaffected, firefox40 unaffected, firefox41 fixed, firefox-esr31 unaffected, firefox-esr38 unaffected)

Details

Attachments

(1 attachment, 1 obsolete attachment)

(Reporter)

Description

3 years ago
14:36:17 INFO - TEST-START | uriloader/exthandler/tests/unit/test_punycodeURIs.js
14:36:19 INFO - TEST-PASS | uriloader/exthandler/tests/unit/test_punycodeURIs.js | took 1624ms
14:36:19 INFO - Retrying tests that failed when run in parallel.
14:36:19 INFO - TEST-START | dom/push/test/xpcshell/test_unregister_invalid_json.js
14:36:21 WARNING - TEST-UNEXPECTED-FAIL | dom/push/test/xpcshell/test_unregister_invalid_json.js | xpcshell return code: 0
14:36:21 INFO - TEST-INFO took 2246ms
14:36:21 INFO - >>>>>>>
14:36:21 INFO - PROCESS | 25619 | [25619] WARNING: Re-registering a CID?: file /builds/slave/m-in-lx-d-00000000000000000000/build/src/xpcom/components/nsComponentManager.cpp, line 551
14:36:21 INFO - PROCESS | 25619 | [25619] WARNING: Couldn't get the user appdata directory. Crash events may not be produced.: file /builds/slave/m-in-lx-d-00000000000000000000/build/src/toolkit/crashreporter/nsExceptionHandler.cpp, line 2312
14:36:21 INFO - (xpcshell/head.js) | test MAIN run_test pending (1)
14:36:21 INFO - (xpcshell/head.js) | test run_next_test 0 pending (2)
14:36:21 INFO - (xpcshell/head.js) | test MAIN run_test finished (2)
14:36:21 INFO - running event loop
14:36:21 INFO - dom/push/test/xpcshell/test_unregister_invalid_json.js | Starting test_unregister_invalid_json
14:36:21 INFO - (xpcshell/head.js) | test test_unregister_invalid_json pending (2)
14:36:21 INFO - PROCESS | 25619 | -*- PushDB.jsm: put(){"channelID":"87902e90-c57e-4d18-8354-013f4a556559","pushEndpoint":"https://example.org/update/1","scope":"https://example.edu/page/1","version":1}
14:36:21 INFO - (xpcshell/head.js) | test run_next_test 0 finished (2)
14:36:21 INFO - PROCESS | 25619 | -*- PushDB.jsm: Request successful. Updated record ID: 87902e90-c57e-4d18-8354-013f4a556559
14:36:21 INFO - PROCESS | 25619 | -*- PushDB.jsm: put(){"channelID":"057caa8f-9b99-47ff-891c-adad18ce603e","pushEndpoint":"https://example.com/update/2","scope":"https://example.net/page/1","version":1}
14:36:21 INFO - PROCESS | 25619 | -*- PushDB.jsm: Request successful. Updated record ID: 057caa8f-9b99-47ff-891c-adad18ce603e
14:36:21 INFO - PROCESS | 25619 | -*- PushDB.jsm: getAllKeyIDs()
14:36:21 INFO - PROCESS | 25619 | -*- PushDB.jsm: getByScope() https://example.edu/page/1
14:36:21 INFO - PROCESS | 25619 | -*- PushDB.jsm: Fetch successful [object Object]
14:36:21 INFO - PROCESS | 25619 | -*- PushServiceWebSocket.jsm: connect
14:36:21 INFO - PROCESS | 25619 | -*- PushServiceWebSocket.jsm: beginWSSetup()
14:36:21 INFO - PROCESS | 25619 | -*- PushServiceWebSocket.jsm: serverURL: wss://push.example.org/
14:36:21 INFO - PROCESS | 25619 | -*- PushServiceWebSocket.jsm: wsOnStart()
14:36:21 INFO - PROCESS | 25619 | -*- PushDB.jsm: getAllKeyIDs()
14:36:21 INFO - PROCESS | 25619 | -*- PushServiceWebSocket.jsm: request() unregister
14:36:21 INFO - PROCESS | 25619 | -*- PushServiceWebSocket.jsm: enqueue
14:36:21 INFO - PROCESS | 25619 | -*- PushServiceWebSocket.jsm: enqueue
14:36:21 INFO - PROCESS | 25619 | -*- PushDB.jsm: delete()
14:36:21 INFO - PROCESS | 25619 | -*- PushDB.jsm: Going to delete 87902e90-c57e-4d18-8354-013f4a556559
14:36:21 INFO - PROCESS | 25619 | -*- PushServiceWebSocket.jsm: Sending message: {"messageType":"hello","uaid":"7f0af1bb-7e1f-4fb8-8e4a-e8de434abde3","channelIDs":["057caa8f-9b99-47ff-891c-adad18ce603e","87902e90-c57e-4d18-8354-013f4a556559"]}
14:36:21 INFO - PROCESS | 25619 | -*- PushServiceWebSocket.jsm: wsOnMessageAvailable() {"messageType":"hello","status":200,"uaid":"7f0af1bb-7e1f-4fb8-8e4a-e8de434abde3"}
14:36:21 INFO - PROCESS | 25619 | -*- PushServiceWebSocket.jsm: handleHelloReply()
14:36:21 INFO - PROCESS | 25619 | -*- PushServiceWebSocket.jsm: New _UAID: 7f0af1bb-7e1f-4fb8-8e4a-e8de434abde3
14:36:21 INFO - PROCESS | 25619 | -*- PushServiceWebSocket.jsm: Sending message: {"channelID":"87902e90-c57e-4d18-8354-013f4a556559","messageType":"unregister"}
14:36:21 INFO - PROCESS | 25619 | -*- PushServiceWebSocket.jsm: wsOnMessageAvailable() );alert(1);(
14:36:21 INFO - PROCESS | 25619 | -*- PushServiceWebSocket.jsm: Parsing JSON failed. text : );alert(1);(
14:36:21 INFO - PROCESS | 25619 | -*- PushDB.jsm: getByKeyID()
14:36:21 INFO - PROCESS | 25619 | -*- PushDB.jsm: Fetch successful undefined
14:36:21 INFO - TEST-PASS | dom/push/test/xpcshell/test_unregister_invalid_json.js | test_unregister_invalid_json - [test_unregister_invalid_json : 67] Failed to delete unregistered record - true == true
14:36:21 INFO - PROCESS | 25619 | -*- PushDB.jsm: getByScope() https://example.net/page/1
14:36:21 INFO - PROCESS | 25619 | -*- PushDB.jsm: Fetch successful [object Object]
14:36:21 INFO - PROCESS | 25619 | -*- PushServiceWebSocket.jsm: request() unregister
14:36:21 INFO - PROCESS | 25619 | -*- PushServiceWebSocket.jsm: enqueue
14:36:21 INFO - PROCESS | 25619 | -*- PushDB.jsm: delete()
14:36:21 INFO - PROCESS | 25619 | -*- PushServiceWebSocket.jsm: Sending message: {"channelID":"057caa8f-9b99-47ff-891c-adad18ce603e","messageType":"unregister"}
14:36:21 INFO - PROCESS | 25619 | -*- PushServiceWebSocket.jsm: wsOnMessageAvailable() );alert(1);(
14:36:21 INFO - PROCESS | 25619 | -*- PushServiceWebSocket.jsm: Parsing JSON failed. text : );alert(1);(
14:36:21 INFO - PROCESS | 25619 | -*- PushDB.jsm: Going to delete 057caa8f-9b99-47ff-891c-adad18ce603e
14:36:21 INFO - PROCESS | 25619 | -*- PushDB.jsm: getByKeyID()
14:36:21 INFO - PROCESS | 25619 | -*- PushDB.jsm: Fetch successful undefined
14:36:21 INFO - TEST-PASS | dom/push/test/xpcshell/test_unregister_invalid_json.js | test_unregister_invalid_json - [test_unregister_invalid_json : 73] Failed to delete unregistered record after receiving invalid JSON - true == true
14:36:21 INFO - (xpcshell/head.js) | test run_next_test 1 pending (2)
14:36:21 INFO - (xpcshell/head.js) | test test_unregister_invalid_json finished (2)
14:36:21 INFO - PROCESS | 25619 | -*- PushServiceWebSocket.jsm: Request timeout: Removing 87902e90-c57e-4d18-8354-013f4a556559
14:36:21 INFO - PROCESS | 25619 | -*- PushServiceWebSocket.jsm: Request timeout: Removing 057caa8f-9b99-47ff-891c-adad18ce603e
14:36:21 INFO - PROCESS | 25619 | -*- PushServiceWebSocket.jsm: shutdownWS()
14:36:21 INFO - PROCESS | 25619 | -*- PushServiceWebSocket.jsm: reconnectAfterBackoff()
14:36:21 INFO - PROCESS | 25619 | -*- PushServiceWebSocket.jsm: _calculateAdaptivePing()
14:36:21 INFO - PROCESS | 25619 | -*- PushServiceWebSocket.jsm: Adaptive ping is disabled
14:36:21 INFO - PROCESS | 25619 | -*- PushServiceWebSocket.jsm: Retry in 150 Try number 1
14:36:21 INFO - (xpcshell/head.js) | test run_next_test 1 finished (1)
14:36:21 INFO - exiting test
14:36:21 INFO - A promise chain failed to handle a rejection: [object Object] - rejection date: Wed Jun 03 2015 14:36:20 GMT-0700 (PDT)
14:36:21 INFO - JS frame :: resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js :: PendingErrors.register :: line 166
14:36:21 INFO - JS frame :: resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js :: this.PromiseWalker.completePromise :: line 691
14:36:21 INFO - JS frame :: resource://gre/modules/PushServiceWebSocket.jsm :: this.PushServiceWebSocket.observe :: line 181
14:36:21 INFO - JS frame :: /builds/slave/test/build/tests/xpcshell/head.js :: _do_main :: line 207
14:36:21 INFO - JS frame :: /builds/slave/test/build/tests/xpcshell/head.js :: _execute_test :: line 513
14:36:21 INFO - JS frame :: -e :: <TOP_LEVEL> :: line 1
14:36:21 INFO - native frame :: <unknown filename> :: <TOP_LEVEL> :: line 0
14:36:21 INFO - A promise chain failed to handle a rejection: [object Object] - rejection date: Wed Jun 03 2015 14:36:20 GMT-0700 (PDT)
14:36:21 INFO - JS frame :: resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js :: PendingErrors.register :: line 166
14:36:21 INFO - JS frame :: resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js :: this.PromiseWalker.completePromise :: line 691
14:36:21 INFO - JS frame :: resource://gre/modules/PushServiceWebSocket.jsm :: this.PushServiceWebSocket.observe :: line 181
14:36:21 INFO - JS frame :: /builds/slave/test/build/tests/xpcshell/head.js :: _do_main :: line 207
14:36:21 INFO - JS frame :: /builds/slave/test/build/tests/xpcshell/head.js :: _execute_test :: line 513
14:36:21 INFO - JS frame :: -e :: <TOP_LEVEL> :: line 1
14:36:21 INFO - native frame :: <unknown filename> :: <TOP_LEVEL> :: line 0
14:36:21 INFO - PROCESS | 25619 | -*- PushDB.jsm: drop()
14:36:21 INFO - PROCESS | 25619 | [25619] WARNING: '!mMainThread', file /builds/slave/m-in-lx-d-00000000000000000000/build/src/xpcom/threads/nsThreadManager.cpp, line 299
14:36:21 INFO - PROCESS | 25619 | [25619] WARNING: 'NS_FAILED(DebuggerOnGCRunnable::Enqueue(aRuntime, aDesc))', file /builds/slave/m-in-lx-d-00000000000000000000/build/src/xpcom/base/CycleCollectedJSRuntime.cpp, line 743
14:36:21 INFO - PROCESS | 25619 | [25619] WARNING: 'NS_FAILED(DebuggerOnGCRunnable::Enqueue(aRuntime, aDesc))', file /builds/slave/m-in-lx-d-00000000000000000000/build/src/xpcom/base/CycleCollectedJSRuntime.cpp, line 743
14:36:21 INFO - PROCESS | 25619 | [25619] WARNING: 'NS_FAILED(DebuggerOnGCRunnable::Enqueue(aRuntime, aDesc))', file /builds/slave/m-in-lx-d-00000000000000000000/build/src/xpcom/base/CycleCollectedJSRuntime.cpp, line 743
14:36:21 INFO - PROCESS | 25619 | [25619] WARNING: 'NS_FAILED(DebuggerOnGCRunnable::Enqueue(aRuntime, aDesc))', file /builds/slave/m-in-lx-d-00000000000000000000/build/src/xpcom/base/CycleCollectedJSRuntime.cpp, line 743
14:36:21 INFO - PROCESS | 25619 | [25619] WARNING: 'NS_FAILED(DebuggerOnGCRunnable::Enqueue(aRuntime, aDesc))', file /builds/slave/m-in-lx-d-00000000000000000000/build/src/xpcom/base/CycleCollectedJSRuntime.cpp, line 743
14:36:21 INFO - PROCESS | 25619 | [25619] WARNING: OOPDeinit() without successful OOPInit(): file /builds/slave/m-in-lx-d-00000000000000000000/build/src/toolkit/crashreporter/nsExceptionHandler.cpp, line 2774
14:36:21 INFO - PROCESS | 25619 | [25619] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/slave/m-in-lx-d-00000000000000000000/build/src/xpcom/base/nsTraceRefcnt.cpp, line 148
14:36:21 INFO - PROCESS | 25619 | [25619] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/slave/m-in-lx-d-00000000000000000000/build/src/xpcom/base/nsTraceRefcnt.cpp, line 148
14:36:21 INFO - PROCESS | 25619 | nsStringStats
14:36:21 INFO - PROCESS | 25619 | => mAllocCount: 4666
14:36:21 INFO - PROCESS | 25619 | => mReallocCount: 344
14:36:21 INFO - PROCESS | 25619 | => mFreeCount: 4666
14:36:21 INFO - PROCESS | 25619 | => mShareCount: 5396
14:36:21 INFO - PROCESS | 25619 | => mAdoptCount: 313
14:36:21 INFO - PROCESS | 25619 | => mAdoptFreeCount: 313
14:36:21 INFO - PROCESS | 25619 | => Process ID: 25619, Thread ID: 2971011264
14:36:21 INFO - <<<<<<<
14:36:21 INFO - TEST-START | services/sync/tests/unit/test_errorhandler.js
14:39:07 INFO - TEST-PASS | services/sync/tests/unit/test_errorhandler.js | took 166171ms
14:39:07 INFO - TEST-START | services/sync/tests/unit/test_syncscheduler.js
14:40:18 INFO - TEST-PASS | services/sync/tests/unit/test_syncscheduler.js | took 70268ms
14:40:18 INFO - Node moz-http2 server shutting down ...
14:40:18 INFO - Node moz-spdy server shutting down ...
14:40:18 INFO - INFO | Result summary:
14:40:18 INFO - INFO | Passed: 2496
14:40:18 WARNING - INFO | Failed: 1
14:40:18 WARNING - One or more unittests failed.
14:40:18 INFO - INFO | Todo: 4
14:40:18 INFO - INFO | Retried: 3
14:40:18 INFO - SUITE-END | took 6672s
14:40:18 ERROR - Return code: 1
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Assignee)

Comment 5

3 years ago
This is probably result of my changes to PushService.
Assignee: nobody → dd.mozilla
Status: NEW → ASSIGNED
Created attachment 8616437 [details] [diff] [review]
1171261.patch

I ran into this fairly consistently, on a slow-ish Mac. I think what's happening is that we're now queuing `unregister` requests, but discarding the promise—so there's no one listening for the rejection when the request times out.

Since we're only interested in tracking `register` requests, it might make sense to only use the pending map for those. What do you think?
Attachment #8616437 - Flags: review?(dd.mozilla)
(Assignee)

Comment 7

3 years ago
(In reply to Kit Cambridge [:kitcambridge] from comment #6)
> Created attachment 8616437 [details] [diff] [review]
> 1171261.patch
> 
> I ran into this fairly consistently, on a slow-ish Mac. I think what's
> happening is that we're now queuing `unregister` requests, but discarding
> the promise—so there's no one listening for the rejection when the request
> times out.
> 
> Since we're only interested in tracking `register` requests, it might make
> sense to only use the pending map for those. What do you think?

WebPush returns promise resolved only if 'unregister' at the PushServer has been a success (maybe something has changed in the last version). So if you make only the changes you suggested to PushServiceWebSocket that will solves this test failure (I expect), but not what SimplePush consumers are expecting. 

What do you think about making this work for both - if it is SimplePush catch the exception and if it is WebPush don't, or something like that ...
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Assignee)

Updated

3 years ago
Attachment #8616437 - Flags: review?(dd.mozilla) → feedback+
> What do you think about making this work for both - if it is SimplePush catch the exception and if it is WebPush don't, or something like that ...

Good call. I think it's not as critical if `unregister` fails—the server should anticipate clients dropping subscriptions, just as clients can expect servers without durable storage to drop subscriptions—but let's make it consistent.
(Assignee)

Comment 13

3 years ago
Comment on attachment 8621999 [details] [diff] [review]
1171261.patch

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

looks good
Attachment #8621999 - Flags: review?(dd.mozilla) → review+
https://hg.mozilla.org/mozilla-central/rev/55c3630373ba
Status: ASSIGNED → RESOLVED
Last Resolved: 3 years ago
status-firefox41: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla41
Comment hidden (Treeherder Robot)
Please nominate this for Aurora approval when you get a chance.
status-firefox39: --- → unaffected
status-firefox40: --- → affected
status-firefox-esr31: --- → unaffected
status-firefox-esr38: --- → unaffected
Flags: needinfo?(dd.mozilla)
(Assignee)

Comment 18

3 years ago
The code that cause this and is fixed with this patch is only added on 3. June so it is not in Aurora. It should not be failing on Aurora.
Flags: needinfo?(dd.mozilla)
Not sure what I was thinking there, thanks.
status-firefox40: affected → unaffected
You need to log in before you can comment on or make changes to this bug.