Running smos-sync-client sync results in SQLITE_BUSY error

[jhbertra]

Reproduction Steps:

1. Install with Stack
2. Configure sync with an existing account

   sync:
    server-url: api.smos.cs-syd.eu
    username: <username>

3. Run smos-sync-client login and provide password
4. Run smos-sync-client sync

Expected Result:

• Files in workflow directory synchronized

Actual Result:

• Database connection error - here is the console dump:

[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Out of retry attempts @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:194:7)
smos-sync-client: SQLite3 returned ErrorBusy while attempting to perform prepare "PRAGMA journal_mode=WAL;": database is locked

Environment info:

• Smos revision: a3ed8fd
• OS: Mac OS Big Sur 11.2.3
• Sqlite version: 3.32.3 2020-06-18 14:16:19 02c344aceaea0d177dd42e62c8541e3cab4a26c757ba33b3a31a43ccc7d4aapl

[NorfairKing]

Wow I've never seen this before. Is it reproducible on your machine? How can I reproduce it?

[jhbertra]

It is 100% reproducible on my machine - is there away to enable trace / debug logs so I can send more information?

[NorfairKing]

@jhbertra you can use --log-level Debug.
Also check the ~/.local/share/smos and ~/.cache/smos dirs to see if there's a spare lock anywhere.

[jhbertra]

@NorfairKing debug logging didn't have any new information - I checked the directories and these were the contents

➜  ~ ls -la ~/.local/share/smos
total 0
drwxr-xr-x  3 jamiebertram  staff   96 28 Apr 08:36 .
drwx------  8 jamiebertram  staff  256 28 Apr 09:09 ..
-rw-r--r--  1 jamiebertram  staff    0 28 Apr 08:36 sync-metadata.sqlite3
➜  ~ ls -la ~/.cache/smos
total 8
drwxr-xr-x  3 jamiebertram  staff   96 30 Apr 10:46 .
drwxr-xr-x  9 jamiebertram  staff  288 30 Apr 10:46 ..
-rw-r--r--  1 jamiebertram  staff  203 30 Apr 10:46 sync-session.dat

[jhbertra]

Does smos-sync-client create multiple connections inside forkIO or similar to talk to the sqlite database? This error happens when there are multiple concurrent attempts to write to an sqlite DB.

[jhbertra]

Here is the debug log:

I might have been premature to claim it showed nothing new... it looks like the error is happening after CLIENT START but before INITIAL_SYNC_START or SYNC_START - which means it's most likely happening while trying to run the migrations - could be a bug in persistent-sqlite maybe?

[Debug] CLIENT START
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Encountered an SQLITE_BUSY, going to retry... @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:201:11)
[Warn] Out of retry attempts @(persistent-sqlite-2.10.6.2-DLoGFQI7HfLDqsZHyoMwNt:Database.Persist.Sqlite ./Database/Persist/Sqlite.hs:194:7)
smos-sync-client: SQLite3 returned ErrorBusy while attempting to perform prepare "PRAGMA journal_mode=WAL;": database is locked

[NorfairKing]

Does smos-sync-client create multiple connections inside forkIO or similar to talk to the sqlite database? This error happens when there are multiple concurrent attempts to write to an sqlite DB.

No, forkIO is banned and we specifically set a connection count of 1:

smos/smos-sync-client/src/Smos/Sync/Client/Command/Sync.hs

Line 64 in a3ed8fd

DB.withSqlitePool (T.pack $ fromAbsFile syncSetMetadataDB) 1 $

Could it be that the database was somehow left in a locked state? What happens if you remove sync-metadata.sqlite3?

[jhbertra]

No, forkIO is banned and we specifically set a connection count of 1:

Yeah, I found that when I started digging into the code a bit.

What happens if you remove sync-metadata.sqlite3?

Same thing happens.

I looked through persistent-sqlite a bit and found this issue from 2015 after which PRAGMA journal_mode=WAL; was enabled during wrapConnection yesodweb/persistent#363

Ironically, it was added to address the exact issue I'm facing. I'm guessing this is a bug in persistent-sqlite. I can open up an issue over there, and maybe see if there is a workaround for the time being.

[NorfairKing]

Ironically, it was added to address the exact issue I'm facing. I'm guessing this is a bug in persistent-sqlite. I can open up an issue over there, and maybe see if there is a workaround for the time being.

Interesting.

I think I just found another issue that may be related to this:
When opening the database connection, we lock the database instead of a separate lock file: I think this will be the problem.

smos/smos-sync-client/src/Smos/Sync/Client/Command/Sync.hs

Line 61 in a3ed8fd

withFileLock (fromAbsFile syncSetMetadataDB) Exclusive $ \_ ->

I think that if you just add ++ ".lock" to that line like so: withFileLock (fromAbsFile syncSetMetadataDB ++ ".lock") Exclusive $ \_ -> it could fix your problem.
However, that doesn't explain why I have never seen this problem before.

[jhbertra]

Hey, that worked! Want me to PR this change?

[NorfairKing]

Hey, that worked! Want me to PR this change?

That would be great! I can't explain it but I'm not going to complain about that too much :P

[jhbertra]

It could be something related to running on MacOS, or it could be something with my specific sqlite3 version... either way, if this is a change you want regardless then great!

[NorfairKing]

either way, if this is a change you want regardless then great!

Yes absolutely! I wrote that line of code before I really understood how file locking works.

[jhbertra]

Yes absolutely! I wrote that line of code before I really understood how file locking works.

Actually, would you mind summarizing how this works for my benefit? I don't really understand the change I just PR'd, so had a hard time summarizing it. From the looks of the withSqlitePool API, I would expect the first argument to be the name of the sqlite DB file, not a lock file. What's the rationale behind the change?

[NorfairKing]

@jhbertra I responded to your question here: #203 (comment)