Intermittent sqlite error after upgrade from 0.5.5 to 0.5.7

[06chaynes]

I am seeing an odd intermittent issue after upgrading from version 0.5.5. I have a number of queries using the sqlx::query function that run in sequence and after the upgrade I see the following error seemingly at random:

thread '<unnamed>' panicked at 'unable to close due to unfinalized statements or unfinished backups', .cargo/registry/src/github.com-1ecc6299db9ec823/sqlx-core-0.5.7/src/sqlite/connection/handle.rs:68:17

If I downgrade back to version 0.5.5 I no longer experience this issue. I have the following features enabled: "runtime-tokio-native-tls", "sqlite", "migrate". Version of SQLite is 3.31.1-4ubuntu0.2 amd64, running on Ubuntu Focal.

For now running version 0.5.5 allows me to continue so it's not critical but I wanted to make sure an issue was opened. If any more details are required, or if I can help troubleshoot further please let me know what's needed and I'd be happy to help if possible.

[abonander]

I actually have no idea what's causing this. Obviously it's a ConnectionHandle getting dropped while some StatementHandle still exists, but I have no idea how.

For one, we make sure to clear all the virtual statements in SqliteConnection::drop(): https://github.com/launchbadge/sqlx/blob/master/sqlx-core/src/sqlite/connection/mod.rs#L105

The comment reminded me that drop order is not defined, but either way it shouldn't be an issue:

If handle: ConnectionHandle is dropped first, that should be fine, as that uses an Arc and sends a strong reference to the statement worker thread to make sure it's dropped last: https://github.com/launchbadge/sqlx/blob/master/sqlx-core/src/sqlite/statement/worker.rs#L79

The crossbeam-channel docs specify that even if all the senders have gone away (so the Sender in the StatementWorker struct getting dropped), the receiver should still be able to empty the channel of messages and thus work through all the remaining StatementHandles that might be queued.

I could see this panic happening if for some reason the thread we spawn in StatementWorker::new() dies prematurely, as that would leave StatementHandles in the channel, and then ConnectionHandle getting dropped before StatementWorker will trigger the panic.

However, the only way the statement worker thread would die first without consuming all the messages in the channel (barring a bug in crossbeam-channel) is by itself panicking; can you look back through your logs to find a panic with a different message?

[06chaynes]

I checked again to be sure and this is the only error I see at all unfortunately. I am going to try to recreate this in a stripped down project to make troubleshooting easier. I will update if I find anything out from that.

[abonander]

@06chaynes the full panic backtrace may also help. It couldn't hurt, at least.

[06chaynes]

thread '<unnamed>' panicked at 'unable to close due to unfinalized statements or unfinished backups', /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/sqlx-core-0.5.7/src/sqlite/connection/handle.rs:68:17
stack backtrace:
   0:     0x558300684bfa - std::backtrace_rs::backtrace::libunwind::trace::h34055254b57d8e79
                               at /rustc/a178d0322ce20e33eac124758e837cbd80a6f633/library/std/src/../../backtrace/src/backtrace/libunwind.rs:90:5
   1:     0x558300684bfa - std::backtrace_rs::backtrace::trace_unsynchronized::h8f1e3fbd9afff6ec
                               at /rustc/a178d0322ce20e33eac124758e837cbd80a6f633/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2:     0x558300684bfa - std::sys_common::backtrace::_print_fmt::h3a99a796b770c360
                               at /rustc/a178d0322ce20e33eac124758e837cbd80a6f633/library/std/src/sys_common/backtrace.rs:67:5
   3:     0x558300684bfa - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h32d1f94a80615d18
                               at /rustc/a178d0322ce20e33eac124758e837cbd80a6f633/library/std/src/sys_common/backtrace.rs:46:22
   4:     0x5583004f8ecc - core::fmt::write::h306731c068f7162c
                               at /rustc/a178d0322ce20e33eac124758e837cbd80a6f633/library/core/src/fmt/mod.rs:1110:17
   5:     0x558300683644 - std::io::Write::write_fmt::hd2fa90334eee2a21
                               at /rustc/a178d0322ce20e33eac124758e837cbd80a6f633/library/std/src/io/mod.rs:1588:15
   6:     0x558300683f25 - std::sys_common::backtrace::_print::h5abaa2601a852287
                               at /rustc/a178d0322ce20e33eac124758e837cbd80a6f633/library/std/src/sys_common/backtrace.rs:49:5
   7:     0x558300683f25 - std::sys_common::backtrace::print::h8d81445442bb638f
                               at /rustc/a178d0322ce20e33eac124758e837cbd80a6f633/library/std/src/sys_common/backtrace.rs:36:9
   8:     0x558300683f25 - std::panicking::default_hook::{{closure}}::hcfe804496a9fa747
                               at /rustc/a178d0322ce20e33eac124758e837cbd80a6f633/library/std/src/panicking.rs:208:50
   9:     0x558300683436 - std::panicking::default_hook::hbea8e3ccf2ba8901
                               at /rustc/a178d0322ce20e33eac124758e837cbd80a6f633/library/std/src/panicking.rs:225:9
  10:     0x558300683436 - std::panicking::rust_panic_with_hook::h7ee9e1a2d0f8975a
                               at /rustc/a178d0322ce20e33eac124758e837cbd80a6f633/library/std/src/panicking.rs:622:17
  11:     0x55830069c0cd - std::panicking::begin_panic_handler::{{closure}}::h8ab3b4491718b2c7
  12:     0x55830069c03c - std::sys_common::backtrace::__rust_end_short_backtrace::hd489062ffa586a9f
                               at /rustc/a178d0322ce20e33eac124758e837cbd80a6f633/library/std/src/sys_common/backtrace.rs:141:18
  13:     0x55830069bfed - rust_begin_unwind
                               at /rustc/a178d0322ce20e33eac124758e837cbd80a6f633/library/std/src/panicking.rs:515:5
  14:     0x55830042bca0 - std::panicking::begin_panic_fmt::h5479575e112541f8
                               at /rustc/a178d0322ce20e33eac124758e837cbd80a6f633/library/std/src/panicking.rs:457:5
  15:     0x558300672a04 - alloc::sync::Arc<T>::drop_slow::h5e9b78887050d417
  16:     0x55830067a4b9 - std::sys_common::backtrace::__rust_begin_short_backtrace::h5e11ff00e096ce1d
  17:     0x558300678691 - core::ops::function::FnOnce::call_once{{vtable.shim}}::hafdf47ca0c764638
  18:     0x5583006ad6d5 - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::h7ece6cfefaff1005
                               at /rustc/a178d0322ce20e33eac124758e837cbd80a6f633/library/alloc/src/boxed.rs:1575:9
  19:     0x5583006ad6d5 - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::hb8b48e55c21f193e
                               at /rustc/a178d0322ce20e33eac124758e837cbd80a6f633/library/alloc/src/boxed.rs:1575:9
  20:     0x5583006ad6d5 - std::sys::unix::thread::Thread::new::thread_start::h8c7c4450dba62914
                               at /rustc/a178d0322ce20e33eac124758e837cbd80a6f633/library/std/src/sys/unix/thread.rs:71:17
  21:     0x7f04d3330609 - start_thread
  22:     0x7f04d3102293 - clone
  23:                0x0 - <unknown>
Aborted (core dumped)

[abonander]

Frustratingly, that doesn't actually show where in non-stdlib code that the panic occurred. It looks like a bunch of inlining has happened here. Considering how shallow the stack is, though, I'm guessing that that is the worker thread panicking when it drops the ConnectionHandleRef: https://github.com/launchbadge/sqlx/blob/master/sqlx-core/src/sqlite/statement/worker.rs#L79

I'm still at a loss as to how this is happening, though. Any progress on that minimal reproduction? It would help to see how you're actually using SQLx.

[06chaynes]

Before I share this really strange looking example think I should share a bit of what led up to this. I started out with a sqlite pool limited to 1 connection but was running into issues, specifically I was seeing connection timeouts. This had me kind of stumped because it seemed no matter what I tried it would run into this connection error a crazy number of times.

So I modified things a bit more and ended up wrapping a SqliteConnection in a mutex and that in an arc, then would clone and wait for an owned lock, do the query, then drop that clone after it finished. This ended up working, though I did notice that after weeks of continuous operation I would see the connection timeout error a few times on some days. This program cycles every 30 seconds, so having an error that rarely isn't an issue for what we are doing.

After moving past v0.5.5 though I started getting the new error. This example can recreate the error at least, https://github.com/06chaynes/sqlxerr, not quite what I'm doing but apparently close enough!

[abonander]

With your example, I figured it out!

The issue is the books: Vec<SqliteRow>, as SqliteRow retains a strong reference to the StatementHandle which finalizes the inner sqlite3_stmt on-drop.

Since you're prematurely dropping the SqliteConnection with drop(conn), it's trying to finalize the sqlite3 instance before it finalizes the Vec<SqliteRow> and thus the sqlite3_stmts contained therin (as the normal drop order in a function is LIFO).

As a temporary fix on your end, make sure to drop books before conn. With that change, the panic no longer happens in your example.

The permanent fix here on our end is probably to retain a ConnectionHandleRef in the SqliteRow struct so the connection cannot be finalized prematurely, or even just in StatementHandle itself, maybe.

[06chaynes]

Ah! I didn't consider that at all, thank you. I'll make those changes as soon as possible and test again.

[definitelycarter]

I hit this error on version 0.5.9.

thread '<unnamed>' panicked at 'unable to close due to unfinalized statements or unfinished backups', /usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/sqlx-core-0.5.9/src/sqlite/connection/handle.rs:69:17

[06chaynes]

@definitelycarter do you have a code snippet that could reproduce the issue by chance?

[06chaynes]

@abonander looks like I am still encountering this error after all. After your comment I had made some changes so I was surprised to see the error pop up again in the logs.

Quick question on the matter, would active_recs in this example also retain a strong reference to the StatementHandle as you mentioned before?

let mut conn = db_conn.clone().lock_owned().await;
let active_recs = sqlx::query_as::<_, WatchModel>(&q)
     .fetch_all(&mut *conn)
     .await?;
drop(conn);

WatchModel here is a struct that derives FromRow

[abonander]

@06chaynes it shouldn't since the rows aren't kept alive past the connection.

I also have some major internal refactors on #1551 that also address this issue as well as some segfaults.

[06chaynes]

That's what I was thinking but wanted to be sure.

Sounds great, really looking forward to these changes!

[06chaynes]

Just to note, after testing your refactor against two of the issues mentioned and seeing it fixed them, I went ahead and rolled it out to a couple deployments I was seeing lock errors on. So far not a single error, things are looking good!

Edit: Did end up with a couple lock errors so will review things again soon