698803 - Hundreds of failed logins keep Firefox spinning after UI shuts down during TPS tests

Status: RESOLVED FIXED

(Firefox :: Sync, defect)

Description

[Jonathan Griffin (:jgriffin)]

Attachment: Set of sync logs

There is some weird stuff going on with sync on the TPS machine.  Quite often (but not all the time), at the end of a (successful) test phase, TPS will close Firefox, and the UI will close promptly, but the process will continue to spin for 5 minutes or longer. Looking at the weave logs for these spinning processes, I see many hundreds of occurrences of this similar to this:

1320109011366    Sync.Service    DEBUG    Exception: Login failed: error.login.reason.network No traceback available
1320109011366    Sync.Service    DEBUG    Not syncing: login returned false.
1320109011366    Sync.ErrorHandler    TRACE    Notifying weave:ui:clear-error. Status.login is error.login.reason.network. Status.sync is success.sync
1320109011448    Sync.Resource    DEBUG    mesg: GET success 200 https://scl2-sync841.services.mozilla.com/1.1/bm3ajf6kr7afbcmsvr7ikalk6npb4cwz/info/collections
1320109011448    Sync.Resource    DEBUG    GET success 200 https://scl2-sync841.services.mozilla.com/1.1/bm3ajf6kr7afbcmsvr7ikalk6npb4cwz/info/collections
1320109011450    Sync.Service    DEBUG    User-Agent: Firefox/10.0a1 FxSync/1.13.0.20111031015614.
1320109011450    Sync.Service    INFO    Starting sync at 2011-10-31 17:56:51
1320109011450    Sync.Service    DEBUG    In sync: should login.
1320109011450    Sync.Service    TRACE    Event: weave:service:login:start
1320109011450    Sync.Status    DEBUG    Status.service: error.login.failed => success.status_ok
1320109011450    Sync.Status    DEBUG    Status.service: success.status_ok => success.status_ok
1320109011451    Sync.Service    INFO    Logging in user bm3ajf6kr7afbcmsvr7ikalk6npb4cwz
1320109011451    Sync.Service    TRACE    Event: weave:service:verify-login:start
1320109011453    Sync.Service    DEBUG    verifyLogin failed: App. Quitting JS Stack trace: Res_get()@resource.js:483 < ()@service.js:749 < WrappedNotify()@util.js:148 < verifyLogin()@service.js:717 < ()@service.js:1006 < WrappedNotify()@util.js:148 < WrappedLock()@util.js:103 < WrappedCatch()@util.js:77 < WeaveSvc_login()@service.js:980 < ()@service.js:1272 < WrappedCatch()@util.js:77 < sync()@service.js:1268
1320109011453    Sync.Status    DEBUG    Status.login: error.login.reason.network => error.login.reason.network
1320109011453    Sync.Status    DEBUG    Status.service: success.status_ok => error.login.failed
1320109011453    Sync.Service    TRACE    Event: weave:service:verify-login:finish
1320109011453    Sync.Service    TRACE    Event: weave:service:login:error
1320109011453    Sync.SyncScheduler    TRACE    Handling weave:service:login:error
1320109011453    Sync.SyncScheduler    DEBUG    Clearing sync triggers.
1320109011453    Sync.SyncScheduler    TRACE    _checkSync returned "".
1320109011453    Sync.SyncScheduler    DEBUG    Global Score threshold hit, triggering sync.
1320109011453    Sync.SyncScheduler    TRACE    There's already a sync scheduled in -99453 ms.
1320109011453    Sync.SyncScheduler    TRACE    Requested sync should happen right away.
1320109011453    Sync.ErrorHandler    TRACE    Handling weave:service:login:error

As I said, this usually occurs with passing tests, so it usually doesn't cause tests to fail, but perhaps it is contributing to the errors we're seeing. 

Full set of logs from one instance of this attached.

Comment 1

[Philipp von Weitershausen [:philikon]]

I was able to reproduce this problem in a test and fixed it in bug 684798 part 6. Hopefully.

Comment 2

[Jonathan Griffin (:jgriffin)]

(In reply to Philipp von Weitershausen [:philikon] from comment #1)
> I was able to reproduce this problem in a test and fixed it in bug 684798
> part 6. Hopefully.

I just watched the TPS run that occurred after this commit, and didn't see any instances of this problem; as well, the only failure reported is the strange mozmill one, which is no doubt unrelated to this.

Comment 3

[Gregory Szorc [:gps]]

Seems to be fixed from bug 684798.