file handle leak?

[superfell]

I have a test suite for my app that does a lot of open/rawQuery/execSQl/close calls on the database, using the standard SQLiteDatabase this test suite runs fine to completion (tested on both 2.1 & 2.2). When i switch to using sqlcipher the test suite gets about 50% through and the stops with a bunch of errors that all seem related to this log line

E/MemoryHeapBase( 1028): error creating ashmem region: Too many open files
E/CursorWindow( 1028): CursorWindow heap allocation failed
I/TestRunner( 1028): ----- begin exception -----
I/TestRunner( 1028):
I/TestRunner( 1028): java.lang.IllegalStateException: Couldn't init cursor window

Are you aware of any file handle leaks, or areas where you may manage file handles differently to the OS supplied SQLiteDatabase ? I'm working on putting together a simple repo case for this.

I've seen this with v0.4 & v0.3 releases.

[superfell]

This is the about the simplest repo case i could get the crash, this will die at around 980 iterations of the loop, if you remove the c.moveToNext() line it doesn't crash, seems like something in the cursor is leaking.

public class SqlciphertestActivity extends Activity {

@Override
public void onCreate(Bundle savedInstanceState) {
    super.onCreate(savedInstanceState);
    setContentView(R.layout.main);
    SQLiteDatabase.loadLibs(this);
}

@Override
public void onResume() {
    super.onResume();
    DbTask t = new DbTask();
    t.execute(this.getDatabasePath("MyDb"));
}

public class DbTask extends AsyncTask<File,Void,Void> {

    @Override
    protected Void doInBackground(File... params) {
        Log.i("db", "starting doInBackground for " + params[0].getAbsolutePath());
        params[0].delete();
        SQLiteDatabase d = SQLiteDatabase.openOrCreateDatabase(params[0], "foo", null);
        d.execSQL("create table foo(_id integer primary key)");
        d.execSQL("insert into foo values(1)");
        try {
            for (int k =0; k < 30000; k++) {
                if (k % 10 == 0) Log.i("db", "k=" + k);
                Cursor c = d.rawQuery("select _id from foo where _id=1",null);
                try {
                    while (c.moveToNext()) {
                    }
                } finally {
                    c.close();
                }
            }
        } finally {
            d.close();
        }
        Log.i("db", "done");
        return null;
    }
}

}

Logcat output will show this
I/db ( 722): k=930
I/db ( 722): k=940
I/db ( 722): k=950
I/db ( 722): k=960
I/db ( 722): k=970
I/db ( 722): k=980
E/MemoryHeapBase( 722): error creating ashmem region: Too many open files
E/CursorWindow( 722): CursorWindow heap allocation failed
W/dalvikvm( 722): threadid=7: thread exiting with uncaught exception (group=0x4001d800)
D/dalvikvm( 722): GC_FOR_MALLOC freed 10019 objects / 451120 bytes in 86ms
E/AndroidRuntime( 722): FATAL EXCEPTION: AsyncTask #1
E/AndroidRuntime( 722): java.lang.RuntimeException: An error occured while executing doInBackground()
E/AndroidRuntime( 722): at android.os.AsyncTask$3.done(AsyncTask.java:200)
E/AndroidRuntime( 722): at java.util.concurrent.FutureTask$Sync.innerSetException(FutureTask.java:273)
E/AndroidRuntime( 722): at java.util.concurrent.FutureTask.setException(FutureTask.java:124)
E/AndroidRuntime( 722): at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:307)
E/AndroidRuntime( 722): at java.util.concurrent.FutureTask.run(FutureTask.java:137)
E/AndroidRuntime( 722): at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1068)
E/AndroidRuntime( 722): at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:561)
E/AndroidRuntime( 722): at java.lang.Thread.run(Thread.java:1096)
E/AndroidRuntime( 722): Caused by: java.lang.IllegalStateException: Couldn't init cursor window
E/AndroidRuntime( 722): at info.guardianproject.database.CursorWindow.native_init(Native Method)
E/AndroidRuntime( 722): at info.guardianproject.database.CursorWindow.(CursorWindow.java:43)
E/AndroidRuntime( 722): at info.guardianproject.database.sqlcipher.SQLiteCursor.fillWindow(SQLiteCursor.java:279)
E/AndroidRuntime( 722): at info.guardianproject.database.sqlcipher.SQLiteCursor.getCount(SQLiteCursor.java:271)
E/AndroidRuntime( 722): at info.guardianproject.database.AbstractCursor.moveToPosition(AbstractCursor.java:172)
E/AndroidRuntime( 722): at info.guardianproject.database.AbstractCursor.moveToNext(AbstractCursor.java:257)
E/AndroidRuntime( 722): at com.superfell.sqlc.SqlciphertestActivity$DbTask.doInBackground(SqlciphertestActivity.java:43)
E/AndroidRuntime( 722): at com.superfell.sqlc.SqlciphertestActivity$DbTask.doInBackground(SqlciphertestActivity.java:1)
E/AndroidRuntime( 722): at android.os.AsyncTask$2.call(AsyncTask.java:185)
E/AndroidRuntime( 722): at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:305)
E/AndroidRuntime( 722): ... 4 more
W/ActivityManager( 72): Force finishing activity com.superfell.sqlc/.SqlciphertestActivity

I've repo'd this with the v0.4 release on a 2.1 emulator, a 2.2 emulator and a moto droid 2 running 2.2

[n8fr8]

In the latest commits (see the 0.0.5 tag), we now have removed our own implementation of Cursor and CursorWindow, and are instead relying upon the built-in android.database package for those classes. We are trying to remove as much unnecessary forking as possible to avoid issues like this.

So, please, run your test suite on the latest update (see downloads for the bin package) and let us know how it goes.

[superfell]

It looks pretty good on 2.2, the above repo case, and my larger test suite both run to completion and pass, but on 2.1, i'm seeing this crash, on both a 2.1 emulator and a real 2.1 device. (a samsung galaxy s)

I/ActivityManager( 53): Displayed activity com.superfell.sqlc/.SqlciphertestActivity: 916 ms (total 916 ms)
I/db ( 3987): starting doInBackground for /data/data/com.superfell.sqlc/databases/db2
I/db ( 3987): k=0
E/CursorWindow( 3987): need to grow: mSize = 1048576, size = 9, freeSpace() = 0, numRows = 1
I/DEBUG ( 2279): *** *** *** *** *** *** *** *** *** *** *** *** *** *** *** ***
I/DEBUG ( 2279): Build fingerprint: 'generic/sdk/generic/:2.1-update1/ECLAIR/35983:eng/test-keys'
I/DEBUG ( 2279): pid: 3987, tid: 3994 >>> com.superfell.sqlc <<<
I/DEBUG ( 2279): signal 11 (SIGSEGV), fault addr 456ca690
I/DEBUG ( 2279): r0 456ca690 r1 00000000 r2 00000001 r3 80000000
I/DEBUG ( 2279): r4 00000000 r5 00000000 r6 00000000 r7 00000000
I/DEBUG ( 2279): r8 00000009 r9 00000000 10 00000001 fp 00000064
I/DEBUG ( 2279): ip 00000000 sp 45386cf0 lr 00000000 pc afe0e2f0 cpsr 80000010
I/DEBUG ( 2279): #00 pc 0000e2f0 /system/lib/libc.so
I/DEBUG ( 2279): #1 pc 00002708 /data/data/com.superfell.sqlc/lib/libdatabase_sqlcipher.so
I/DEBUG ( 2279): #2 pc 00003b34 /data/data/com.superfell.sqlc/lib/libdatabase_sqlcipher.so
I/DEBUG ( 2279): #3 pc 0000f1f4 /system/lib/libdvm.so
I/DEBUG ( 2279): #4 pc 000039d6 /data/data/com.superfell.sqlc/lib/libdatabase_sqlcipher.so
I/DEBUG ( 2279):
I/DEBUG ( 2279): code around pc:
I/DEBUG ( 2279): afe0e2e0 e0422003 e1b03e03 28a04002 28a04002
I/DEBUG ( 2279): afe0e2f0 48a04002 e1b03103 24801004 e2522020
I/DEBUG ( 2279): afe0e300 e1a03001 4a000002 e2522020 e8a050fa
I/DEBUG ( 2279):
I/DEBUG ( 2279): code around lr:
I/DEBUG ( 2279):
I/DEBUG ( 2279): stack:
I/DEBUG ( 2279): 45386cb0 000000c8
I/DEBUG ( 2279): 45386cb4 001229c0 [heap]
I/DEBUG ( 2279): 45386cb8 00000001
I/DEBUG ( 2279): 45386cbc b76f0305
I/DEBUG ( 2279): 45386cc0 410adfc4 /dev/ashmem/dalvik-LinearAlloc (deleted)
I/DEBUG ( 2279): 45386cc4 002f65b8 [heap]
I/DEBUG ( 2279): 45386cc8 00000009
I/DEBUG ( 2279): 45386ccc 00000000
I/DEBUG ( 2279): 45386cd0 80d05128 /data/data/com.superfell.sqlc/lib/libdatabase_sqlcipher.so
I/DEBUG ( 2279): 45386cd4 80d025f5 /data/data/com.superfell.sqlc/lib/libdatabase_sqlcipher.so
I/DEBUG ( 2279): 45386cd8 80d043c0 /data/data/com.superfell.sqlc/lib/libdatabase_sqlcipher.so
I/DEBUG ( 2279): 45386cdc 00100000 [heap]
I/DEBUG ( 2279): 45386ce0 00000009
I/DEBUG ( 2279): 45386ce4 00000000
I/DEBUG ( 2279): 45386ce8 df002777
I/DEBUG ( 2279): 45386cec e3a070ad
I/DEBUG ( 2279): #00 45386cf0 456ca690
I/DEBUG ( 2279): 45386cf4 002f65b8 [heap]
I/DEBUG ( 2279): 45386cf8 456ca690
I/DEBUG ( 2279): 45386cfc 453d2008 /dev/ashmem/CursorWindow (deleted)
I/DEBUG ( 2279): 45386d00 002f8690 [heap]
I/DEBUG ( 2279): 45386d04 80d0270b /data/data/com.superfell.sqlc/lib/libdatabase_sqlcipher.so
I/DEBUG ( 2279): #1 45386d08 00000000
I/DEBUG ( 2279): 45386d0c 00000000
I/DEBUG ( 2279): 45386d10 80d06b84 /data/data/com.superfell.sqlc/lib/libdatabase_sqlcipher.so
I/DEBUG ( 2279): 45386d14 002f65b8 [heap]
I/DEBUG ( 2279): 45386d18 002f56b0 [heap]
I/DEBUG ( 2279): 45386d1c 80d03b39 /data/data/com.superfell.sqlc/lib/libdatabase_sqlcipher.so
D/Zygote ( 30): Process 3987 terminated by signal (11)

[superfell]

I can get what looks like the same crash using the supplied NoteCipher app on 2.1

[superfell]

I'm guessing this is related to the TARGET_PLATFORM := android-8 in jni/Android.mk.

[PARASOFT-zz]

@superfell The problem you are facing seems similar to mine, check this:
https://github.com/guardianproject/android-database-sqlcipher/issues/17

[superfell]

Retested this with the new build, many of the crashes i was previously seeing are gone (yay!), but am back to the original issue in this bug. Something is leaking, after you've run enough queries (~900) you get an out of memory crash.

I/db (26696): k=800
E/MemoryHeapBase(26696): mmap(fd=903, size=2097152) failed (Out of memory)
E/CursorWindow(26696): CursorWindow heap allocation failed
W/dalvikvm(26696): threadid=8: thread exiting with uncaught exception (group=0x4001d7d0)
D/dalvikvm(26696): GC_FOR_MALLOC freed 10112 objects / 438344 bytes in 43ms
E/AndroidRuntime(26696): FATAL EXCEPTION: AsyncTask #1
E/AndroidRuntime(26696): java.lang.RuntimeException: An error occured while executing doInBackground()
E/AndroidRuntime(26696): at android.os.AsyncTask$3.done(AsyncTask.java:200)
E/AndroidRuntime(26696): at java.util.concurrent.FutureTask$Sync.innerSetException(FutureTask.java:273)
E/AndroidRuntime(26696): at java.util.concurrent.FutureTask.setException(FutureTask.java:124)
E/AndroidRuntime(26696): at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:307)
E/AndroidRuntime(26696): at java.util.concurrent.FutureTask.run(FutureTask.java:137)
E/AndroidRuntime(26696): at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1068)
E/AndroidRuntime(26696): at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:561)
E/AndroidRuntime(26696): at java.lang.Thread.run(Thread.java:1096)
E/AndroidRuntime(26696): Caused by: java.lang.IllegalStateException: Couldn't init cursor window
E/AndroidRuntime(26696): at android.database.CursorWindow.native_init(Native Method)
E/AndroidRuntime(26696): at android.database.CursorWindow.(CursorWindow.java:73)
E/AndroidRuntime(26696): at android.database.CursorWindow.(CursorWindow.java:42)
E/AndroidRuntime(26696): at info.guardianproject.database.CursorWindow.(CursorWindow.java:41)
E/AndroidRuntime(26696): at info.guardianproject.database.sqlcipher.SQLiteCursor.fillWindow(SQLiteCursor.java:281)
E/AndroidRuntime(26696): at info.guardianproject.database.sqlcipher.SQLiteCursor.getCount(SQLiteCursor.java:273)
E/AndroidRuntime(26696): at info.guardianproject.database.AbstractCursor.moveToPosition(AbstractCursor.java:168)
E/AndroidRuntime(26696): at info.guardianproject.database.AbstractCursor.moveToNext(AbstractCursor.java:253)
E/AndroidRuntime(26696): at android.database.CursorWrapper.moveToNext(CursorWrapper.java:191)
E/AndroidRuntime(26696): at com.superfell.sqlc.SqlciphertestActivity$DbTask.doInBackground(SqlciphertestActivity.java:44)
E/AndroidRuntime(26696): at com.superfell.sqlc.SqlciphertestActivity$DbTask.doInBackground(SqlciphertestActivity.java:1)
E/AndroidRuntime(26696): at android.os.AsyncTask$2.call(AsyncTask.java:185)
E/AndroidRuntime(26696): at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:305)
E/AndroidRuntime(26696): ... 4 more

[n8fr8]

Thanks for the testing and note. We did roll back some code in order to make the majority of the implementation work better and properly. We'll be working with Zetetic crew on reproducing this.

[n8fr8]

Just to clarify, by new build, you mean:
https://github.com/downloads/guardianproject/android-database-sqlcipher/SQLCipherForAndroid-SDK-0.0.6-BETA-DP3.tar.gz

?

[superfell]

Yes.

[superfell]

The Leak appears to be related to info.guardianproject.database.CursorWindow, which has all its own native hooks etc, but also at the same time extends android.database.CursorWindow which is also trying to manage native memory and so on. From what i can tell so far, the i.g.d.CursorWindow cleans up its own native memory ok, but is not calling through to android.database.CursorWindow to do its cleanup.

[superfell]

I just sent a pull request that has a fix for this.

[n8fr8]

Fantastic. Will review tomorrow.

Simon Fell reply@reply.github.com wrote:

I just sent a pull request that has a fix for this.

Reply to this email directly or view it on GitHub:
https://github.com/guardianproject/android-database-sqlcipher/issues/6#issuecomment-2584728

[n8fr8]

I've merged your code. Appreciate the contribution. Will do some more extensive testing tomorrow, using this build with our app Gibberbot.