sqlite misses database updates when program closes shortly afterwards

[dc25]

This may be the same issue as : SQLite backend does not close database (which was closed 2 years ago).

This program adds an item to the database and then either exits or sleeps a little and then exits. If the sleep happens then the database gets properly inserted into but with no sleep, the insert does not seem to happen. Use command line option "-s" to choose to sleep. This seems to be most reproducible on linux but I saw it happen on windows as well. Also -wal and -shm files remain after the program runs ( is that a problem? ).

use structopt::StructOpt;
use sqlx::sqlite::SqlitePool;
use std::{thread, time};


#[derive(StructOpt)]
struct Opt {
    #[structopt(short = "s")]
    sleep: bool
}


#[tokio::main]
async fn main() -> Result<(), sqlx::Error> {
  let opts = Opt::from_args();
  let pool = SqlitePool::connect("sqlite://test.db").await?;

  {
      let mut conn = pool.acquire().await?;

      // Create a table if not existing
      sqlx::query(
        r#"
        CREATE TABLE IF NOT EXISTS contacts (
          contact_id INTEGER PRIMARY KEY,
          name TEXT NOT NULL
        );"#
      )
      .execute(&mut conn)
      .await?;
  }

  {
      let mut conn = pool.acquire().await?;
      // insert some new data
      let res: (i64, ) = sqlx::query_as("insert into contacts (name) values ($1) returning contact_id")
          .bind("JamesBond")
          .fetch_one(&mut conn)
          .await?;
      println!("With sleep = {:?}, Inserted contact id: {:?}", opts.sleep, res.0);
  }


  // Things start to go wrong when this sleep is removed
  if opts.sleep {
      thread::sleep(time::Duration::from_millis(1));
  }

  Ok(())
}

Below is a transcript. Note that with the -s option, new records get inserted but that stops happening without the -s

dave@2022-02-16--w--ub2110:/repos/gitnc/sqlx_bug_demo$ !1322
sqlite3 test.db "VACUUM;"
dave@2022-02-16--w--ub2110:/repos/gitnc/sqlx_bug_demo$ cargo run -s
error: Found argument '-s' which wasn't expected, or isn't valid in this context

USAGE:
    cargo run [OPTIONS] [--] [args]...

For more information try --help
dave@2022-02-16--w--ub2110:/repos/gitnc/sqlx_bug_demo$ cargo run -- -s
    Finished dev [unoptimized + debuginfo] target(s) in 0.27s
     Running `target/debug/sqlx_bug_demo -s`
With sleep = true, Inserted contact id: 1
dave@2022-02-16--w--ub2110:/repos/gitnc/sqlx_bug_demo$ cargo run -- -s
    Finished dev [unoptimized + debuginfo] target(s) in 0.29s
     Running `target/debug/sqlx_bug_demo -s`
With sleep = true, Inserted contact id: 2
dave@2022-02-16--w--ub2110:/repos/gitnc/sqlx_bug_demo$ cargo run -- -s
    Finished dev [unoptimized + debuginfo] target(s) in 0.30s
     Running `target/debug/sqlx_bug_demo -s`
With sleep = true, Inserted contact id: 3
dave@2022-02-16--w--ub2110:/repos/gitnc/sqlx_bug_demo$ cargo run -- -s
    Finished dev [unoptimized + debuginfo] target(s) in 0.30s
     Running `target/debug/sqlx_bug_demo -s`
With sleep = true, Inserted contact id: 4
dave@2022-02-16--w--ub2110:/repos/gitnc/sqlx_bug_demo$ cargo run -- -s
    Finished dev [unoptimized + debuginfo] target(s) in 0.30s
     Running `target/debug/sqlx_bug_demo -s`
With sleep = true, Inserted contact id: 5
dave@2022-02-16--w--ub2110:/repos/gitnc/sqlx_bug_demo$ cargo run -- -s
    Finished dev [unoptimized + debuginfo] target(s) in 0.30s
     Running `target/debug/sqlx_bug_demo -s`
With sleep = true, Inserted contact id: 6
dave@2022-02-16--w--ub2110:/repos/gitnc/sqlx_bug_demo$ cargo run -- -s
    Finished dev [unoptimized + debuginfo] target(s) in 0.28s
     Running `target/debug/sqlx_bug_demo -s`
With sleep = true, Inserted contact id: 7
dave@2022-02-16--w--ub2110:/repos/gitnc/sqlx_bug_demo$ cargo run -- -s
    Finished dev [unoptimized + debuginfo] target(s) in 0.29s
     Running `target/debug/sqlx_bug_demo -s`
With sleep = true, Inserted contact id: 8
dave@2022-02-16--w--ub2110:/repos/gitnc/sqlx_bug_demo$ cargo run
    Finished dev [unoptimized + debuginfo] target(s) in 0.29s
     Running `target/debug/sqlx_bug_demo`
With sleep = false, Inserted contact id: 9
dave@2022-02-16--w--ub2110:/repos/gitnc/sqlx_bug_demo$ cargo run
    Finished dev [unoptimized + debuginfo] target(s) in 0.29s
     Running `target/debug/sqlx_bug_demo`
With sleep = false, Inserted contact id: 9
dave@2022-02-16--w--ub2110:/repos/gitnc/sqlx_bug_demo$ cargo run
    Finished dev [unoptimized + debuginfo] target(s) in 0.29s
     Running `target/debug/sqlx_bug_demo`
With sleep = false, Inserted contact id: 9
dave@2022-02-16--w--ub2110:/repos/gitnc/sqlx_bug_demo$ cargo run
    Finished dev [unoptimized + debuginfo] target(s) in 0.29s
     Running `target/debug/sqlx_bug_demo`
With sleep = false, Inserted contact id: 9
dave@2022-02-16--w--ub2110:/repos/gitnc/sqlx_bug_demo$ cargo run
    Finished dev [unoptimized + debuginfo] target(s) in 0.29s
     Running `target/debug/sqlx_bug_demo`
With sleep = false, Inserted contact id: 9
dave@2022-02-16--w--ub2110:/repos/gitnc/sqlx_bug_demo$ cargo run
    Finished dev [unoptimized + debuginfo] target(s) in 0.30s
     Running `target/debug/sqlx_bug_demo`
With sleep = false, Inserted contact id: 9
dave@2022-02-16--w--ub2110:/repos/gitnc/sqlx_bug_demo$ sqlite3 test.db
SQLite version 3.35.5 2021-04-19 18:32:05
Enter ".help" for usage hints.
sqlite> select * from contacts;
1|JamesBond
2|JamesBond
3|JamesBond
4|JamesBond
5|JamesBond
6|JamesBond
7|JamesBond
8|JamesBond
sqlite>

dave@2022-02-16--w--ub2110:/repos/gitnc/sqlx_bug_demo$

I'm using sqlx 0.5.11 .
Here's my Cargo.toml

[package]
name = "sqlx_bug_demo"
version = "0.1.0"
edition = "2021"

# See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html

[dependencies]
sqlx = { version = "0.5.11", features = ["runtime-tokio-rustls", "sqlite"] }
structopt = "0.3.26"
tokio = { version = "1.17.0", features = ["full"] }

And here's a repo with the bug demo: https://github.com/dc25/sqlx_bug_demo

[dc25]

This may be related to the use of query_as() . The symptom does not reproduce using query() instead. Here's a version of the demo code with query() and query_as() (commented out).

This demo version does not use SqlitePool . This simplifies the code a little but had no effect on the symptom.

use structopt::StructOpt;
use sqlx::prelude::Connection;
use std::{thread, time};


#[derive(StructOpt)]
struct Opt {
    #[structopt(short = "s")]
    sleep: bool
}


#[tokio::main]
async fn main() -> Result<(), sqlx::Error> {
  let opts = Opt::from_args();

  let mut conn = sqlx::SqliteConnection::connect("sqlite://test.db").await?;

  // Create a table if not existing
  sqlx::query(
    r#"
    CREATE TABLE IF NOT EXISTS contacts (
      contact_id INTEGER PRIMARY KEY,
      name TEXT NOT NULL
    );"#
  )
  .execute(&mut conn)
  .await?;

  // insert some new data

  // This does not work without sleep
  /*
  let _res: (i64, ) = sqlx::query_as("insert into contacts (name) values ($1) returning contact_id")
      .bind("JamesBond")
      .fetch_one(&mut conn)
      .await?;
  */

  // This works without sleep.
  sqlx::query("insert into contacts (name) values ($1) returning contact_id")
      .bind("Houdini")
      .execute(&mut conn)
      .await?;

  // Things start to go wrong when this sleep is removed
  if opts.sleep {
      thread::sleep(time::Duration::from_millis(1));
  }

  Ok(())
}

[abonander]

It's not query_as, it's .fetch_one(), which doesn't run the SQLite statement to completion. It gets the first result row and immediately returns, but SQLite probably would rather have us run sqlite3_step() until we actually get SQLITE_DONE as it may still have some work to do.

This was a design decision we made early on as polling for a second row if the query wasn't limited would make the operation take basically twice as long as it should, but that was more for client/server database like Postgres where the server pushes rows to us as it fetches them.

The worker does reset the statement when it's done which should make sure the results are committed, but without that sleep() there your program exits immediately and doesn't give it time to do that.

If you end your program with conn.close().await it should make sure the results are correctly written to disk.

[dc25]

Thank you. That makes sense and yes, adding the .close() does seem to get rid of the symptom. It would be nice if there was some automated way to do this as it is unintuitive and the new user may not be able to figure it out w/o talking to an expert.

Even with the close(), the "-shm" file remains in place. Is that anything to be concerned about?

[abonander]

Because this is async land we can't do blocking drops like the I/O handles in std can. We have a few places where we spawn a task on-drop to execute some cleanup in the background but running background tasks won't keep #[tokio::main] from exiting which is a deliberate design decision on their part: tokio-rs/tokio#1703

It's really just something you need to be aware of.

As for the -shm file, it's supposed to be deleted when the database handle is closed, so I'm not sure why it's not in your case. However, it's just a temporary file used to implement shared memory in a crossplatform fashion so you can safely delete it if your application isn't running.

[dc25]

Darn. Well, thank you for thinking about it and for responding.