740326 - Unable to Sync - ch.boye.httpclientandroidlib.impl.conn.tsccm.ThreadSafeClientConnManager( 2443): Closing expired connections

Status: VERIFIED FIXED

(Firefox for Android Graveyard :: Android Sync, defect, P1)

Description

[Aaron Train [:aaronmt]]

I/SyncAuthService( 1745): AccountManager.get(org.mozilla.gecko.sync.setup.SyncAuthenticatorService@41c24ec0)
I/SyncAuthService( 1745): Setting username. Null? false
I/SyncAuthService( 1745): Setting Sync Key. Null? false
I/SyncAdapter( 1745): AccountManagerCallback invoked.
D/SyncAdapter( 1745): Username: n2enpae4egvynkzecwbtnxjfq73fcsxb
D/SyncAdapter( 1745): Server:   https://auth.services.mozilla.com/
D/SyncAdapter( 1745): Password? true
D/SyncAdapter( 1745): Key?      true
I/SyncAdapter( 1745): Performing sync.
I/GlobalSession( 1745): GlobalSession initialized with bundle Bundle[{ignore_backoff=true, ignore_settings=true, force=true}]
I/SyncConfiguration( 1745): Set clusterURL from bundle: https://phx-sync507.services.mozilla.com/
I/SyncAdapter( 1745): Stage completed: idle
I/GlobalSession( 1745): Running next stage checkPreconditions (org.mozilla.gecko.sync.stage.CheckPreconditionsStage@41c2ed48)...
I/SyncAdapter( 1745): Stage completed: checkPreconditions
I/GlobalSession( 1745): Running next stage ensureClusterURL (org.mozilla.gecko.sync.stage.EnsureClusterURLStage@41c2eda0)...
I/EnsureClusterURLStage( 1745): Cluster URL is already set and not stale. Continuing with sync.
I/SyncAdapter( 1745): Stage completed: ensureClusterURL
I/GlobalSession( 1745): Running next stage fetchInfoCollections (org.mozilla.gecko.sync.stage.FetchInfoCollectionsStage@41c2edd0)...
D/class ch.boye.httpclientandroidlib.impl.conn.tsccm.ThreadSafeClientConnManager( 1745): Closing expired connections
D/class ch.boye.httpclientandroidlib.impl.conn.tsccm.ConnPoolByRoute( 1745): Closing expired connections
D/class ch.boye.httpclientandroidlib.impl.conn.tsccm.ThreadSafeClientConnManager( 1745): Closing expired connections
D/class ch.boye.httpclientandroidlib.impl.conn.tsccm.ConnPoolByRoute( 1745): Closing expired connections
D/class ch.boye.httpclientandroidlib.impl.conn.tsccm.ThreadSafeClientConnManager( 1745): Closing expired connections
D/class ch.boye.httpclientandroidlib.impl.conn.tsccm.ConnPoolByRoute( 1745): Closing expired connections
D/class ch.boye.httpclientandroidlib.impl.conn.tsccm.ThreadSafeClientConnManager( 1745): Closing expired connections
D/class ch.boye.httpclientandroidlib.impl.conn.tsccm.ConnPoolByRoute( 1745): Closing expired connections
D/class ch.boye.httpclientandroidlib.impl.conn.tsccm.ThreadSafeClientConnManager( 1745): Closing expired connections
D/class ch.boye.httpclientandroidlib.impl.conn.tsccm.ConnPoolByRoute( 1745): Closing expired connections
D/class ch.boye.httpclientandroidlib.impl.conn.tsccm.ThreadSafeClientConnManager( 1745): Closing expired connections
D/class ch.boye.httpclientandroidlib.impl.conn.tsccm.ConnPoolByRoute( 1745): Closing expired connections
D/class ch.boye.httpclientandroidlib.impl.conn.tsccm.ThreadSafeClientConnManager( 1745): Closing expired connections
D/class ch.boye.httpclientandroidlib.impl.conn.tsccm.ConnPoolByRoute( 1745): Closing expired connections

--
Samsung Galaxy Nexus (Android 4.0.2)
20120329040237
Inbound 8dd9a07db9a7

Comment 1

[Aaron Train [:aaronmt]]

This repeats ad infinitum.

Comment 2

[Tony Chung [:tchung]]

I can reproduce easily.  My logcat is flooded with these requests.

03-29 08:45:27.448: DEBUG/class ch.boye.httpclientandroidlib.impl.conn.tsccm.ConnPoolByRoute(1999): Closing expired connections
03-29 08:45:32.440: DEBUG/class ch.boye.httpclientandroidlib.impl.conn.tsccm.ThreadSafeClientConnManager(1999): Closing expired connections
03-29 08:45:32.440: DEBUG/class ch.boye.httpclientandroidlib.impl.conn.tsccm.ConnPoolByRoute(1999): Closing expired connections
03-29 08:45:37.448: DEBUG/class ch.boye.httpclientandroidlib.impl.conn.tsccm.ThreadSafeClientConnManager(1999): Closing expired connections
03-29 08:45:37.448: DEBUG/class ch.boye.httpclientandroidlib.impl.conn.tsccm.ConnPoolByRoute(1999): Closing expired connections
03-29 08:45:42.448: DEBUG/class ch.boye.httpclientandroidlib.impl.conn.tsccm.ThreadSafeClientConnManager(1999): Closing expired connections
03-29 08:45:42.448: DEBUG/class ch.boye.httpclientandroidlib.impl.conn.tsccm.ConnPoolByRoute(1999): Closing expired connections
03-29 08:45:47.448: DEBUG/class ch.boye.httpclientandroidlib.impl.conn.tsccm.ThreadSafeClientConnManager(1999): Closing expired connections
03-29 08:45:47.448: DEBUG/class ch.boye.httpclientandroidlib.impl.conn.tsccm.ConnPoolByRoute(1999): Closing expired connections
03-29 08:45:52.448: DEBUG/class ch.boye.httpclientandroidlib.impl.conn.tsccm.ThreadSafeClientConnManager(1999): Closing expired connections
03-29 08:45:52.448: DEBUG/class ch.boye.httpclientandroidlib.impl.conn.tsccm.ConnPoolByRoute(1999): Closing expired connections

Comment 3

[Tracy Walker [:tracy]]

These messages aren't there until sync is connected to an account.

UI corroborates sync failure as the syncing icon in Settings > Accounts & Sync > Sync Nightly just spins endlessly.  Sync is untestable with nightly build of 20120329. 
 
What? ...removing the Sync Account doesn't stop the "Closing expired connections" messages from continuing.  Force stopping nightly is required at that point.  restart Nightly without connecting to Sync and the "Closing expired connections" messages aren't there.

Comment 4

[Richard Newman [:rnewman]]

(In reply to Tracy Walker [:tracy] from comment #3)

Weird. I take back what I said in my email!

I've seen this precisely once, ever; it disappeared on my next install. I don't know why.

> What? ...removing the Sync Account doesn't stop the "Closing expired
> connections" messages from continuing.  Force stopping nightly is required
> at that point.  restart Nightly without connecting to Sync and the "Closing
> expired connections" messages aren't there.

This is a separate thread acting in-process; so long as Fennec hasn't been killed by the OS, this will continue to happen.

Comment 5

[Richard Newman [:rnewman]]

Can I get a log with timestamps from the start of the sync, Tracy?

* Uninstall Fennec
* Install Fennec
* Run this in a terminal on your machine:

https://gist.github.com/2240379

* Set up Sync
* Turn on logging in a terminal with infinite scrollback, or pipe to a file.

You'll get a lot of log output.

Thanks!

Comment 6

[Nick Alexander :nalexander [he/him]]

I get

could not set property

on the LOG_TAG mentioned early (sync res delegate).

Comment 7

[Tracy Walker [:tracy]]

Attachment: bug log from eclipse

I get could not set property as well.

supplying log from eclipse from just before sync begins setup to well after it begins failing

Comment 8

[Richard Newman [:rnewman]]

Fixed in inbound:

https://hg.mozilla.org/integration/mozilla-inbound/rev/dee1a66e125b

Someone who's not on PTO can pull that into m-c if it's urgent.

Comment 9

[Mark Finkle (:mfinkle) (use needinfo?)]

(In reply to Richard Newman [:rnewman] from comment #8)
> Fixed in inbound:
> 
> https://hg.mozilla.org/integration/mozilla-inbound/rev/dee1a66e125b
> 
> Someone who's not on PTO can pull that into m-c if it's urgent.

Normal m-i to m-c is fine

Comment 10

[Tracy Walker [:tracy]]

confirmed the patch fixed Android Sync with rnewmans build on people.

Comment 11

[Aaron Train [:aaronmt]]

Verified fixed on latest-inbound -- back in business. Thanks.

Comment 12

[Ed Morley [:emorley]]

(Don't believe checkin-needed should still be set, please revert if not the case)

https://hg.mozilla.org/mozilla-central/rev/dee1a66e125b

Comment 13

[Tony Chung [:tchung]]

Verified on trunk

Comment 14

[Mark Finkle (:mfinkle) (use needinfo?)]

https://hg.mozilla.org/releases/mozilla-aurora/rev/d56f6d981918

Comment 15

[Paul Feher]

Verified/fixed on:
Aurora Fennec 13.0a2 (2012-04-06)
Nightly Fennec 14.0a1 (2012-04-06)
Device: HTC Desire
OS: Android 2.2.2