drift icon indicating copy to clipboard operation
drift copied to clipboard

database is locked error with WAL journal mode

Open albe-jj opened this issue 1 year ago • 7 comments

Note: I activated WAL journal mode on the sql database.

In my flutter application when trying to insert a specific entry into the database I get the error below. I can insert other entries in the database before and after getting this error but every time I try to insert this specific entry it throws the error below. I'm using one single database connection for all insert operations. When restarting the flutter app then I can insert the specific entry to the database without any problem.

In summary it appears that the database (set in WAL mode) is locked only for the insertion of this specific entry and after reconnecting to the database i can insert the entry without any problem.

SqliteException(5): while executing statement, database is locked, database is locked (code 5)
  Causing statement: INSERT INTO "datasets" ("uuid", "alt_uid", "collected", "created", "modified", "name", "scope_id", "creator", "description", "keywords", "search_helper", "ranking", "synchronized") VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?), parameters: 16896f843dfc4f31901cef9ec5f1e989, null, 2024-05-30 16:10:23.818075, 2024-05-30 16:10:24.665727, 2024-05-30 16:10:37.462207, 2D_Sweep_0D_param_test, 14, sphilips, null, [], 16896f84-3dfc-4f31-901c-ef9ec5f1e989 2D_Sweep_0D_param_test, 0, 1
#0   package:sqlite3/src/implementation/exception.dart 75               throwException
#1   package:sqlite3/src/implementation/statement.dart 109              StatementImplementation._execute
#2   package:sqlite3/src/implementation/statement.dart 289              StatementImplementation.executeWith
#3   package:sqlite3/src/statement.dart 72                              CommonPreparedStatement.execute
#4   package:drift/src/sqlite3/database.dart 149                        Sqlite3Delegate.runWithArgsSync
#5   package:drift/native.dart 332                                      _NativeDelegate.runInsert.<fn>
#6   package:drift/native.dart 331                                      _NativeDelegate.runInsert
#7   package:drift/src/runtime/executor/helpers/engines.dart 105        _BaseExecutor.runInsert.<fn>

albe-jj avatar Jun 04 '24 15:06 albe-jj

Well, what's the specific entry? It's pretty weird that the database is only locked with the one particular row though. Also, are you sure it's related to the entry and not something like "the first 5 inserts work and then this happens"?

simolus3 avatar Jun 05 '24 09:06 simolus3

In the case above the insert that failed was INSERT INTO "datasets" ("uuid", "alt_uid", "collected", "created", "modified", "name", "scope_id", "creator", "description", "keywords", "search_helper", "ranking", "synchronized") VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?), parameters: 16896f843dfc4f31901cef9ec5f1e989, null, 2024-05-30 16:10:23.818075, 2024-05-30 16:10:24.665727, 2024-05-30 16:10:37.462207, 2D_Sweep_0D_param_test, 14, sphilips, null, [], 16896f84-3dfc-4f31-901c-ef9ec5f1e989

But i get this randomly every say 500 inserts, for different datasets entries I try to insert.

I can insert other dataset entries before and after getting "database locked error when inserting dataset X", to be able to insert database X into the database i need to restart the application. If I don't restart the application I can still insert other datasets but every time I try to insert dataset X i get "database locked" error.

The application is running on windows desktop app.

Let me know if there is any useful test I could do to debug this.

albe-jj avatar Jun 05 '24 12:06 albe-jj

I managed to systematically reproduce the error with the following code.

void main() async {

  final db = MyDb('test_db.sql');
  final db2 = MyDb('test_db.sql');

  final futures = [];
  for (int i=0; i<100; i++) {
    futures.add(db.into(db.datasets).insert(createRandomDataset(scopeId: 1)));
    futures.add(db2.into(db2.datasets).insert(createRandomDataset(scopeId: 1)));
    print('insert: $i');
  }

  for (var f in futures) {
    await f;
  }

  // await Future.delayed(const Duration(seconds: 10));
  await db.close();
  await db2.close();
}

I set the database WAL mode like this:

  @override
  MigrationStrategy get migration => MigrationStrategy(
        beforeOpen: (details) async {
          await customStatement('PRAGMA journal_mode=WAL'); //TO enable access from multiple processes
        },
      );

I have most recent dependencies

dependencies:
  drift: ^2.18.0
  sqlite3_flutter_libs: ^0.5.0
  path_provider: ^2.0.0
  path: ^1.9.0

dev_dependencies:
  drift_dev: ^2.18.0
  build_runner: ^2.4.9

and running latest dart sdk Dart SDK version: 3.4.1 (stable) and stable flutter: 3.22.1

Let me know if there is something wrong from my side.

albe-jj avatar Jun 06 '24 08:06 albe-jj

Do you have multiple concurrent writers in your real application as well? WAL only allows concurrent reads and a single writer. Two concurrent writers will still cause lock errors with WAL. If that's the problem you could try setting the busy_timeout pragma which will make sqlite3 sleep and retry the operation shortly afterwards if a lock is active. That can reduce the likelihood of the error, a proper solution is to coordinate access between the two databases to avoid concurrent writers (doable with drift, I can provide more pointers on this if that turns out to be the root cause, but it gets much harder if one of the databases is opened natively and not from Dart).

simolus3 avatar Jun 06 '24 21:06 simolus3

I'm having similar issue and even with WAL and busy_timeout, the write does not succeed.

Here's the setup:

return NativeDatabase(
  File(dbPath),
  setup: (db) {
    // Check that we're actually running with SQLCipher by querying the
    // cipher_version pragma.
    final result = db.select('pragma cipher_version');
    if (result.isEmpty) {
      throw UnsupportedError(
        'This database needs to run with SQLCipher, but that library is '
        'not available!',
      );
    }

    db
      // Set the database password.
      ..execute("pragma key = '${credentials.databasePass}'")
      ..execute('pragma journal_mode=WAL;')
      ..execute('pragma synchronous=normal;')
      ..execute('pragma busy_timeout=500;')

      // Test that the key is correct by selecting from a table.
      ..execute('select count(*) from sqlite_master');
  },
);
});

After struggling with this issue I came up with a following wrapper for write operations, but it still tends to fail :/ There may be multiple write operations happening but they should not take more than few hundred milliseconds. Even though waiting for 2-3 seconds doesn't help.

  /// Generic function to retry a query that might fail due to
  /// [SqliteException] e.g. when database is locked.
  Future<T> retry<T>(Future<T> Function() computation) async {
    var retryCount = 0;

    while (retryCount < 5) {
      try {
        final rs = await computation();
        if (retryCount > 0) {
          _log.i('Successfully recovered from database access issue');
        }
        return rs;
      } catch (e, s) {
        if (e is DriftRemoteException || e is SqliteException) {
          if (retryCount == 5) {
            _log.e('Did not manage to recover the database despite retrying');
            Error.throwWithStackTrace(e, s);
          }
          if (retryCount == 4) {
            // Last chance to fix the access issue, let's close the connection
            // and try to reconnect
            _log.w('Closing database to recover from access issue');
            await _bgDatabase?.close();
            _bgDatabase = null;
          }
          retryCount++;
          _log.w('Problem with accessing the database, retry $retryCount', e);
        } else {
          Error.throwWithStackTrace(e, s);
        }
      }
      await Future<void>.delayed(const Duration(milliseconds: 300));
    }
    throw Exception('Did not manage to recover the database despite retrying');
  }

And example operation:

2024-11-12T15:08:29.605541Z +4 W [ALDC] SqliteException(5): while executing statement, database is locked, database is locked (code 5)
2024-11-12T15:08:29.605935Z +4 W [ALDC]   Causing statement: INSERT OR IGNORE INTO "average_heart_rate" ("timestamp", "heart_rate", "source") VALUES (?, ?, ?), parameters: 1731384000000, 92, local
2024-11-12T15:08:29.605993Z +4 W [ALDC] Problem with accessing the database, retry 2
2024-11-12T15:08:30.923184Z +5 W [ALDC] SqliteException(5): while executing statement, database is locked, database is locked (code 5)
2024-11-12T15:08:30.923242Z +5 W [ALDC]   Causing statement: INSERT OR IGNORE INTO "average_heart_rate" ("timestamp", "heart_rate", "source") VALUES (?, ?, ?), parameters: 1731384000000, 92, local
2024-11-12T15:08:30.923246Z +5 W [ALDC] Problem with accessing the database, retry 3
2024-11-12T15:08:31.840791Z +6 I [AppLifecycleHandler] App state changed to AppLifecycleState.inactive, last action was 2024-11-12 15:08:25.808535
2024-11-12T15:08:32.231507Z +6 W [ALDC] SqliteException(5): while executing statement, database is locked, database is locked (code 5)
2024-11-12T15:08:32.231714Z +6 W [ALDC]   Causing statement: INSERT OR IGNORE INTO "average_heart_rate" ("timestamp", "heart_rate", "source") VALUES (?, ?, ?), parameters: 1731384000000, 92, local
2024-11-12T15:08:32.231743Z +6 W [ALDC] Problem with accessing the database, retry 4
2024-11-12T15:08:33.546673Z +8 W [ALDC] Closing database to recover from access issue
2024-11-12T15:08:33.549480Z +8 W [ALDC] SqliteException(5): while executing statement, database is locked, database is locked (code 5)
2024-11-12T15:08:33.549885Z +8 W [ALDC]   Causing statement: INSERT OR IGNORE INTO "average_heart_rate" ("timestamp", "heart_rate", "source") VALUES (?, ?, ?), parameters: 1731384000000, 92, local
2024-11-12T15:08:33.549918Z +8 W [ALDC] Problem with accessing the database, retry 5
2024-11-12T15:08:33.855383Z +8 E [] Exception: Did not manage to recover the database despite retrying
2024-11-12T15:08:33.855605Z +8 E [] #0   AverageHrDatabaseClient.retry (package:local_database_client/src/average_hr_database_client.dart:74)
2024-11-12T15:08:33.855638Z +8 E [] #1   <asynchronous suspension>
2024-11-12T15:08:33.855659Z +8 E [] #2   HeartRateDataRepository.syncAverageHeartRate (package:heart_rate_data_repository/src/heart_rate_data_repository.dart:158)
2024-11-12T15:08:33.855692Z +8 E [] #3   <asynchronous suspension>
2024-11-12T15:08:33.855713Z +8 E [] #4   HeartRateSyncCubit.processHrData (package:visible_app/pace_points/cubit/heart_rate_sync_cubit.dart:150)
2024-11-12T15:08:33.855811Z +8 E [] #5   <asynchronous suspension>
2024-11-12T15:08:33.855834Z +8 E [] #6   HeartRateSyncCubit.onLifecycleResumed.<anonymous closure> (package:visible_app/pace_points/cubit/heart_rate_sync_cubit.dart:99)
2024-11-12T15:08:33.855858Z +8 E [] #7   <asynchronous suspension>
2024-11-12T15:08:33.855885Z +8 E [] Received error from Flutter in PlatformDispatcher.onError

orestesgaolin avatar Nov 13 '24 08:11 orestesgaolin

Are you using long-running transactions anywhere? If you have a way to reproduce this, it might be helpful to enable statement logging across all isolates using the database to see why the database is locked for so long.

simolus3 avatar Nov 13 '24 10:11 simolus3

I solved it by running the PRAGMA statements with the native client, instead of the drizzle client.

secure12 avatar May 22 '25 14:05 secure12