Sql error library routine called out of sequence

    java.lang.RuntimeException: An error occurred while executing doInBackground()
        at android.os.AsyncTask$3.done(AsyncTask.java:309)
        at java.util.concurrent.FutureTask.finishCompletion(FutureTask.java:354)
        at java.util.concurrent.FutureTask.setException(FutureTask.java:223)
        at java.util.concurrent.FutureTask.run(FutureTask.java:242)
        at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:234)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1113)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:588)
        at java.lang.Thread.run(Thread.java:818)
    Caused by: net.sqlcipher.database.SQLiteMisuseException: library routine called out of sequence: , while compiling: SELECT * FROM h_entries WHERE chapterID=? ORDER BY _id
        at net.sqlcipher.database.SQLiteCompiledSql.native_compile(SQLiteCompiledSql.java)
        at net.sqlcipher.database.SQLiteCompiledSql.compile(SQLiteCompiledSql.java:91)
        at net.sqlcipher.database.SQLiteCompiledSql.<init>(SQLiteCompiledSql.java:64)
        at net.sqlcipher.database.SQLiteProgram.<init>(SQLiteProgram.java:83)
        at net.sqlcipher.database.SQLiteQuery.<init>(SQLiteQuery.java:49)
        at net.sqlcipher.database.SQLiteDirectCursorDriver.query(SQLiteDirectCursorDriver.java:42)
        at net.sqlcipher.database.SQLiteDatabase.rawQueryWithFactory(SQLiteDatabase.java:1762)
        at net.sqlcipher.database.SQLiteDatabase.queryWithFactory(SQLiteDatabase.java:1624)
        at net.sqlcipher.database.SQLiteDatabase.query(SQLiteDatabase.java:1576)
        at net.sqlcipher.database.SQLiteDatabase.query(SQLiteDatabase.java:1665)
        at org.blueletterbible.blb.DataBaseHelper.fetchHighlightsByChapter(DataBaseHelper.java:681)

    public class DataBaseHelper extends SQLiteOpenHelper {

    public static synchronized DataBaseHelper getInstance(Context context, String dbName) {
        DataBaseHelper sInstance;

        mContext = context.getApplicationContext();
        if(sInstances.containsKey(dbName)) {
            sInstance = sInstances.get(dbName);
            if (sInstance == null) {
                sInstance = new DataBaseHelper(mContext, dbName);
                sInstances.put(dbName, sInstance);
            }
        } else {
            sInstance = new DataBaseHelper(mContext, dbName);
            sInstances.put(dbName, sInstance);
        }
        return sInstance;
    }


    public Cursor fetchHighlightsByChapter(int chapterID) {
        String[] whereArgs = {Integer.toString(chapterID)};
        openDb();
        return db.query(H_ENTRIES, new String[]{"*"}, KEY_CHAPTERID+"=?", whereArgs, null, null, KEY_ROWID);
    }

Unfortunately, I’ve not run into this myself. These are reports from the wild and as such I don’t have a way to replicate the problem, nor run the test suite on them. I’m hoping that since the error is right from sqlcipher, that you might be able to shed some light on it. Our app has never even experienced an error from your library until I bumped up to 3.5.2 from 3.4.0.

I saw this error happen exactly once when I was testing some changes last year and reported it in #176.

I am almost positive that this is triggered by the sqlite3_prepare16_v2() call in net_sqlcipher_database_SQLiteCompiledSql.cpp. I found an excellent reference at: http://stackoverflow.com/questions/8372871/library-routine-called-out-of-sequence-sqlite3-prepare-v2create-table

I have worked quite a bit with the code in this project and there are plenty of guards against using sqlite3_prepare16_v2() among other sqlite3 calls on invalid database handles. I am wondering if this may be due to concurrency issues, i.e. «Trying to use the same database connection at the same instant in time from two or more threads.».

If this is the case, I wonder if we should use locking to ensure this does not happen?

Hi @brodybits, @theBlbDan,

Thank you for your feedback. I would like to see if we can recreate the issue before we attempt to resolve it by making changes to the code. @theBlbDan if there is any additional information you think you can share regarding the scenario including the query, schema, setup we would like to look into this further. Thanks!

Hi @developernotes, agreed.

Assuming I am right that this is a problem due to concurrency, it should be possible to use synchronized methods or blocks in the application code to prevent this from happening. Just an idea.

I’m not sure how related this might be, but here’s another issue since bumping up to 3.5.2 from 3.4.0.

    java.lang.RuntimeException: An error occurred while executing doInBackground()
        at android.os.AsyncTask$3.done(AsyncTask.java:309)
        at java.util.concurrent.FutureTask.finishCompletion(FutureTask.java:354)
        at java.util.concurrent.FutureTask.setException(FutureTask.java:223)
        at java.util.concurrent.FutureTask.run(FutureTask.java:242)
        at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:234)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1113)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:588)
        at java.lang.Thread.run(Thread.java:818)
    Caused by: java.lang.IllegalStateException: database not open
        at net.sqlcipher.database.SQLiteDatabase.rawQueryWithFactory(SQLiteDatabase.java:1760)
        at net.sqlcipher.database.SQLiteDatabase.queryWithFactory(SQLiteDatabase.java:1634)
        at net.sqlcipher.database.SQLiteDatabase.query(SQLiteDatabase.java:1586)
        at net.sqlcipher.database.SQLiteDatabase.query(SQLiteDatabase.java:1675)
        at org.blueletterbible.blb.DataBaseHelper.fetchHighlightsByChapter(DataBaseHelper.java:711)

highlights.blb schema.

CREATE TABLE [highlights] (
  [_id] INTEGER NOT NULL PRIMARY KEY AUTOINCREMENT, 
  [h_name] TEXT NOT NULL, 
  [h_alpha] CHAR(2) NOT NULL, 
  [h_red] CHAR(2) NOT NULL, 
  [h_green] CHAR(2) NOT NULL, 
  [h_blue] CHAR(2) NOT NULL);


CREATE TABLE [h_entries] (
  [_id] INTEGER NOT NULL PRIMARY KEY AUTOINCREMENT, 
  [highlight_id] INTEGER NOT NULL, 
  [bibleID] INTEGER NOT NULL, 
  [chapterID] INTEGER NOT NULL);

One of the events was on my own device last week (Google was slow on the uptake as the report just arrived today); it was a Samsung Galaxy S2 on 4.0.4. I left a note for myself in the crash report that I had simply rotated the device. Meaning the device had stopped and restarted the app, thus the app went through the process of onDestroy() where I close and dismiss all DataBaseHelper instances via

    public static void closeAllInstances() {
        for (Object o : sInstances.entrySet()) {
            Map.Entry pair = (Map.Entry) o;
            ((DataBaseHelper) pair.getValue()).close();
            Log.d(TAG, pair.getKey() + " closed.");
        }
        sInstances.clear();
    }

and restart.

The app structure is using SlidingMenu with fragments. One fragment for the menu, one for the main view. I call SQLiteDatabase.loadLibs(this) in the main activity onCreate. I use my DataBaseHelper.getInstance() prior to executing any DataBaseHelper method, such as fetchHighlightsByChapter(). Both the constructor and all methods make a call to openDb().

    private String DATABASE_NAME;
    private String DATABASE_PATH;
    private static HashMap<String, DataBaseHelper> sInstances = new HashMap<>();
    private SQLiteDatabase db = null;
    private static Context mContext;

    private DataBaseHelper(Context context, String dbName) {
        super(context, dbName, null, 1);
        DATABASE_NAME = dbName;
        DATABASE_PATH = mContext.getFilesDir().getPath() + "/databases/" + DATABASE_NAME + ".blb";
        openDb();
    }

    private void openDb() {
        if(db != null && db.isOpen()) { return; }
        synchronized (BibleReaderActivity.sDataLock) {
            try {
                String s = "SQLite format 3";
                byte[] b = new byte[s.length()];
                final int bytesRead = FileUtils.openInputStream(new File(DATABASE_PATH)).read(b);
                if(bytesRead == s.length() && s.equals(new String(b))) {
                    // Unencrypted
                    db = SQLiteDatabase.openDatabase(DATABASE_PATH, "", null, SQLiteDatabase.OPEN_READWRITE);    // Not an encrypted DB
                } else {
                    // Can we open it with the key?
                    db = SQLiteDatabase.openDatabase(DATABASE_PATH, "abc123", null, SQLiteDatabase.OPEN_READWRITE);
                }
            } catch (IOException e) {
                crashingCallHome("openDb()", e);
                System.exit(0);
            }
        }
    }

As you can see, I’m already synchronizing around the SQLiteDatabase.openDatabase() process. Since SQLLite is supposed to already be thread safe, there isn’t a point to synchronize each query call. Hope this helps. Let me know if there is any more I can do.

Guys, I don’t know how serious you are taking this, or if there is more that I can provide, but I am seeing about 4-5 crashes a day for Caused by: java.lang.IllegalStateException: database not open when clearly the DB should already be open. It appears that this is happening specifically when the app is reloaded due to device rotation or task switching. I cannot reproduce it at all, but it is happening a lot.

Hi @theBlbDan — we have taken a brief look at this, but have not been unable to reproduce either issue.

That said, we’re wondering if its possible that this might not actually be a problem with SQLCipher, but simply caused by a threading issue. From your sample code, it appears that there is an AsyncTask running query logic. It doesn’t appear, however, that there is anything in place to prevent a race condition where the application gets an instance of the DataBaseHelper that is subsequently closed by the app restart. Consider this scenario:

1. Application uses DatabaseHelper.getInstance().
2. fetchHighightsByChapter() executes asynchronously and calls openDb().
3. openDb() calls isOpen(), which returns true, so the call proceeds and attempts to run a query
4. System rotates / restarts, onDestroy() is called, and thus the static DataBaseHelper.closeAllInstances()
5. The SQLiteDatabase instance db is closed, but the fetchHiglightsByChapter() call is already running using the db instance directly
6. SQLiteDatabase.rawQueryWithFactory() checks the state of the db handle before use internally, finds that it’s closed, and throws an InvalidStateException: database not opened (see https://github.com/sqlcipher/android-database-sqlcipher/blob/master/src/net/sqlcipher/database/SQLiteDatabase.java#L1760)

As far as we are aware, AsyncTasks are not guaranteed to end in a timely manner following onDestroy unless explicitly cancelled by the application.

This same scenario would plausibly explain the original exception you were seeing (library routine called out of sequence). Consider the same flow, but where the db instance is closed by onDestroy after the isOpen() check executes in SQLiteDatabase.rawQueryWithFactory(). In that case, instead of getting a specific InvalidStateExeception thrown by the java wrapper, you’d instead expect a misuse exception, because the closed database handle would be passed to the native sqlite3 functions. SQLITE_MISUSE occurs any time an sqlite3 API call is made using a database handle that has previously been closed by sqlite3_close() — see http://www2.sqlite.org/cvstrac/wiki?p=LibraryRoutineCalledOutOfSequence https://www.sqlite.org/rescode.html#misuse for more information on this.

Thus, it seems at least possible that both issues could be caused by a race condition resulting from the threading model and the way the application handles database connections on restart. Without reports of this issue from other developers, or the ability to reliably reproduce this in a test case, it is really difficult for us proceed further.

The fact that you started to see this after upgrading to 3.5.x is a curious data point, but perhaps not conclusive. Out of curiosity, were there any other application changes that were made in the same release? Have you considered an alternate model for handling database connections, or explicitly cancelling all running AsyncTasks when the activity is destroyed?

@sjlombardo, @developernotes,

Thank you for taking the time to read, research, and respond to this issue. As it likely is for any developer, this was a huge problem for our app due to the large number of customers being affected by it. It does appear that we may have created the problem our selves by misunderstanding an error being provided in LogCat about the databases not being properly closed. It made zero sense, since the error stated that either the database or a cursor was not properly closed.

We ran a full review of cursor access across the project and could not find an unclosed cursor. From this we deduced that it must be complaining that we’re not closing DB’s, so we assumed that we should close them inside the application’s onDestroy(). Obviously, this means every device rotation, which inherently is a lot of open() close(), which is not good. Older, slower devices were going to be severely impacted, but it caused the error to go away.

We allowed ourselves to be seduced by the lack of red in LogCat instead of continuing to research the problem. Based on your previous response about «AsyncTasks are not guaranteed to end in a timely manner … unless explicitly cancelled by the application,» it became obvious that we created the error conditions. We made a gross, noob mistake and I cannot even fathom how we got there, since we should have known better. Somehow, when we created out singleton class, we failed to extend SQLiteOpenHelper, which was the cause for the initial errors.

So, after all of this, I wanted to say thank you for 1) All the work you are doing for the Android community by providing SQLCipher, & 2) your continued patience in providing valuable feedback to the community, even when the problem lies in their court.

Hello @theBlbDan — thanks so much for the kind words, and for letting us know this issue is resolved now!

Code: Select all

const
  IB_MAX_EVENT_BLOCK = 15;   // maximum events handled per block by InterBase
  IB_MAX_EVENT_LENGTH = 64;  // maximum event name length
  {$IFDEF LINUX}
  INFINITE = $FFFFFFFF;
  {$ENDIF}

//error it's the bottom line
{$IFDEF VER140BELOW}
  INFINITE = $FFFFFFFF;
  {$ENDIF}


threadvar
  FStatusVector: TARRAY_ISC_STATUS; 

Code: Select all

procedure Tfrm_depart.FormCreate%u28Sender%u3a TObject%u29;
begin

//Création du fichier log pour tracer les éventuelles erreurs
assignfile%u28log,ExtractFilePath%u28Application.ExeName%u29 + 'athletes.log'%u29;
rewrite%u28log%u29;

writeln%u28log,'********** ENTREE DANS LA PROCEDURE FORMCREATE ***********'%u29;  

Code: Select all

  
  try
    begin
      ZConnectionSQL.Disconnect;
      Path := ExtractFilePath(Application.exename);
      ZConnectionSQL.Database := Path + 'playa.sqlite';
      ZConnectionSQL.Connect;
    end;
  except
    MessageDlg('Error!!', mtWarning, [mbOK], 0);
  end;