Sqlite connection hangs then terminates when service is started using sqlite DB?

[ra0x3]

• We offer Sqlite support
• However, when attempting to start the service using sqlite the service seems to hang, and then fail with the error below
• This no doubt broke some time ago but has gone missing since we don't have e2e tests for sqlite
• We should split e2e tests out by database and feature flag each

➜  fuel-indexer git:(1fb92f1) SQLX_OFFLINE=1 cargo run --bin fuel-indexer -- --manifest fuel-indexer-tests/assets/fuel_indexer_test.yaml --database sqlite --sqlite-database /Users/rashad/Development/repos/fuel-indexer/fuel-indexer-tests/test.db
   Compiling tokio v1.22.0
   Compiling backtrace v0.3.66
   Compiling clap v3.2.23
   Compiling fuel-tx v0.23.1
   Compiling graphql-parser v0.3.0
   Compiling cranelift-codegen v0.82.3
   Compiling tracing-subscriber v0.2.25
   Compiling wasmer-types v2.3.0
   Compiling cynic-codegen v1.0.0
   Compiling fuel-vm v0.22.4
   Compiling wasmer-compiler v2.3.0
   Compiling tokio-rustls v0.23.4
   Compiling tokio-stream v0.1.11
   Compiling wasmer-artifact v2.3.0
   Compiling wasmer-object v2.3.0
   Compiling sqlx-rt v0.6.2
   Compiling wasmer-vm v2.3.0
   Compiling tokio-util v0.7.4
   Compiling fuel-indexer-lib v0.1.6 (/Users/rashad/Development/repos/fuel-indexer/fuel-indexer-lib)
   Compiling fuels-types v0.30.0
   Compiling sqlx-core v0.6.2
   Compiling deadpool v0.7.0
   Compiling tower v0.4.13
   Compiling tokio-io-timeout v1.2.0
   Compiling tokio-rustls v0.22.0
   Compiling wasmer-engine-universal-artifact v2.3.0
   Compiling http-client v6.5.3
   Compiling h2 v0.3.15
   Compiling fuels-core v0.30.0
   Compiling wasmer-engine v2.3.0
   Compiling surf v2.3.2
   Compiling tower-http v0.3.4
   Compiling wasmer-engine-universal v2.3.0
   Compiling fuel-indexer-types v0.1.6 (/Users/rashad/Development/repos/fuel-indexer/fuel-indexer-types)
   Compiling wasmer-engine-dylib v2.3.0
   Compiling cynic-proc-macros v1.0.0
   Compiling cynic v1.0.0
   Compiling cranelift-frontend v0.82.3
   Compiling hyper v0.14.23
   Compiling wasmer-compiler-cranelift v2.3.0
   Compiling wasmer v2.3.0
   Compiling hyper-rustls v0.22.1
   Compiling hyper-timeout v0.4.1
   Compiling hyper-rustls v0.23.1
   Compiling axum v0.5.17
   Compiling eventsource-client v0.10.2
   Compiling fuel-gql-client v0.14.1
   Compiling sqlx-macros v0.6.2
   Compiling sqlx v0.6.2
   Compiling fuel-indexer-postgres v0.1.6 (/Users/rashad/Development/repos/fuel-indexer/fuel-indexer-database/postgres)
   Compiling fuel-indexer-sqlite v0.1.6 (/Users/rashad/Development/repos/fuel-indexer/fuel-indexer-database/sqlite)
   Compiling fuel-indexer-database v0.1.6 (/Users/rashad/Development/repos/fuel-indexer/fuel-indexer-database)
   Compiling fuel-indexer-schema v0.1.6 (/Users/rashad/Development/repos/fuel-indexer/fuel-indexer-schema)
   Compiling fuel-indexer-api-server v0.1.6 (/Users/rashad/Development/repos/fuel-indexer/fuel-indexer-api-server)
   Compiling fuel-indexer v0.1.6 (/Users/rashad/Development/repos/fuel-indexer/fuel-indexer)
    Finished dev [unoptimized + debuginfo] target(s) in 51.17s
     Running `target/debug/fuel-indexer --manifest fuel-indexer-tests/assets/fuel_indexer_test.yaml --database sqlite --sqlite-database /Users/rashad/Development/repos/fuel-indexer/fuel-indexer-tests/test.db`
Nov 28 16:20:03.247  INFO fuel_indexer: Configuration: IndexerConfig { fuel_node: FuelNodeConfig { host: "127.0.0.1", port: "4000" }, graphql_api: GraphQLConfig { host: "127.0.0.1", port: "29987", run_migrations: None }, database: SqliteConfig { path: "/Users/rashad/Development/repos/fuel-indexer/fuel-indexer-tests/test.db" }, metrics: false }
Nov 28 16:20:03.250  INFO sqlx::query: PRAGMA foreign_keys = ON; …; rows affected: 0, rows returned: 0, elapsed: 93.578µs

PRAGMA foreign_keys = ON;

Nov 28 16:20:03.254  INFO sqlx::query: CREATE TABLE IF NOT …; rows affected: 0, rows returned: 0, elapsed: 669.571µs

CREATE TABLE IF NOT EXISTS _sqlx_migrations (
  version BIGINT PRIMARY KEY,
  description TEXT NOT NULL,
  installed_on TIMESTAMP NOT NULL DEFAULT CURRENT_TIMESTAMP,
  success BOOLEAN NOT NULL,
  checksum BLOB NOT NULL,
  execution_time BIGINT NOT NULL
);

Nov 28 16:20:03.256  INFO sqlx::query: SELECT version FROM _sqlx_migrations …; rows affected: 0, rows returned: 0, elapsed: 708.705µs

SELECT
  version
FROM
  _sqlx_migrations
WHERE
  success = false
ORDER BY
  version
LIMIT
  1

Nov 28 16:20:03.257  INFO sqlx::query: SELECT version, checksum FROM …; rows affected: 0, rows returned: 2, elapsed: 115.404µs

SELECT
  version,
  checksum
FROM
  _sqlx_migrations
ORDER BY
  version

Nov 28 16:20:03.258  INFO fuel_indexer: Subscribing to Fuel node at 127.0.0.1:4000
Nov 28 16:20:03.259  INFO sqlx::query: PRAGMA foreign_keys = ON; …; rows affected: 0, rows returned: 0, elapsed: 20.979µs

PRAGMA foreign_keys = ON;

Nov 28 16:20:03.259  INFO fuel_indexer: Using bootstrap manifest file located at 'fuel-indexer-tests/assets/fuel_indexer_test.yaml'
Nov 28 16:20:03.262  INFO sqlx::query: PRAGMA foreign_keys = ON; …; rows affected: 0, rows returned: 0, elapsed: 23.636µs

PRAGMA foreign_keys = ON;

Nov 28 16:20:03.262  INFO sqlx::query: BEGIN; rows affected: 0, rows returned: 0, elapsed: 26.050µs
Nov 28 16:20:03.264  INFO sqlx::query: SELECT * FROM index_registry …; rows affected: 0, rows returned: 0, elapsed: 784.412µs

SELECT
  *
FROM
  index_registry
WHERE
  namespace = 'fuel_indexer_test'
  AND identifier = 'index1'

Nov 28 16:20:03.265  INFO sqlx::query: INSERT INTO index_registry (namespace, …; rows affected: 1, rows returned: 1, elapsed: 306.083µs

INSERT INTO
  index_registry (namespace, identifier)
VALUES
  ('fuel_indexer_test', 'index1') RETURNING *

Nov 28 16:20:03.266  INFO sqlx::query: SELECT count(*) as num …; rows affected: 0, rows returned: 1, elapsed: 459.633µs

SELECT
  count(*) as num
FROM
  graph_registry_type_ids
WHERE
  schema_name = 'fuel_indexer_test'
  AND schema_version = 'd7381f65aa9c83306bd225120853605c0e7c15aaedc154262a0df26ebe73f4ac'

thread 'main' panicked at 'Failed to build new schema: error returned from database: (code: 5) database is locked', /Users/rashad/Development/repos/fuel-indexer/fuel-indexer-schema/src/db/manager.rs:36:41
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

[deekerno]

Work can be tracked in the deekerno/369-sqlite-why-hast-thou-forsaken-us branch.

Dumping some data here:

• Code 5 correlates to SQLITE_BUSY. This generally indicates that there is a conflict with a database connection in a separate process. I've disabled anything that automatically calls database environment variables (read: rust-analyzer) and tried again with a fresh DB to no avail. I've also created DB files outside of the repository and instructed the indexer to use them by including the full path; no success there either.
• The offending query can be found in the new_graph_root SQLite query. This is called as part of schema creation, which happens directly after index registration, but prior to any asset execution or registration.
• A number of issues on the SQLx project have also run into similar problems with SQLite; they recommended a number of different configuration options that should be tried when connecting to the SQLite database. To that end, I've adjusted the connection behavior to allow for options to be passed to our databases, which also allows for us to offer functionality for users down the line. In any case, here are the options that I've tried with no success:
  • Using the Write-Ahead Log (WAL): generally speaking, this allows for multiple readers, but only one writer
  • Setting max_connections of the pool to 1
  • Increasing the busy timeout: this should allow more time for the connection to check if the DB is no longer busy
  • Setting synchronous to Full: this instructs SQLite to flush to disk less often

[deekerno]

Update:

• Through some research, I've found that fetch_one() doesn't wait for the underlying query to run to completion; see sqlite misses database updates when program closes shortly afterwards launchbadge/sqlx#1760 (comment) for more information. This means that for certain queries, the connection isn't returned to the pool as quickly as it should be; this is probably one of the causes of our database locking. I'm going to try a couple of things: connection closing or limiting returned rows where possible; the former would force the pool to create a new connection while the latter should hopefully cause SQLITE_DONE to be sent to sqlx's executor.
• While debugging pool connections, I found that max_connections() wasn't being respected for SQLite. This is because multiple pools were being created across the indexer. As such, I've cleaned up pool usage to be more in line with the use case of a pool (see Fix pool usage across the indexer #403).
• After fixing pool usage and forcing SQLite to use only one connection, it seems that the service now hangs directly after the register_index query in which we INSERT namespace and identifier details into the database; however, the hang is due to a PoolTimeout rather than database locking. This is in line with what I would expect with the use of fetch_one, so hopefully either of the aforementioned approaches work and allow the service to move forward.

[deekerno]

Another update:

• Switching from fetch_one() to fetch() to force statements to run to completion did not yield any successful outcomes; it still hangs on the new_graph_root() SQLite query.
• @ra0x3 and I have already discussed this, but it may be prudent to put SQLite functionality behind a feature flag for now while we figure out what's going on here.
• Last resort: Implementing the SQLite part of IndexerConnectionPool as a combination of a reader pool and a writer pool, as recommended in SQLite Code 5 Database Is Locked launchbadge/sqlx#451. This may not actually work and could just move the problem to a query further in the schema building process.

I'll pick this back up after we complete some other tasks.