[BUG] IO Error - Unable to complete backup; java.io.IOException / java.net.SocketException / com.fsck.k9.mail.MessagingException

[AlexHimself]

Expected behaviour

Backup should complete successfully or at least partially complete. It seems like it's ALL or nothing.

Actual behaviour

Attempted 5 times and it errored each time after a period of time (5-60 minutes?) with the following logs:

Attempt 1:

02-15 17:21 Backup requested (manual)
02-15 17:21 Starting backup (MANUAL)
02-15 17:21 Backing up (71650 SMS, 62201 MMS, 2000 call log)
02-15 17:21 Using config: BackupConfig{imap=BackupImapStore{uri=imap+ssl+://PLAIN:XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX@imap.gmail.com:993}, currentTry=0, maxItemsPerSync=-1, groupToBackup=ContactGroup{_id=-1, type=EVERYBODY}, backupType=MANUAL, debug=true, typesToBackup=[SMS, MMS, CALLLOG]}
02-15 17:34 General error: IO Error (exception: com.fsck.k9.mail.MessagingException: IO Error, underlying=java.io.IOException: readStringUntil(): end of stream reached)
02-15 17:34 BackupState{currentSyncedItems=773, itemsToSync=135851, backupType=MANUAL, exception=com.fsck.k9.mail.MessagingException: IO Error, state=ERROR}
02-15 17:34 Backup finished

Attempt 2: I have many SMS message to backup and it would take a while, so I suspected battery optimization features may be putting the app to sleep or interfering in some way so for the second attempt I did:

1. Battery and Device Care> Memory > Excluded apps - Exclude SMS Backup+
2. Battery and Device Care > Battery > Background usage limits > Never sleeping apps - Add SMS Backup+

02-16 04:56 Backup requested (manual)
02-16 04:56 Starting backup (MANUAL)
02-16 04:56 Backing up (70877 SMS, 62201 MMS, 2000 call log)
02-16 04:56 Using config: BackupConfig{imap=BackupImapStore{uri=imap+ssl+://PLAIN:XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX@imap.gmail.com:993}, currentTry=0, maxItemsPerSync=-1, groupToBackup=ContactGroup{_id=-1, type=EVERYBODY}, backupType=MANUAL, debug=true, typesToBackup=[SMS, MMS, CALLLOG]}
02-16 05:18 General error: IO Error (exception: com.fsck.k9.mail.MessagingException: IO Error, underlying=java.net.SocketException: Software caused connection abort)
02-16 05:18 BackupState{currentSyncedItems=1281, itemsToSync=135078, backupType=MANUAL, exception=com.fsck.k9.mail.MessagingException: IO Error, state=ERROR}
02-16 05:18 Backup finished

Attempts 3,4,5

Each of these I just clicked "backup now".

02-16 08:05 Backup requested (manual)
02-16 08:05 Starting backup (MANUAL)
02-16 08:05 Backup requested (manual)
02-16 08:05 Starting backup (MANUAL)
02-16 08:05 Backing up (69597 SMS, 62202 MMS, 2000 call log)
02-16 08:05 Using config: BackupConfig{imap=BackupImapStore{uri=imap+ssl+://PLAIN:XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX@imap.gmail.com:993}, currentTry=0, maxItemsPerSync=-1, groupToBackup=ContactGroup{_id=-1, type=EVERYBODY}, backupType=MANUAL, debug=true, typesToBackup=[SMS, MMS, CALLLOG]}
02-16 13:21 General error: IO Error (exception: com.fsck.k9.mail.MessagingException: IO Error, underlying=java.net.SocketException: Software caused connection abort)
02-16 13:21 BackupState{currentSyncedItems=17956, itemsToSync=133799, backupType=MANUAL, exception=com.fsck.k9.mail.MessagingException: IO Error, state=ERROR}
02-16 13:21 Backup finished

02-20 10:44 Backup requested (manual)
02-20 10:44 Starting backup (MANUAL)
02-20 10:44 Backing up (51760 SMS, 62267 MMS, 2000 call log)
02-20 10:44 Using config: BackupConfig{imap=BackupImapStore{uri=imap+ssl+://PLAIN:XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX@imap.gmail.com:993}, currentTry=0, maxItemsPerSync=-1, groupToBackup=ContactGroup{_id=-1, type=EVERYBODY}, backupType=MANUAL, debug=true, typesToBackup=[SMS, MMS, CALLLOG]}
02-20 11:24 General error: IO Error (exception: com.fsck.k9.mail.MessagingException: IO Error, underlying=java.net.SocketException: Software caused connection abort)
02-20 11:24 BackupState{currentSyncedItems=2127, itemsToSync=116027, backupType=MANUAL, exception=com.fsck.k9.mail.MessagingException: IO Error, state=ERROR}
02-20 11:24 Backup finished

02-21 22:00 Backup requested (manual)
02-21 22:00 Starting backup (MANUAL)
02-21 22:00 Backing up (49646 SMS, 62272 MMS, 2000 call log)
02-21 22:00 Using config: BackupConfig{imap=BackupImapStore{uri=imap+ssl+://PLAIN:XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX@imap.gmail.com:993}, currentTry=0, maxItemsPerSync=-1, groupToBackup=ContactGroup{_id=-1, type=EVERYBODY}, backupType=MANUAL, debug=true, typesToBackup=[SMS, MMS, CALLLOG]}
02-21 22:24 General error: IO Error (exception: com.fsck.k9.mail.MessagingException: IO Error, underlying=java.net.SocketException: Software caused connection abort)
02-21 22:24 BackupState{currentSyncedItems=1017, itemsToSync=113918, backupType=MANUAL, exception=com.fsck.k9.mail.MessagingException: IO Error, state=ERROR}
02-21 22:24 Backup finished

Reproduce by

Attempt to backup many SMS/MMS messages. Unsure how to reproduce.

Android version

13 (2022)

Phone brand

Samsung Galaxy

Phone model number

S22+

SMS Backup+ version

v1.5.11

Messaging app

Google Messages

Other details

• This is the first attempt using SMS Backup+ on this phone.
• Freshly configured IMAP settings
• 133799+ SMS messages to backup along with unknown number of MMS
• Backup settings: SMS + MMS + Call Log
• Contacts to backup - No radio button selected. This seems suspicious that a default (i.e. Everybody) isn't preselected. I chose "Everybody" in subsequent attempts with no change.

It seems like SMS Backup+ should batch backup messages so that a failure doesn't prevent all progress. Or for large backups of many SMS's, it can chip away at it over time.

[kurahaupo]

@AlexHimself Hi,

The IMAP backup assumes an uninterrupted socket connection to the IMAP server.

I run a few apps that require raw TCP sockets, and in all recent versions of Android there are serious problems holding a socket open for more than a few tens of minutes. Typically sockets will time out in less than an hour, but very occasionally I will see a session run uninterrupted all night.

I would be interested to know what's happening on your IMAP server end; how quickly are messages being transferred? Do they flow smoothly, or are there frequent pauses?

Does the "number of messages still to send" go down after each connection, or does it start over sending the same messages again? (Do you see duplicates on the server end?)

This should probably be modified to log out and back in again every so many messages or every so many minutes.

[AlexHimself]

@AlexHimself Hi,

The IMAP backup assumes an uninterrupted socket connection to the IMAP server.

I run a few apps that require raw TCP sockets, and in all recent versions of Android there are serious problems holding a socket open for more than a few tens of minutes. Typically sockets will time out in less than an hour, but very occasionally I will see a session run uninterrupted all night.

I would be interested to know what's happening on your IMAP server end; how quickly are messages being transferred? Do they flow smoothly, or are there frequent pauses?

Does the "number of messages still to send" go down after each connection, or does it start over sending the same messages again? (Do you see duplicates on the server end?)

This should probably be modified to log out and back in again every so many messages or every so many minutes.

That makes sense and good questions.

On my end I see the number of items backed up steadily increase at maybe 1.5 texts/second. I do not see any messages make it to GMail with my SMS label though. I'm still frozen with the last successful one in 2020.

I'm surprised SMSBackup+ doesn't upload texts in batches for both performance and reliability. It could potentially do multiple threads and then each batch could be atomic. That way specific failures with some texts wouldn't impact the other texts from being backed up.

If I had to guess, I'd assume SMSBackup+ does this for the simplicity of tracking the last date/time of SMS's to resume from previously?

[AlexHimself]

I don't suppose there's any solution to this? I haven't had a successful backup since 2020...

[kurahaupo]

@AlexHimself the "IO Error" is simply that the TCP/IP network connection is unexpectedly broken.

Gmail IMAP connections have a time limit of about 70 minutes, after which the IMAP server process at Google's end is abruptly terminated.

This means it doesn't get a chance to send an IMAP BYE notification, and once the process is dead, the OS on the server sends a TCP RST to shut down the socket connection.

That in turn means that the client unexpected sees "End of File" when it tries to read from the socket, which it treats as an IO Error. (Or alternatively, that it gets an IO Error when it tries to send LOGOUT to the server.)

Arguably this should be treated the same as a received BYE; I will look and see if any patching is needed.

[AlexHimself]

@AlexHimself the "IO Error" is simply that the TCP/IP network connection is unexpectedly broken.

Gmail IMAP connections have a time limit of about 70 minutes, after which the IMAP server process at Google's end is abruptly terminated.

This means it doesn't get a chance to send an IMAP BYE notification, and once the process is dead, the OS on the server sends a TCP RST to shut down the socket connection.

That in turn means that the client unexpected sees "End of File" when it tries to read from the socket, which it treats as an IO Error. (Or alternatively, that it gets an IO Error when it tries to send LOGOUT to the server.)

Arguably this should be treated the same as a received BYE; I will look and see if any patching is needed.

Ahhh. If I'm understanding you correctly, it sounds like the app is opening a persistent connection, uploading, and then Google is forcing a timeout and disconnecting. It seems this is being treated like a SQL begin tran/commit tran except it never commits so it just discards everything uploaded?

Would a simple solution be to just close/reopen the connection every 10 minutes or so? Thanks for the great info/reply!

[kurahaupo]

The timeout is sometimes a lot shorter. I suspect it's actually a process run-time limit, and if it's already been servicing other clients for 65 minutes, it'll die after only 5 minutes.

So several things need fixing:

1. Fix the batch size limit so that it doesn't rely on inserting a LIMIT into the SQL statement (this was broken by Android 11).
2. Handle dropped connections gracefully, committing any changes already made.
3. Schedule a disconnection every 5 or 10 minutes (to minimize the likelihood of a message being in-flight when an involuntary disconnection occurs, leaving the status of that message in doubt).
4. Automatically restart with the 'next batch'
5. During the initial backup:
   • allow the user to specify a starting timestamp or date, or perhaps "how long ago" from today;
   • display the most recent message timestamp (especially upon interruption, so it can be used to manually restart later, but also as a progress indicator with a live clock underneath it)
   • allow it to be interrupted
   • after an interruption, set fill the start timestamp field with the timestamp of the last message successfully backed up (and set the 'all/since/none' option to 'since').

[AlexHimself]

That sounds like a true fix, but not a minor task I'd think. It would be tremendous if it can be done!