760360 - Throwing Second RecordsChannel onFlowStoreFailed errors on first sync

Status: RESOLVED DUPLICATE of bug 760614

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

Description

[Tony Chung [:tchung]]

Attachment: full logcat

I'm hitting errors on first time sync in:  Second RecordsChannel onFlowStoreFailed. 

Repro:
1) Install Fennec Inbound, 5-31-2012, HTC Sensation 2.3.4
2) do a first time sync to a large profile, using JPAKE setup
3) Watch logs, and verify errors thrown.  

** See attachment for full logcat.  

Log snippet:  (more in https://gist.github.com/837c88c8895461a8b3c1)
05-31 21:30:35.841: W/RecordUploadRunnable(31405): Got request error: javax.net.ssl.SSLException: Write error: ssl=0x750848: I/O error during system call, Broken pipe
05-31 21:30:35.841: W/RecordUploadRunnable(31405): javax.net.ssl.SSLException: Write error: ssl=0x750848: I/O error during system call, Broken pipe
05-31 21:30:35.841: W/RecordUploadRunnable(31405): 	at org.apache.harmony.xnet.provider.jsse.NativeCrypto.SSL_write(Native Method)
05-31 21:30:35.841: W/RecordUploadRunnable(31405): 	at org.apache.harmony.xnet.provider.jsse.OpenSSLSocketImpl$SSLOutputStream.write(OpenSSLSocketImpl.java:839)
05-31 21:30:35.841: W/RecordUploadRunnable(31405): 	at ch.boye.httpclientandroidlib.impl.io.AbstractSessionOutputBuffer.write(AbstractSessionOutputBuffer.java:153)
05-31 21:30:35.841: W/RecordUploadRunnable(31405): 	at ch.boye.httpclientandroidlib.impl.io.ContentLengthOutputStream.write(ContentLengthOutputStream.java:114)
05-31 21:30:35.841: W/RecordUploadRunnable(31405): 	at ch.boye.httpclientandroidlib.impl.io.ContentLengthOutputStream.write(ContentLengthOutputStream.java:120)
05-31 21:30:35.841: W/RecordUploadRunnable(31405): 	at org.mozilla.gecko.sync.repositories.Server11RepositorySession$RecordUploadRunnable$ByteArraysContentProducer.writeTo(Server11RepositorySession.java:547)
05-31 21:30:35.841: W/RecordUploadRunnable(31405): 	at ch.boye.httpclientandroidlib.entity.EntityTemplate.writeTo(EntityTemplate.java:68)
05-31 21:30:35.841: W/RecordUploadRunnable(31405): 	at ch.boye.httpclientandroidlib.entity.HttpEntityWrapper.writeTo(HttpEntityWrapper.java:96)
05-31 21:30:35.841: W/RecordUploadRunnable(31405): 	at ch.boye.httpclientandroidlib.impl.client.EntityEnclosingRequestWrapper$EntityWrapper.writeTo(EntityEnclosingRequestWrapper.java:108)
05-31 21:30:35.841: W/RecordUploadRunnable(31405): 	at ch.boye.httpclientandroidlib.impl.entity.EntitySerializer.serialize(EntitySerializer.java:120)
05-31 21:30:35.841: W/RecordUploadRunnable(31405): 	at ch.boye.httpclientandroidlib.impl.AbstractHttpClientConnection.sendRequestEntity(AbstractHttpClientConnection.java:263)
05-31 21:30:35.841: W/RecordUploadRunnable(31405): 	at ch.boye.httpclientandroidlib.impl.conn.AbstractClientConnAdapter.sendRequestEntity(AbstractClientConnAdapter.java:227)
05-31 21:30:35.841: W/RecordUploadRunnable(31405): 	at ch.boye.httpclientandroidlib.protocol.HttpRequestExecutor.doSendRequest(HttpRequestExecutor.java:255)
05-31 21:30:35.841: W/RecordUploadRunnable(31405): 	at ch.boye.httpclientandroidlib.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:123)
05-31 21:30:35.841: W/RecordUploadRunnable(31405): 	at ch.boye.httpclientandroidlib.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:645)
05-31 21:30:35.841: W/RecordUploadRunnable(31405): 	at ch.boye.httpclientandroidlib.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:464)
05-31 21:30:35.841: W/RecordUploadRunnable(31405): 	at ch.boye.httpclientandroidlib.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:818)
05-31 21:30:35.841: W/RecordUploadRunnable(31405): 	at ch.boye.httpclientandroidlib.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:752)
05-31 21:30:35.841: W/RecordUploadRunnable(31405): 	at org.mozilla.gecko.sync.net.BaseResource.execute(BaseResource.java:242)
05-31 21:30:35.841: W/RecordUploadRunnable(31405): 	at org.mozilla.gecko.sync.net.BaseResource.go(BaseResource.java:281)
05-31 21:30:35.841: W/RecordUploadRunnable(31405): 	at org.mozilla.gecko.sync.net.BaseResource.post(BaseResource.java:301)
05-31 21:30:35.841: W/RecordUploadRunnable(31405): 	at org.mozilla.gecko.sync.net.SyncStorageRequest.post(SyncStorageRequest.java:170)
05-31 21:30:35.841: W/RecordUploadRunnable(31405): 	at org.mozilla.gecko.sync.repositories.Server11RepositorySession$RecordUploadRunnable.run(Server11RepositorySession.java:607)
05-31 21:30:35.841: W/RecordUploadRunnable(31405): 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1088)
05-31 21:30:35.841: W/RecordUploadRunnable(31405): 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:581)
05-31 21:30:35.841: W/RecordUploadRunnable(31405): 	at java.lang.Thread.run(Thread.java:1027)
05-31 21:30:35.851: W/SynchronizerSession(31405): Second RecordsChannel onFlowStoreFailed. Logging remote store error.
05-31 21:30:35.851: W/SynchronizerSession(31405): javax.net.ssl.SSLException: Write error: ssl=0x750848: I/O error during system call, Broken pipe
05-31 21:30:35.851: W/SynchronizerSession(31405): 	at org.apache.harmony.xnet.provider.jsse.NativeCrypto.SSL_write(Native Method)
05-31 21:30:35.851: W/SynchronizerSession(31405): 	at org.apache.harmony.xnet.provider.jsse.OpenSSLSocketImpl$SSLOutputStream.write(OpenSSLSocketImpl.java:839)
05-31 21:30:35.851: W/SynchronizerSession(31405): 	at ch.boye.httpclientandroidlib.impl.io.AbstractSessionOutputBuffer.write(AbstractSessionOutputBuffer.java:153)
05-31 21:30:35.851: W/SynchronizerSession(31405): 	at ch.boye.httpclientandroidlib.impl.io.ContentLengthOutputStream.write(ContentLengthOutputStream.java:114)
05-31 21:30:35.851: W/SynchronizerSession(31405): 	at ch.boye.httpclientandroidlib.impl.io.ContentLengthOutputStream.write(ContentLengthOutputStream.java:120)
05-31 21:30:35.851: W/SynchronizerSession(31405): 	at org.mozilla.gecko.sync.repositories.Server11RepositorySession$RecordUploadRunnable$ByteArraysContentProducer.writeTo(Server11RepositorySession.java:547)
05-31 21:30:35.851: W/SynchronizerSession(31405): 	at ch.boye.httpclientandroidlib.entity.EntityTemplate.writeTo(EntityTemplate.java:68)
05-31 21:30:35.851: W/SynchronizerSession(31405): 	at ch.boye.httpclientandroidlib.entity.HttpEntityWrapper.writeTo(HttpEntityWrapper.java:96)
05-31 21:30:35.851: W/SynchronizerSession(31405): 	at ch.boye.httpclientandroidlib.impl.client.EntityEnclosingRequestWrapper$EntityWrapper.writeTo(EntityEnclosingRequestWrapper.java:108)
05-31 21:30:35.851: W/SynchronizerSession(31405): 	at ch.boye.httpclientandroidlib.impl.entity.EntitySerializer.serialize(EntitySerializer.java:120)
05-31 21:30:35.851: W/SynchronizerSession(31405): 	at ch.boye.httpclientandroidlib.impl.AbstractHttpClientConnection.sendRequestEntity(AbstractHttpClientConnection.java:263)
05-31 21:30:35.851: W/SynchronizerSession(31405): 	at ch.boye.httpclientandroidlib.impl.conn.AbstractClientConnAdapter.sendRequestEntity(AbstractClientConnAdapter.java:227)
05-31 21:30:35.851: W/SynchronizerSession(31405): 	at ch.boye.httpclientandroidlib.protocol.HttpRequestExecutor.doSendRequest(HttpRequestExecutor.java:255)
05-31 21:30:35.851: W/SynchronizerSession(31405): 	at ch.boye.httpclientandroidlib.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:123)
05-31 21:30:35.851: W/SynchronizerSession(31405): 	at ch.boye.httpclientandroidlib.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:645)
05-31 21:30:35.851: W/SynchronizerSession(31405): 	at ch.boye.httpclientandroidlib.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:464)
05-31 21:30:35.851: W/SynchronizerSession(31405): 	at ch.boye.httpclientandroidlib.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:818)
05-31 21:30:35.851: W/SynchronizerSession(31405): 	at ch.boye.httpclientandroidlib.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:752)
05-31 21:30:35.851: W/SynchronizerSession(31405): 	at org.mozilla.gecko.sync.net.BaseResource.execute(BaseResource.java:242)
05-31 21:30:35.851: W/SynchronizerSession(31405): 	at org.mozilla.gecko.sync.net.BaseResource.go(BaseResource.java:281)
05-31 21:30:35.851: W/SynchronizerSession(31405): 	at org.mozilla.gecko.sync.net.BaseResource.post(BaseResource.java:301)
05-31 21:30:35.851: W/SynchronizerSession(31405): 	at org.mozilla.gecko.sync.net.SyncStorageRequest.post(SyncStorageRequest.java:170)
05-31 21:30:35.851: W/SynchronizerSession(31405): 	at org.mozilla.gecko.sync.repositories.Server11RepositorySession$RecordUploadRunnable.run(Server11RepositorySession.java:607)
05-31 21:30:35.851: W/SynchronizerSession(31405): 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1088)
05-31 21:30:35.851: W/SynchronizerSession(31405): 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:581)
05-31 21:30:35.851: W/SynchronizerSession(31405): 	at java.lang.Thread.run(Thread.java:1027)

Comment 1

[Richard Newman [:rnewman]]

21:53:30 < rnewman> it looks like a straightforward network error
21:54:34 < rnewman> the multiple log lines are because we report the same exception for every failed record

The latter is perhaps not desirable, or at least it's not desirable to log the same exception more than once. Nick?

Comment 2

[Richard Newman [:rnewman]]

Here's the interesting part.

05-31 22:06:51.930: I/RecordsChannel(5481): onFetchCompleted. Stopping consumer once stores are done.
05-31 22:06:51.930: I/RecordsChannel(5481): Fetch timestamp is 1338527204111
05-31 22:06:51.930: I/CRecordConsumer(5481): Consumer is done. Processed 0 records.
05-31 22:06:51.930: I/RecordUploadRunnable(5481): Preparing record upload for 17 records (37187 bytes).
05-31 22:06:52.030: D/class ch.boye.httpclientandroidlib.impl.conn.DefaultClientConnection(5481): Connection closed
05-31 22:06:52.030: D/class ch.boye.httpclientandroidlib.impl.client.DefaultHttpClient(5481): Closing the connection.
05-31 22:06:52.030: D/class ch.boye.httpclientandroidlib.impl.conn.DefaultClientConnection(5481): Connection closed
05-31 22:06:52.030: D/class ch.boye.httpclientandroidlib.impl.conn.DefaultClientConnection(5481): Connection shut down
05-31 22:06:52.040: W/RecordUploadRunnable(5481): Got request error: javax.net.ssl.SSLException: Write error: ssl=0x64cef8: I/O error during system call, Broken pipe
05-31 22:06:52.040: W/RecordUploadRunnable(5481): javax.net.ssl.SSLException: Write error: ssl=0x64cef8: I/O error during system call, Broken pipe


The download takes a long time, so it looks like the connection is being closed (or is detected as being closed). But we're not closing it.

Comment 3

[Tony Chung [:tchung]]

Attachment: 5-30-2012 logcat

Reran a fresh install and sync from the 5-30-2012 nightly build.  history items were sync'd this time, but the network connection failure still exists.

Comment 4

[Richard Newman [:rnewman]]

22:19:13 < tchung> rnewman: 5-30 nightly build repros.  hmm.    
22:19:14 < tchung> https://gist.github.com/4079134d2053ddacc31f

This bug appears to be a broken pipe or otherwise closed connection during/after download, which then manifests as an upload failure.

After Bug 736393, we don't abort on download store failure, but we do fail on upload failure.

So now, rather than failing to upload and continuing on, we fail to upload and quit.

Of course, the original behavior is also awful -- we fail to upload any records, and just carry on. Not good.

The solutions to this are:

Bug 758382: keep rollin'. At least we'll sync the rest of your stuff, and maybe things will work themselves out on another network.

Bug ??????: try to retry or otherwise handle potentially transient network errors. It might be enough to reissue the request, which ought to open a new connection if possible.

Comment 5

[Richard Newman [:rnewman]]

Note that the behavior that Tony observed with an older build is just us skipping over upload failures, which is the "also awful" that I mentioned.

Comment 6

[Allison Naaktgeboren :ally]

syn triage: p1, trying option 2

Comment 7

[Chenxia Liu [:liuche]]

Bug 760614 filed for the general case of retrying connections on unreliable networks.

Comment 8

[Tony Chung [:tchung]]

My reason for blocking nom: the user never actually sees a failed sync message on the phone.  but because of connection timeout, they will also not see the items that never get sync'd, and may wonder why sync was not successful.  

(eg. my first logcat, none of my history items got sync'ed because connection died before the last 18 bookmark records were synced)

Comment 10

[Allison Naaktgeboren :ally]

this is a resolved duplicate, so it should lose its flag.