Nondeterministic `ErrorMisuse` on multiple runs of the same application test

[aryairani]

I know this is kind of a long shot to post here, but I'm kind of desperate. I have an application written on top of sqlite-simple, which uses direct-sqlite under the hood; and on some repeated runs of the same unit tests, I get ErrorMisuse and no idea of where to look next. All of the connections are executing from a single application thread. I don't prepare any of the statements myself, that all happens in library code or in deterministic instances.

From a successful run:

Sqlite's debug output (Sqlite.setTrace conn (Just $ traceM . Text.unpack)):

SELECT base32 FROM hash WHERE id = 2

My debug output:

query "SELECT base32 FROM hash WHERE id = ?"
  input: Only {fromOnly = HashId 2}
 output: [Only {fromOnly = UnsafeBase32Hex {toText = "iipvjg8ufk4mohtnad5du7nk1ge6cp4gpoe1pbaa4il910b1t19eam27nk3nmufomplej5g520uqv1qo2kambnolaqpfbbbif111ch0"}}]

From a failing run:

Sqlite debug output: (none)
My debug output:

query "SELECT base32 FROM hash WHERE id = ?"
  input: Only {fromOnly = HashId 2}
(and crashed)

SQLite3 returned ErrorMisuse while attempting to perform prepare "SELECT base32 FROM hash WHERE id = ?": bad parameter or other API misuse

I know there's not a lot to go on here, but it seems like "not a me thing". Can you offer any suggestions for how to find out more about what's going wrong?

[IreneKnapp]

My recollection is that sqlite returns that error when the number of parameter bindings doesn't match the number the prepared statement is expecting. I see that the inputs are deterministic, so... maybe check whether there was an earlier failure when the statement was prepared?

[aryairani]

Hi @IreneKnapp, thanks for the quick reply and suggestion! Though... I'm not sure how to do that? 😅

Looking at https://github.com/nurpax/sqlite-simple/blob/master/Database/SQLite/Simple.hs#L195 it looks like there is already a runtime check that would throw a different sort of error if the number of parameter bindings doesn't match the number the prepared statement is expecting.

And preparing the statement with sqlite-simple's query looks like it's calling direct-sqlite's prepare, which should throw its own error if something failed when the statement was prepared, if I'm reading it right?

Do you know of any way to make sqlite chattier to maybe explain itself about this? :) Or did I overlook some other important thing? *pokes at sqlite3 C source*

Thanks in advance :)

[aryairani]

Maybe I need to run with a version of sqlite3 that has SQLITE_DEBUG enabled? Do you happen to know how to do that? direct-sqlite is kind of magic to me, just being a dependency of the sqlite-simple library I was directly using, and I have no common sense around how C libraries (like sqlite) maybe get bundled with Haskell libraries (like direct-sqlite). Ok thanks :)

[aryairani]

Maybe it's this. 🤞

[aryairani]

Update: It wasn't that. 😞

[aryairani]

Or maybe I need to enable SQLITE_CONFIG_LOG also? I'm trying to add an interface to sqlite3_config to enable it; but don't hesitate to let me know if I'm headed in the wrong direction.

[aryairani]

After [unsuccessfully?] adding support to direct-sqlite for providing a custom logging handler:

setLogger :: Maybe (Error -> Utf8 -> IO ()) -> IO Error

I changed tactics and added a printf to sqlite.c where it normally invokes the logging handler, and and found that I'm somehow sometimes using a connection after closing it. So that gives me something to go on, even though I'm not sure how it's happening so unpredictably.

Let me know if you'd want to end up with a PR for setLogger, in which case I'd ask for your help to understand why my implementation doesn't actually log anything. 🙃

If not, feel free to close this, etc.

[IreneKnapp]

Glad you figured it out!

That PR sounds handy, I encourage you to send it. Note that I'm not the maintainer anymore, I just happened to see your issue and figured I'd try to help. @sigrlami will review the PR.

[aryairani]

@IreneKnapp I appreciate it!