Sporadic (but frequent) crash when uploading on Android 11

[mvglasow]

What steps will reproduce the problem?

1. Record some data.
2. Upload your session.

What is the expected output? What do you see instead?

Expected: session uploads and is marked as successfully exported.

Actual: Radiobeacon uploads all data but then crashes. This seems to be sporadic (more often than not) and it usually takes a few attempts for the export to complete successfully.

What version are you using? On what operating system?

93f6577 on Android 11 (LineageOS).

Please provide any additional information below.

This started after I updated from Android 10 to 11. The exception thrown is android.database.sqlite.SQLiteDatabaseLockedException: database is locked (code 5 SQLITE_BUSY); the sporadic nature indicates a possible race condition.

Also, it seems that immediately after exporting one out of multiple sessions successfully, uploading another session will also succeed.

I fiddled around with this a bit on my own: I hunted down all calls to getWritableDatabase(); with one exception, all occur in the content provider. The one exception is the vacuum operation, though I do not believe that to be involved in this issue.

I added synchronized to each and every content provider method which accesses the database and retried – same error. Maybe you can shed some light on this: which threads (also background tasks etc.) would access the database, and which of these could be running at the time a track is exported?

07-08 11:50:20.394 17654 17654 E AndroidRuntime: android.database.sqlite.SQLiteDatabaseLockedException: database is locked (code 5 SQLITE_BUSY)
07-08 11:50:20.394 17654 17654 E AndroidRuntime: 	at android.database.sqlite.SQLiteConnection.nativeExecuteForChangedRowCount(Native Method)
07-08 11:50:20.394 17654 17654 E AndroidRuntime: 	at android.database.sqlite.SQLiteConnection.executeForChangedRowCount(SQLiteConnection.java:890)
07-08 11:50:20.394 17654 17654 E AndroidRuntime: 	at android.database.sqlite.SQLiteSession.executeForChangedRowCount(SQLiteSession.java:756)
07-08 11:50:20.394 17654 17654 E AndroidRuntime: 	at android.database.sqlite.SQLiteStatement.executeUpdateDelete(SQLiteStatement.java:66)
07-08 11:50:20.394 17654 17654 E AndroidRuntime: 	at android.database.sqlite.SQLiteDatabase.updateWithOnConflict(SQLiteDatabase.java:1806)
07-08 11:50:20.394 17654 17654 E AndroidRuntime: 	at android.database.sqlite.SQLiteDatabase.update(SQLiteDatabase.java:1752)
07-08 11:50:20.394 17654 17654 E AndroidRuntime: 	at org.openbmap.db.ContentProvider.updateTable(ContentProvider.java:542)
07-08 11:50:20.394 17654 17654 E AndroidRuntime: 	at org.openbmap.db.ContentProvider.update(ContentProvider.java:514)
07-08 11:50:20.394 17654 17654 E AndroidRuntime: 	at android.content.ContentProvider.update(ContentProvider.java:1807)
07-08 11:50:20.394 17654 17654 E AndroidRuntime: 	at android.content.ContentProvider$Transport.update(ContentProvider.java:457)
07-08 11:50:20.394 17654 17654 E AndroidRuntime: 	at android.content.ContentResolver.update(ContentResolver.java:2356)
07-08 11:50:20.394 17654 17654 E AndroidRuntime: 	at android.content.ContentResolver.update(ContentResolver.java:2318)
07-08 11:50:20.394 17654 17654 E AndroidRuntime: 	at org.openbmap.db.DataHelper.storeSession(DataHelper.java:398)
07-08 11:50:20.394 17654 17654 E AndroidRuntime: 	at org.openbmap.activities.StartscreenActivity.onUploadCompleted(StartscreenActivity.java:600)
07-08 11:50:20.394 17654 17654 E AndroidRuntime: 	at org.openbmap.activities.UploadTaskFragment.onUploadCompleted(UploadTaskFragment.java:276)
07-08 11:50:20.394 17654 17654 E AndroidRuntime: 	at org.openbmap.soapclient.ExportSessionTask.onPostExecute(ExportSessionTask.java:416)
07-08 11:50:20.394 17654 17654 E AndroidRuntime: 	at org.openbmap.soapclient.ExportSessionTask.onPostExecute(ExportSessionTask.java:50)
07-08 11:50:20.394 17654 17654 E AndroidRuntime: 	at android.os.AsyncTask.finish(AsyncTask.java:771)
07-08 11:50:20.394 17654 17654 E AndroidRuntime: 	at android.os.AsyncTask.access$900(AsyncTask.java:199)
07-08 11:50:20.394 17654 17654 E AndroidRuntime: 	at android.os.AsyncTask$InternalHandler.handleMessage(AsyncTask.java:788)
07-08 11:50:20.394 17654 17654 E AndroidRuntime: 	at android.os.Handler.dispatchMessage(Handler.java:106)
07-08 11:50:20.394 17654 17654 E AndroidRuntime: 	at android.os.Looper.loop(Looper.java:223)
07-08 11:50:20.394 17654 17654 E AndroidRuntime: 	at android.app.ActivityThread.main(ActivityThread.java:7664)
07-08 11:50:20.394 17654 17654 E AndroidRuntime: 	at java.lang.reflect.Method.invoke(Native Method)
07-08 11:50:20.394 17654 17654 E AndroidRuntime: 	at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:592)
07-08 11:50:20.394 17654 17654 E AndroidRuntime: 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:947)
07-08 11:50:20.408   721 18668 I DropBoxManagerService: add tag=data_app_crash isTagEnabled=true flags=0x2
07-08 11:50:20.408   721  2867 W ActivityTaskManager:   Force finishing activity org.openbmap/.activities.StartscreenActivity

[mvglasow]

Update: after vacuuming the DB (which took over half an hour) I am not seeing any more issues. So this could have to do with Android’s timing behavior, possibly with changes in Android 11 over 10 which would cause the method call for the update to return while some database work is still going on in the background (resulting in the DB being locked).

The crash seems to happen at the end of the export, when the session is updated (marked a exported etc), in org.openbmap.db.DataHelper.storeSession. This is called from org.openbmap.soapclient.ExportSessionTask.onPostExecute, via a listener. That means this last DB update no longer happens on the ExportSessionTask thread but on the UI thread. Not sure if the thread change has anything to do with this (I can only speculate that two threads launching a transaction in quick succession might cause a race condition). However, interacting with the DB on the UI thread is definitely not nice.

I would recommend updating the table on the ExportSessionTask thread, just before it exits.

@wish7code I know the project is on hiatus, but maybe you can provide some pointers as to what parts of the code I need to change. I see the DB update happens through one of two listeners; the other one seems to do some UI-related stuff and might need to run on the UI thread, hence we might need to move the DB update part away from the listeners and straight into the export task.

[mvglasow]

A few sessions later, I am getting crashes again. Another DB reorganization (which again took at least half an hour) provided relief for the moment. (I should mention that I have some 250 sessions in my DB. Sizes vary from a few minutes’ duration, one cell and a few wifis to as much as 10 hours, 10K wifis and several hundred cells.) A botched DB (as in: any condition a reorg would fix) thus seems unlikely; however DB size may be a contributing factor.