[spotify] Fix possible deadlock during Spotify scan

[chme]

I ran into a deadlock between the library thread and a worker thread for an artwork request. The deadlock occurs when the library thread does the Spotify scan and an artwork request is made.

• During the scan, the library thread holds the lock on the spotify credential mutex.

• When there is an artwork request in parallel (e. g. opening the albums page in the web UI), this request is processed in one of the worker threads. Finding artwork opens a DB query to fetch the files (in process_items) and steps over the result set. This results in a DB lock held until the query is finalized.

• The Spotify artwork source now tries to find the artwork in Spotify and blocks because the library thread still holds the lock on the credential mutex.

• During the scan in the library thread, it want's now to write into the files table. This will block because the worker/artwork thread holds the DB lock.

The result is a deadlock. The library thread waits for worker/artwork thread to release the DB lock, and the worker/artwork thread waits for the library thread to release the lock on the spotify credentials.

This PR solves it by only holding the lock on the spotify credentials as short as possible. It introduces "credentials_*" functions that should be used instead of directly accessing the spotify_credentials global.

[ejurgensen]

Good find and nice fix, it looks very clean to me. I didn't review every changed line, but those I did all looked good, so you are welcome to merge.

I actually thought a sqlite read wouldn't block a write. Their docs say "Writers merely append new content to the end of the WAL file. Because writers do nothing that would interfere with the actions of readers, writers and readers can run at the same time. However, since there is only one WAL file, there can only be one writer at a time."

There are quite a few dbmfi loops like in process_items(), so I wonder if that means there are problems other places.

[chme]

I actually thought a sqlite read wouldn't block a write.

By default, owntone uses the "DELETE" journal mode (with a rollback journal). I was thinking that switching to "WAL" (with write-ahead logging) would solve this deadlock. But unfortunately it did not.

There are quite a few dbmfi loops like in process_items(), so I wonder if that means there are problems other places.

The special thing in this case is, that while holding the lock on the mutex an additional write lock on the DB was requested.
Probably unlikely, that this applies to other places.

---

Here the log for such a DB lock, that will never be unlocked (I added logging of thread name/tid). This is with "WAL" set as journal mode in owntone.conf.

[2025-02-16 05:37:42] [DEBUG] [library (6362)      ]       db: Running query 'BEGIN TRANSACTION;'
[2025-02-16 05:37:42] [DEBUG] [library (6362)      ]  spotify: Making request to 'https://api.spotify.com/v1/playlists/37i9dQZF1DX9wa6XirBPv8/tracks?market=DE'
[2025-02-16 05:37:42] [ SPAM] [worker (6360)       ]  artwork: Checking group source 'cache'
[2025-02-16 05:37:42] [ SPAM] [worker (6360)       ]  artwork: Checking group source 'directory'
[2025-02-16 05:37:42] [DEBUG] [worker (6360)       ]       db: Running query 'SELECT g.type FROM groups g WHERE g.persistentid = 4689083598046747417;'
[2025-02-16 05:37:42] [DEBUG] [worker (6360)       ]       db: Running query 'SELECT COUNT(DISTINCT(SUBSTR(f.path, 1, LENGTH(f.path) - LENGTH(f.fname) - 1))) FROM files f WHERE f.disabled = 0 AND f.songalbumid = 4689083598046747417;'
[2025-02-16 05:37:42] [DEBUG] [worker (6360)       ]       db: Starting query 'SELECT DISTINCT(SUBSTR(f.path, 1, LENGTH(f.path) - LENGTH(f.fname) - 1)) FROM files f WHERE f.disabled = 0 AND f.songalbumid = 4689083598046747417  ;'
[2025-02-16 05:37:42] [DEBUG] [worker (6360)       ]       db: End of query results
[2025-02-16 05:37:42] [ INFO] [library (6362)      ]     http: Making request for https://api.spotify.com/v1/playlists/37i9dQZF1DX9wa6XirBPv8/tracks?market=DE
[2025-02-16 05:37:42] [DEBUG] [worker (6360)       ]       db: Running query 'SELECT g.type FROM groups g WHERE g.persistentid = 4689083598046747417;'
[2025-02-16 05:37:42] [DEBUG] [worker (6360)       ]       db: Running query 'SELECT COUNT(*) FROM files f WHERE f.disabled = 0 AND f.songalbumid = 4689083598046747417;'
[2025-02-16 05:37:42] [DEBUG] [worker (6360)       ]       db: Starting query 'SELECT f.* FROM files f WHERE f.disabled = 0 AND f.songalbumid = 4689083598046747417  ;'
[2025-02-16 05:37:42] [ SPAM] [worker (6360)       ]  artwork: Checking item source 'cache'
[2025-02-16 05:37:42] [ SPAM] [worker (6360)       ]  artwork: Checking item source 'Spotify track web api'
[2025-02-16 05:37:42] [DEBUG] [library (6362)      ]  spotify: Got JSON response for request to 'https://api.spotify.com/v1/playlists/37i9dQZF1DX9wa6XirBPv8/tracks?market=DE'
[2025-02-16 05:37:42] [DEBUG] [library (6362)      ]       db: Running query 'SELECT d.id FROM directories d WHERE d.virtual_path = '/spotify:/My Chemical Romance';'
[2025-02-16 05:37:42] [DEBUG] [library (6362)      ]       db: Running query 'UPDATE directories SET virtual_path = TRIM('/spotify:/My Chemical Romance'), db_timestamp = 1739684262, disabled = 0, parent_id = 4, path = TRIM(NULL), scan_kind = 2 WHERE id = 1952;'
[2025-02-16 05:37:42] [DEBUG] [library (6362)      ]       db: Updated directory '/spotify:/My Chemical Romance' with id 1952
[2025-02-16 05:37:42] [DEBUG] [library (6362)      ]       db: Running query 'SELECT d.id FROM directories d WHERE d.virtual_path = '/spotify:/My Chemical Romance/Three Cheers for Sweet Revenge';'
[2025-02-16 05:37:42] [DEBUG] [library (6362)      ]       db: Running query 'UPDATE directories SET virtual_path = TRIM('/spotify:/My Chemical Romance/Three Cheers for Sweet Revenge'), db_timestamp = 1739684262, disabled = 0, parent_id = 1952, path = TRIM(NULL), scan_kind = 2 WHERE id = 1953;'
[2025-02-16 05:37:42] [DEBUG] [library (6362)      ]       db: Updated directory '/spotify:/My Chemical Romance/Three Cheers for Sweet Revenge' with id 1953
[2025-02-16 05:37:42] [DEBUG] [library (6362)      ]       db: Running query 'UPDATE files SET db_timestamp = 1739684262, disabled = 0 WHERE path = 'spotify:track:7lRlq939cDG4SzWOF4VAnd' AND db_timestamp > 1737077785;'
[2025-02-16 05:37:42] [ INFO] [library (6362)      ]       db: Waiting for database unlock

[ejurgensen]

Thanks for the clarification, good to hear that it's probably not a general problem. Would it be ok to merge the PR? I'm thinking of making a release soon, since there have been a few good fixes since 28.11, and it would be nice to have this one among them.

[chme]

Sure, merged it now :-)