Exception when activating "Log to external file"

[biociahi]

Okay.

I’ve found that toggling “Log to external file” crashes DAVdroid with

E/SQLiteDatabase( 1446): close() was never explicitly called on database '/data/data/at.bitfire.davdroid/databases/services.db' 
E/SQLiteDatabase( 1446): android.database.sqlite.DatabaseObjectNotClosedException: Application did not close the cursor or database object that was opened here
E/SQLiteDatabase( 1446): 	at android.database.sqlite.SQLiteDatabase.<init>(SQLiteDatabase.java:1943)
E/SQLiteDatabase( 1446): 	at android.database.sqlite.SQLiteDatabase.openDatabase(SQLiteDatabase.java:1007)
E/SQLiteDatabase( 1446): 	at android.database.sqlite.SQLiteDatabase.openDatabase(SQLiteDatabase.java:986)
E/SQLiteDatabase( 1446): 	at android.database.sqlite.SQLiteDatabase.openOrCreateDatabase(SQLiteDatabase.java:1051)
E/SQLiteDatabase( 1446): 	at android.app.ContextImpl.openOrCreateDatabase(ContextImpl.java:770)
E/SQLiteDatabase( 1446): 	at android.content.ContextWrapper.openOrCreateDatabase(ContextWrapper.java:221)
E/SQLiteDatabase( 1446): 	at android.database.sqlite.SQLiteOpenHelper.getWritableDatabase(SQLiteOpenHelper.java:157)
E/SQLiteDatabase( 1446): 	at android.database.sqlite.SQLiteOpenHelper.getReadableDatabase(SQLiteOpenHelper.java:231)
E/SQLiteDatabase( 1446): 	at at.bitfire.davdroid.ui.AppSettingsActivity$SettingsFragment.onCreatePreferences(AppSettingsActivity.java:57)
E/SQLiteDatabase( 1446): 	at android.support.v7.preference.PreferenceFragmentCompat.onCreate(PreferenceFragmentCompat.java:216)
E/SQLiteDatabase( 1446): 	at android.support.v4.app.Fragment.performCreate(Fragment.java:1951)
E/SQLiteDatabase( 1446): 	at android.support.v4.app.FragmentManagerImpl.moveToState(FragmentManager.java:1029)
E/SQLiteDatabase( 1446): 	at android.support.v4.app.FragmentManagerImpl.moveToState(FragmentManager.java:1252)
E/SQLiteDatabase( 1446): 	at android.support.v4.app.BackStackRecord.run(BackStackRecord.java:742)
E/SQLiteDatabase( 1446): 	at android.support.v4.app.FragmentManagerImpl.execPendingActions(FragmentManager.java:1617)
E/SQLiteDatabase( 1446): 	at android.support.v4.app.FragmentController.execPendingActions(FragmentController.java:339)
E/SQLiteDatabase( 1446): 	at android.support.v4.app.FragmentActivity.onStart(FragmentActivity.java:601)
E/SQLiteDatabase( 1446): 	at android.app.Instrumentation.callActivityOnStart(Instrumentation.java:1133)
E/SQLiteDatabase( 1446): 	at android.app.Activity.performStart(Activity.java:4475)
E/SQLiteDatabase( 1446): 	at android.app.ActivityThread.performLaunchActivity(ActivityThread.java:1929)
E/SQLiteDatabase( 1446): 	at android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:1981)
E/SQLiteDatabase( 1446): 	at android.app.ActivityThread.access$600(ActivityThread.java:123)
E/SQLiteDatabase( 1446): 	at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1147)
E/SQLiteDatabase( 1446): 	at android.os.Handler.dispatchMessage(Handler.java:99)
E/SQLiteDatabase( 1446): 	at android.os.Looper.loop(Looper.java:137)
E/SQLiteDatabase( 1446): 	at android.app.ActivityThread.main(ActivityThread.java:4424)
E/SQLiteDatabase( 1446): 	at java.lang.reflect.Method.invokeNative(Native Method)
E/SQLiteDatabase( 1446): 	at java.lang.reflect.Method.invoke(Method.java:511)
E/SQLiteDatabase( 1446): 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:784)
E/SQLiteDatabase( 1446): 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:551)
E/SQLiteDatabase( 1446): 	at dalvik.system.NativeStart.main(Native Method)
I/SqliteDatabaseCpp( 1446): sqlite returned: error code = 5, msg = statement aborts at 1: [PRAGMA journal_mode=TRUNCATE] , db=/data/data/at.bitfire.davdroid/databases/services.db
D/AndroidRuntime( 1446): Shutting down VM
W/dalvikvm( 1446): threadid=1: thread exiting with uncaught exception (group=0xb5015180)
E/AndroidRuntime( 1446): FATAL EXCEPTION: main
E/AndroidRuntime( 1446): android.database.sqlite.SQLiteDatabaseLockedException: error code 5: database is locked
E/AndroidRuntime( 1446): 	at android.database.sqlite.SQLiteStatement.native_1x1_string(Native Method)
E/AndroidRuntime( 1446): 	at android.database.sqlite.SQLiteStatement.simpleQueryForString(SQLiteStatement.java:161)
E/AndroidRuntime( 1446): 	at android.database.DatabaseUtils.stringForQuery(DatabaseUtils.java:813)
E/AndroidRuntime( 1446): 	at android.database.DatabaseUtils.stringForQuery(DatabaseUtils.java:801)
E/AndroidRuntime( 1446): 	at android.database.sqlite.SQLiteDatabase.setJournalMode(SQLiteDatabase.java:1060)
E/AndroidRuntime( 1446): 	at android.database.sqlite.SQLiteDatabase.openDatabase(SQLiteDatabase.java:996)
E/AndroidRuntime( 1446): 	at android.database.sqlite.SQLiteDatabase.openOrCreateDatabase(SQLiteDatabase.java:1051)
E/AndroidRuntime( 1446): 	at android.app.ContextImpl.openOrCreateDatabase(ContextImpl.java:770)
E/AndroidRuntime( 1446): 	at android.content.ContextWrapper.openOrCreateDatabase(ContextWrapper.java:221)
E/AndroidRuntime( 1446): 	at android.database.sqlite.SQLiteOpenHelper.getWritableDatabase(SQLiteOpenHelper.java:157)
E/AndroidRuntime( 1446): 	at at.bitfire.davdroid.ui.AppSettingsActivity$SettingsFragment.setExternalLogging(AppSettingsActivity.java:100)
E/AndroidRuntime( 1446): 	at at.bitfire.davdroid.ui.AppSettingsActivity$SettingsFragment.onPreferenceTreeClick(AppSettingsActivity.java:69)
E/AndroidRuntime( 1446): 	at android.support.v7.preference.Preference.performClick(Preference.java:962)
E/AndroidRuntime( 1446): 	at android.support.v7.preference.Preference.performClick(Preference.java:938)
E/AndroidRuntime( 1446): 	at android.support.v7.preference.SwitchPreferenceCompat.performClick(SwitchPreferenceCompat.java:203)
E/AndroidRuntime( 1446): 	at android.support.v7.preference.Preference$1.onClick(Preference.java:142)
E/AndroidRuntime( 1446): 	at android.view.View.performClick(View.java:3511)
E/AndroidRuntime( 1446): 	at android.view.View$PerformClick.run(View.java:14105)
E/AndroidRuntime( 1446): 	at android.os.Handler.handleCallback(Handler.java:605)
E/AndroidRuntime( 1446): 	at android.os.Handler.dispatchMessage(Handler.java:92)
E/AndroidRuntime( 1446): 	at android.os.Looper.loop(Looper.java:137)
E/AndroidRuntime( 1446): 	at android.app.ActivityThread.main(ActivityThread.java:4424)
E/AndroidRuntime( 1446): 	at java.lang.reflect.Method.invokeNative(Native Method)
E/AndroidRuntime( 1446): 	at java.lang.reflect.Method.invoke(Method.java:511)
E/AndroidRuntime( 1446): 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:784)
E/AndroidRuntime( 1446): 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:551)
E/AndroidRuntime( 1446): 	at dalvik.system.NativeStart.main(Native Method)
W/ActivityManager(  871):   Force finishing activity at.bitfire.davdroid/.ui.AppSettingsActivity
W/WindowManager(  871): Failure taking screenshot for (180x300) to layer 21015
W/ActivityManager(  871): Activity pause timeout for ActivityRecord{b5904498 at.bitfire.davdroid/.ui.AppSettingsActivity}

Edit: Please enclose logs with ```, otherwise I have to do it. It’s not that much work.

I’m on master @ 91234a68 running Android 4.0.3 x86 emulator. Is this a known bug? Sorry for posting here, but you’ve disabled issue tracker too…

[rfc2822]

@biociahi said in Exception when activating "Log to external file":

I’m on master @ 91234a68 running Android 4.0.3 x86 emulator. Is this a known bug?

No, it’s not (until now). I have seen some concurrency (locking) database problems with Android <4.1, which I think might be related to the fact that setWriteAheadLoggingEnabled is only available since API level 16 and WAL has to be activated for the already-opened database for lower Android versions.

However, a DatabaseObjectNotClosedException seems not to be related to that.

Sorry for posting here, but you’ve disabled issue tracker too…

The “issue tracker” is not disabled, but not enabled. This forum is a much better ways to handle support requests, and enhancement requests and discussion. If you don’t like it, you don’t have to use it. Please accept our way of project management.

Also, please enclose your logs with ``` to make them readable and create a new topic for … new topics. You wouldn’t post a non-related “issue” into another “issue”, too, would you? I have now split the previous topic.

[biociahi]

Looks like multiple DB connections don’t work very well, see http://www.dmytrodanylyk.com/concurrent-database-access/

F-Droid also had those “database locked” issues and solved them by making SQLiteOpenHelper a singleton, see https://gitlab.com/fdroid/fdroidclient/merge_requests/196

[rfc2822]

I have read that article before and even bought an SQLite book to get some insights, but there seem to be little useful resources about the combination Android/SQLite (+WAL). DAVdroid uses two processes (one for the UI, one :sync process), so there have to be at least two connections (one per process) when synchronization is active.

For performance reasons and because WAL is an option in Android, I have chosen to use multiple connections even for a single process. Until now, it was possible to resolve every problem, at least for Android ≥ 4.1.

If your exception is reproducible, please provide steps to reproduce and I’ll have a look. It should be possible to fix this, because database connections are closeable (and as far as I know, all connections are closed, but it’s of course possible that it’s missing somewhere).

[biociahi]

Steps to reproduce:

1. Set up API 15 x86 emulator.
2. Install DAVdroid compiled from the master branch into the emulator.
3. Open DAVdroid settings.
4. Click “Log to external file” several times.

It always crashes after 1–3 clicks. I was unable to reproduce this on a real device running Marshmallow, though.

[biociahi]

Multiple concurrent write connections are the source of this issue (multiple concurrent read connections are OK). You can easily check this by making two SQLiteOpenHelper.getWritableDatabase() calls from concurrent threads. I’ve made SQLiteOpenHelper a singleton with a reference counter and this fixed “database locked” crashes.

Let me know if you want me to prepare a patch.

[rfc2822]

@biociahi As far as I understand it, the database should not be locked when two writing threads are active and using beginTransactionNonExclusive() with activated WAL.

[biociahi]

@rfc2822, this seems to be correct because I couldn’t reproduce this issue in Android 4.1 emulator. But WAL is not supported on Android 4.0. So, another possible fix is to bump minSdk from 15 to 16 (especially given that ICS has smaller market share than Gingerbread).