search

jberkel / sms-backup-plus

Backup Android SMS, MMS and call log to Gmail / Gcal / IMAP
https://play.google.com/store/apps/details?id=com.zegoggles.smssync
Apache License 2.0
1.81k stars 498 forks source link

I/O ERROR (timeout after 5 minutes) #499

Closed LSmith6938 closed 9 years ago

LSmith6938 commented 10 years ago

getting I/O Error when trying to back up about 22k text messages. error occurs after several hundred messages have been "backed up"... it stops backing up between 500 and 1000 messages, randomly. i have disabled wifi backup, enabled wifi backup, restarted the app, reset the app, uninstalled the app, checked gmail settings, etc.

what's interesting is that the app says it's backing up, but does not create gmail messages. the folder is empty, even though SMS backup tells me it's backed up a number of messages. i only have 1 gmail account linked on my phone.

please help. i desperately need to data reset my nexus 5, and i dont want to lose my texts, so i've been waiting to data reset the phone until after i have backed up all my texts.

here is the link to the sync log: https://gist.github.com/LSmith6938/dc9b14681caf6d2592dc

jberkel commented 10 years ago

weird, looks like this is a timeout issue. how many messages are already stored on the gmail side, in the SMS folder ? you could try moving some of them to a different label (temporarily) before doing the backup.

LSmith6938 commented 10 years ago

so, i moved all my backed up text messages to a new folder i just created ' SMS 2 '

SMS back up is being told to back everything up to the SMS folder in gmail. i tried it again, still getting the same I/O error.

jberkel commented 10 years ago

i'm running out of ideas. the default timeout is 5 minutes, and looking at your logs it always happens 5 minutes after the backup got initiated. i think the backup never started properly and you get the timeout whilst connecting to the server. do you use the standard gmail config?

jberkel commented 10 years ago

also if possible, can you paste the full adb log while doing a backup ? it might help to debug

LSmith6938 commented 10 years ago

how would i do this?

jberkel commented 10 years ago

if you have a rooted phone you can use this app: https://play.google.com/store/apps/details?id=org.jtb.alogcat

if not, you'll need to install the android sdk and then use the adb logcat command https://developer.android.com/tools/help/logcat.html

LSmith6938 commented 9 years ago

i'm more of a intermediate smart phone user... not an advanced user. i've clicked the link you provided, but i'm not sure where to go to download and install this program. could you give me more specific instructions? sorry to be a pain. :/

flomin commented 9 years ago

Hi, I just got the same problem: backup wouldn't finish with IO Error during calculating phase. So I disconnected and reconnected to my gmail account and it started to backup the sms from the start. It seems I still have the SMS messages on my account in only one copy without changing anything on gmail. But it stucked at some point with the same error. There are already 20k+ messages saved on my account and still 2080 messages to backup. I tried to move all messages to another label on gmail, but I still get the same error.

The error comes after a timeout of five minutes during the calculating phase. Here is the logcat filtered for appname 'com.zegoggles.smssync': 

12-11 01:48:02.387: W/ContextImpl(26570): Implicit intents with startService are not safe: Intent { act=com.android.vending.billing.InAppBillingService.BIND } android.content.ContextWrapper.bindService:517 com.github.jberkel.pay.me.IabHelper.startSetup:152 com.zegoggles.smssync.activity.donation.DonationActivity.checkUserHasDonated:244 
12-11 01:48:02.410: I/Choreographer(26570): Skipped 78 frames!  The application may be doing too much work on its main thread.
12-11 01:48:02.605: I/Timeline(26570): Timeline: Activity_idle id: android.os.BinderProxy@41a08578 time:88964481
12-11 01:48:45.832: D/SMSBackup+(26570): using new contacts API
12-11 01:48:46.074: D/Whassup(26570): db /storage/emulated/0/Whatsapp/Databases/msgstore.db.crypt does not exist
12-11 01:48:46.074: I/SMSBackup+(26570): Starting backup (2080 messages)
12-11 01:48:46.582: D/k9(26570): Untagged response #null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-11 01:48:46.582: D/k9(26570): Untagged response #2# [OK, blablabla@gmail.com, authenticated, [Success]]
12-11 01:48:47.582: D/k9(26570): Untagged response #null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-11 01:48:47.582: D/k9(26570): Untagged response #2# [OK, blablabla@gmail.com, authenticated, [Success]]
12-11 01:48:47.941: D/k9(26570): Untagged response #null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-11 01:48:47.949: D/k9(26570): Untagged response #2# [OK, blablabla@gmail.com, authenticated, [Success]]
12-11 01:53:48.426: E/k9(26570): IOException for null:SMS/AsyncTask #3/conn1107469056
12-11 01:53:48.426: E/k9(26570): java.net.SocketTimeoutException: Read timed out
12-11 01:53:48.426: E/k9(26570):    at com.android.org.conscrypt.NativeCrypto.SSL_read(Native Method)
12-11 01:53:48.426: E/k9(26570):    at com.android.org.conscrypt.OpenSSLSocketImpl$SSLInputStream.read(OpenSSLSocketImpl.java:689)
12-11 01:53:48.426: E/k9(26570):    at java.io.InputStream.read(InputStream.java:162)
12-11 01:53:48.426: E/k9(26570):    at java.io.BufferedInputStream.fillbuf(BufferedInputStream.java:142)
12-11 01:53:48.426: E/k9(26570):    at java.io.BufferedInputStream.read(BufferedInputStream.java:227)
12-11 01:53:48.426: E/k9(26570):    at com.fsck.k9.mail.filter.PeekableInputStream.read(PeekableInputStream.java:28)
12-11 01:53:48.426: E/k9(26570):    at com.fsck.k9.mail.filter.PeekableInputStream.peek(PeekableInputStream.java:41)
12-11 01:53:48.426: E/k9(26570):    at com.fsck.k9.mail.store.ImapResponseParser.readResponse(ImapResponseParser.java:49)
12-11 01:53:48.426: E/k9(26570):    at com.fsck.k9.mail.store.ImapStore$ImapConnection.readResponse(ImapStore.java:2670)
12-11 01:53:48.426: E/k9(26570):    at com.fsck.k9.mail.store.ImapStore$ImapConnection.readResponse(ImapStore.java:2663)
12-11 01:53:48.426: E/k9(26570):    at com.fsck.k9.mail.store.ImapStore$ImapConnection.access$1200(ImapStore.java:2092)
12-11 01:53:48.426: E/k9(26570):    at com.fsck.k9.mail.store.ImapStore$ImapFolder.appendMessages(ImapStore.java:1835)
12-11 01:53:48.426: E/k9(26570):    at com.fsck.k9.mail.store.ImapStore$ImapFolder.appendMessages(ImapStore.java:1803)
12-11 01:53:48.426: E/k9(26570):    at com.zegoggles.smssync.service.BackupTask.backupCursors(BackupTask.java:253)
12-11 01:53:48.426: E/k9(26570):    at com.zegoggles.smssync.service.BackupTask.fetchAndBackupItems(BackupTask.java:138)
12-11 01:53:48.426: E/k9(26570):    at com.zegoggles.smssync.service.BackupTask.acquireLocksAndBackup(BackupTask.java:118)
12-11 01:53:48.426: E/k9(26570):    at com.zegoggles.smssync.service.BackupTask.doInBackground(BackupTask.java:111)
12-11 01:53:48.426: E/k9(26570):    at com.zegoggles.smssync.service.BackupTask.doInBackground(BackupTask.java:38)
12-11 01:53:48.426: E/k9(26570):    at android.os.AsyncTask$2.call(AsyncTask.java:288)
12-11 01:53:48.426: E/k9(26570):    at java.util.concurrent.FutureTask.run(FutureTask.java:237)
12-11 01:53:48.426: E/k9(26570):    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
12-11 01:53:48.426: E/k9(26570):    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
12-11 01:53:48.426: E/k9(26570):    at java.lang.Thread.run(Thread.java:841)

I can do some more tests if you'd like. I really want to backup my messages before trying to update my cyanogenmod rom...

Btw aLogcat doesn't seem to be able to read logs past his, you need to grant him permission by console with root access...

jberkel commented 9 years ago

@flomin does this happen consistently? i will send you a build which has more logging enabled, maybe it will help

jberkel commented 9 years ago

@flomin please reproduce with https://github.com/jberkel/sms-backup-plus/releases/tag/1.5.6-BETA6 and post logs again

LSmith6938 commented 9 years ago

please let me know if there is anything i can do to help with this. i'm no expert, but i can certainly follow directions.

i've been putting off a much needed data reset for about a month now. :)

flomin commented 9 years ago

@jberkel I tried several times because the backup of all the messages took something like 12 hours and I had several IO Errors due to wifi deconnections when I used my phone or moved too far away. And at the end I got a few IO Errors before it worked for the last time. Now it's consistent, the IO Error happens every time, and I tried something like 10 times in a row.

I'll install the beta version and give you the logcat result ! I just hope it won't start backing up everything again or it'll take a very long time...

flomin commented 9 years ago

Ok I got the same error with the new version (which updated the old one, so no need to backup everything again). Just for the information, I currently have a SMS label on gmail which is empty and a SMS-Old label nested in it which contains 1141 conversations (more than 22k messages, I don't know how to have the exact number on gmail). Here is the logcat (I removed personal information):

12-11 11:05:48.740: D/ActivityThread(15207): setTargetHeapUtilization:0.75
12-11 11:05:48.740: D/ActivityThread(15207): setTargetHeapMinFree:2097152
12-11 11:05:49.404: W/Resources(15207): Converting to string: TypedValue{t=0x10/d=0x1c20 a=-1}
12-11 11:05:49.404: W/Resources(15207): Converting to string: TypedValue{t=0x10/d=0x1c20 a=-1}
12-11 11:05:49.412: W/Resources(15207): Converting to string: TypedValue{t=0x10/d=0xb4 a=-1}
12-11 11:05:49.412: W/Resources(15207): Converting to string: TypedValue{t=0x10/d=0xb4 a=-1}
12-11 11:05:49.436: W/Resources(15207): Converting to string: TypedValue{t=0x10/d=0xffffffff a=-1}
12-11 11:05:49.443: W/Resources(15207): Converting to string: TypedValue{t=0x10/d=0xffffffff a=-1}
12-11 11:05:49.443: W/Resources(15207): Converting to string: TypedValue{t=0x10/d=0xffffffff a=-1}
12-11 11:05:49.443: W/Resources(15207): Converting to string: TypedValue{t=0x10/d=0xffffffff a=-1}
12-11 11:05:49.459: W/Resources(15207): Converting to string: TypedValue{t=0x10/d=0xffffffff a=-1}
12-11 11:05:49.459: W/Resources(15207): Converting to string: TypedValue{t=0x10/d=0xffffffff a=-1}
12-11 11:05:49.639: V/SMSBackup+(15207): dataChanged()
12-11 11:05:49.857: V/WebViewChromiumFactoryProvider(15207): Binding Chromium to main looper Looper (main, tid 1) {41a0b6c8}
12-11 11:05:49.896: I/LibraryLoader(15207): Expected native library version number "",actual native library version number ""
12-11 11:05:49.959: I/chromium(15207): [INFO:library_loader_hooks.cc(116)] Chromium logging enabled: level = 0, default verbosity = 0
12-11 11:05:49.990: I/BrowserStartupController(15207): Initializing chromium process, renderers=0
12-11 11:05:50.217: E/AudioManagerAndroid(15207): BLUETOOTH permission is missing!
12-11 11:05:50.279: D/libEGL(15207): loaded /vendor/lib/egl/libEGL_POWERVR_SGX540_120.so
12-11 11:05:50.287: D/libEGL(15207): loaded /vendor/lib/egl/libGLESv1_CM_POWERVR_SGX540_120.so
12-11 11:05:50.295: D/libEGL(15207): loaded /vendor/lib/egl/libGLESv2_POWERVR_SGX540_120.so
12-11 11:05:50.607: W/chromium(15207): [WARNING:proxy_service.cc(890)] PAC support disabled because there is no system implementation
12-11 11:05:51.146: D/SMSBackup+(15207): onResume()
12-11 11:05:51.568: D/SMSBackup+(15207): id:2, name:Anniversaires, synced:true
12-11 11:05:51.568: D/SMSBackup+(15207): id:10, name:Boulot, synced:true
12-11 11:05:51.568: D/SMSBackup+(15207): id:7, name:Calendrier LyonJUG, synced:false
12-11 11:05:51.568: D/SMSBackup+(15207): id:9, name:DebouLyon, synced:false
12-11 11:05:51.568: D/SMSBackup+(15207): id:1, name:Blabla Bla, synced:true
12-11 11:05:51.568: D/SMSBackup+(15207): id:13, name:Important, synced:false
12-11 11:05:51.568: D/SMSBackup+(15207): id:3, name:Jours fériés en France, synced:true
12-11 11:05:51.568: D/SMSBackup+(15207): id:5, name:Météo, synced:true
12-11 11:05:51.568: D/SMSBackup+(15207): id:6, name:Pas là, synced:true
12-11 11:05:51.568: D/SMSBackup+(15207): id:4, name:Phases de la Lune, synced:true
12-11 11:05:51.568: D/SMSBackup+(15207): id:8, name:Private, synced:true
12-11 11:05:51.568: D/SMSBackup+(15207): id:11, name:TODO, synced:false
12-11 11:05:54.264: W/ContextImpl(15207): Implicit intents with startService are not safe: Intent { act=com.android.vending.billing.InAppBillingService.BIND } android.content.ContextWrapper.bindService:517 com.github.jberkel.pay.me.IabHelper.startSetup:152 com.zegoggles.smssync.activity.donation.DonationActivity.checkUserHasDonated:244 
12-11 11:05:54.271: I/Choreographer(15207): Skipped 186 frames!  The application may be doing too much work on its main thread.
12-11 11:05:55.865: I/Choreographer(15207): Skipped 35 frames!  The application may be doing too much work on its main thread.
12-11 11:05:56.529: I/Timeline(15207): Timeline: Activity_idle id: android.os.BinderProxy@41a0d070 time:119340080
12-11 11:06:13.834: V/SMSBackup+(15207): user requested sync
12-11 11:06:13.936: V/SMSBackup+(15207): backupStateChanged:BackupState{currentSyncedItems=0, itemsToSync=0, backupType=UNKNOWN, exception=null, state =INITIAL}
12-11 11:06:13.936: V/SMSBackup+(15207): handleIntent(Intent { cmp=com.zegoggles.smssync/.service.SmsBackupService (has extras) }, android.util.MapCollections$KeySet@fd9f6acd, type=MANUAL)
12-11 11:06:13.975: V/SMSBackup+(15207): [AppLog]: 11-12 11:06 Sauvegarde demandée (manuel)
12-11 11:06:13.975: V/SMSBackup+(15207): [AppLog]: 11-12 11:06 Démarrage de la sauvegarde (MANUAL)
12-11 11:06:13.975: D/SMSBackup+(15207): using new contacts API
12-11 11:06:13.982: V/SMSBackup+(15207): whitelisted ids for backup: null
12-11 11:06:14.100: V/SMSBackup+(15207): getItemsForDataType(type=SMS, max=-1)
12-11 11:06:14.350: V/SMSBackup+(15207): getItemsForDataType(type=MMS, max=-1)
12-11 11:06:14.357: V/SMSBackup+(15207): getItemsForDataType(type=WHATSAPP, max=-1)
12-11 11:06:14.373: V/SMSBackup+(15207): getItems(max=-1)
12-11 11:06:14.404: D/Whassup(15207): could not find db
12-11 11:06:14.404: V/SMSBackup+(15207): No whatsapp backup DB found, returning empty
12-11 11:06:14.404: V/SMSBackup+(15207): [AppLog]: 11-12 11:06 Sauvegarde en cours (2005 SMS, 83 MMS, 0 appels)
12-11 11:06:14.428: V/SMSBackup+(15207): [AppLog]: 11-12 11:06 Using config: BackupConfig{imap=BackupImapStore{uri=imap+ssl+://xoauth2:XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX@imap.gmail.com:993}, skip=false, currentTry=0, maxItemsPerSync=-1, groupToBackup=ContactGroup{_id=-1, type=EVERYBODY}, backupType=MANUAL, debug=true, typesToBackup=[SMS, MMS, WHATSAPP]}
12-11 11:06:14.428: I/SMSBackup+(15207): Starting backup (2088 messages)
12-11 11:06:14.428: V/SMSBackup+(15207): backupStateChanged:BackupState{currentSyncedItems=0, itemsToSync=0, backupType=MANUAL, exception=null, state =LOGIN}
12-11 11:06:14.709: D/k9(15207): connecting to imap.gmail.com as imap.gmail.com/74.125.206.108
12-11 11:06:14.811: V/k9(15207): Setting socket read timeout to 300000
12-11 11:06:14.975: V/k9(15207): DomainNameChecker.matchDns(): this domain: imap.gmail.com that domain: imap.gmail.com
12-11 11:06:15.053: V/k9(15207): conn1105547512<<<#null# [OK, Gimap, ready, for, requests, from, 1.2.3.42, q46mb1853833wez]
12-11 11:06:15.053: I/k9(15207): Did not get capabilities in banner, requesting CAPABILITY for conn1105547512
12-11 11:06:15.061: V/k9(15207): conn1105547512>>> 1 CAPABILITY
12-11 11:06:15.178: V/k9(15207): conn1105547512<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, XYZZY, SASL-IR, AUTH=XOAUTH, AUTH=XOAUTH2, AUTH=PLAIN, AUTH=PLAIN-CLIENTTOKEN]
12-11 11:06:15.178: V/k9(15207): conn1105547512<<<#1# [OK, Thats, all, she, wrote!, q46mb1853833wez]
12-11 11:06:15.178: D/k9(15207): Saving 16 capabilities for conn1105547512
12-11 11:06:15.193: I/k9(15207): Authenticate using XOAUTH2
12-11 11:06:15.217: V/k9(15207): conn1105547512>>> [Command Hidden, Enable Sensitive Debug Logging To Show]
12-11 11:06:15.287: V/k9(15207): conn1105547512<<<#+# [eyJzdGF0dXMiOiI0MDAiLCJzY2hlbWVzIjoiQmVhcmVyIiwic2NvcGUiOiJodHRwczovL21haWwuZ29vZ2xlLmNvbS8ifQ==]
12-11 11:06:15.295: D/k9(15207): Untagged response #+# [eyJzdGF0dXMiOiI0MDAiLCJzY2hlbWVzIjoiQmVhcmVyIiwic2NvcGUiOiJodHRwczovL21haWwuZ29vZ2xlLmNvbS8ifQ==]
12-11 11:06:15.350: V/k9(15207): conn1105547512<<<#2# [NO, [ALERT], Invalid, credentials, [Failure]]
12-11 11:06:15.350: D/k9(15207): Untagged response #2# [NO, [ALERT], Invalid, credentials, [Failure]]
12-11 11:06:15.357: E/k9(15207): Failed to login, closing connection for conn1105547512
12-11 11:06:15.357: V/SMSBackup+(15207): [AppLog]: 11-12 11:06 need to perform xoauth2 token refresh
12-11 11:06:17.107: V/SMSBackup+(15207): [AppLog]: 11-12 11:06 token refreshed, retrying
12-11 11:06:17.115: V/SMSBackup+(15207): getItemsForDataType(type=SMS, max=-1)
12-11 11:06:17.311: V/SMSBackup+(15207): getItemsForDataType(type=MMS, max=-1)
12-11 11:06:17.318: V/SMSBackup+(15207): getItemsForDataType(type=WHATSAPP, max=-1)
12-11 11:06:17.318: V/SMSBackup+(15207): getItems(max=-1)
12-11 11:06:17.326: D/Whassup(15207): could not find db
12-11 11:06:17.326: V/SMSBackup+(15207): No whatsapp backup DB found, returning empty
12-11 11:06:17.326: V/SMSBackup+(15207): [AppLog]: 11-12 11:06 Sauvegarde en cours (2005 SMS, 83 MMS, 0 appels)
12-11 11:06:17.334: V/SMSBackup+(15207): [AppLog]: 11-12 11:06 Using config: BackupConfig{imap=BackupImapStore{uri=imap+ssl+://xoauth2:XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX@imap.gmail.com:993}, skip=false, currentTry=1, maxItemsPerSync=-1, groupToBackup=ContactGroup{_id=-1, type=EVERYBODY}, backupType=MANUAL, debug=true, typesToBackup=[SMS, MMS, WHATSAPP]}
12-11 11:06:17.334: I/SMSBackup+(15207): Starting backup (2088 messages)
12-11 11:06:17.334: D/k9(15207): connecting to imap.gmail.com as imap.gmail.com/74.125.206.108
12-11 11:06:17.334: V/SMSBackup+(15207): backupStateChanged:BackupState{currentSyncedItems=0, itemsToSync=0, backupType=MANUAL, exception=null, state =LOGIN}
12-11 11:06:17.373: V/k9(15207): Setting socket read timeout to 300000
12-11 11:06:17.436: V/k9(15207): DomainNameChecker.matchDns(): this domain: imap.gmail.com that domain: imap.gmail.com
12-11 11:06:17.490: V/k9(15207): conn1105915712<<<#null# [OK, Gimap, ready, for, requests, from, 1.2.3.42, ev4mb2098261web]
12-11 11:06:17.490: I/k9(15207): Did not get capabilities in banner, requesting CAPABILITY for conn1105915712
12-11 11:06:17.498: V/k9(15207): conn1105915712>>> 1 CAPABILITY
12-11 11:06:17.607: V/k9(15207): conn1105915712<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, XYZZY, SASL-IR, AUTH=XOAUTH, AUTH=XOAUTH2, AUTH=PLAIN, AUTH=PLAIN-CLIENTTOKEN]
12-11 11:06:17.607: V/k9(15207): conn1105915712<<<#1# [OK, Thats, all, she, wrote!, ev4mb2098261web]
12-11 11:06:17.607: D/k9(15207): Saving 16 capabilities for conn1105915712
12-11 11:06:17.607: I/k9(15207): Authenticate using XOAUTH2
12-11 11:06:17.615: V/k9(15207): conn1105915712>>> [Command Hidden, Enable Sensitive Debug Logging To Show]
12-11 11:06:17.795: V/k9(15207): conn1105915712<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-11 11:06:17.795: D/k9(15207): Untagged response #null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-11 11:06:17.795: V/k9(15207): conn1105915712<<<#2# [OK, blablabla@gmail.com, authenticated, [Success]]
12-11 11:06:17.795: D/k9(15207): Untagged response #2# [OK, blablabla@gmail.com, authenticated, [Success]]
12-11 11:06:17.803: D/k9(15207): COMPRESS=DEFLATE = false
12-11 11:06:17.803: D/k9(15207): NAMESPACE = true, mPathPrefix = null
12-11 11:06:17.803: I/k9(15207): mPathPrefix is unset and server has NAMESPACE capability
12-11 11:06:17.803: V/k9(15207): conn1105915712>>> 3 NAMESPACE
12-11 11:06:17.842: V/k9(15207): conn1105915712<<<#null# [NAMESPACE, [[, /]], NIL, NIL]
12-11 11:06:17.842: V/k9(15207): conn1105915712<<<#3# [OK, Success]
12-11 11:06:17.842: D/k9(15207): Got NAMESPACE response #null# [NAMESPACE, [[, /]], NIL, NIL] on conn1105915712
12-11 11:06:17.842: D/k9(15207): Got personal namespaces: [[, /]]
12-11 11:06:17.842: D/k9(15207): Got first personal namespaces: [, /]
12-11 11:06:17.842: D/k9(15207): Got path '' and separator '/'
12-11 11:06:17.842: V/SMSBackup+(15207): backing up: CursorAndType{type=SMS, cursor=android.content.ContentResolver$CursorWrapperInner@41ea5250}
12-11 11:06:17.850: V/SMSBackup+(15207): backupStateChanged:BackupState{currentSyncedItems=0, itemsToSync=0, backupType=MANUAL, exception=null, state =CALC}
12-11 11:06:19.295: V/SMSBackup+(15207): sending 1 SMS message(s) to server.
12-11 11:06:19.295: D/k9(15207): connecting to imap.gmail.com as imap.gmail.com/74.125.206.108
12-11 11:06:19.334: V/k9(15207): Setting socket read timeout to 300000
12-11 11:06:19.428: V/k9(15207): DomainNameChecker.matchDns(): this domain: imap.gmail.com that domain: imap.gmail.com
12-11 11:06:19.490: V/k9(15207): conn1106809792<<<#null# [OK, Gimap, ready, for, requests, from, 1.2.3.42, u9mb2213096wjw]
12-11 11:06:19.490: I/k9(15207): Did not get capabilities in banner, requesting CAPABILITY for conn1106809792
12-11 11:06:19.490: V/k9(15207): conn1106809792>>> 1 CAPABILITY
12-11 11:06:19.615: V/k9(15207): conn1106809792<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, XYZZY, SASL-IR, AUTH=XOAUTH, AUTH=XOAUTH2, AUTH=PLAIN, AUTH=PLAIN-CLIENTTOKEN]
12-11 11:06:19.615: V/k9(15207): conn1106809792<<<#1# [OK, Thats, all, she, wrote!, u9mb2213096wjw]
12-11 11:06:19.615: D/k9(15207): Saving 16 capabilities for conn1106809792
12-11 11:06:19.623: I/k9(15207): Authenticate using XOAUTH2
12-11 11:06:19.623: V/k9(15207): conn1106809792>>> [Command Hidden, Enable Sensitive Debug Logging To Show]
12-11 11:06:19.678: V/k9(15207): conn1106809792<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-11 11:06:19.686: D/k9(15207): Untagged response #null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-11 11:06:19.686: V/k9(15207): conn1106809792<<<#2# [OK, blablabla@gmail.com, authenticated, [Success]]
12-11 11:06:19.686: D/k9(15207): Untagged response #2# [OK, blablabla@gmail.com, authenticated, [Success]]
12-11 11:06:19.686: D/k9(15207): COMPRESS=DEFLATE = false
12-11 11:06:19.686: D/k9(15207): NAMESPACE = true, mPathPrefix = 
12-11 11:06:19.693: D/k9(15207): connecting to imap.gmail.com as imap.gmail.com/74.125.206.108
12-11 11:06:19.732: V/k9(15207): Setting socket read timeout to 300000
12-11 11:06:19.811: V/k9(15207): DomainNameChecker.matchDns(): this domain: imap.gmail.com that domain: imap.gmail.com
12-11 11:06:19.873: V/k9(15207): conn1106809552<<<#null# [OK, Gimap, ready, for, requests, from, 1.2.3.42, ba9mb2309851wib]
12-11 11:06:19.873: I/k9(15207): Did not get capabilities in banner, requesting CAPABILITY for conn1106809552
12-11 11:06:19.873: V/k9(15207): conn1106809552>>> 1 CAPABILITY
12-11 11:06:19.998: V/k9(15207): conn1106809552<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, XYZZY, SASL-IR, AUTH=XOAUTH, AUTH=XOAUTH2, AUTH=PLAIN, AUTH=PLAIN-CLIENTTOKEN]
12-11 11:06:20.006: V/k9(15207): conn1106809552<<<#1# [OK, Thats, all, she, wrote!, ba9mb2309851wib]
12-11 11:06:20.006: D/k9(15207): Saving 16 capabilities for conn1106809552
12-11 11:06:20.006: I/k9(15207): Authenticate using XOAUTH2
12-11 11:06:20.014: V/k9(15207): conn1106809552>>> [Command Hidden, Enable Sensitive Debug Logging To Show]
12-11 11:06:20.076: V/k9(15207): conn1106809552<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-11 11:06:20.076: D/k9(15207): Untagged response #null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-11 11:06:20.084: V/k9(15207): conn1106809552<<<#2# [OK, blablabla@gmail.com, authenticated, [Success]]
12-11 11:06:20.084: D/k9(15207): Untagged response #2# [OK, blablabla@gmail.com, authenticated, [Success]]
12-11 11:06:20.084: D/k9(15207): COMPRESS=DEFLATE = false
12-11 11:06:20.084: D/k9(15207): NAMESPACE = true, mPathPrefix = 
12-11 11:06:20.084: V/k9(15207): conn1106809552>>> 3 STATUS "SMS" (UIDVALIDITY)
12-11 11:06:20.123: V/k9(15207): conn1106809552<<<#null# [STATUS, SMS, [UIDVALIDITY, 51]]
12-11 11:06:20.131: V/k9(15207): conn1106809552<<<#3# [OK, Success]
12-11 11:06:20.131: V/k9(15207): conn1106809792>>> 3 NOOP
12-11 11:06:20.170: V/k9(15207): conn1106809792<<<#3# [OK, Success]
12-11 11:06:20.170: V/k9(15207): conn1106809792>>> 4 SELECT "SMS"
12-11 11:06:20.623: V/k9(15207): conn1106809792<<<#null# [FLAGS, [\Answered, \Flagged, \Draft, \Deleted, \Seen, $Phishing, $NotPhishing]]
12-11 11:06:20.631: V/k9(15207): conn1106809792<<<#null# [OK, [PERMANENTFLAGS, [\Answered, \Flagged, \Draft, \Deleted, \Seen, $Phishing, $NotPhishing, \*]], Flags, permitted.]
12-11 11:06:20.631: V/k9(15207): conn1106809792<<<#null# [OK, [UIDVALIDITY, 51], UIDs, valid.]
12-11 11:06:20.631: V/k9(15207): conn1106809792<<<#null# [0, EXISTS]
12-11 11:06:20.639: V/k9(15207): conn1106809792<<<#null# [0, RECENT]
12-11 11:06:20.639: V/k9(15207): conn1106809792<<<#null# [OK, [UIDNEXT, 49600], Predicted, next, UID.]
12-11 11:06:20.639: V/k9(15207): conn1106809792<<<#null# [OK, [HIGHESTMODSEQ, 7743484]]
12-11 11:06:20.646: V/k9(15207): conn1106809792<<<#4# [OK, [READ-WRITE], SMS, selected., [Success]]
12-11 11:06:20.646: D/k9(15207): Got untagged EXISTS with value 0 for null:SMS/AsyncTask #2/conn1106809792
12-11 11:06:20.646: D/k9(15207): Got UidNext = 49600 for null:SMS/AsyncTask #2/conn1106809792
12-11 11:06:20.678: V/k9(15207): conn1106809792>>> 5 APPEND "SMS" (\Seen) "30-Oct-2014 02:57:22 +0100" {3544}
12-11 11:06:20.725: V/k9(15207): conn1106809792<<<#+# [go, ahead]
12-11 11:11:21.123: E/k9(15207): IOException for null:SMS/AsyncTask #2/conn1106809792
12-11 11:11:21.123: E/k9(15207): java.net.SocketTimeoutException: Read timed out
12-11 11:11:21.123: E/k9(15207):    at com.android.org.conscrypt.NativeCrypto.SSL_read(Native Method)
12-11 11:11:21.123: E/k9(15207):    at com.android.org.conscrypt.OpenSSLSocketImpl$SSLInputStream.read(OpenSSLSocketImpl.java:689)
12-11 11:11:21.123: E/k9(15207):    at java.io.InputStream.read(InputStream.java:162)
12-11 11:11:21.123: E/k9(15207):    at java.io.BufferedInputStream.fillbuf(BufferedInputStream.java:142)
12-11 11:11:21.123: E/k9(15207):    at java.io.BufferedInputStream.read(BufferedInputStream.java:227)
12-11 11:11:21.123: E/k9(15207):    at com.fsck.k9.mail.filter.PeekableInputStream.read(PeekableInputStream.java:28)
12-11 11:11:21.123: E/k9(15207):    at com.fsck.k9.mail.filter.PeekableInputStream.peek(PeekableInputStream.java:41)
12-11 11:11:21.123: E/k9(15207):    at com.fsck.k9.mail.store.ImapResponseParser.readResponse(ImapResponseParser.java:49)
12-11 11:11:21.123: E/k9(15207):    at com.fsck.k9.mail.store.ImapStore$ImapConnection.readResponse(ImapStore.java:2677)
12-11 11:11:21.123: E/k9(15207):    at com.fsck.k9.mail.store.ImapStore$ImapConnection.readResponse(ImapStore.java:2670)
12-11 11:11:21.123: E/k9(15207):    at com.fsck.k9.mail.store.ImapStore$ImapConnection.access$1200(ImapStore.java:2092)
12-11 11:11:21.123: E/k9(15207):    at com.fsck.k9.mail.store.ImapStore$ImapFolder.appendMessages(ImapStore.java:1835)
12-11 11:11:21.123: E/k9(15207):    at com.fsck.k9.mail.store.ImapStore$ImapFolder.appendMessages(ImapStore.java:1803)
12-11 11:11:21.123: E/k9(15207):    at com.zegoggles.smssync.service.BackupTask.backupCursors(BackupTask.java:257)
12-11 11:11:21.123: E/k9(15207):    at com.zegoggles.smssync.service.BackupTask.fetchAndBackupItems(BackupTask.java:138)
12-11 11:11:21.123: E/k9(15207):    at com.zegoggles.smssync.service.BackupTask.handleAuthError(BackupTask.java:173)
12-11 11:11:21.123: E/k9(15207):    at com.zegoggles.smssync.service.BackupTask.fetchAndBackupItems(BackupTask.java:152)
12-11 11:11:21.123: E/k9(15207):    at com.zegoggles.smssync.service.BackupTask.acquireLocksAndBackup(BackupTask.java:118)
12-11 11:11:21.123: E/k9(15207):    at com.zegoggles.smssync.service.BackupTask.doInBackground(BackupTask.java:111)
12-11 11:11:21.123: E/k9(15207):    at com.zegoggles.smssync.service.BackupTask.doInBackground(BackupTask.java:38)
12-11 11:11:21.123: E/k9(15207):    at android.os.AsyncTask$2.call(AsyncTask.java:288)
12-11 11:11:21.123: E/k9(15207):    at java.util.concurrent.FutureTask.run(FutureTask.java:237)
12-11 11:11:21.123: E/k9(15207):    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
12-11 11:11:21.123: E/k9(15207):    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
12-11 11:11:21.123: E/k9(15207):    at java.lang.Thread.run(Thread.java:841)
12-11 11:11:21.131: V/SMSBackup+(15207): backupStateChanged:BackupState{currentSyncedItems=0, itemsToSync=0, backupType=MANUAL, exception=com.fsck.k9.mail.MessagingException: IO Error, state =ERROR}
12-11 11:11:21.295: V/SMSBackup+(15207): [AppLog]: 11-12 11:11 Erreur générale : IO Error (exception: com.fsck.k9.mail.MessagingException: IO Error, underlying=java.net.SocketTimeoutException: Read timed out)
12-11 11:11:21.311: V/SMSBackup+(15207): [AppLog]: 11-12 11:11 BackupState{currentSyncedItems=0, itemsToSync=0, backupType=MANUAL, exception=com.fsck.k9.mail.MessagingException: IO Error, state =ERROR}
12-11 11:11:21.318: V/SMSBackup+(15207): [AppLog]: 11-12 11:11 Sauvegarde effectuée
12-11 11:11:21.451: V/SMSBackup+(15207): AppLog#close()
12-11 11:11:21.451: V/SMSBackup+(15207): SmsBackupService#onDestroy(state=BackupState{currentSyncedItems=0, itemsToSync=0, backupType=MANUAL, exception=com.fsck.k9.mail.MessagingException: IO Error, state =ERROR})
jberkel commented 9 years ago

@flomin this is very useful, thanks. i have some ideas what might cause this. in the meantime, does it always happen with the same message ? you can tell by looking at the APPEND line just before it stops:

5 APPEND "SMS" (\Seen) "30-Oct-2014 02:57:22 +0100" {3544}

If it always stops during this message it might be an indication that the timeout is caused by one specific SMS on the device, rather than a random failure.

flomin commented 9 years ago

Here are a few other logs:

12-11 13:27:37.992: V/SMSBackup+(1728): user requested sync
12-11 13:27:38.070: V/SMSBackup+(1728): backupStateChanged:BackupState{currentSyncedItems=0, itemsToSync=0, backupType=UNKNOWN, exception=null, state =INITIAL}
12-11 13:27:38.070: V/SMSBackup+(1728): handleIntent(Intent { cmp=com.zegoggles.smssync/.service.SmsBackupService (has extras) }, android.util.MapCollections$KeySet@fd9f6acd, type=MANUAL)
12-11 13:27:38.070: V/SMSBackup+(1728): [AppLog]: 11-12 13:27 Sauvegarde demandée (manuel)
12-11 13:27:38.078: V/SMSBackup+(1728): [AppLog]: 11-12 13:27 Démarrage de la sauvegarde (MANUAL)
12-11 13:27:38.078: D/SMSBackup+(1728): using new contacts API
12-11 13:27:38.078: V/SMSBackup+(1728): whitelisted ids for backup: null
12-11 13:27:38.140: V/SMSBackup+(1728): getItemsForDataType(type=SMS, max=-1)
12-11 13:27:38.390: V/SMSBackup+(1728): getItemsForDataType(type=MMS, max=-1)
12-11 13:27:38.398: V/SMSBackup+(1728): getItemsForDataType(type=WHATSAPP, max=-1)
12-11 13:27:38.398: V/SMSBackup+(1728): getItems(max=-1)
12-11 13:27:38.414: D/Whassup(1728): could not find db
12-11 13:27:38.414: V/SMSBackup+(1728): No whatsapp backup DB found, returning empty
12-11 13:27:38.414: V/SMSBackup+(1728): [AppLog]: 11-12 13:27 Sauvegarde en cours (2016 SMS, 83 MMS, 0 appels)
12-11 13:27:38.437: V/SMSBackup+(1728): [AppLog]: 11-12 13:27 Using config: BackupConfig{imap=BackupImapStore{uri=imap+ssl+://xoauth2:XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX@imap.gmail.com:993}, skip=false, currentTry=0, maxItemsPerSync=-1, groupToBackup=ContactGroup{_id=-1, type=EVERYBODY}, backupType=MANUAL, debug=true, typesToBackup=[SMS, MMS, WHATSAPP]}
12-11 13:27:38.437: I/SMSBackup+(1728): Starting backup (2099 messages)
12-11 13:27:38.437: V/SMSBackup+(1728): backupStateChanged:BackupState{currentSyncedItems=0, itemsToSync=0, backupType=MANUAL, exception=null, state =LOGIN}
12-11 13:27:38.546: D/k9(1728): connecting to imap.gmail.com as imap.gmail.com/74.125.71.109
12-11 13:27:38.593: V/k9(1728): Setting socket read timeout to 300000
12-11 13:27:38.711: V/k9(1728): DomainNameChecker.matchDns(): this domain: imap.gmail.com that domain: imap.gmail.com
12-11 13:27:38.765: V/k9(1728): conn1105208896<<<#null# [OK, Gimap, ready, for, requests, from, 1.2.3.42, lv1mb4005240wic]
12-11 13:27:38.765: I/k9(1728): Did not get capabilities in banner, requesting CAPABILITY for conn1105208896
12-11 13:27:38.773: V/k9(1728): conn1105208896>>> 1 CAPABILITY
12-11 13:27:38.890: V/k9(1728): conn1105208896<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, XYZZY, SASL-IR, AUTH=XOAUTH, AUTH=XOAUTH2, AUTH=PLAIN, AUTH=PLAIN-CLIENTTOKEN]
12-11 13:27:38.890: V/k9(1728): conn1105208896<<<#1# [OK, Thats, all, she, wrote!, lv1mb4005240wic]
12-11 13:27:38.890: D/k9(1728): Saving 16 capabilities for conn1105208896
12-11 13:27:38.890: I/k9(1728): Authenticate using XOAUTH2
12-11 13:27:38.898: V/k9(1728): conn1105208896>>> [Command Hidden, Enable Sensitive Debug Logging To Show]
12-11 13:27:38.945: V/k9(1728): conn1105208896<<<#+# [eyJzdGF0dXMiOiI0MDAiLCJzY2hlbWVzIjoiQmVhcmVyIiwic2NvcGUiOiJodHRwczovL21haWwuZ29vZ2xlLmNvbS8ifQ==]
12-11 13:27:38.945: D/k9(1728): Untagged response #+# [eyJzdGF0dXMiOiI0MDAiLCJzY2hlbWVzIjoiQmVhcmVyIiwic2NvcGUiOiJodHRwczovL21haWwuZ29vZ2xlLmNvbS8ifQ==]
12-11 13:27:38.992: V/k9(1728): conn1105208896<<<#2# [NO, [ALERT], Invalid, credentials, [Failure]]
12-11 13:27:38.992: D/k9(1728): Untagged response #2# [NO, [ALERT], Invalid, credentials, [Failure]]
12-11 13:27:38.992: E/k9(1728): Failed to login, closing connection for conn1105208896
12-11 13:27:38.992: V/SMSBackup+(1728): [AppLog]: 11-12 13:27 need to perform xoauth2 token refresh
12-11 13:27:40.046: V/SMSBackup+(1728): [AppLog]: 11-12 13:27 token refreshed, retrying
12-11 13:27:40.070: V/SMSBackup+(1728): getItemsForDataType(type=SMS, max=-1)
12-11 13:27:40.304: V/SMSBackup+(1728): getItemsForDataType(type=MMS, max=-1)
12-11 13:27:40.312: V/SMSBackup+(1728): getItemsForDataType(type=WHATSAPP, max=-1)
12-11 13:27:40.320: V/SMSBackup+(1728): getItems(max=-1)
12-11 13:27:40.320: D/Whassup(1728): could not find db
12-11 13:27:40.320: V/SMSBackup+(1728): No whatsapp backup DB found, returning empty
12-11 13:27:40.320: V/SMSBackup+(1728): [AppLog]: 11-12 13:27 Sauvegarde en cours (2016 SMS, 83 MMS, 0 appels)
12-11 13:27:40.328: V/SMSBackup+(1728): [AppLog]: 11-12 13:27 Using config: BackupConfig{imap=BackupImapStore{uri=imap+ssl+://xoauth2:XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX@imap.gmail.com:993}, skip=false, currentTry=1, maxItemsPerSync=-1, groupToBackup=ContactGroup{_id=-1, type=EVERYBODY}, backupType=MANUAL, debug=true, typesToBackup=[SMS, MMS, WHATSAPP]}
12-11 13:27:40.328: I/SMSBackup+(1728): Starting backup (2099 messages)
12-11 13:27:40.328: V/SMSBackup+(1728): backupStateChanged:BackupState{currentSyncedItems=0, itemsToSync=0, backupType=MANUAL, exception=null, state =LOGIN}
12-11 13:27:40.328: D/k9(1728): connecting to imap.gmail.com as imap.gmail.com/74.125.71.109
12-11 13:27:40.367: V/k9(1728): Setting socket read timeout to 300000
12-11 13:27:40.445: V/k9(1728): DomainNameChecker.matchDns(): this domain: imap.gmail.com that domain: imap.gmail.com
12-11 13:27:40.500: V/k9(1728): conn1105581960<<<#null# [OK, Gimap, ready, for, requests, from, 1.2.3.42, br13mb4068824wib]
12-11 13:27:40.507: I/k9(1728): Did not get capabilities in banner, requesting CAPABILITY for conn1105581960
12-11 13:27:40.507: V/k9(1728): conn1105581960>>> 1 CAPABILITY
12-11 13:27:40.625: V/k9(1728): conn1105581960<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, XYZZY, SASL-IR, AUTH=XOAUTH, AUTH=XOAUTH2, AUTH=PLAIN, AUTH=PLAIN-CLIENTTOKEN]
12-11 13:27:40.625: V/k9(1728): conn1105581960<<<#1# [OK, Thats, all, she, wrote!, br13mb4068824wib]
12-11 13:27:40.625: D/k9(1728): Saving 16 capabilities for conn1105581960
12-11 13:27:40.632: I/k9(1728): Authenticate using XOAUTH2
12-11 13:27:40.632: V/k9(1728): conn1105581960>>> [Command Hidden, Enable Sensitive Debug Logging To Show]
12-11 13:27:40.726: V/k9(1728): conn1105581960<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-11 13:27:40.726: D/k9(1728): Untagged response #null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-11 13:27:40.726: V/k9(1728): conn1105581960<<<#2# [OK, 1.2.3.42@gmail.com, authenticated, [Success]]
12-11 13:27:40.726: D/k9(1728): Untagged response #2# [OK, 1.2.3.42@gmail.com, authenticated, [Success]]
12-11 13:27:40.734: D/k9(1728): COMPRESS=DEFLATE = false
12-11 13:27:40.734: D/k9(1728): NAMESPACE = true, mPathPrefix = null
12-11 13:27:40.734: I/k9(1728): mPathPrefix is unset and server has NAMESPACE capability
12-11 13:27:40.734: V/k9(1728): conn1105581960>>> 3 NAMESPACE
12-11 13:27:40.773: V/k9(1728): conn1105581960<<<#null# [NAMESPACE, [[, /]], NIL, NIL]
12-11 13:27:40.773: V/k9(1728): conn1105581960<<<#3# [OK, Success]
12-11 13:27:40.773: D/k9(1728): Got NAMESPACE response #null# [NAMESPACE, [[, /]], NIL, NIL] on conn1105581960
12-11 13:27:40.773: D/k9(1728): Got personal namespaces: [[, /]]
12-11 13:27:40.773: D/k9(1728): Got first personal namespaces: [, /]
12-11 13:27:40.773: D/k9(1728): Got path '' and separator '/'
12-11 13:27:40.781: V/SMSBackup+(1728): backupStateChanged:BackupState{currentSyncedItems=0, itemsToSync=0, backupType=MANUAL, exception=null, state =CALC}
12-11 13:27:40.781: V/SMSBackup+(1728): backing up: CursorAndType{type=SMS, cursor=android.content.ContentResolver$CursorWrapperInner@41e52a90}
12-11 13:27:41.429: V/SMSBackup+(1728): sending 1 SMS message(s) to server.
12-11 13:27:41.429: D/k9(1728): connecting to imap.gmail.com as imap.gmail.com/74.125.71.109
12-11 13:27:41.484: V/k9(1728): Setting socket read timeout to 300000
12-11 13:27:41.562: V/k9(1728): DomainNameChecker.matchDns(): this domain: imap.gmail.com that domain: imap.gmail.com
12-11 13:27:41.734: V/k9(1728): conn1106471696<<<#null# [OK, Gimap, ready, for, requests, from, 1.2.3.42, e127mb1345662wlb]
12-11 13:27:41.734: I/k9(1728): Did not get capabilities in banner, requesting CAPABILITY for conn1106471696
12-11 13:27:41.734: V/k9(1728): conn1106471696>>> 1 CAPABILITY
12-11 13:27:41.851: V/k9(1728): conn1106471696<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, XYZZY, SASL-IR, AUTH=XOAUTH, AUTH=XOAUTH2, AUTH=PLAIN, AUTH=PLAIN-CLIENTTOKEN]
12-11 13:27:41.851: V/k9(1728): conn1106471696<<<#1# [OK, Thats, all, she, wrote!, e127mb1345662wlb]
12-11 13:27:41.851: D/k9(1728): Saving 16 capabilities for conn1106471696
12-11 13:27:41.851: I/k9(1728): Authenticate using XOAUTH2
12-11 13:27:41.851: V/k9(1728): conn1106471696>>> [Command Hidden, Enable Sensitive Debug Logging To Show]
12-11 13:27:42.015: V/k9(1728): conn1106471696<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-11 13:27:42.015: D/k9(1728): Untagged response #null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-11 13:27:42.015: V/k9(1728): conn1106471696<<<#2# [OK, 1.2.3.42@gmail.com, authenticated, [Success]]
12-11 13:27:42.015: D/k9(1728): Untagged response #2# [OK, 1.2.3.42@gmail.com, authenticated, [Success]]
12-11 13:27:42.015: D/k9(1728): COMPRESS=DEFLATE = false
12-11 13:27:42.015: D/k9(1728): NAMESPACE = true, mPathPrefix = 
12-11 13:27:42.023: D/k9(1728): connecting to imap.gmail.com as imap.gmail.com/74.125.71.109
12-11 13:27:42.062: V/k9(1728): Setting socket read timeout to 300000
12-11 13:27:42.140: V/k9(1728): DomainNameChecker.matchDns(): this domain: imap.gmail.com that domain: imap.gmail.com
12-11 13:27:42.195: V/k9(1728): conn1106471456<<<#null# [OK, Gimap, ready, for, requests, from, 1.2.3.42, je15mb4181151wic]
12-11 13:27:42.195: I/k9(1728): Did not get capabilities in banner, requesting CAPABILITY for conn1106471456
12-11 13:27:42.195: V/k9(1728): conn1106471456>>> 1 CAPABILITY
12-11 13:27:42.312: V/k9(1728): conn1106471456<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, XYZZY, SASL-IR, AUTH=XOAUTH, AUTH=XOAUTH2, AUTH=PLAIN, AUTH=PLAIN-CLIENTTOKEN]
12-11 13:27:42.320: V/k9(1728): conn1106471456<<<#1# [OK, Thats, all, she, wrote!, je15mb4181151wic]
12-11 13:27:42.320: D/k9(1728): Saving 16 capabilities for conn1106471456
12-11 13:27:42.320: I/k9(1728): Authenticate using XOAUTH2
12-11 13:27:42.320: V/k9(1728): conn1106471456>>> [Command Hidden, Enable Sensitive Debug Logging To Show]
12-11 13:27:42.414: V/k9(1728): conn1106471456<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-11 13:27:42.414: D/k9(1728): Untagged response #null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-11 13:27:42.414: V/k9(1728): conn1106471456<<<#2# [OK, 1.2.3.42@gmail.com, authenticated, [Success]]
12-11 13:27:42.414: D/k9(1728): Untagged response #2# [OK, 1.2.3.42@gmail.com, authenticated, [Success]]
12-11 13:27:42.421: D/k9(1728): COMPRESS=DEFLATE = false
12-11 13:27:42.421: D/k9(1728): NAMESPACE = true, mPathPrefix = 
12-11 13:27:42.421: V/k9(1728): conn1106471456>>> 3 STATUS "SMS" (UIDVALIDITY)
12-11 13:27:42.461: V/k9(1728): conn1106471456<<<#null# [STATUS, SMS, [UIDVALIDITY, 51]]
12-11 13:27:42.461: V/k9(1728): conn1106471456<<<#3# [OK, Success]
12-11 13:27:42.461: V/k9(1728): conn1106471696>>> 3 NOOP
12-11 13:27:42.507: V/k9(1728): conn1106471696<<<#3# [OK, Success]
12-11 13:27:42.507: V/k9(1728): conn1106471696>>> 4 SELECT "SMS"
12-11 13:27:42.898: V/k9(1728): conn1106471696<<<#null# [FLAGS, [\Answered, \Flagged, \Draft, \Deleted, \Seen, $Phishing, $NotPhishing]]
12-11 13:27:42.906: V/k9(1728): conn1106471696<<<#null# [OK, [PERMANENTFLAGS, [\Answered, \Flagged, \Draft, \Deleted, \Seen, $Phishing, $NotPhishing, \*]], Flags, permitted.]
12-11 13:27:42.906: V/k9(1728): conn1106471696<<<#null# [OK, [UIDVALIDITY, 51], UIDs, valid.]
12-11 13:27:42.906: V/k9(1728): conn1106471696<<<#null# [0, EXISTS]
12-11 13:27:42.906: V/k9(1728): conn1106471696<<<#null# [0, RECENT]
12-11 13:27:42.914: V/k9(1728): conn1106471696<<<#null# [OK, [UIDNEXT, 49600], Predicted, next, UID.]
12-11 13:27:42.914: V/k9(1728): conn1106471696<<<#null# [OK, [HIGHESTMODSEQ, 7744352]]
12-11 13:27:42.914: V/k9(1728): conn1106471696<<<#4# [OK, [READ-WRITE], SMS, selected., [Success]]
12-11 13:27:42.914: D/k9(1728): Got untagged EXISTS with value 0 for null:SMS/AsyncTask #2/conn1106471696
12-11 13:27:42.914: D/k9(1728): Got UidNext = 49600 for null:SMS/AsyncTask #2/conn1106471696
12-11 13:27:42.937: V/k9(1728): conn1106471696>>> 5 APPEND "SMS" (\Seen) "30-Oct-2014 02:57:22 +0100" {3544}
12-11 13:27:42.976: V/k9(1728): conn1106471696<<<#+# [go, ahead]
12-11 13:28:08.632: W/IInputConnectionWrapper(1728): getExtractedText on inactive InputConnection
12-11 13:28:08.632: W/IInputConnectionWrapper(1728): getTextBeforeCursor on inactive InputConnection
12-11 13:28:08.632: W/IInputConnectionWrapper(1728): getSelectedText on inactive InputConnection
12-11 13:28:08.632: W/IInputConnectionWrapper(1728): getTextAfterCursor on inactive InputConnection
12-11 13:32:43.054: E/k9(1728): IOException for null:SMS/AsyncTask #2/conn1106471696
12-11 13:32:43.054: E/k9(1728): java.net.SocketTimeoutException: Read timed out
12-11 13:32:43.054: E/k9(1728):     at com.android.org.conscrypt.NativeCrypto.SSL_read(Native Method)
12-11 13:32:43.054: E/k9(1728):     at com.android.org.conscrypt.OpenSSLSocketImpl$SSLInputStream.read(OpenSSLSocketImpl.java:689)
12-11 13:32:43.054: E/k9(1728):     at java.io.InputStream.read(InputStream.java:162)
12-11 13:32:43.054: E/k9(1728):     at java.io.BufferedInputStream.fillbuf(BufferedInputStream.java:142)
12-11 13:32:43.054: E/k9(1728):     at java.io.BufferedInputStream.read(BufferedInputStream.java:227)
12-11 13:32:43.054: E/k9(1728):     at com.fsck.k9.mail.filter.PeekableInputStream.read(PeekableInputStream.java:28)
12-11 13:32:43.054: E/k9(1728):     at com.fsck.k9.mail.filter.PeekableInputStream.peek(PeekableInputStream.java:41)
12-11 13:32:43.054: E/k9(1728):     at com.fsck.k9.mail.store.ImapResponseParser.readResponse(ImapResponseParser.java:49)
12-11 13:32:43.054: E/k9(1728):     at com.fsck.k9.mail.store.ImapStore$ImapConnection.readResponse(ImapStore.java:2677)
12-11 13:32:43.054: E/k9(1728):     at com.fsck.k9.mail.store.ImapStore$ImapConnection.readResponse(ImapStore.java:2670)
12-11 13:32:43.054: E/k9(1728):     at com.fsck.k9.mail.store.ImapStore$ImapConnection.access$1200(ImapStore.java:2092)
12-11 13:32:43.054: E/k9(1728):     at com.fsck.k9.mail.store.ImapStore$ImapFolder.appendMessages(ImapStore.java:1835)
12-11 13:32:43.054: E/k9(1728):     at com.fsck.k9.mail.store.ImapStore$ImapFolder.appendMessages(ImapStore.java:1803)
12-11 13:32:43.054: E/k9(1728):     at com.zegoggles.smssync.service.BackupTask.backupCursors(BackupTask.java:257)
12-11 13:32:43.054: E/k9(1728):     at com.zegoggles.smssync.service.BackupTask.fetchAndBackupItems(BackupTask.java:138)
12-11 13:32:43.054: E/k9(1728):     at com.zegoggles.smssync.service.BackupTask.handleAuthError(BackupTask.java:173)
12-11 13:32:43.054: E/k9(1728):     at com.zegoggles.smssync.service.BackupTask.fetchAndBackupItems(BackupTask.java:152)
12-11 13:32:43.054: E/k9(1728):     at com.zegoggles.smssync.service.BackupTask.acquireLocksAndBackup(BackupTask.java:118)
12-11 13:32:43.054: E/k9(1728):     at com.zegoggles.smssync.service.BackupTask.doInBackground(BackupTask.java:111)
12-11 13:32:43.054: E/k9(1728):     at com.zegoggles.smssync.service.BackupTask.doInBackground(BackupTask.java:38)
12-11 13:32:43.054: E/k9(1728):     at android.os.AsyncTask$2.call(AsyncTask.java:288)
12-11 13:32:43.054: E/k9(1728):     at java.util.concurrent.FutureTask.run(FutureTask.java:237)
12-11 13:32:43.054: E/k9(1728):     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
12-11 13:32:43.054: E/k9(1728):     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
12-11 13:32:43.054: E/k9(1728):     at java.lang.Thread.run(Thread.java:841)
12-11 13:32:43.078: V/SMSBackup+(1728): [AppLog]: 11-12 13:32 Erreur générale : IO Error (exception: com.fsck.k9.mail.MessagingException: IO Error, underlying=java.net.SocketTimeoutException: Read timed out)
12-11 13:32:43.086: V/SMSBackup+(1728): [AppLog]: 11-12 13:32 BackupState{currentSyncedItems=0, itemsToSync=0, backupType=MANUAL, exception=com.fsck.k9.mail.MessagingException: IO Error, state =ERROR}
12-11 13:32:43.086: V/SMSBackup+(1728): [AppLog]: 11-12 13:32 Sauvegarde effectuée
12-11 13:32:43.093: V/SMSBackup+(1728): AppLog#close()
12-11 13:32:43.093: V/SMSBackup+(1728): SmsBackupService#onDestroy(state=BackupState{currentSyncedItems=0, itemsToSync=0, backupType=MANUAL, exception=com.fsck.k9.mail.MessagingException: IO Error, state =ERROR})
12-11 13:40:52.016: V/SMSBackup+(4496): user requested sync
12-11 13:40:52.055: V/SMSBackup+(4496): backupStateChanged:BackupState{currentSyncedItems=0, itemsToSync=0, backupType=UNKNOWN, exception=null, state =INITIAL}
12-11 13:40:52.055: V/SMSBackup+(4496): handleIntent(Intent { cmp=com.zegoggles.smssync/.service.SmsBackupService (has extras) }, android.util.MapCollections$KeySet@fd9f6acd, type=MANUAL)
12-11 13:40:52.055: V/SMSBackup+(4496): [AppLog]: 11-12 13:40 Sauvegarde demandée (manuel)
12-11 13:40:52.062: V/SMSBackup+(4496): [AppLog]: 11-12 13:40 Démarrage de la sauvegarde (MANUAL)
12-11 13:40:52.062: D/SMSBackup+(4496): using new contacts API
12-11 13:40:52.070: V/SMSBackup+(4496): whitelisted ids for backup: null
12-11 13:40:52.133: V/SMSBackup+(4496): getItemsForDataType(type=SMS, max=-1)
12-11 13:40:52.359: V/SMSBackup+(4496): getItemsForDataType(type=MMS, max=-1)
12-11 13:40:52.375: V/SMSBackup+(4496): getItemsForDataType(type=WHATSAPP, max=-1)
12-11 13:40:52.391: V/SMSBackup+(4496): getItems(max=-1)
12-11 13:40:52.398: D/Whassup(4496): could not find db
12-11 13:40:52.398: V/SMSBackup+(4496): No whatsapp backup DB found, returning empty
12-11 13:40:52.398: V/SMSBackup+(4496): [AppLog]: 11-12 13:40 Sauvegarde en cours (2016 SMS, 83 MMS, 0 appels)
12-11 13:40:52.414: V/SMSBackup+(4496): [AppLog]: 11-12 13:40 Using config: BackupConfig{imap=BackupImapStore{uri=imap+ssl+://xoauth2:XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX@imap.gmail.com:993}, skip=false, currentTry=0, maxItemsPerSync=-1, groupToBackup=ContactGroup{_id=-1, type=EVERYBODY}, backupType=MANUAL, debug=true, typesToBackup=[SMS, MMS, WHATSAPP]}
12-11 13:40:52.414: I/SMSBackup+(4496): Starting backup (2099 messages)
12-11 13:40:52.422: V/SMSBackup+(4496): backupStateChanged:BackupState{currentSyncedItems=0, itemsToSync=0, backupType=MANUAL, exception=null, state =LOGIN}
12-11 13:40:52.492: D/k9(4496): connecting to imap.gmail.com as imap.gmail.com/74.125.71.108
12-11 13:40:52.562: V/k9(4496): Setting socket read timeout to 300000
12-11 13:40:52.734: V/k9(4496): DomainNameChecker.matchDns(): this domain: imap.gmail.com that domain: imap.gmail.com
12-11 13:40:52.859: V/k9(4496): conn1105262848<<<#null# [OK, Gimap, ready, for, requests, from, 1.2.3.42, h5mb4079845wic]
12-11 13:40:52.859: I/k9(4496): Did not get capabilities in banner, requesting CAPABILITY for conn1105262848
12-11 13:40:52.859: V/k9(4496): conn1105262848>>> 1 CAPABILITY
12-11 13:40:52.984: V/k9(4496): conn1105262848<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, XYZZY, SASL-IR, AUTH=XOAUTH, AUTH=XOAUTH2, AUTH=PLAIN, AUTH=PLAIN-CLIENTTOKEN]
12-11 13:40:52.984: V/k9(4496): conn1105262848<<<#1# [OK, Thats, all, she, wrote!, h5mb4079845wic]
12-11 13:40:52.984: D/k9(4496): Saving 16 capabilities for conn1105262848
12-11 13:40:52.992: I/k9(4496): Authenticate using XOAUTH2
12-11 13:40:52.992: V/k9(4496): conn1105262848>>> [Command Hidden, Enable Sensitive Debug Logging To Show]
12-11 13:40:53.055: V/k9(4496): conn1105262848<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-11 13:40:53.070: D/k9(4496): Untagged response #null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-11 13:40:53.070: V/k9(4496): conn1105262848<<<#2# [OK, florian.minjat@gmail.com, authenticated, [Success]]
12-11 13:40:53.078: D/k9(4496): Untagged response #2# [OK, florian.minjat@gmail.com, authenticated, [Success]]
12-11 13:40:53.078: D/k9(4496): COMPRESS=DEFLATE = false
12-11 13:40:53.078: D/k9(4496): NAMESPACE = true, mPathPrefix = null
12-11 13:40:53.078: I/k9(4496): mPathPrefix is unset and server has NAMESPACE capability
12-11 13:40:53.078: V/k9(4496): conn1105262848>>> 3 NAMESPACE
12-11 13:40:53.133: V/k9(4496): conn1105262848<<<#null# [NAMESPACE, [[, /]], NIL, NIL]
12-11 13:40:53.133: V/k9(4496): conn1105262848<<<#3# [OK, Success]
12-11 13:40:53.133: D/k9(4496): Got NAMESPACE response #null# [NAMESPACE, [[, /]], NIL, NIL] on conn1105262848
12-11 13:40:53.133: D/k9(4496): Got personal namespaces: [[, /]]
12-11 13:40:53.133: D/k9(4496): Got first personal namespaces: [, /]
12-11 13:40:53.133: D/k9(4496): Got path '' and separator '/'
12-11 13:40:53.141: V/SMSBackup+(4496): backing up: CursorAndType{type=SMS, cursor=android.content.ContentResolver$CursorWrapperInner@41df8290}
12-11 13:40:53.141: V/SMSBackup+(4496): backupStateChanged:BackupState{currentSyncedItems=0, itemsToSync=0, backupType=MANUAL, exception=null, state =CALC}
12-11 13:40:54.226: V/SMSBackup+(4496): sending 1 SMS message(s) to server.
12-11 13:40:54.226: D/k9(4496): connecting to imap.gmail.com as imap.gmail.com/74.125.71.108
12-11 13:40:54.273: V/k9(4496): Setting socket read timeout to 300000
12-11 13:40:54.375: V/k9(4496): DomainNameChecker.matchDns(): this domain: imap.gmail.com that domain: imap.gmail.com
12-11 13:40:54.430: V/k9(4496): conn1106273976<<<#null# [OK, Gimap, ready, for, requests, from, 1.2.3.42, y19mb3464661web]
12-11 13:40:54.430: I/k9(4496): Did not get capabilities in banner, requesting CAPABILITY for conn1106273976
12-11 13:40:54.430: V/k9(4496): conn1106273976>>> 1 CAPABILITY
12-11 13:40:54.547: V/k9(4496): conn1106273976<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, XYZZY, SASL-IR, AUTH=XOAUTH, AUTH=XOAUTH2, AUTH=PLAIN, AUTH=PLAIN-CLIENTTOKEN]
12-11 13:40:54.547: V/k9(4496): conn1106273976<<<#1# [OK, Thats, all, she, wrote!, y19mb3464661web]
12-11 13:40:54.547: D/k9(4496): Saving 16 capabilities for conn1106273976
12-11 13:40:54.555: I/k9(4496): Authenticate using XOAUTH2
12-11 13:40:54.562: V/k9(4496): conn1106273976>>> [Command Hidden, Enable Sensitive Debug Logging To Show]
12-11 13:40:54.625: V/k9(4496): conn1106273976<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-11 13:40:54.625: D/k9(4496): Untagged response #null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-11 13:40:54.625: V/k9(4496): conn1106273976<<<#2# [OK, florian.minjat@gmail.com, authenticated, [Success]]
12-11 13:40:54.633: D/k9(4496): Untagged response #2# [OK, florian.minjat@gmail.com, authenticated, [Success]]
12-11 13:40:54.633: D/k9(4496): COMPRESS=DEFLATE = false
12-11 13:40:54.633: D/k9(4496): NAMESPACE = true, mPathPrefix = 
12-11 13:40:54.641: D/k9(4496): connecting to imap.gmail.com as imap.gmail.com/74.125.71.108
12-11 13:40:54.680: V/k9(4496): Setting socket read timeout to 300000
12-11 13:40:54.750: V/k9(4496): DomainNameChecker.matchDns(): this domain: imap.gmail.com that domain: imap.gmail.com
12-11 13:40:54.812: V/k9(4496): conn1106273736<<<#null# [OK, Gimap, ready, for, requests, from, 1.2.3.42, d48mb3736358wek]
12-11 13:40:54.812: I/k9(4496): Did not get capabilities in banner, requesting CAPABILITY for conn1106273736
12-11 13:40:54.812: V/k9(4496): conn1106273736>>> 1 CAPABILITY
12-11 13:40:54.930: V/k9(4496): conn1106273736<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, XYZZY, SASL-IR, AUTH=XOAUTH, AUTH=XOAUTH2, AUTH=PLAIN, AUTH=PLAIN-CLIENTTOKEN]
12-11 13:40:54.930: V/k9(4496): conn1106273736<<<#1# [OK, Thats, all, she, wrote!, d48mb3736358wek]
12-11 13:40:54.937: D/k9(4496): Saving 16 capabilities for conn1106273736
12-11 13:40:54.937: I/k9(4496): Authenticate using XOAUTH2
12-11 13:40:54.937: V/k9(4496): conn1106273736>>> [Command Hidden, Enable Sensitive Debug Logging To Show]
12-11 13:40:55.000: V/k9(4496): conn1106273736<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-11 13:40:55.008: D/k9(4496): Untagged response #null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-11 13:40:55.008: V/k9(4496): conn1106273736<<<#2# [OK, florian.minjat@gmail.com, authenticated, [Success]]
12-11 13:40:55.008: D/k9(4496): Untagged response #2# [OK, florian.minjat@gmail.com, authenticated, [Success]]
12-11 13:40:55.008: D/k9(4496): COMPRESS=DEFLATE = false
12-11 13:40:55.008: D/k9(4496): NAMESPACE = true, mPathPrefix = 
12-11 13:40:55.008: V/k9(4496): conn1106273736>>> 3 STATUS "SMS" (UIDVALIDITY)
12-11 13:40:55.047: V/k9(4496): conn1106273736<<<#null# [STATUS, SMS, [UIDVALIDITY, 51]]
12-11 13:40:55.047: V/k9(4496): conn1106273736<<<#3# [OK, Success]
12-11 13:40:55.055: V/k9(4496): conn1106273976>>> 3 NOOP
12-11 13:40:55.094: V/k9(4496): conn1106273976<<<#3# [OK, Success]
12-11 13:40:55.094: V/k9(4496): conn1106273976>>> 4 SELECT "SMS"
12-11 13:40:55.547: V/k9(4496): conn1106273976<<<#null# [FLAGS, [\Answered, \Flagged, \Draft, \Deleted, \Seen, $Phishing, $NotPhishing]]
12-11 13:40:55.555: V/k9(4496): conn1106273976<<<#null# [OK, [PERMANENTFLAGS, [\Answered, \Flagged, \Draft, \Deleted, \Seen, $Phishing, $NotPhishing, \*]], Flags, permitted.]
12-11 13:40:55.555: V/k9(4496): conn1106273976<<<#null# [OK, [UIDVALIDITY, 51], UIDs, valid.]
12-11 13:40:55.555: V/k9(4496): conn1106273976<<<#null# [0, EXISTS]
12-11 13:40:55.555: V/k9(4496): conn1106273976<<<#null# [0, RECENT]
12-11 13:40:55.562: V/k9(4496): conn1106273976<<<#null# [OK, [UIDNEXT, 49600], Predicted, next, UID.]
12-11 13:40:55.570: V/k9(4496): conn1106273976<<<#null# [OK, [HIGHESTMODSEQ, 7744379]]
12-11 13:40:55.570: V/k9(4496): conn1106273976<<<#4# [OK, [READ-WRITE], SMS, selected., [Success]]
12-11 13:40:55.570: D/k9(4496): Got untagged EXISTS with value 0 for null:SMS/AsyncTask #2/conn1106273976
12-11 13:40:55.570: D/k9(4496): Got UidNext = 49600 for null:SMS/AsyncTask #2/conn1106273976
**12-11 13:40:55.601: V/k9(4496): conn1106273976>>> 5 APPEND "SMS" (\Seen) "30-Oct-2014 02:57:22 +0100" {3544}**
12-11 13:40:55.633: V/k9(4496): conn1106273976<<<#+# [go, ahead]
12-11 13:45:55.726: E/k9(4496): IOException for null:SMS/AsyncTask #2/conn1106273976
12-11 13:45:55.726: E/k9(4496): java.net.SocketTimeoutException: Read timed out
12-11 13:45:55.726: E/k9(4496):     at com.android.org.conscrypt.NativeCrypto.SSL_read(Native Method)
12-11 13:45:55.726: E/k9(4496):     at com.android.org.conscrypt.OpenSSLSocketImpl$SSLInputStream.read(OpenSSLSocketImpl.java:689)
12-11 13:45:55.726: E/k9(4496):     at java.io.InputStream.read(InputStream.java:162)
12-11 13:45:55.726: E/k9(4496):     at java.io.BufferedInputStream.fillbuf(BufferedInputStream.java:142)
12-11 13:45:55.726: E/k9(4496):     at java.io.BufferedInputStream.read(BufferedInputStream.java:227)
12-11 13:45:55.726: E/k9(4496):     at com.fsck.k9.mail.filter.PeekableInputStream.read(PeekableInputStream.java:28)
12-11 13:45:55.726: E/k9(4496):     at com.fsck.k9.mail.filter.PeekableInputStream.peek(PeekableInputStream.java:41)
12-11 13:45:55.726: E/k9(4496):     at com.fsck.k9.mail.store.ImapResponseParser.readResponse(ImapResponseParser.java:49)
12-11 13:45:55.726: E/k9(4496):     at com.fsck.k9.mail.store.ImapStore$ImapConnection.readResponse(ImapStore.java:2677)
12-11 13:45:55.726: E/k9(4496):     at com.fsck.k9.mail.store.ImapStore$ImapConnection.readResponse(ImapStore.java:2670)
12-11 13:45:55.726: E/k9(4496):     at com.fsck.k9.mail.store.ImapStore$ImapConnection.access$1200(ImapStore.java:2092)
12-11 13:45:55.726: E/k9(4496):     at com.fsck.k9.mail.store.ImapStore$ImapFolder.appendMessages(ImapStore.java:1835)
12-11 13:45:55.726: E/k9(4496):     at com.fsck.k9.mail.store.ImapStore$ImapFolder.appendMessages(ImapStore.java:1803)
12-11 13:45:55.726: E/k9(4496):     at com.zegoggles.smssync.service.BackupTask.backupCursors(BackupTask.java:257)
12-11 13:45:55.726: E/k9(4496):     at com.zegoggles.smssync.service.BackupTask.fetchAndBackupItems(BackupTask.java:138)
12-11 13:45:55.726: E/k9(4496):     at com.zegoggles.smssync.service.BackupTask.acquireLocksAndBackup(BackupTask.java:118)
12-11 13:45:55.726: E/k9(4496):     at com.zegoggles.smssync.service.BackupTask.doInBackground(BackupTask.java:111)
12-11 13:45:55.726: E/k9(4496):     at com.zegoggles.smssync.service.BackupTask.doInBackground(BackupTask.java:38)
12-11 13:45:55.726: E/k9(4496):     at android.os.AsyncTask$2.call(AsyncTask.java:288)
12-11 13:45:55.726: E/k9(4496):     at java.util.concurrent.FutureTask.run(FutureTask.java:237)
12-11 13:45:55.726: E/k9(4496):     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
12-11 13:45:55.726: E/k9(4496):     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
12-11 13:45:55.726: E/k9(4496):     at java.lang.Thread.run(Thread.java:841)
12-11 13:45:55.742: V/SMSBackup+(4496): backupStateChanged:BackupState{currentSyncedItems=0, itemsToSync=0, backupType=MANUAL, exception=com.fsck.k9.mail.MessagingException: IO Error, state =ERROR}
12-11 13:45:55.812: V/SMSBackup+(4496): [AppLog]: 11-12 13:45 Erreur générale : IO Error (exception: com.fsck.k9.mail.MessagingException: IO Error, underlying=java.net.SocketTimeoutException: Read timed out)
12-11 13:45:55.820: V/SMSBackup+(4496): [AppLog]: 11-12 13:45 BackupState{currentSyncedItems=0, itemsToSync=0, backupType=MANUAL, exception=com.fsck.k9.mail.MessagingException: IO Error, state =ERROR}
12-11 13:45:55.820: V/SMSBackup+(4496): [AppLog]: 11-12 13:45 Sauvegarde effectuée
12-11 13:45:55.851: V/SMSBackup+(4496): AppLog#close()
12-11 13:45:55.859: V/SMSBackup+(4496): SmsBackupService#onDestroy(state=BackupState{currentSyncedItems=0, itemsToSync=0, backupType=MANUAL, exception=com.fsck.k9.mail.MessagingException: IO Error, state =ERROR})

Both APPEND lines: 

12-11 13:27:42.937: V/k9(1728): conn1106471696>>> 5 APPEND "SMS" (\Seen) "30-Oct-2014 02:57:22 +0100" {3544}
12-11 13:40:55.601: V/k9(4496): conn1106273976>>> 5 APPEND "SMS" (\Seen) "30-Oct-2014 02:57:22 +0100" {3544}

So it seems its a message which is in fault. How can I find this particular message easily ?

flomin commented 9 years ago

I found the faulty message, which is quite personal (too much for public forum :-P). I can say it's a really long message (2567chars), which was sent using SMS (several SMS used to transmit the whole one). I can't see any problematic char in it, perhaps it's its length which causes problem ?

I have a lot of very big SMS afterwards (big epistolary correspondence), so removing this one won't solve the issue (and I'd like to keep it if possible).

jberkel commented 9 years ago

@flomin ok that's a good pointer, it might be the length. i'll send you a new version to try soon

jberkel commented 9 years ago

@flomin ok, please try again with https://github.com/jberkel/sms-backup-plus/releases/tag/1.5.6-BETA7

it's a stab in the dark since i can't reprodruce locally, but it might fix the problem

flomin commented 9 years ago

@jberkel Same error after five minutes, but no APPEND message this time:

12-12 14:20:34.989: I/SMSBackup+(2476): Starting backup (2134 messages)
12-12 14:20:35.653: D/k9(2476): Untagged response #+# [eyJzdGF0dXMiOiI0MDAiLCJzY2hlbWVzIjoiQmVhcmVyIiwic2NvcGUiOiJodHRwczovL21haWwuZ29vZ2xlLmNvbS8ifQ==]
12-12 14:20:35.700: D/k9(2476): Untagged response #2# [NO, [ALERT], Invalid credentials (Failure)]
12-12 14:20:35.700: E/k9(2476): Failed to login, closing connection for conn1105226296
12-12 14:20:37.192: D/Whassup(2476): could not find db
12-12 14:20:37.200: I/SMSBackup+(2476): Starting backup (2134 messages)
12-12 14:20:38.153: D/k9(2476): Untagged response #null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-12 14:20:38.153: D/k9(2476): Untagged response #2# [OK, blablabla@gmail.com authenticated (Success)]
12-12 14:20:39.215: D/k9(2476): Untagged response #null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-12 14:20:39.215: D/k9(2476): Untagged response #2# [OK, blablabla@gmail.com authenticated (Success)]
12-12 14:20:39.637: D/k9(2476): Untagged response #null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-12 14:20:39.637: D/k9(2476): Untagged response #2# [OK, blablabla@gmail.com authenticated (Success)]
12-12 14:25:40.371: E/k9(2476): IOException for null:SMS/AsyncTask #2/conn1106448792
12-12 14:25:40.371: E/k9(2476): java.net.SocketTimeoutException: Read timed out
12-12 14:25:40.371: E/k9(2476):     at com.android.org.conscrypt.NativeCrypto.SSL_read(Native Method)
12-12 14:25:40.371: E/k9(2476):     at com.android.org.conscrypt.OpenSSLSocketImpl$SSLInputStream.read(OpenSSLSocketImpl.java:689)
12-12 14:25:40.371: E/k9(2476):     at java.io.InputStream.read(InputStream.java:162)
12-12 14:25:40.371: E/k9(2476):     at java.io.BufferedInputStream.fillbuf(BufferedInputStream.java:142)
12-12 14:25:40.371: E/k9(2476):     at java.io.BufferedInputStream.read(BufferedInputStream.java:227)
12-12 14:25:40.371: E/k9(2476):     at com.fsck.k9.mail.filter.PeekableInputStream.read(PeekableInputStream.java:28)
12-12 14:25:40.371: E/k9(2476):     at com.fsck.k9.mail.filter.PeekableInputStream.peek(PeekableInputStream.java:41)
12-12 14:25:40.371: E/k9(2476):     at com.fsck.k9.mail.store.ImapResponseParser.readResponse(ImapResponseParser.java:42)
12-12 14:25:40.371: E/k9(2476):     at com.fsck.k9.mail.store.ImapStore$ImapConnection.readResponse(ImapStore.java:2709)
12-12 14:25:40.371: E/k9(2476):     at com.fsck.k9.mail.store.ImapStore$ImapConnection.readResponse(ImapStore.java:2702)
12-12 14:25:40.371: E/k9(2476):     at com.fsck.k9.mail.store.ImapStore$ImapConnection.access$1200(ImapStore.java:2124)
12-12 14:25:40.371: E/k9(2476):     at com.fsck.k9.mail.store.ImapStore$ImapFolder.appendMessages(ImapStore.java:1868)
12-12 14:25:40.371: E/k9(2476):     at com.fsck.k9.mail.store.ImapStore$ImapFolder.appendMessages(ImapStore.java:1836)
12-12 14:25:40.371: E/k9(2476):     at com.zegoggles.smssync.service.BackupTask.backupCursors(BackupTask.java:257)
12-12 14:25:40.371: E/k9(2476):     at com.zegoggles.smssync.service.BackupTask.fetchAndBackupItems(BackupTask.java:138)
12-12 14:25:40.371: E/k9(2476):     at com.zegoggles.smssync.service.BackupTask.handleAuthError(BackupTask.java:173)
12-12 14:25:40.371: E/k9(2476):     at com.zegoggles.smssync.service.BackupTask.fetchAndBackupItems(BackupTask.java:152)
12-12 14:25:40.371: E/k9(2476):     at com.zegoggles.smssync.service.BackupTask.acquireLocksAndBackup(BackupTask.java:118)
12-12 14:25:40.371: E/k9(2476):     at com.zegoggles.smssync.service.BackupTask.doInBackground(BackupTask.java:111)
12-12 14:25:40.371: E/k9(2476):     at com.zegoggles.smssync.service.BackupTask.doInBackground(BackupTask.java:38)
12-12 14:25:40.371: E/k9(2476):     at android.os.AsyncTask$2.call(AsyncTask.java:288)
12-12 14:25:40.371: E/k9(2476):     at java.util.concurrent.FutureTask.run(FutureTask.java:237)
12-12 14:25:40.371: E/k9(2476):     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
12-12 14:25:40.371: E/k9(2476):     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
12-12 14:25:40.371: E/k9(2476):     at java.lang.Thread.run(Thread.java:841)

Can't you send yourself a big message to test ?

jberkel commented 9 years ago

i tried it, didn't hang.... at least on the emulator. have some more ideas how to fix it, i'll keep you posted

jberkel commented 9 years ago

@flomin ok, there's another beta for you to try, it has lots more debug enabled so should help. there's a lot of new code in there as well so other things might get broken

https://github.com/jberkel/sms-backup-plus/releases/tag/1.5.6-BETA9

flomin commented 9 years ago

@jberkel With the new version the backup began just fine ! But after a while it stopped with another IO Error which is reproductible. Here are the intial working log, the first error after some successful backups, and the reproduced error. I couldn't find the APPEND log with the faulty SMS details this time.

12-16 11:15:57.173 V/SMSBackup+(23125): user requested sync
12-16 11:15:57.204 V/SMSBackup+(23125): backupStateChanged:BackupState{currentSyncedItems=0, itemsToSync=0, backupType=UNKNOWN, exception=null, state =INITIAL}
12-16 11:15:57.212 V/SMSBackup+(23125): handleIntent(Intent { cmp=com.zegoggles.smssync/.service.SmsBackupService (has extras) }, android.util.MapCollections$KeySet@fd9f6acd, type=MANUAL)
12-16 11:15:57.212 V/SMSBackup+(23125): [AppLog]: 16-12 11:15 Sauvegarde demandée (manuel)
12-16 11:15:57.212 V/SMSBackup+(23125): [AppLog]: 16-12 11:15 Démarrage de la sauvegarde (MANUAL)
12-16 11:15:57.212 D/SMSBackup+(23125): using new contacts API
12-16 11:15:57.212 V/SMSBackup+(23125): whitelisted ids for backup: null
12-16 11:15:57.290 V/SMSBackup+(23125): getItemsForDataType(type=SMS, max=-1)
12-16 11:16:00.673 V/SMSBackup+(23125): getItemsForDataType(type=MMS, max=-1)
12-16 11:16:00.704 V/SMSBackup+(23125): getItemsForDataType(type=WHATSAPP, max=-1)
12-16 11:16:00.704 V/SMSBackup+(23125): getItems(max=-1)
12-16 11:16:00.712 D/Whassup (23125): could not find db
12-16 11:16:00.712 V/SMSBackup+(23125): No whatsapp backup DB found, returning empty
12-16 11:16:00.712 V/SMSBackup+(23125): [AppLog]: 16-12 11:16 Sauvegarde en cours (2252 SMS, 84 MMS, 0 appels)
12-16 11:16:00.743 V/SMSBackup+(23125): [AppLog]: 16-12 11:16 Using config: BackupConfig{imap=BackupImapStore{uri=imap+ssl+://XOAUTH2:XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX@imap.gmail.com:993}, skip=false, currentTry=0, maxItemsPerSync=-1, groupToBackup=ContactGroup{_id=-1, type=EVERYBODY}, backupType=MANUAL, debug=true, typesToBackup=[SMS, MMS, WHATSAPP]}
12-16 11:16:00.743 I/SMSBackup+(23125): Starting backup (2336 messages)
12-16 11:16:00.743 V/SMSBackup+(23125): backupStateChanged:BackupState{currentSyncedItems=0, itemsToSync=0, backupType=MANUAL, exception=null, state =LOGIN}
12-16 11:16:00.798 D/k9      (23125): Connecting to imap.gmail.com as imap.gmail.com/64.233.166.109
12-16 11:16:00.813 W/k9      (23125): Local key store has not been initialized
12-16 11:16:01.087 V/k9      (23125): conn1106955224<<<#null# [OK, Gimap ready for requests from 1.1.1.42 eb18mb42215993wic]
12-16 11:16:01.087 I/k9      (23125): Did not get capabilities in banner, requesting CAPABILITY for conn1106955224
12-16 11:16:01.087 V/k9      (23125): conn1106955224>>> 1 CAPABILITY
12-16 11:16:01.134 V/k9      (23125): conn1106955224<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, XYZZY, SASL-IR, AUTH=XOAUTH, AUTH=XOAUTH2, AUTH=PLAIN, AUTH=PLAIN-CLIENTTOKEN]
12-16 11:16:01.134 V/k9      (23125): conn1106955224<<<#1# [OK, Thats all she wrote! eb18mb42215993wic]
12-16 11:16:01.134 D/k9      (23125): Saving 16 capabilities for conn1106955224
12-16 11:16:01.149 V/k9      (23125): conn1106955224>>> [Command Hidden, Enable Sensitive Debug Logging To Show]
12-16 11:16:01.204 V/k9      (23125): conn1106955224<<<#+# [eyJzdGF0dXMiOiI0MDAiLCJzY2hlbWVzIjoiQmVhcmVyIiwic2NvcGUiOiJodHRwczovL21haWwuZ29vZ2xlLmNvbS8ifQ==]
12-16 11:16:01.204 D/k9      (23125): Untagged response #+# [eyJzdGF0dXMiOiI0MDAiLCJzY2hlbWVzIjoiQmVhcmVyIiwic2NvcGUiOiJodHRwczovL21haWwuZ29vZ2xlLmNvbS8ifQ==]
12-16 11:16:01.259 V/k9      (23125): conn1106955224<<<#2# [NO, [ALERT], Invalid credentials (Failure)]
12-16 11:16:01.259 D/k9      (23125): Untagged response #2# [NO, [ALERT], Invalid credentials (Failure)]
12-16 11:16:01.259 E/k9      (23125): Failed to login, closing connection for conn1106955224
12-16 11:16:01.266 V/SMSBackup+(23125): [AppLog]: 16-12 11:16 need to perform xoauth2 token refresh
12-16 11:16:02.360 V/SMSBackup+(23125): [AppLog]: 16-12 11:16 token refreshed, retrying
12-16 11:16:02.368 V/SMSBackup+(23125): getItemsForDataType(type=SMS, max=-1)
12-16 11:16:02.540 V/SMSBackup+(23125): getItemsForDataType(type=MMS, max=-1)
12-16 11:16:02.548 V/SMSBackup+(23125): getItemsForDataType(type=WHATSAPP, max=-1)
12-16 11:16:02.548 V/SMSBackup+(23125): getItems(max=-1)
12-16 11:16:02.548 D/Whassup (23125): could not find db
12-16 11:16:02.548 V/SMSBackup+(23125): No whatsapp backup DB found, returning empty
12-16 11:16:02.556 V/SMSBackup+(23125): [AppLog]: 16-12 11:16 Sauvegarde en cours (2252 SMS, 84 MMS, 0 appels)
12-16 11:16:02.556 V/SMSBackup+(23125): [AppLog]: 16-12 11:16 Using config: BackupConfig{imap=BackupImapStore{uri=imap+ssl+://XOAUTH2:XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX@imap.gmail.com:993}, skip=false, currentTry=1, maxItemsPerSync=-1, groupToBackup=ContactGroup{_id=-1, type=EVERYBODY}, backupType=MANUAL, debug=true, typesToBackup=[SMS, MMS, WHATSAPP]}
12-16 11:16:02.556 I/SMSBackup+(23125): Starting backup (2336 messages)
12-16 11:16:02.556 D/k9      (23125): Connecting to imap.gmail.com as imap.gmail.com/64.233.166.109
12-16 11:16:02.556 V/SMSBackup+(23125): backupStateChanged:BackupState{currentSyncedItems=0, itemsToSync=0, backupType=MANUAL, exception=null, state =LOGIN}
12-16 11:16:02.759 V/k9      (23125): conn1107372320<<<#null# [OK, Gimap ready for requests from 1.1.1.42 hh8mb43019162wjc]
12-16 11:16:02.759 I/k9      (23125): Did not get capabilities in banner, requesting CAPABILITY for conn1107372320
12-16 11:16:02.759 V/k9      (23125): conn1107372320>>> 1 CAPABILITY
12-16 11:16:02.806 V/k9      (23125): conn1107372320<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, XYZZY, SASL-IR, AUTH=XOAUTH, AUTH=XOAUTH2, AUTH=PLAIN, AUTH=PLAIN-CLIENTTOKEN]
12-16 11:16:02.806 V/k9      (23125): conn1107372320<<<#1# [OK, Thats all she wrote! hh8mb43019162wjc]
12-16 11:16:02.806 D/k9      (23125): Saving 16 capabilities for conn1107372320
12-16 11:16:02.806 V/k9      (23125): conn1107372320>>> [Command Hidden, Enable Sensitive Debug Logging To Show]
12-16 11:16:03.001 V/k9      (23125): conn1107372320<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-16 11:16:03.009 D/k9      (23125): Untagged response #null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-16 11:16:03.009 V/k9      (23125): conn1107372320<<<#2# [OK, blablabla@gmail.com authenticated (Success)]
12-16 11:16:03.009 D/k9      (23125): Untagged response #2# [OK, blablabla@gmail.com authenticated (Success)]
12-16 11:16:03.009 D/k9      (23125): COMPRESS=DEFLATE = false
12-16 11:16:03.009 D/k9      (23125): NAMESPACE = true, mPathPrefix = null
12-16 11:16:03.009 I/k9      (23125): mPathPrefix is unset and server has NAMESPACE capability
12-16 11:16:03.009 V/k9      (23125): conn1107372320>>> 3 NAMESPACE
12-16 11:16:03.063 V/k9      (23125): conn1107372320<<<#null# [NAMESPACE, [[, /]], NIL, NIL]
12-16 11:16:03.063 V/k9      (23125): conn1107372320<<<#3# [OK, Success]
12-16 11:16:03.063 D/k9      (23125): Got NAMESPACE response #null# [NAMESPACE, [[, /]], NIL, NIL] on conn1107372320
12-16 11:16:03.063 D/k9      (23125): Got personal namespaces: [[, /]]
12-16 11:16:03.063 D/k9      (23125): Got first personal namespaces: [, /]
12-16 11:16:03.063 D/k9      (23125): Got path '' and separator '/'
12-16 11:16:03.071 D/k9      (23125): Folder auto-configuration: Using XLIST.
12-16 11:16:03.071 V/k9      (23125): conn1107372320>>> 4 XLIST "" "*"
12-16 11:16:03.110 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\HasNoChildren], /, Call log]
12-16 11:16:03.110 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\HasNoChildren], /, Deal]
12-16 11:16:03.110 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\HasNoChildren], /, Divers]
12-16 11:16:03.110 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\HasNoChildren], /, D&AOk-croissance]
12-16 11:16:03.118 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\HasNoChildren], /, Fuentes]
12-16 11:16:03.118 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\HasNoChildren, \Inbox], /, Inbox]
12-16 11:16:03.118 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\HasNoChildren], /, Info]
12-16 11:16:03.118 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\HasNoChildren], /, MH]
12-16 11:16:03.118 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\HasChildren], /, Mailing]
12-16 11:16:03.118 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\HasNoChildren], /, Mailing/Artifactory-Users]
12-16 11:16:03.118 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\HasNoChildren], /, Mailing/DebouLyon]
12-16 11:16:03.118 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\HasNoChildren], /, Mailing/Magma]
12-16 11:16:03.118 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\HasNoChildren], /, Mailing/RezoSup]
12-16 11:16:03.118 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\HasNoChildren], /, Mailing/Seaside]
12-16 11:16:03.118 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\HasNoChildren], /, Mailing/Squeak-dev]
12-16 11:16:03.126 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\HasNoChildren], /, Mailing/Squeak-fr]
12-16 11:16:03.126 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\HasNoChildren], /, Mailing/android-developers]
12-16 11:16:03.126 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\HasNoChildren], /, Perso]
12-16 11:16:03.126 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\HasChildren], /, SMS]
12-16 11:16:03.126 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\HasNoChildren], /, SMS/SMS-Old]
12-16 11:16:03.126 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\HasNoChildren], /, SoFreshTeam]
12-16 11:16:03.126 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\HasChildren], /, Social]
12-16 11:16:03.126 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\HasNoChildren], /, Social/Facebook]
12-16 11:16:03.126 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\HasNoChildren], /, Social/Google+]
12-16 11:16:03.134 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\HasNoChildren], /, Social/LinkedIn]
12-16 11:16:03.134 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\HasNoChildren], /, Thaanis]
12-16 11:16:03.134 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\HasNoChildren], /, Work]
12-16 11:16:03.134 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\HasChildren, \Noselect], /, [Gmail]]
12-16 11:16:03.134 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\AllMail, \HasNoChildren], /, [Gmail]/All Mail]
12-16 11:16:03.134 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\HasNoChildren], /, [Gmail]/Chats]
12-16 11:16:03.134 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\HasNoChildren, \Drafts], /, [Gmail]/Drafts]
12-16 11:16:03.134 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\Important, \HasNoChildren], /, [Gmail]/Important]
12-16 11:16:03.134 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\Sent, \HasNoChildren], /, [Gmail]/Sent Mail]
12-16 11:16:03.134 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\Spam, \HasNoChildren], /, [Gmail]/Spam]
12-16 11:16:03.141 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\Starred, \HasNoChildren], /, [Gmail]/Starred]
12-16 11:16:03.141 V/k9      (23125): conn1107372320<<<#null# [XLIST, [\HasNoChildren, \Trash], /, [Gmail]/Trash]
12-16 11:16:03.141 V/k9      (23125): conn1107372320<<<#4# [OK, Success]
12-16 11:16:03.157 D/k9      (23125): Folder auto-configuration detected draft folder: [Gmail]/Drafts
12-16 11:16:03.157 D/k9      (23125): Folder auto-configuration detected sent folder: [Gmail]/Sent Mail
12-16 11:16:03.157 D/k9      (23125): Folder auto-configuration detected spam folder: [Gmail]/Spam
12-16 11:16:03.157 D/k9      (23125): Folder auto-configuration detected trash folder: [Gmail]/Trash
12-16 11:16:03.157 V/SMSBackup+(23125): backupStateChanged:BackupState{currentSyncedItems=0, itemsToSync=0, backupType=MANUAL, exception=null, state =CALC}
12-16 11:16:03.157 V/SMSBackup+(23125): backing up: CursorAndType{type=SMS, cursor=android.content.ContentResolver$CursorWrapperInner@42008c60}
12-16 11:16:03.282 V/SMSBackup+(23125): sending 1 SMS message(s) to server.
12-16 11:16:03.282 D/k9      (23125): Connecting to imap.gmail.com as imap.gmail.com/64.233.166.109
12-16 11:16:03.501 V/k9      (23125): conn1107852472<<<#null# [OK, Gimap ready for requests from 1.1.1.42 hr18mb42024630wib]
12-16 11:16:03.501 I/k9      (23125): Did not get capabilities in banner, requesting CAPABILITY for conn1107852472
12-16 11:16:03.501 V/k9      (23125): conn1107852472>>> 1 CAPABILITY
12-16 11:16:03.548 V/k9      (23125): conn1107852472<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, XYZZY, SASL-IR, AUTH=XOAUTH, AUTH=XOAUTH2, AUTH=PLAIN, AUTH=PLAIN-CLIENTTOKEN]
12-16 11:16:03.548 V/k9      (23125): conn1107852472<<<#1# [OK, Thats all she wrote! hr18mb42024630wib]
12-16 11:16:03.548 D/k9      (23125): Saving 16 capabilities for conn1107852472
12-16 11:16:03.556 V/k9      (23125): conn1107852472>>> [Command Hidden, Enable Sensitive Debug Logging To Show]
12-16 11:16:03.618 V/k9      (23125): conn1107852472<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-16 11:16:03.626 D/k9      (23125): Untagged response #null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-16 11:16:03.626 V/k9      (23125): conn1107852472<<<#2# [OK, blablabla@gmail.com authenticated (Success)]
12-16 11:16:03.626 D/k9      (23125): Untagged response #2# [OK, blablabla@gmail.com authenticated (Success)]
12-16 11:16:03.626 D/k9      (23125): COMPRESS=DEFLATE = false
12-16 11:16:03.626 D/k9      (23125): NAMESPACE = true, mPathPrefix = 
12-16 11:16:03.634 D/k9      (23125): Connecting to imap.gmail.com as imap.gmail.com/64.233.166.109
12-16 11:16:03.852 V/k9      (23125): conn1107852216<<<#null# [OK, Gimap ready for requests from 1.1.1.42 bp7mb35961615wib]
12-16 11:16:03.852 I/k9      (23125): Did not get capabilities in banner, requesting CAPABILITY for conn1107852216
12-16 11:16:03.852 V/k9      (23125): conn1107852216>>> 1 CAPABILITY
12-16 11:16:03.891 V/k9      (23125): conn1107852216<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, XYZZY, SASL-IR, AUTH=XOAUTH, AUTH=XOAUTH2, AUTH=PLAIN, AUTH=PLAIN-CLIENTTOKEN]
12-16 11:16:03.891 V/k9      (23125): conn1107852216<<<#1# [OK, Thats all she wrote! bp7mb35961615wib]
12-16 11:16:03.891 D/k9      (23125): Saving 16 capabilities for conn1107852216
12-16 11:16:03.899 V/k9      (23125): conn1107852216>>> [Command Hidden, Enable Sensitive Debug Logging To Show]
12-16 11:16:03.977 V/k9      (23125): conn1107852216<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-16 11:16:03.977 D/k9      (23125): Untagged response #null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-16 11:16:03.977 V/k9      (23125): conn1107852216<<<#2# [OK, blablabla@gmail.com authenticated (Success)]
12-16 11:16:03.977 D/k9      (23125): Untagged response #2# [OK, blablabla@gmail.com authenticated (Success)]
12-16 11:16:03.977 D/k9      (23125): COMPRESS=DEFLATE = false
12-16 11:16:03.977 D/k9      (23125): NAMESPACE = true, mPathPrefix = 
12-16 11:16:03.977 V/k9      (23125): conn1107852216>>> 3 STATUS "SMS" (UIDVALIDITY)
12-16 11:16:04.024 V/k9      (23125): conn1107852216<<<#null# [STATUS, SMS, [UIDVALIDITY, 51]]
12-16 11:16:04.024 V/k9      (23125): conn1107852216<<<#3# [OK, Success]
12-16 11:16:04.024 V/k9      (23125): conn1107852472>>> 3 NOOP
12-16 11:16:04.071 V/k9      (23125): conn1107852472<<<#3# [OK, Success]
12-16 11:16:04.071 V/k9      (23125): conn1107852472>>> 4 SELECT "SMS"
12-16 11:16:04.493 V/k9      (23125): conn1107852472<<<#null# [FLAGS, [\Answered, \Flagged, \Draft, \Deleted, \Seen, $Phishing, $NotPhishing]]
12-16 11:16:04.501 V/k9      (23125): conn1107852472<<<#null# [OK, [PERMANENTFLAGS, [\Answered, \Flagged, \Draft, \Deleted, \Seen, $Phishing, $NotPhishing, \*]], Flags permitted.]
12-16 11:16:04.501 V/k9      (23125): conn1107852472<<<#null# [OK, [UIDVALIDITY, 51], UIDs valid.]
12-16 11:16:04.501 V/k9      (23125): conn1107852472<<<#null# [0, EXISTS]
12-16 11:16:04.501 V/k9      (23125): conn1107852472<<<#null# [0, RECENT]
12-16 11:16:04.501 V/k9      (23125): conn1107852472<<<#null# [OK, [UIDNEXT, 49600], Predicted next UID.]
12-16 11:16:04.509 V/k9      (23125): conn1107852472<<<#null# [OK, [HIGHESTMODSEQ, 7756170]]
12-16 11:16:04.509 V/k9      (23125): conn1107852472<<<#4# [OK, [READ-WRITE], SMS selected. (Success)]
12-16 11:16:04.509 D/k9      (23125): Got untagged EXISTS with value 0 for com.zegoggles.smssync.mail.BackupStoreConfig@420066d8:SMS/AsyncTask #2/conn1107852472
12-16 11:16:04.509 D/k9      (23125): Got UidNext = 49600 for com.zegoggles.smssync.mail.BackupStoreConfig@420066d8:SMS/AsyncTask #2/conn1107852472
12-16 11:16:04.509 V/k9      (23125): conn1107852472>>> 5 NOOP
12-16 11:16:04.548 V/k9      (23125): conn1107852472<<<#5# [OK, Success]
12-16 11:16:04.563 V/k9      (23125): conn1107852472>>> 6 APPEND "SMS" (\Seen) {3316}
12-16 11:16:04.563 D/k9      (23125): about to read response
12-16 11:16:04.602 V/k9      (23125): conn1107852472<<<#+# [go ahead]
12-16 11:16:04.602 D/k9      (23125): got #+# [go ahead]
12-16 11:16:04.618 D/k9      (23125): about to read response
12-16 11:16:06.548 V/k9      (23125): conn1107852472<<<#null# [1, EXISTS]
12-16 11:16:06.548 D/k9      (23125): got #null# [1, EXISTS]
12-16 11:16:06.556 D/k9      (23125): Got untagged EXISTS with value 1 for com.zegoggles.smssync.mail.BackupStoreConfig@420066d8:SMS/AsyncTask #2/conn1107852472
12-16 11:16:06.556 D/k9      (23125): no continuation requested for #null# [1, EXISTS]
12-16 11:16:06.556 D/k9      (23125): about to read response
12-16 11:16:06.556 V/k9      (23125): conn1107852472<<<#6# [OK, [APPENDUID, 51, 49600], (Success)]
12-16 11:16:06.556 D/k9      (23125): got #6# [OK, [APPENDUID, 51, 49600], (Success)]
12-16 11:16:06.556 D/k9      (23125): no continuation requested for #6# [OK, [APPENDUID, 51, 49600], (Success)]
12-16 11:16:06.626 V/SMSBackup+(23125): backing up: CursorAndType{type=SMS, cursor=android.content.ContentResolver$CursorWrapperInner@42008c60}
12-16 11:16:06.634 V/SMSBackup+(23125): dataChanged()
12-16 11:16:06.657 V/SMSBackup+(23125): backupStateChanged:BackupState{currentSyncedItems=1, itemsToSync=2336, backupType=MANUAL, exception=null, state =BACKUP}
12-16 11:16:06.696 V/SMSBackup+(23125): sending 1 SMS message(s) to server.
12-16 11:16:06.696 V/k9      (23125): conn1107852472>>> 7 NOOP
12-16 11:16:06.743 V/k9      (23125): conn1107852472<<<#7# [OK, Success]
12-16 11:16:06.743 V/k9      (23125): conn1107852472>>> 8 APPEND "SMS" (\Seen) {715}
12-16 11:16:06.751 D/k9      (23125): about to read response
12-16 11:16:06.790 V/k9      (23125): conn1107852472<<<#+# [go ahead]
12-16 11:16:06.790 D/k9      (23125): got #+# [go ahead]
12-16 11:16:06.790 D/k9      (23125): about to read response
12-16 11:16:08.290 V/k9      (23125): conn1107852472<<<#null# [2, EXISTS]
12-16 11:16:08.290 D/k9      (23125): got #null# [2, EXISTS]
12-16 11:16:08.290 D/k9      (23125): Got untagged EXISTS with value 2 for com.zegoggles.smssync.mail.BackupStoreConfig@420066d8:SMS/AsyncTask #2/conn1107852472
12-16 11:16:08.290 D/k9      (23125): no continuation requested for #null# [2, EXISTS]
12-16 11:16:08.290 D/k9      (23125): about to read response
12-16 11:16:08.298 V/k9      (23125): conn1107852472<<<#8# [OK, [APPENDUID, 51, 49601], (Success)]
12-16 11:16:08.298 D/k9      (23125): got #8# [OK, [APPENDUID, 51, 49601], (Success)]
12-16 11:16:08.298 D/k9      (23125): no continuation requested for #8# [OK, [APPENDUID, 51, 49601], (Success)]
12-16 11:16:08.345 V/SMSBackup+(23125): dataChanged()
12-16 11:16:08.352 V/SMSBackup+(23125): backupStateChanged:BackupState{currentSyncedItems=2, itemsToSync=2336, backupType=MANUAL, exception=null, state =BACKUP}
12-16 11:16:08.352 V/SMSBackup+(23125): backing up: CursorAndType{type=SMS, cursor=android.content.ContentResolver$CursorWrapperInner@42008c60}
12-16 11:16:08.399 V/SMSBackup+(23125): sending 1 SMS message(s) to server.
12-16 11:16:08.399 V/k9      (23125): conn1107852472>>> 9 NOOP
12-16 11:16:08.470 V/k9      (23125): conn1107852472<<<#9# [OK, Success]
12-16 11:16:08.470 V/k9      (23125): conn1107852472>>> 10 APPEND "SMS" (\Seen) {765}
12-16 11:16:08.477 D/k9      (23125): about to read response
12-16 11:16:08.516 V/k9      (23125): conn1107852472<<<#+# [go ahead]
12-16 11:16:08.516 D/k9      (23125): got #+# [go ahead]
12-16 11:16:08.524 D/k9      (23125): about to read response
12-16 11:16:09.954 V/k9      (23125): conn1107852472<<<#null# [3, EXISTS]
12-16 11:16:09.954 D/k9      (23125): got #null# [3, EXISTS]
12-16 11:16:09.954 D/k9      (23125): Got untagged EXISTS with value 3 for com.zegoggles.smssync.mail.BackupStoreConfig@420066d8:SMS/AsyncTask #2/conn1107852472
12-16 11:16:09.954 D/k9      (23125): no continuation requested for #null# [3, EXISTS]
12-16 11:16:09.954 D/k9      (23125): about to read response
12-16 11:16:09.962 V/k9      (23125): conn1107852472<<<#10# [OK, [APPENDUID, 51, 49602], (Success)]
12-16 11:16:09.962 D/k9      (23125): got #10# [OK, [APPENDUID, 51, 49602], (Success)]
12-16 11:16:09.962 D/k9      (23125): no continuation requested for #10# [OK, [APPENDUID, 51, 49602], (Success)]
[...]
12-16 11:17:56.759 V/SMSBackup+(23125): backing up: CursorAndType{type=SMS, cursor=android.content.ContentResolver$CursorWrapperInner@42008c60}
12-16 11:17:56.774 V/SMSBackup+(23125): sending 1 SMS message(s) to server.
12-16 11:17:56.774 V/k9      (23125): conn1107852472>>> 169 NOOP
12-16 11:17:56.876 V/k9      (23125): conn1107852472<<<#169# [OK, Success]
12-16 11:17:56.876 V/k9      (23125): conn1107852472>>> 170 APPEND "SMS" (\Seen) {1143}
12-16 11:17:56.876 D/k9      (23125): about to read response
12-16 11:17:56.931 V/k9      (23125): conn1107852472<<<#+# [go ahead]
12-16 11:17:56.931 D/k9      (23125): got #+# [go ahead]
12-16 11:17:56.938 D/k9      (23125): about to read response
12-16 11:20:02.095 V/BackupServiceBinder(23125): doBackup() invoked
12-16 11:20:02.095 V/SMSBackup+(23125): onBackup()
12-16 11:20:02.095 D/BackupHelperDispatcher(23125): handling existing helper 'prefs' android.app.backup.SharedPreferencesBackupHelper@41b85030
12-16 11:20:02.290 V/BackupServiceBinder(23125): doBackup() invoked
12-16 11:20:02.290 V/SMSBackup+(23125): onBackup()
12-16 11:20:02.290 D/BackupHelperDispatcher(23125): handling existing helper 'prefs' android.app.backup.SharedPreferencesBackupHelper@42331778
12-16 11:20:02.415 V/BackupServiceBinder(23125): doBackup() invoked
12-16 11:20:02.415 V/SMSBackup+(23125): onBackup()
12-16 11:20:02.415 D/BackupHelperDispatcher(23125): handling existing helper 'prefs' android.app.backup.SharedPreferencesBackupHelper@42315be8
12-16 11:20:02.579 V/BackupServiceBinder(23125): doBackup() invoked
12-16 11:20:02.579 V/SMSBackup+(23125): onBackup()
12-16 11:20:02.579 D/BackupHelperDispatcher(23125): handling existing helper 'prefs' android.app.backup.SharedPreferencesBackupHelper@423168c8
12-16 11:22:57.095 E/k9      (23125): IOException for com.zegoggles.smssync.mail.BackupStoreConfig@420066d8:SMS/AsyncTask #2/conn1107852472
12-16 11:22:57.095 E/k9      (23125): java.net.SocketTimeoutException: Read timed out
12-16 11:22:57.095 E/k9      (23125):   at com.android.org.conscrypt.NativeCrypto.SSL_read(Native Method)
12-16 11:22:57.095 E/k9      (23125):   at com.android.org.conscrypt.OpenSSLSocketImpl$SSLInputStream.read(OpenSSLSocketImpl.java:689)
12-16 11:22:57.095 E/k9      (23125):   at java.io.InputStream.read(InputStream.java:162)
12-16 11:22:57.095 E/k9      (23125):   at java.io.BufferedInputStream.fillbuf(BufferedInputStream.java:142)
12-16 11:22:57.095 E/k9      (23125):   at java.io.BufferedInputStream.read(BufferedInputStream.java:227)
12-16 11:22:57.095 E/k9      (23125):   at com.fsck.k9.mail.filter.PeekableInputStream.peek(PeekableInputStream.java:34)
12-16 11:22:57.095 E/k9      (23125):   at com.fsck.k9.mail.store.ImapResponseParser.readResponse(ImapResponseParser.java:42)
12-16 11:22:57.095 E/k9      (23125):   at com.fsck.k9.mail.store.ImapStore$ImapConnection.readResponse(ImapStore.java:2869)
12-16 11:22:57.095 E/k9      (23125):   at com.fsck.k9.mail.store.ImapStore$ImapConnection.readResponse(ImapStore.java:2864)
12-16 11:22:57.095 E/k9      (23125):   at com.fsck.k9.mail.store.ImapStore$ImapFolder.appendMessages(ImapStore.java:1983)
12-16 11:22:57.095 E/k9      (23125):   at com.zegoggles.smssync.service.BackupTask.backupCursors(BackupTask.java:265)
12-16 11:22:57.095 E/k9      (23125):   at com.zegoggles.smssync.service.BackupTask.fetchAndBackupItems(BackupTask.java:146)
12-16 11:22:57.095 E/k9      (23125):   at com.zegoggles.smssync.service.BackupTask.handleAuthError(BackupTask.java:181)
12-16 11:22:57.095 E/k9      (23125):   at com.zegoggles.smssync.service.BackupTask.fetchAndBackupItems(BackupTask.java:160)
12-16 11:22:57.095 E/k9      (23125):   at com.zegoggles.smssync.service.BackupTask.acquireLocksAndBackup(BackupTask.java:126)
12-16 11:22:57.095 E/k9      (23125):   at com.zegoggles.smssync.service.BackupTask.doInBackground(BackupTask.java:119)
12-16 11:22:57.095 E/k9      (23125):   at com.zegoggles.smssync.service.BackupTask.doInBackground(BackupTask.java:46)
12-16 11:22:57.095 E/k9      (23125):   at android.os.AsyncTask$2.call(AsyncTask.java:288)
12-16 11:22:57.095 E/k9      (23125):   at java.util.concurrent.FutureTask.run(FutureTask.java:237)
12-16 11:22:57.095 E/k9      (23125):   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
12-16 11:22:57.095 E/k9      (23125):   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
12-16 11:22:57.095 E/k9      (23125):   at java.lang.Thread.run(Thread.java:841)
12-16 11:22:57.110 V/SMSBackup+(23125): [AppLog]: 16-12 11:22 Erreur générale : IO Error (exception: com.fsck.k9.mail.MessagingException: IO Error, underlying=java.net.SocketTimeoutException: Read timed out)
12-16 11:22:57.110 V/SMSBackup+(23125): [AppLog]: 16-12 11:22 BackupState{currentSyncedItems=82, itemsToSync=2336, backupType=MANUAL, exception=com.fsck.k9.mail.MessagingException: IO Error, state =ERROR}
12-16 11:22:57.118 V/SMSBackup+(23125): [AppLog]: 16-12 11:22 Sauvegarde effectuée
12-16 11:22:57.118 V/SMSBackup+(23125): AppLog#close()
12-16 11:31:33.767 V/Zygote  (24766): Switching descriptor 33 to /dev/null
12-16 11:31:33.767 V/Zygote  (24766): Switching descriptor 10 to /dev/null
12-16 11:31:33.806 I/dalvikvm(24766): Enabling JNI app bug workarounds for target SDK version 10...
12-16 11:31:33.846 D/ActivityThread(24766): handleBindApplication:com.zegoggles.smssync
12-16 11:31:33.853 D/ActivityThread(24766): setTargetHeapUtilization:0.75
12-16 11:31:33.853 D/ActivityThread(24766): setTargetHeapMinFree:2097152
12-16 11:31:34.322 W/Resources(24766): Converting to string: TypedValue{t=0x10/d=0x1c20 a=-1}
12-16 11:31:34.322 W/Resources(24766): Converting to string: TypedValue{t=0x10/d=0x1c20 a=-1}
12-16 11:31:34.330 W/Resources(24766): Converting to string: TypedValue{t=0x10/d=0xb4 a=-1}
12-16 11:31:34.330 W/Resources(24766): Converting to string: TypedValue{t=0x10/d=0xb4 a=-1}
12-16 11:31:34.346 W/Resources(24766): Converting to string: TypedValue{t=0x10/d=0xffffffff a=-1}
12-16 11:31:34.346 W/Resources(24766): Converting to string: TypedValue{t=0x10/d=0xffffffff a=-1}
12-16 11:31:34.346 W/Resources(24766): Converting to string: TypedValue{t=0x10/d=0xffffffff a=-1}
12-16 11:31:34.346 W/Resources(24766): Converting to string: TypedValue{t=0x10/d=0xffffffff a=-1}
12-16 11:31:34.353 W/Resources(24766): Converting to string: TypedValue{t=0x10/d=0xffffffff a=-1}
12-16 11:31:34.353 W/Resources(24766): Converting to string: TypedValue{t=0x10/d=0xffffffff a=-1}
12-16 11:31:34.431 D/SMSBackup+(24766): onResume()
12-16 11:31:34.681 D/SMSBackup+(24766): id:2, name:Anniversaires, synced:true
12-16 11:31:34.681 D/SMSBackup+(24766): id:10, name:Boulot, synced:true
12-16 11:31:34.681 D/SMSBackup+(24766): id:7, name:Calendrier LyonJUG, synced:false
12-16 11:31:34.681 D/SMSBackup+(24766): id:9, name:DebouLyon, synced:false
12-16 11:31:34.681 D/SMSBackup+(24766): id:1, name:Bla Bla, synced:true
12-16 11:31:34.681 D/SMSBackup+(24766): id:13, name:Important, synced:false
12-16 11:31:34.681 D/SMSBackup+(24766): id:3, name:Jours fériés en France, synced:true
12-16 11:31:34.681 D/SMSBackup+(24766): id:5, name:Météo, synced:true
12-16 11:31:34.681 D/SMSBackup+(24766): id:6, name:Pas là, synced:true
12-16 11:31:34.681 D/SMSBackup+(24766): id:4, name:Phases de la Lune, synced:true
12-16 11:31:34.681 D/SMSBackup+(24766): id:8, name:Private, synced:true
12-16 11:31:34.681 D/SMSBackup+(24766): id:11, name:TODO, synced:false
12-16 11:31:34.908 W/ContextImpl(24766): Implicit intents with startService are not safe: Intent { act=com.android.vending.billing.InAppBillingService.BIND } android.content.ContextWrapper.bindService:517 com.github.jberkel.pay.me.IabHelper.startSetup:152 com.zegoggles.smssync.activity.donation.DonationActivity.checkUserHasDonated:244 
12-16 11:31:35.353 I/Timeline(24766): Timeline: Activity_idle id: android.os.BinderProxy@41b8bec8 time:146959906
12-16 11:31:37.213 V/SMSBackup+(24766): user requested sync
12-16 11:31:37.244 V/SMSBackup+(24766): backupStateChanged:BackupState{currentSyncedItems=0, itemsToSync=0, backupType=UNKNOWN, exception=null, state =INITIAL}
12-16 11:31:37.244 V/SMSBackup+(24766): handleIntent(Intent { cmp=com.zegoggles.smssync/.service.SmsBackupService (has extras) }, android.util.MapCollections$KeySet@fd9f6acd, type=MANUAL)
12-16 11:31:37.244 V/SMSBackup+(24766): [AppLog]: 16-12 11:31 Sauvegarde demandée (manuel)
12-16 11:31:37.252 V/SMSBackup+(24766): [AppLog]: 16-12 11:31 Démarrage de la sauvegarde (MANUAL)
12-16 11:31:37.252 D/SMSBackup+(24766): using new contacts API
12-16 11:31:37.252 V/SMSBackup+(24766): whitelisted ids for backup: null
12-16 11:31:37.306 V/SMSBackup+(24766): getItemsForDataType(type=SMS, max=-1)
12-16 11:31:37.564 V/SMSBackup+(24766): getItemsForDataType(type=MMS, max=-1)
12-16 11:31:37.572 V/SMSBackup+(24766): getItemsForDataType(type=WHATSAPP, max=-1)
12-16 11:31:37.572 V/SMSBackup+(24766): getItems(max=-1)
12-16 11:31:37.588 D/Whassup (24766): could not find db
12-16 11:31:37.588 V/SMSBackup+(24766): No whatsapp backup DB found, returning empty
12-16 11:31:37.596 V/SMSBackup+(24766): [AppLog]: 16-12 11:31 Sauvegarde en cours (2170 SMS, 84 MMS, 0 appels)
12-16 11:31:37.603 V/SMSBackup+(24766): [AppLog]: 16-12 11:31 Using config: BackupConfig{imap=BackupImapStore{uri=imap+ssl+://XOAUTH2:XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX@imap.gmail.com:993}, skip=false, currentTry=0, maxItemsPerSync=-1, groupToBackup=ContactGroup{_id=-1, type=EVERYBODY}, backupType=MANUAL, debug=true, typesToBackup=[SMS, MMS, WHATSAPP]}
12-16 11:31:37.603 I/SMSBackup+(24766): Starting backup (2254 messages)
12-16 11:31:37.603 V/SMSBackup+(24766): backupStateChanged:BackupState{currentSyncedItems=0, itemsToSync=0, backupType=MANUAL, exception=null, state =LOGIN}
12-16 11:31:37.681 D/k9      (24766): Connecting to imap.gmail.com as imap.gmail.com/74.125.133.109
12-16 11:31:37.681 W/k9      (24766): Local key store has not been initialized
12-16 11:31:37.978 V/k9      (24766): conn1106791016<<<#null# [OK, Gimap ready for requests from 1.1.1.42 e127mb43441348wlb]
12-16 11:31:37.978 I/k9      (24766): Did not get capabilities in banner, requesting CAPABILITY for conn1106791016
12-16 11:31:37.986 V/k9      (24766): conn1106791016>>> 1 CAPABILITY
12-16 11:31:38.025 V/k9      (24766): conn1106791016<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, XYZZY, SASL-IR, AUTH=XOAUTH, AUTH=XOAUTH2, AUTH=PLAIN, AUTH=PLAIN-CLIENTTOKEN]
12-16 11:31:38.033 V/k9      (24766): conn1106791016<<<#1# [OK, Thats all she wrote! e127mb43441348wlb]
12-16 11:31:38.033 D/k9      (24766): Saving 16 capabilities for conn1106791016
12-16 11:31:38.041 V/k9      (24766): conn1106791016>>> [Command Hidden, Enable Sensitive Debug Logging To Show]
12-16 11:31:38.111 V/k9      (24766): conn1106791016<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-16 11:31:38.111 D/k9      (24766): Untagged response #null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-16 11:31:38.111 V/k9      (24766): conn1106791016<<<#2# [OK, blablabla@gmail.com authenticated (Success)]
12-16 11:31:38.111 D/k9      (24766): Untagged response #2# [OK, blablabla@gmail.com authenticated (Success)]
12-16 11:31:38.119 D/k9      (24766): COMPRESS=DEFLATE = false
12-16 11:31:38.119 D/k9      (24766): NAMESPACE = true, mPathPrefix = null
12-16 11:31:38.119 I/k9      (24766): mPathPrefix is unset and server has NAMESPACE capability
12-16 11:31:38.119 V/k9      (24766): conn1106791016>>> 3 NAMESPACE
12-16 11:31:38.166 V/k9      (24766): conn1106791016<<<#null# [NAMESPACE, [[, /]], NIL, NIL]
12-16 11:31:38.166 V/k9      (24766): conn1106791016<<<#3# [OK, Success]
12-16 11:31:38.166 D/k9      (24766): Got NAMESPACE response #null# [NAMESPACE, [[, /]], NIL, NIL] on conn1106791016
12-16 11:31:38.166 D/k9      (24766): Got personal namespaces: [[, /]]
12-16 11:31:38.166 D/k9      (24766): Got first personal namespaces: [, /]
12-16 11:31:38.166 D/k9      (24766): Got path '' and separator '/'
12-16 11:31:38.174 D/k9      (24766): Folder auto-configuration: Using XLIST.
12-16 11:31:38.174 V/k9      (24766): conn1106791016>>> 4 XLIST "" "*"
12-16 11:31:38.213 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\HasNoChildren], /, Call log]
12-16 11:31:38.221 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\HasNoChildren], /, Deal]
12-16 11:31:38.221 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\HasNoChildren], /, Divers]
12-16 11:31:38.221 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\HasNoChildren], /, D&AOk-croissance]
12-16 11:31:38.221 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\HasNoChildren], /, Fuentes]
12-16 11:31:38.221 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\HasNoChildren, \Inbox], /, Inbox]
12-16 11:31:38.221 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\HasNoChildren], /, Info]
12-16 11:31:38.221 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\HasNoChildren], /, MH]
12-16 11:31:38.228 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\HasChildren], /, Mailing]
12-16 11:31:38.228 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\HasNoChildren], /, Mailing/Artifactory-Users]
12-16 11:31:38.228 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\HasNoChildren], /, Mailing/DebouLyon]
12-16 11:31:38.228 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\HasNoChildren], /, Mailing/Magma]
12-16 11:31:38.228 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\HasNoChildren], /, Mailing/RezoSup]
12-16 11:31:38.236 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\HasNoChildren], /, Mailing/Seaside]
12-16 11:31:38.236 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\HasNoChildren], /, Mailing/Squeak-dev]
12-16 11:31:38.236 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\HasNoChildren], /, Mailing/Squeak-fr]
12-16 11:31:38.236 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\HasNoChildren], /, Mailing/android-developers]
12-16 11:31:38.236 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\HasNoChildren], /, Perso]
12-16 11:31:38.244 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\HasChildren], /, SMS]
12-16 11:31:38.244 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\HasNoChildren], /, SMS/SMS-Old]
12-16 11:31:38.244 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\HasNoChildren], /, SoFreshTeam]
12-16 11:31:38.244 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\HasChildren], /, Social]
12-16 11:31:38.252 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\HasNoChildren], /, Social/Facebook]
12-16 11:31:38.252 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\HasNoChildren], /, Social/Google+]
12-16 11:31:38.252 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\HasNoChildren], /, Social/LinkedIn]
12-16 11:31:38.252 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\HasNoChildren], /, Thaanis]
12-16 11:31:38.252 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\HasNoChildren], /, Work]
12-16 11:31:38.252 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\HasChildren, \Noselect], /, [Gmail]]
12-16 11:31:38.252 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\AllMail, \HasNoChildren], /, [Gmail]/All Mail]
12-16 11:31:38.252 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\HasNoChildren], /, [Gmail]/Chats]
12-16 11:31:38.252 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\HasNoChildren, \Drafts], /, [Gmail]/Drafts]
12-16 11:31:38.260 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\Important, \HasNoChildren], /, [Gmail]/Important]
12-16 11:31:38.260 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\Sent, \HasNoChildren], /, [Gmail]/Sent Mail]
12-16 11:31:38.260 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\Spam, \HasNoChildren], /, [Gmail]/Spam]
12-16 11:31:38.260 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\Starred, \HasNoChildren], /, [Gmail]/Starred]
12-16 11:31:38.260 V/k9      (24766): conn1106791016<<<#null# [XLIST, [\HasNoChildren, \Trash], /, [Gmail]/Trash]
12-16 11:31:38.260 V/k9      (24766): conn1106791016<<<#4# [OK, Success]
12-16 11:31:38.267 D/k9      (24766): Folder auto-configuration detected draft folder: [Gmail]/Drafts
12-16 11:31:38.267 D/k9      (24766): Folder auto-configuration detected sent folder: [Gmail]/Sent Mail
12-16 11:31:38.267 D/k9      (24766): Folder auto-configuration detected spam folder: [Gmail]/Spam
12-16 11:31:38.267 D/k9      (24766): Folder auto-configuration detected trash folder: [Gmail]/Trash
12-16 11:31:38.275 V/SMSBackup+(24766): backing up: CursorAndType{type=SMS, cursor=android.content.ContentResolver$CursorWrapperInner@41f71860}
12-16 11:31:38.275 V/SMSBackup+(24766): backupStateChanged:BackupState{currentSyncedItems=0, itemsToSync=0, backupType=MANUAL, exception=null, state =CALC}
12-16 11:31:38.346 V/SMSBackup+(24766): sending 1 SMS message(s) to server.
12-16 11:31:38.346 D/k9      (24766): Connecting to imap.gmail.com as imap.gmail.com/74.125.133.109
12-16 11:31:38.533 V/k9      (24766): conn1107408112<<<#null# [OK, Gimap ready for requests from 1.1.1.42 t20mb42642615wiv]
12-16 11:31:38.533 I/k9      (24766): Did not get capabilities in banner, requesting CAPABILITY for conn1107408112
12-16 11:31:38.533 V/k9      (24766): conn1107408112>>> 1 CAPABILITY
12-16 11:31:38.572 V/k9      (24766): conn1107408112<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, XYZZY, SASL-IR, AUTH=XOAUTH, AUTH=XOAUTH2, AUTH=PLAIN, AUTH=PLAIN-CLIENTTOKEN]
12-16 11:31:38.572 V/k9      (24766): conn1107408112<<<#1# [OK, Thats all she wrote! t20mb42642615wiv]
12-16 11:31:38.572 D/k9      (24766): Saving 16 capabilities for conn1107408112
12-16 11:31:38.580 V/k9      (24766): conn1107408112>>> [Command Hidden, Enable Sensitive Debug Logging To Show]
12-16 11:31:38.642 V/k9      (24766): conn1107408112<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-16 11:31:38.642 D/k9      (24766): Untagged response #null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-16 11:31:38.642 V/k9      (24766): conn1107408112<<<#2# [OK, blablabla@gmail.com authenticated (Success)]
12-16 11:31:38.642 D/k9      (24766): Untagged response #2# [OK, blablabla@gmail.com authenticated (Success)]
12-16 11:31:38.650 D/k9      (24766): COMPRESS=DEFLATE = false
12-16 11:31:38.650 D/k9      (24766): NAMESPACE = true, mPathPrefix = 
12-16 11:31:38.650 D/k9      (24766): Connecting to imap.gmail.com as imap.gmail.com/74.125.133.109
12-16 11:31:38.877 V/k9      (24766): conn1107407856<<<#null# [OK, Gimap ready for requests from s1.1.1.42 lg11mb12492621wic]
12-16 11:31:38.877 I/k9      (24766): Did not get capabilities in banner, requesting CAPABILITY for conn1107407856
12-16 11:31:38.877 V/k9      (24766): conn1107407856>>> 1 CAPABILITY
12-16 11:31:38.931 V/k9      (24766): conn1107407856<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, XYZZY, SASL-IR, AUTH=XOAUTH, AUTH=XOAUTH2, AUTH=PLAIN, AUTH=PLAIN-CLIENTTOKEN]
12-16 11:31:38.931 V/k9      (24766): conn1107407856<<<#1# [OK, Thats all she wrote! lg11mb12492621wic]
12-16 11:31:38.931 D/k9      (24766): Saving 16 capabilities for conn1107407856
12-16 11:31:38.931 V/k9      (24766): conn1107407856>>> [Command Hidden, Enable Sensitive Debug Logging To Show]
12-16 11:31:39.002 V/k9      (24766): conn1107407856<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-16 11:31:39.002 D/k9      (24766): Untagged response #null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-16 11:31:39.002 V/k9      (24766): conn1107407856<<<#2# [OK, blablabla@gmail.com authenticated (Success)]
12-16 11:31:39.002 D/k9      (24766): Untagged response #2# [OK, blablabla@gmail.com authenticated (Success)]
12-16 11:31:39.002 D/k9      (24766): COMPRESS=DEFLATE = false
12-16 11:31:39.002 D/k9      (24766): NAMESPACE = true, mPathPrefix = 
12-16 11:31:39.002 V/k9      (24766): conn1107407856>>> 3 STATUS "SMS" (UIDVALIDITY)
12-16 11:31:39.049 V/k9      (24766): conn1107407856<<<#null# [STATUS, SMS, [UIDVALIDITY, 51]]
12-16 11:31:39.049 V/k9      (24766): conn1107407856<<<#3# [OK, Success]
12-16 11:31:39.049 V/k9      (24766): conn1107408112>>> 3 NOOP
12-16 11:31:39.096 V/k9      (24766): conn1107408112<<<#3# [OK, Success]
12-16 11:31:39.096 V/k9      (24766): conn1107408112>>> 4 SELECT "SMS"
12-16 11:31:39.322 V/k9      (24766): conn1107408112<<<#null# [FLAGS, [\Answered, \Flagged, \Draft, \Deleted, \Seen, $Phishing, $NotPhishing]]
12-16 11:31:39.330 V/k9      (24766): conn1107408112<<<#null# [OK, [PERMANENTFLAGS, [\Answered, \Flagged, \Draft, \Deleted, \Seen, $Phishing, $NotPhishing, \*]], Flags permitted.]
12-16 11:31:39.330 V/k9      (24766): conn1107408112<<<#null# [OK, [UIDVALIDITY, 51], UIDs valid.]
12-16 11:31:39.338 V/k9      (24766): conn1107408112<<<#null# [82, EXISTS]
12-16 11:31:39.338 V/k9      (24766): conn1107408112<<<#null# [0, RECENT]
12-16 11:31:39.338 V/k9      (24766): conn1107408112<<<#null# [OK, [UIDNEXT, 49682], Predicted next UID.]
12-16 11:31:39.338 V/k9      (24766): conn1107408112<<<#null# [OK, [HIGHESTMODSEQ, 7757097]]
12-16 11:31:39.338 V/k9      (24766): conn1107408112<<<#4# [OK, [READ-WRITE], SMS selected. (Success)]
12-16 11:31:39.338 D/k9      (24766): Got untagged EXISTS with value 82 for com.zegoggles.smssync.mail.BackupStoreConfig@41f609f8:SMS/AsyncTask #2/conn1107408112
12-16 11:31:39.346 D/k9      (24766): Got UidNext = 49682 for com.zegoggles.smssync.mail.BackupStoreConfig@41f609f8:SMS/AsyncTask #2/conn1107408112
12-16 11:31:39.346 V/k9      (24766): conn1107408112>>> 5 NOOP
12-16 11:31:39.385 V/k9      (24766): conn1107408112<<<#5# [OK, Success]
12-16 11:31:39.385 V/k9      (24766): conn1107408112>>> 6 APPEND "SMS" (\Seen) {1143}
12-16 11:31:39.392 D/k9      (24766): about to read response
12-16 11:31:39.439 V/k9      (24766): conn1107408112<<<#+# [go ahead]
12-16 11:31:39.439 D/k9      (24766): got #+# [go ahead]
12-16 11:31:39.447 D/k9      (24766): about to read response
12-16 11:31:40.088 W/InputEventReceiver(24766): Attempted to finish an input event but the input event receiver has already been disposed.
12-16 11:36:39.580 E/k9      (24766): IOException for com.zegoggles.smssync.mail.BackupStoreConfig@41f609f8:SMS/AsyncTask #2/conn1107408112
12-16 11:36:39.580 E/k9      (24766): java.net.SocketTimeoutException: Read timed out
12-16 11:36:39.580 E/k9      (24766):   at com.android.org.conscrypt.NativeCrypto.SSL_read(Native Method)
12-16 11:36:39.580 E/k9      (24766):   at com.android.org.conscrypt.OpenSSLSocketImpl$SSLInputStream.read(OpenSSLSocketImpl.java:689)
12-16 11:36:39.580 E/k9      (24766):   at java.io.InputStream.read(InputStream.java:162)
12-16 11:36:39.580 E/k9      (24766):   at java.io.BufferedInputStream.fillbuf(BufferedInputStream.java:142)
12-16 11:36:39.580 E/k9      (24766):   at java.io.BufferedInputStream.read(BufferedInputStream.java:227)
12-16 11:36:39.580 E/k9      (24766):   at com.fsck.k9.mail.filter.PeekableInputStream.peek(PeekableInputStream.java:34)
12-16 11:36:39.580 E/k9      (24766):   at com.fsck.k9.mail.store.ImapResponseParser.readResponse(ImapResponseParser.java:42)
12-16 11:36:39.580 E/k9      (24766):   at com.fsck.k9.mail.store.ImapStore$ImapConnection.readResponse(ImapStore.java:2869)
12-16 11:36:39.580 E/k9      (24766):   at com.fsck.k9.mail.store.ImapStore$ImapConnection.readResponse(ImapStore.java:2864)
12-16 11:36:39.580 E/k9      (24766):   at com.fsck.k9.mail.store.ImapStore$ImapFolder.appendMessages(ImapStore.java:1983)
12-16 11:36:39.580 E/k9      (24766):   at com.zegoggles.smssync.service.BackupTask.backupCursors(BackupTask.java:265)
12-16 11:36:39.580 E/k9      (24766):   at com.zegoggles.smssync.service.BackupTask.fetchAndBackupItems(BackupTask.java:146)
12-16 11:36:39.580 E/k9      (24766):   at com.zegoggles.smssync.service.BackupTask.acquireLocksAndBackup(BackupTask.java:126)
12-16 11:36:39.580 E/k9      (24766):   at com.zegoggles.smssync.service.BackupTask.doInBackground(BackupTask.java:119)
12-16 11:36:39.580 E/k9      (24766):   at com.zegoggles.smssync.service.BackupTask.doInBackground(BackupTask.java:46)
12-16 11:36:39.580 E/k9      (24766):   at android.os.AsyncTask$2.call(AsyncTask.java:288)
12-16 11:36:39.580 E/k9      (24766):   at java.util.concurrent.FutureTask.run(FutureTask.java:237)
12-16 11:36:39.580 E/k9      (24766):   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
12-16 11:36:39.580 E/k9      (24766):   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
12-16 11:36:39.580 E/k9      (24766):   at java.lang.Thread.run(Thread.java:841)
12-16 11:36:39.596 V/SMSBackup+(24766): [AppLog]: 16-12 11:36 Erreur générale : IO Error (exception: com.fsck.k9.mail.MessagingException: IO Error, underlying=java.net.SocketTimeoutException: Read timed out)
12-16 11:36:39.603 V/SMSBackup+(24766): [AppLog]: 16-12 11:36 BackupState{currentSyncedItems=0, itemsToSync=0, backupType=MANUAL, exception=com.fsck.k9.mail.MessagingException: IO Error, state =ERROR}
12-16 11:36:39.603 V/SMSBackup+(24766): [AppLog]: 16-12 11:36 Sauvegarde effectuée
12-16 11:36:39.611 V/SMSBackup+(24766): AppLog#close()
12-16 11:36:39.627 V/SMSBackup+(24766): SmsBackupService#onDestroy(state=BackupState{currentSyncedItems=0, itemsToSync=0, backupType=MANUAL, exception=com.fsck.k9.mail.MessagingException: IO Error, state =ERROR})
jberkel commented 9 years ago

cool, that's helpful. i think basically what happens is the following:

now need to figure out why this happens. what i don't understand is that if there's some elementary flaw with the logic a lot more users should be affected by this problem

flomin commented 9 years ago

Can't you add a log for the size of data sent ? Even if very verbose, for debug usage, it would be very useful. And perhaps put back the date of the backing up message to be able to find it and see why it could pose problem?

jberkel commented 9 years ago

@flomin this is one of the most annoying bugs i've encountered so far.

i've created a new version which will dump the size and content of the whole message to the log once it gets stuck, this should hopefully help:

https://github.com/jberkel/sms-backup-plus/releases/tag/1.5.6-BETA10

flomin commented 9 years ago

@jberkel If it can reassure you, I had worse, with nobody to help debug, just random bugs coming from specific devices which completely crashed the system and not reproducible... I only had the ACRA reports. I spent weeks on this one...

On the bright side, this version works ! At least for now, 300 messages saved on 2367. And the backup seems to be much quicker than before. I'll tell you the result when it stops. Here is the log so far:

12-17 10:01:05.323: D/ActivityThread(17421): handleBindApplication:com.zegoggles.smssync
12-17 10:01:05.323: D/ActivityThread(17421): setTargetHeapUtilization:0.75
12-17 10:01:05.339: D/ActivityThread(17421): setTargetHeapMinFree:2097152
12-17 10:01:06.456: W/Resources(17421): Converting to string: TypedValue{t=0x10/d=0x1c20 a=-1}
12-17 10:01:06.456: W/Resources(17421): Converting to string: TypedValue{t=0x10/d=0x1c20 a=-1}
12-17 10:01:06.464: W/Resources(17421): Converting to string: TypedValue{t=0x10/d=0xb4 a=-1}
12-17 10:01:06.464: W/Resources(17421): Converting to string: TypedValue{t=0x10/d=0xb4 a=-1}
12-17 10:01:06.495: W/Resources(17421): Converting to string: TypedValue{t=0x10/d=0xffffffff a=-1}
12-17 10:01:06.495: W/Resources(17421): Converting to string: TypedValue{t=0x10/d=0xffffffff a=-1}
12-17 10:01:06.495: W/Resources(17421): Converting to string: TypedValue{t=0x10/d=0xffffffff a=-1}
12-17 10:01:06.495: W/Resources(17421): Converting to string: TypedValue{t=0x10/d=0xffffffff a=-1}
12-17 10:01:06.495: W/Resources(17421): Converting to string: TypedValue{t=0x10/d=0xffffffff a=-1}
12-17 10:01:06.495: W/Resources(17421): Converting to string: TypedValue{t=0x10/d=0xffffffff a=-1}
12-17 10:01:07.292: D/SMSBackup+(17421): onResume()
12-17 10:01:07.808: D/SMSBackup+(17421): id:2, name:Anniversaires, synced:true
12-17 10:01:07.808: D/SMSBackup+(17421): id:10, name:Boulot, synced:true
12-17 10:01:07.808: D/SMSBackup+(17421): id:7, name:Calendrier LyonJUG, synced:false
12-17 10:01:07.808: D/SMSBackup+(17421): id:9, name:DebouLyon, synced:false
12-17 10:01:07.808: D/SMSBackup+(17421): id:1, name:blablabla, synced:true
12-17 10:01:07.816: D/SMSBackup+(17421): id:13, name:Important, synced:false
12-17 10:01:07.816: D/SMSBackup+(17421): id:3, name:Jours fériés en France, synced:true
12-17 10:01:07.816: D/SMSBackup+(17421): id:5, name:Météo, synced:true
12-17 10:01:07.816: D/SMSBackup+(17421): id:6, name:Pas là, synced:true
12-17 10:01:07.816: D/SMSBackup+(17421): id:4, name:Phases de la Lune, synced:true
12-17 10:01:07.816: D/SMSBackup+(17421): id:8, name:Private, synced:true
12-17 10:01:07.816: D/SMSBackup+(17421): id:11, name:TODO, synced:false
12-17 10:01:10.542: W/ContextImpl(17421): Implicit intents with startService are not safe: Intent { act=com.android.vending.billing.InAppBillingService.BIND } android.content.ContextWrapper.bindService:517 com.github.jberkel.pay.me.IabHelper.startSetup:152 com.zegoggles.smssync.activity.donation.DonationActivity.checkUserHasDonated:244 
12-17 10:01:10.620: I/Timeline(17421): Timeline: Activity_idle id: android.os.BinderProxy@41b5b910 time:26724131
12-17 10:01:10.863: E/ActivityThread(17421): Performing stop of activity that is not resumed: {com.zegoggles.smssync/com.zegoggles.smssync.activity.MainActivity}
12-17 10:01:10.863: E/ActivityThread(17421): java.lang.RuntimeException: Performing stop of activity that is not resumed: {com.zegoggles.smssync/com.zegoggles.smssync.activity.MainActivity}
12-17 10:01:10.863: E/ActivityThread(17421):    at android.app.ActivityThread.performStopActivityInner(ActivityThread.java:3166)
12-17 10:01:10.863: E/ActivityThread(17421):    at android.app.ActivityThread.handleStopActivity(ActivityThread.java:3253)
12-17 10:01:10.863: E/ActivityThread(17421):    at android.app.ActivityThread.access$1100(ActivityThread.java:145)
12-17 10:01:10.863: E/ActivityThread(17421):    at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1233)
12-17 10:01:10.863: E/ActivityThread(17421):    at android.os.Handler.dispatchMessage(Handler.java:102)
12-17 10:01:10.863: E/ActivityThread(17421):    at android.os.Looper.loop(Looper.java:136)
12-17 10:01:10.863: E/ActivityThread(17421):    at android.app.ActivityThread.main(ActivityThread.java:5141)
12-17 10:01:10.863: E/ActivityThread(17421):    at java.lang.reflect.Method.invokeNative(Native Method)
12-17 10:01:10.863: E/ActivityThread(17421):    at java.lang.reflect.Method.invoke(Method.java:515)
12-17 10:01:10.863: E/ActivityThread(17421):    at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:795)
12-17 10:01:10.863: E/ActivityThread(17421):    at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:611)
12-17 10:01:10.863: E/ActivityThread(17421):    at dalvik.system.NativeStart.main(Native Method)
12-17 10:01:55.855: D/SMSBackup+(17421): onResume()
12-17 10:01:55.894: D/SMSBackup+(17421): id:2, name:Anniversaires, synced:true
12-17 10:01:55.894: D/SMSBackup+(17421): id:10, name:Boulot, synced:true
12-17 10:01:55.894: D/SMSBackup+(17421): id:7, name:Calendrier LyonJUG, synced:false
12-17 10:01:55.894: D/SMSBackup+(17421): id:9, name:DebouLyon, synced:false
12-17 10:01:55.894: D/SMSBackup+(17421): id:1, name:blablabla, synced:true
12-17 10:01:55.894: D/SMSBackup+(17421): id:13, name:Important, synced:false
12-17 10:01:55.894: D/SMSBackup+(17421): id:3, name:Jours fériés en France, synced:true
12-17 10:01:55.894: D/SMSBackup+(17421): id:5, name:Météo, synced:true
12-17 10:01:55.894: D/SMSBackup+(17421): id:6, name:Pas là, synced:true
12-17 10:01:55.894: D/SMSBackup+(17421): id:4, name:Phases de la Lune, synced:true
12-17 10:01:55.894: D/SMSBackup+(17421): id:8, name:Private, synced:true
12-17 10:01:55.894: D/SMSBackup+(17421): id:11, name:TODO, synced:false
12-17 10:01:56.003: W/ContextImpl(17421): Implicit intents with startService are not safe: Intent { act=com.android.vending.billing.InAppBillingService.BIND } android.content.ContextWrapper.bindService:517 com.github.jberkel.pay.me.IabHelper.startSetup:152 com.zegoggles.smssync.activity.donation.DonationActivity.checkUserHasDonated:244 
12-17 10:01:56.464: I/Timeline(17421): Timeline: Activity_idle id: android.os.BinderProxy@41b5b910 time:26769969
12-17 10:02:23.417: V/SMSBackup+(17421): user requested sync
12-17 10:02:23.448: V/SMSBackup+(17421): backupStateChanged:BackupState{currentSyncedItems=0, itemsToSync=0, backupType=UNKNOWN, exception=null, state =INITIAL}
12-17 10:02:23.448: V/SMSBackup+(17421): handleIntent(Intent { cmp=com.zegoggles.smssync/.service.SmsBackupService (has extras) }, android.util.MapCollections$KeySet@fd9f6acd, type=MANUAL)
12-17 10:02:23.456: V/SMSBackup+(17421): [AppLog]: 17-12 10:02 Sauvegarde demandée (manuel)
12-17 10:02:23.456: V/SMSBackup+(17421): [AppLog]: 17-12 10:02 Démarrage de la sauvegarde (MANUAL)
12-17 10:02:23.456: D/SMSBackup+(17421): using new contacts API
12-17 10:02:23.464: V/SMSBackup+(17421): whitelisted ids for backup: null
12-17 10:02:23.573: V/SMSBackup+(17421): getItemsForDataType(type=SMS, max=-1)
12-17 10:02:23.816: V/SMSBackup+(17421): getItemsForDataType(type=MMS, max=-1)
12-17 10:02:23.823: V/SMSBackup+(17421): getItemsForDataType(type=WHATSAPP, max=-1)
12-17 10:02:23.823: V/SMSBackup+(17421): getItems(max=-1)
12-17 10:02:23.847: D/Whassup(17421): could not find db
12-17 10:02:23.847: V/SMSBackup+(17421): No whatsapp backup DB found, returning empty
12-17 10:02:23.847: V/SMSBackup+(17421): [AppLog]: 17-12 10:02 Sauvegarde en cours (2274 SMS, 93 MMS, 0 appels)
12-17 10:02:23.855: V/SMSBackup+(17421): [AppLog]: 17-12 10:02 Using config: BackupConfig{imap=BackupImapStore{uri=imap+ssl+://XOAUTH2:XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX@imap.gmail.com:993}, skip=false, currentTry=0, maxItemsPerSync=-1, groupToBackup=ContactGroup{_id=-1, type=EVERYBODY}, backupType=MANUAL, debug=true, typesToBackup=[SMS, MMS, WHATSAPP]}
12-17 10:02:23.855: I/SMSBackup+(17421): Starting backup (2367 messages)
12-17 10:02:23.855: V/SMSBackup+(17421): backupStateChanged:BackupState{currentSyncedItems=0, itemsToSync=0, backupType=MANUAL, exception=null, state =LOGIN}
12-17 10:02:23.909: D/k9(17421): Connecting to imap.gmail.com as imap.gmail.com/64.233.166.109
12-17 10:02:23.917: W/k9(17421): Local key store has not been initialized
12-17 10:02:24.144: V/k9(17421): conn1106654752<<<#null# [OK, Gimap ready for requests from 1.2.3.42 g7mb15606202wjq]
12-17 10:02:24.144: I/k9(17421): Did not get capabilities in banner, requesting CAPABILITY for conn1106654752
12-17 10:02:24.152: V/k9(17421): conn1106654752>>> 1 CAPABILITY
12-17 10:02:24.198: V/k9(17421): conn1106654752<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, XYZZY, SASL-IR, AUTH=XOAUTH, AUTH=XOAUTH2, AUTH=PLAIN, AUTH=PLAIN-CLIENTTOKEN]
12-17 10:02:24.198: V/k9(17421): conn1106654752<<<#1# [OK, Thats all she wrote! g7mb15606202wjq]
12-17 10:02:24.198: D/k9(17421): Saving 16 capabilities for conn1106654752
12-17 10:02:24.206: V/k9(17421): conn1106654752>>> [Command Hidden, Enable Sensitive Debug Logging To Show]
12-17 10:02:27.738: V/k9(17421): conn1106654752<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-17 10:02:27.745: D/k9(17421): Untagged response #null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-17 10:02:27.745: V/k9(17421): conn1106654752<<<#2# [OK, blablabla@gmail.com authenticated (Success)]
12-17 10:02:27.745: D/k9(17421): Untagged response #2# [OK, blablabla@gmail.com authenticated (Success)]
12-17 10:02:27.745: D/k9(17421): COMPRESS=DEFLATE = false
12-17 10:02:27.745: D/k9(17421): NAMESPACE = true, mPathPrefix = null
12-17 10:02:27.745: I/k9(17421): mPathPrefix is unset and server has NAMESPACE capability
12-17 10:02:27.745: V/k9(17421): conn1106654752>>> 3 NAMESPACE
12-17 10:02:27.878: V/k9(17421): conn1106654752<<<#null# [NAMESPACE, [[, /]], NIL, NIL]
12-17 10:02:27.878: V/k9(17421): conn1106654752<<<#3# [OK, Success]
12-17 10:02:27.886: D/k9(17421): Got NAMESPACE response #null# [NAMESPACE, [[, /]], NIL, NIL] on conn1106654752
12-17 10:02:27.886: D/k9(17421): Got personal namespaces: [[, /]]
12-17 10:02:27.886: D/k9(17421): Got first personal namespaces: [, /]
12-17 10:02:27.886: D/k9(17421): Got path '' and separator '/'
12-17 10:02:27.886: D/k9(17421): Folder auto-configuration: Using XLIST.
12-17 10:02:27.886: V/k9(17421): conn1106654752>>> 4 XLIST "" "*"
12-17 10:02:28.027: V/k9(17421): conn1106654752<<<#null# [XLIST, [\HasNoChildren], /, Call log]
12-17 10:02:28.027: V/k9(17421): conn1106654752<<<#null# [XLIST, [\HasNoChildren], /, Deal]
12-17 10:02:28.027: V/k9(17421): conn1106654752<<<#null# [XLIST, [\HasNoChildren], /, Divers]
12-17 10:02:28.034: V/k9(17421): conn1106654752<<<#null# [XLIST, [\HasNoChildren], /, D&AOk-croissance]
12-17 10:02:28.034: V/k9(17421): conn1106654752<<<#null# [XLIST, [\HasNoChildren], /, Fuentes]
12-17 10:02:28.034: V/k9(17421): conn1106654752<<<#null# [XLIST, [\Inbox, \HasNoChildren], /, Inbox]
12-17 10:02:28.034: V/k9(17421): conn1106654752<<<#null# [XLIST, [\HasNoChildren], /, Info]
12-17 10:02:28.034: V/k9(17421): conn1106654752<<<#null# [XLIST, [\HasNoChildren], /, MH]
12-17 10:02:28.042: V/k9(17421): conn1106654752<<<#null# [XLIST, [\HasChildren], /, Mailing]
12-17 10:02:28.042: V/k9(17421): conn1106654752<<<#null# [XLIST, [\HasNoChildren], /, Mailing/Artifactory-Users]
12-17 10:02:28.042: V/k9(17421): conn1106654752<<<#null# [XLIST, [\HasNoChildren], /, Mailing/DebouLyon]
12-17 10:02:28.042: V/k9(17421): conn1106654752<<<#null# [XLIST, [\HasNoChildren], /, Mailing/Magma]
12-17 10:02:28.042: V/k9(17421): conn1106654752<<<#null# [XLIST, [\HasNoChildren], /, Mailing/RezoSup]
12-17 10:02:28.042: V/k9(17421): conn1106654752<<<#null# [XLIST, [\HasNoChildren], /, Mailing/Seaside]
12-17 10:02:28.042: V/k9(17421): conn1106654752<<<#null# [XLIST, [\HasNoChildren], /, Mailing/Squeak-dev]
12-17 10:02:28.050: V/k9(17421): conn1106654752<<<#null# [XLIST, [\HasNoChildren], /, Mailing/Squeak-fr]
12-17 10:02:28.050: V/k9(17421): conn1106654752<<<#null# [XLIST, [\HasNoChildren], /, Mailing/android-developers]
12-17 10:02:28.050: V/k9(17421): conn1106654752<<<#null# [XLIST, [\HasNoChildren], /, Perso]
12-17 10:02:28.050: V/k9(17421): conn1106654752<<<#null# [XLIST, [\HasChildren], /, SMS]
12-17 10:02:28.050: V/k9(17421): conn1106654752<<<#null# [XLIST, [\HasNoChildren], /, SMS/SMS-Old]
12-17 10:02:28.050: V/k9(17421): conn1106654752<<<#null# [XLIST, [\HasNoChildren], /, SoFreshTeam]
12-17 10:02:28.050: V/k9(17421): conn1106654752<<<#null# [XLIST, [\HasChildren], /, Social]
12-17 10:02:28.050: V/k9(17421): conn1106654752<<<#null# [XLIST, [\HasNoChildren], /, Social/Facebook]
12-17 10:02:28.050: V/k9(17421): conn1106654752<<<#null# [XLIST, [\HasNoChildren], /, Social/Google+]
12-17 10:02:28.050: V/k9(17421): conn1106654752<<<#null# [XLIST, [\HasNoChildren], /, Social/LinkedIn]
12-17 10:02:28.050: V/k9(17421): conn1106654752<<<#null# [XLIST, [\HasNoChildren], /, Thaanis]
12-17 10:02:28.050: V/k9(17421): conn1106654752<<<#null# [XLIST, [\HasNoChildren], /, Work]
12-17 10:02:28.050: V/k9(17421): conn1106654752<<<#null# [XLIST, [\Noselect, \HasChildren], /, [Gmail]]
12-17 10:02:28.058: V/k9(17421): conn1106654752<<<#null# [XLIST, [\HasNoChildren, \AllMail], /, [Gmail]/All Mail]
12-17 10:02:28.058: V/k9(17421): conn1106654752<<<#null# [XLIST, [\HasNoChildren], /, [Gmail]/Chats]
12-17 10:02:28.058: V/k9(17421): conn1106654752<<<#null# [XLIST, [\HasNoChildren, \Drafts], /, [Gmail]/Drafts]
12-17 10:02:28.058: V/k9(17421): conn1106654752<<<#null# [XLIST, [\Important, \HasNoChildren], /, [Gmail]/Important]
12-17 10:02:28.058: V/k9(17421): conn1106654752<<<#null# [XLIST, [\Sent, \HasNoChildren], /, [Gmail]/Sent Mail]
12-17 10:02:28.058: V/k9(17421): conn1106654752<<<#null# [XLIST, [\Spam, \HasNoChildren], /, [Gmail]/Spam]
12-17 10:02:28.058: V/k9(17421): conn1106654752<<<#null# [XLIST, [\Starred, \HasNoChildren], /, [Gmail]/Starred]
12-17 10:02:28.058: V/k9(17421): conn1106654752<<<#null# [XLIST, [\HasNoChildren, \Trash], /, [Gmail]/Trash]
12-17 10:02:28.058: V/k9(17421): conn1106654752<<<#4# [OK, Success]
12-17 10:02:28.073: D/k9(17421): Folder auto-configuration detected draft folder: [Gmail]/Drafts
12-17 10:02:28.073: D/k9(17421): Folder auto-configuration detected sent folder: [Gmail]/Sent Mail
12-17 10:02:28.073: D/k9(17421): Folder auto-configuration detected spam folder: [Gmail]/Spam
12-17 10:02:28.073: D/k9(17421): Folder auto-configuration detected trash folder: [Gmail]/Trash
12-17 10:02:28.105: V/SMSBackup+(17421): backupStateChanged:BackupState{currentSyncedItems=0, itemsToSync=0, backupType=MANUAL, exception=null, state =CALC}
12-17 10:02:28.105: V/SMSBackup+(17421): backing up: CursorAndType{type=SMS, cursor=android.content.ContentResolver$CursorWrapperInner@41f51900}
12-17 10:02:28.363: V/SMSBackup+(17421): sending 1 SMS message(s) to server.
12-17 10:02:28.370: D/k9(17421): Connecting to imap.gmail.com as imap.gmail.com/64.233.166.109
12-17 10:02:28.761: V/k9(17421): conn1107277096<<<#null# [OK, Gimap ready for requests from 1.2.3.42 e2mb56467274wli]
12-17 10:02:28.761: I/k9(17421): Did not get capabilities in banner, requesting CAPABILITY for conn1107277096
12-17 10:02:28.761: V/k9(17421): conn1107277096>>> 1 CAPABILITY
12-17 10:02:28.909: V/k9(17421): conn1107277096<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, XYZZY, SASL-IR, AUTH=XOAUTH, AUTH=XOAUTH2, AUTH=PLAIN, AUTH=PLAIN-CLIENTTOKEN]
12-17 10:02:28.909: V/k9(17421): conn1107277096<<<#1# [OK, Thats all she wrote! e2mb56467274wli]
12-17 10:02:28.917: D/k9(17421): Saving 16 capabilities for conn1107277096
12-17 10:02:28.917: V/k9(17421): conn1107277096>>> [Command Hidden, Enable Sensitive Debug Logging To Show]
12-17 10:02:29.050: V/k9(17421): conn1107277096<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-17 10:02:29.050: D/k9(17421): Untagged response #null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-17 10:02:29.050: V/k9(17421): conn1107277096<<<#2# [OK, blablabla@gmail.com authenticated (Success)]
12-17 10:02:29.050: D/k9(17421): Untagged response #2# [OK, blablabla@gmail.com authenticated (Success)]
12-17 10:02:29.050: D/k9(17421): COMPRESS=DEFLATE = false
12-17 10:02:29.050: D/k9(17421): NAMESPACE = true, mPathPrefix = 
12-17 10:02:29.058: D/k9(17421): Connecting to imap.gmail.com as imap.gmail.com/64.233.166.109
12-17 10:02:29.245: V/k9(17421): conn1107276840<<<#null# [OK, Gimap ready for requests from 1.2.3.42 b53mb56858189wec]
12-17 10:02:29.245: I/k9(17421): Did not get capabilities in banner, requesting CAPABILITY for conn1107276840
12-17 10:02:29.245: V/k9(17421): conn1107276840>>> 1 CAPABILITY
12-17 10:02:29.284: V/k9(17421): conn1107276840<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, XYZZY, SASL-IR, AUTH=XOAUTH, AUTH=XOAUTH2, AUTH=PLAIN, AUTH=PLAIN-CLIENTTOKEN]
12-17 10:02:29.284: V/k9(17421): conn1107276840<<<#1# [OK, Thats all she wrote! b53mb56858189wec]
12-17 10:02:29.284: D/k9(17421): Saving 16 capabilities for conn1107276840
12-17 10:02:29.292: V/k9(17421): conn1107276840>>> [Command Hidden, Enable Sensitive Debug Logging To Show]
12-17 10:02:29.355: V/k9(17421): conn1107276840<<<#null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-17 10:02:29.355: D/k9(17421): Untagged response #null# [CAPABILITY, IMAP4rev1, UNSELECT, IDLE, NAMESPACE, QUOTA, ID, XLIST, CHILDREN, X-GM-EXT-1, UIDPLUS, COMPRESS=DEFLATE, ENABLE, MOVE, CONDSTORE, ESEARCH, UTF8=ACCEPT]
12-17 10:02:29.355: V/k9(17421): conn1107276840<<<#2# [OK, blablabla@gmail.com authenticated (Success)]
12-17 10:02:29.355: D/k9(17421): Untagged response #2# [OK, blablabla@gmail.com authenticated (Success)]
12-17 10:02:29.355: D/k9(17421): COMPRESS=DEFLATE = false
12-17 10:02:29.355: D/k9(17421): NAMESPACE = true, mPathPrefix = 
12-17 10:02:29.355: V/k9(17421): conn1107276840>>> 3 STATUS "SMS" (UIDVALIDITY)
12-17 10:02:29.402: V/k9(17421): conn1107276840<<<#null# [STATUS, SMS, [UIDVALIDITY, 51]]
12-17 10:02:29.402: V/k9(17421): conn1107276840<<<#3# [OK, Success]
12-17 10:02:29.402: V/k9(17421): conn1107277096>>> 3 NOOP
12-17 10:02:29.448: V/k9(17421): conn1107277096<<<#3# [OK, Success]
12-17 10:02:29.448: V/k9(17421): conn1107277096>>> 4 SELECT "SMS"
12-17 10:02:29.894: V/k9(17421): conn1107277096<<<#null# [FLAGS, [\Answered, \Flagged, \Draft, \Deleted, \Seen, $Phishing, $NotPhishing]]
12-17 10:02:29.894: V/k9(17421): conn1107277096<<<#null# [OK, [PERMANENTFLAGS, [\Answered, \Flagged, \Draft, \Deleted, \Seen, $Phishing, $NotPhishing, \*]], Flags permitted.]
12-17 10:02:29.894: V/k9(17421): conn1107277096<<<#null# [OK, [UIDVALIDITY, 51], UIDs valid.]
12-17 10:02:29.894: V/k9(17421): conn1107277096<<<#null# [82, EXISTS]
12-17 10:02:29.902: V/k9(17421): conn1107277096<<<#null# [0, RECENT]
12-17 10:02:29.902: V/k9(17421): conn1107277096<<<#null# [OK, [UIDNEXT, 49682], Predicted next UID.]
12-17 10:02:29.902: V/k9(17421): conn1107277096<<<#null# [OK, [HIGHESTMODSEQ, 7760462]]
12-17 10:02:29.909: V/k9(17421): conn1107277096<<<#4# [OK, [READ-WRITE], SMS selected. (Success)]
12-17 10:02:29.909: D/k9(17421): Got untagged EXISTS with value 82 for com.zegoggles.smssync.mail.BackupStoreConfig@41f40aa0:SMS/AsyncTask #3/conn1107277096
12-17 10:02:29.909: D/k9(17421): Got UidNext = 49682 for com.zegoggles.smssync.mail.BackupStoreConfig@41f40aa0:SMS/AsyncTask #3/conn1107277096
12-17 10:02:29.909: V/k9(17421): conn1107277096>>> 5 NOOP
12-17 10:02:29.956: V/k9(17421): conn1107277096<<<#5# [OK, Success]
12-17 10:02:29.972: V/k9(17421): conn1107277096>>> 6 APPEND "SMS" (\Seen) {1148}
12-17 10:02:29.972: D/k9(17421): about to read response
12-17 10:02:30.011: V/k9(17421): conn1107277096<<<#+# [go ahead]
12-17 10:02:30.011: D/k9(17421): got #+# [go ahead]
12-17 10:02:30.011: D/k9(17421): about to read response
12-17 10:02:31.831: V/k9(17421): conn1107277096<<<#null# [83, EXISTS]
12-17 10:02:31.839: D/k9(17421): got #null# [83, EXISTS]
12-17 10:02:31.839: D/k9(17421): Got untagged EXISTS with value 83 for com.zegoggles.smssync.mail.BackupStoreConfig@41f40aa0:SMS/AsyncTask #3/conn1107277096
12-17 10:02:31.839: D/k9(17421): no continuation requested for #null# [83, EXISTS]
12-17 10:02:31.839: D/k9(17421): about to read response
12-17 10:02:31.839: V/k9(17421): conn1107277096<<<#6# [OK, [APPENDUID, 51, 49682], (Success)]
12-17 10:02:31.839: D/k9(17421): got #6# [OK, [APPENDUID, 51, 49682], (Success)]
12-17 10:02:31.847: D/k9(17421): no continuation requested for #6# [OK, [APPENDUID, 51, 49682], (Success)]
12-17 10:02:31.902: V/SMSBackup+(17421): dataChanged()
12-17 10:02:31.902: V/SMSBackup+(17421): backing up: CursorAndType{type=SMS, cursor=android.content.ContentResolver$CursorWrapperInner@41f51900}
12-17 10:02:31.902: V/SMSBackup+(17421): backupStateChanged:BackupState{currentSyncedItems=1, itemsToSync=2367, backupType=MANUAL, exception=null, state =BACKUP}
12-17 10:02:31.980: V/SMSBackup+(17421): sending 1 SMS message(s) to server.
12-17 10:02:31.980: V/k9(17421): conn1107277096>>> 7 NOOP
12-17 10:02:32.034: V/k9(17421): conn1107277096<<<#7# [OK, Success]
12-17 10:02:32.034: V/k9(17421): conn1107277096>>> 8 APPEND "SMS" (\Seen) {756}
12-17 10:02:32.034: D/k9(17421): about to read response
12-17 10:02:32.081: V/k9(17421): conn1107277096<<<#+# [go ahead]
12-17 10:02:32.081: D/k9(17421): got #+# [go ahead]
12-17 10:02:32.081: D/k9(17421): about to read response
12-17 10:02:33.167: V/k9(17421): conn1107277096<<<#null# [84, EXISTS]
12-17 10:02:33.167: D/k9(17421): got #null# [84, EXISTS]
12-17 10:02:33.167: D/k9(17421): Got untagged EXISTS with value 84 for com.zegoggles.smssync.mail.BackupStoreConfig@41f40aa0:SMS/AsyncTask #3/conn1107277096
12-17 10:02:33.167: D/k9(17421): no continuation requested for #null# [84, EXISTS]
12-17 10:02:33.167: D/k9(17421): about to read response
12-17 10:02:33.167: V/k9(17421): conn1107277096<<<#8# [OK, [APPENDUID, 51, 49683], (Success)]
12-17 10:02:33.167: D/k9(17421): got #8# [OK, [APPENDUID, 51, 49683], (Success)]
12-17 10:02:33.175: D/k9(17421): no continuation requested for #8# [OK, [APPENDUID, 51, 49683], (Success)]
12-17 10:02:33.230: V/SMSBackup+(17421): dataChanged()
12-17 10:02:33.230: V/SMSBackup+(17421): backupStateChanged:BackupState{currentSyncedItems=2, itemsToSync=2367, backupType=MANUAL, exception=null, state =BACKUP}
12-17 10:02:33.230: V/SMSBackup+(17421): backing up: CursorAndType{type=SMS, cursor=android.content.ContentResolver$CursorWrapperInner@41f51900}
12-17 10:02:33.238: V/SMSBackup+(17421): sending 1 SMS message(s) to server.
12-17 10:02:33.245: V/k9(17421): conn1107277096>>> 9 NOOP
12-17 10:02:33.292: V/k9(17421): conn1107277096<<<#9# [OK, Success]
12-17 10:02:33.292: V/k9(17421): conn1107277096>>> 10 APPEND "SMS" (\Seen) {816}
12-17 10:02:33.292: D/k9(17421): about to read response
12-17 10:02:33.331: V/k9(17421): conn1107277096<<<#+# [go ahead]
12-17 10:02:33.331: D/k9(17421): got #+# [go ahead]
12-17 10:02:33.331: D/k9(17421): about to read response
12-17 10:02:34.292: V/k9(17421): conn1107277096<<<#null# [85, EXISTS]
12-17 10:02:34.292: D/k9(17421): got #null# [85, EXISTS]
12-17 10:02:34.292: D/k9(17421): Got untagged EXISTS with value 85 for com.zegoggles.smssync.mail.BackupStoreConfig@41f40aa0:SMS/AsyncTask #3/conn1107277096
12-17 10:02:34.292: D/k9(17421): no continuation requested for #null# [85, EXISTS]
12-17 10:02:34.292: D/k9(17421): about to read response
12-17 10:02:34.300: V/k9(17421): conn1107277096<<<#10# [OK, [APPENDUID, 51, 49684], (Success)]
12-17 10:02:34.300: D/k9(17421): got #10# [OK, [APPENDUID, 51, 49684], (Success)]
12-17 10:02:34.300: D/k9(17421): no continuation requested for #10# [OK, [APPENDUID, 51, 49684], (Success)]
12-17 10:02:34.386: V/SMSBackup+(17421): dataChanged()
12-17 10:02:34.386: V/SMSBackup+(17421): backupStateChanged:BackupState{currentSyncedItems=3, itemsToSync=2367, backupType=MANUAL, exception=null, state =BACKUP}
12-17 10:02:34.386: V/SMSBackup+(17421): backing up: CursorAndType{type=SMS, cursor=android.content.ContentResolver$CursorWrapperInner@41f51900}
12-17 10:02:34.417: V/SMSBackup+(17421): sending 1 SMS message(s) to server.
12-17 10:02:34.425: V/k9(17421): conn1107277096>>> 11 NOOP
12-17 10:02:34.464: V/k9(17421): conn1107277096<<<#11# [OK, Success]
12-17 10:02:34.464: V/k9(17421): conn1107277096>>> 12 APPEND "SMS" (\Seen) {837}
12-17 10:02:34.464: D/k9(17421): about to read response
12-17 10:02:34.503: V/k9(17421): conn1107277096<<<#+# [go ahead]
12-17 10:02:34.503: D/k9(17421): got #+# [go ahead]
12-17 10:02:34.503: D/k9(17421): about to read response
12-17 10:02:35.316: V/k9(17421): conn1107277096<<<#null# [86, EXISTS]
12-17 10:02:35.316: D/k9(17421): got #null# [86, EXISTS]
12-17 10:02:35.316: D/k9(17421): Got untagged EXISTS with value 86 for com.zegoggles.smssync.mail.BackupStoreConfig@41f40aa0:SMS/AsyncTask #3/conn1107277096
12-17 10:02:35.316: D/k9(17421): no continuation requested for #null# [86, EXISTS]
12-17 10:02:35.316: D/k9(17421): about to read response
12-17 10:02:35.316: V/k9(17421): conn1107277096<<<#12# [OK, [APPENDUID, 51, 49685], (Success)]
12-17 10:02:35.316: D/k9(17421): got #12# [OK, [APPENDUID, 51, 49685], (Success)]
12-17 10:02:35.316: D/k9(17421): no continuation requested for #12# [OK, [APPENDUID, 51, 49685], (Success)]
12-17 10:02:35.355: V/SMSBackup+(17421): dataChanged()
12-17 10:02:35.355: V/SMSBackup+(17421): backing up: CursorAndType{type=SMS, cursor=android.content.ContentResolver$CursorWrapperInner@41f51900}
12-17 10:02:35.355: V/SMSBackup+(17421): backupStateChanged:BackupState{currentSyncedItems=4, itemsToSync=2367, backupType=MANUAL, exception=null, state =BACKUP}
12-17 10:02:35.363: V/SMSBackup+(17421): sending 1 SMS message(s) to server.
12-17 10:02:35.363: V/k9(17421): conn1107277096>>> 13 NOOP
12-17 10:02:35.409: V/k9(17421): conn1107277096<<<#13# [OK, Success]
12-17 10:02:35.409: V/k9(17421): conn1107277096>>> 14 APPEND "SMS" (\Seen) {898}
12-17 10:02:35.409: D/k9(17421): about to read response
12-17 10:02:35.550: V/k9(17421): conn1107277096<<<#+# [go ahead]
12-17 10:02:35.550: D/k9(17421): got #+# [go ahead]
12-17 10:02:35.550: D/k9(17421): about to read response
12-17 10:02:36.441: V/k9(17421): conn1107277096<<<#null# [87, EXISTS]
12-17 10:02:36.441: D/k9(17421): got #null# [87, EXISTS]
12-17 10:02:36.448: D/k9(17421): Got untagged EXISTS with value 87 for com.zegoggles.smssync.mail.BackupStoreConfig@41f40aa0:SMS/AsyncTask #3/conn1107277096
12-17 10:02:36.448: D/k9(17421): no continuation requested for #null# [87, EXISTS]
12-17 10:02:36.448: D/k9(17421): about to read response
12-17 10:02:36.448: V/k9(17421): conn1107277096<<<#14# [OK, [APPENDUID, 51, 49686], (Success)]
12-17 10:02:36.448: D/k9(17421): got #14# [OK, [APPENDUID, 51, 49686], (Success)]
12-17 10:02:36.448: D/k9(17421): no continuation requested for #14# [OK, [APPENDUID, 51, 49686], (Success)]
12-17 10:02:36.503: V/SMSBackup+(17421): dataChanged()
12-17 10:02:36.503: V/SMSBackup+(17421): backupStateChanged:BackupState{currentSyncedItems=5, itemsToSync=2367, backupType=MANUAL, exception=null, state =BACKUP}
jberkel commented 9 years ago

cool, fingers crossed

flomin commented 9 years ago

There was this one error during the save, but not blocking. Now it's backing up the MMS ! Can I be sure all the SMS got backed up ?

12-17 10:11:31.433: V/SMSBackup+(17421): backupStateChanged:BackupState{currentSyncedItems=448, itemsToSync=2367, backupType=MANUAL, exception=null, state =BACKUP}
12-17 10:11:31.441: V/SMSBackup+(17421): backing up: CursorAndType{type=SMS, cursor=android.content.ContentResolver$CursorWrapperInner@41f51900}
12-17 10:11:31.464: V/SMSBackup+(17421): sending 1 SMS message(s) to server.
12-17 10:11:31.464: V/k9(17421): conn1107277096>>> 901 NOOP
12-17 10:11:31.527: E/k9(17421): IOException for com.zegoggles.smssync.mail.BackupStoreConfig@41f40aa0:SMS/AsyncTask #3/conn1107277096
12-17 10:11:31.527: E/k9(17421): java.io.IOException: readStringUntil(): end of stream reached
12-17 10:11:31.527: E/k9(17421):    at com.fsck.k9.mail.store.ImapResponseParser.readStringUntil(ImapResponseParser.java:356)
12-17 10:11:31.527: E/k9(17421):    at com.fsck.k9.mail.store.ImapResponseParser.parseTaggedResponse(ImapResponseParser.java:198)
12-17 10:11:31.527: E/k9(17421):    at com.fsck.k9.mail.store.ImapResponseParser.readResponse(ImapResponseParser.java:50)
12-17 10:11:31.527: E/k9(17421):    at com.fsck.k9.mail.store.ImapResponseParser.readResponse(ImapResponseParser.java:29)
12-17 10:11:31.527: E/k9(17421):    at com.fsck.k9.mail.store.ImapStore$ImapConnection.readStatusResponse(ImapStore.java:2812)
12-17 10:11:31.527: E/k9(17421):    at com.fsck.k9.mail.store.ImapStore$ImapConnection.executeSimpleCommand(ImapStore.java:2962)
12-17 10:11:31.527: E/k9(17421):    at com.fsck.k9.mail.store.ImapStore$ImapConnection.executeSimpleCommand(ImapStore.java:2939)
12-17 10:11:31.527: E/k9(17421):    at com.fsck.k9.mail.store.ImapStore$ImapFolder.executeSimpleCommand(ImapStore.java:825)
12-17 10:11:31.527: E/k9(17421):    at com.fsck.k9.mail.store.ImapStore$ImapFolder.internalOpen(ImapStore.java:847)
12-17 10:11:31.527: E/k9(17421):    at com.fsck.k9.mail.store.ImapStore$ImapFolder.open(ImapStore.java:834)
12-17 10:11:31.527: E/k9(17421):    at com.fsck.k9.mail.store.ImapStore$ImapFolder.appendMessages(ImapStore.java:1968)
12-17 10:11:31.527: E/k9(17421):    at com.zegoggles.smssync.service.BackupTask.backupCursors(BackupTask.java:265)
12-17 10:11:31.527: E/k9(17421):    at com.zegoggles.smssync.service.BackupTask.fetchAndBackupItems(BackupTask.java:146)
12-17 10:11:31.527: E/k9(17421):    at com.zegoggles.smssync.service.BackupTask.acquireLocksAndBackup(BackupTask.java:126)
12-17 10:11:31.527: E/k9(17421):    at com.zegoggles.smssync.service.BackupTask.doInBackground(BackupTask.java:119)
12-17 10:11:31.527: E/k9(17421):    at com.zegoggles.smssync.service.BackupTask.doInBackground(BackupTask.java:46)
12-17 10:11:31.527: E/k9(17421):    at android.os.AsyncTask$2.call(AsyncTask.java:288)
12-17 10:11:31.527: E/k9(17421):    at java.util.concurrent.FutureTask.run(FutureTask.java:237)
12-17 10:11:31.527: E/k9(17421):    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
12-17 10:11:31.527: E/k9(17421):    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
12-17 10:11:31.527: E/k9(17421):    at java.lang.Thread.run(Thread.java:841)
12-17 10:11:31.534: V/k9(17421): conn1107276840>>> 4 NOOP
12-17 10:11:31.573: V/k9(17421): conn1107276840<<<#4# [OK, Success]
12-17 10:11:31.573: V/k9(17421): conn1107276840>>> 5 SELECT "SMS"
12-17 10:11:31.777: V/k9(17421): conn1107276840<<<#null# [FLAGS, [\Answered, \Flagged, \Draft, \Deleted, \Seen, $Phishing, $NotPhishing]]
12-17 10:11:31.777: V/k9(17421): conn1107276840<<<#null# [OK, [PERMANENTFLAGS, [\Answered, \Flagged, \Draft, \Deleted, \Seen, $Phishing, $NotPhishing, \*]], Flags permitted.]
12-17 10:11:31.784: V/k9(17421): conn1107276840<<<#null# [OK, [UIDVALIDITY, 51], UIDs valid.]
12-17 10:11:31.784: V/k9(17421): conn1107276840<<<#null# [530, EXISTS]
12-17 10:11:31.784: V/k9(17421): conn1107276840<<<#null# [0, RECENT]
12-17 10:11:31.784: V/k9(17421): conn1107276840<<<#null# [OK, [UIDNEXT, 50130], Predicted next UID.]
12-17 10:11:31.784: V/k9(17421): conn1107276840<<<#null# [OK, [HIGHESTMODSEQ, 7765503]]
12-17 10:11:31.792: V/k9(17421): conn1107276840<<<#5# [OK, [READ-WRITE], SMS selected. (Success)]
12-17 10:11:31.792: D/k9(17421): Got untagged EXISTS with value 530 for com.zegoggles.smssync.mail.BackupStoreConfig@41f40aa0:SMS/AsyncTask #3/conn1107276840
12-17 10:11:31.792: D/k9(17421): Got UidNext = 50130 for com.zegoggles.smssync.mail.BackupStoreConfig@41f40aa0:SMS/AsyncTask #3/conn1107276840
12-17 10:11:31.792: V/k9(17421): conn1107276840>>> 6 APPEND "SMS" (\Seen) {756}
12-17 10:11:31.800: D/k9(17421): about to read response
12-17 10:11:31.847: V/k9(17421): conn1107276840<<<#+# [go ahead]
12-17 10:11:31.847: D/k9(17421): got #+# [go ahead]
12-17 10:11:31.847: D/k9(17421): about to read response
12-17 10:11:32.925: V/k9(17421): conn1107276840<<<#null# [531, EXISTS]
12-17 10:11:32.925: D/k9(17421): got #null# [531, EXISTS]
12-17 10:11:32.925: D/k9(17421): Got untagged EXISTS with value 531 for com.zegoggles.smssync.mail.BackupStoreConfig@41f40aa0:SMS/AsyncTask #3/conn1107276840
12-17 10:11:32.925: D/k9(17421): no continuation requested for #null# [531, EXISTS]
12-17 10:11:32.925: D/k9(17421): about to read response
12-17 10:11:32.925: V/k9(17421): conn1107276840<<<#6# [OK, [APPENDUID, 51, 50130], (Success)]
12-17 10:11:32.925: D/k9(17421): got #6# [OK, [APPENDUID, 51, 50130], (Success)]
12-17 10:11:32.925: D/k9(17421): no continuation requested for #6# [OK, [APPENDUID, 51, 50130], (Success)]
12-17 10:11:32.972: V/SMSBackup+(17421): backupStateChanged:BackupState{currentSyncedItems=449, itemsToSync=2367, backupType=MANUAL, exception=null, state =BACKUP}
flomin commented 9 years ago

I worked !

12-17 10:52:31.425: V/SMSBackup+(17421): user requested sync
12-17 10:52:31.441: V/SMSBackup+(17421): backupStateChanged:BackupState{currentSyncedItems=0, itemsToSync=0, backupType=UNKNOWN, exception=null, state =INITIAL}
12-17 10:52:31.441: V/SMSBackup+(17421): handleIntent(Intent { cmp=com.zegoggles.smssync/.service.SmsBackupService (has extras) }, android.util.MapCollections$KeySet@fd9f6acd, type=MANUAL)
12-17 10:52:31.441: V/SMSBackup+(17421): [AppLog]: 17-12 10:52 Sauvegarde demandée (manuel)
12-17 10:52:31.448: V/SMSBackup+(17421): [AppLog]: 17-12 10:52 Démarrage de la sauvegarde (MANUAL)
12-17 10:52:31.448: D/SMSBackup+(17421): using new contacts API
12-17 10:52:31.448: V/SMSBackup+(17421): whitelisted ids for backup: null
12-17 10:52:31.464: V/SMSBackup+(17421): getItemsForDataType(type=SMS, max=-1)
12-17 10:52:31.620: V/SMSBackup+(17421): getItemsForDataType(type=MMS, max=-1)
12-17 10:52:31.628: V/SMSBackup+(17421): getItemsForDataType(type=WHATSAPP, max=-1)
12-17 10:52:31.628: V/SMSBackup+(17421): getItems(max=-1)
12-17 10:52:31.644: D/Whassup(17421): could not find db
12-17 10:52:31.644: V/SMSBackup+(17421): No whatsapp backup DB found, returning empty
12-17 10:52:31.644: V/SMSBackup+(17421): [AppLog]: 17-12 10:52 Skipped (no items found)
12-17 10:52:31.644: I/SMSBackup+(17421): Nothing to do.
12-17 10:52:31.667: V/SMSBackup+(17421): backupStateChanged:BackupState{currentSyncedItems=0, itemsToSync=0, backupType=MANUAL, exception=null, state =FINISHED_BACKUP}
12-17 10:52:31.667: V/SMSBackup+(17421): [AppLog]: 17-12 10:52 BackupState{currentSyncedItems=0, itemsToSync=0, backupType=MANUAL, exception=null, state =FINISHED_BACKUP}
12-17 10:52:31.675: V/SMSBackup+(17421): [AppLog]: 17-12 10:52 Sauvegarde effectuée
12-17 10:52:31.683: V/SMSBackup+(17421): AppLog#close()
12-17 10:52:31.683: V/SMSBackup+(17421): SmsBackupService#onDestroy(state=BackupState{currentSyncedItems=0, itemsToSync=0, backupType=MANUAL, exception=null, state =FINISHED_BACKUP})

The MMS got backed up too and everything seems fine !

jberkel commented 9 years ago

phew.. glad this one's fixed. still not 100% sure what caused it, but will find out i hope

flomin commented 9 years ago

Yes thanks a lot for this !

There is one problem though: I tend to send a lot of MMS, and as the MMS are backed up after the SMS, they are completely out of timeline on my mail account, even if the date is OK. Isn't it possible to save them at the same time as the SMS ?

I also got some whatsapp messages which were not backed up: 'D/Whassup(17421): could not find db' in the log.

But these are other bugs I can fill different bug reports if you like.

jberkel commented 9 years ago

you mean the date on the mail itself is ok, but is displayed out of order? the time when the mail saved should not have an effect on the way it is displayed, but gmail is always a bit particular. i would first check if the ordering is ok if you look at the folder with a normal mail client, not gmail. it might be gmail's internal threading which gets easily confused. and yes, please report as new bug....

did you enable whatsapp backups? if not it should not show the debug message...

jberkel commented 9 years ago

@LSmith6938 could you try with https://github.com/jberkel/sms-backup-plus/releases/tag/1.5.6-BETA10 as well and report back? thanks!

flomin commented 9 years ago

Thanks a lot for the time you spent solving this issue !

SMS and MMS timeline issue here: https://github.com/jberkel/sms-backup-plus/issues/509 Whatsapp issue here: https://github.com/jberkel/sms-backup-plus/issues/510

flomin commented 9 years ago

BTW, you should add ACRA to log debug informations on errors, it's great ! I developed a PHP website to manage (a lot) of ACRA issues. Not perfect, but worth it, if you'd like to try...

LSmith6938 commented 9 years ago

hi everyone -- thanks for your help with this! i have initiated the back up process. it seems to be working, as the text messages are now showing in the SMS gmail label. i have about 26k pending texts, so this is going to take all day. i'll sign back in tomorrow when this is complete to let you know it finished. :)

jberkel commented 9 years ago

great to hear, hope it works out. and also wondering how you managed to accumulate 26k worth of text messages :)

jberkel commented 9 years ago

i'm closing this for now. reopen if problem occurs again

LSmith6938 commented 9 years ago

thanks! it took all day, but i got everything backed up! i am an avid texter -- i usually hit about 5k/month. :D

i've been using your app for years, btw. it's awesome!

robotcmastr5000 commented 7 years ago

Was running a Sprint Note 4 With Marshmallow update. SMS Backup + has worked on there. I can see all the messages in my gmail. However, my note 4 stopped working. And I now have a galaxy s7 running marshmallow as well. But i cannot get SMS Backup + to restore with out the I/O Error - Please help?

Fisherpon commented 6 years ago

I'm on a Samsung S8 running Android 7.0, and I'm having the same issue as this thread (I/O error between 500 and 1000 messages). I tried installing the beta APK that seemed to fix it for others (https://github.com/jberkel/sms-backup-plus/releases/tag/1.5.6-BETA10), but it wouldn't let me install it as 'the packet seems to be corrupt' (Can't remember if it said packet or package). Was that beta APK rolled out into the main app at any point?