search

owntone / owntone-server

Linux/FreeBSD DAAP (iTunes) and MPD audio server with support for AirPlay 1 and 2 speakers (multiroom), Apple Remote (and compatibles), Chromecast, Spotify and internet radio.
https://owntone.github.io/owntone-server
GNU General Public License v2.0
2.1k stars 237 forks source link

Manual sqlite3 DB file cleanup. Unplayable spotify:local songs #388

Closed BIAndrews closed 7 years ago

BIAndrews commented 7 years ago

I have local /srv/music MP3 files working fine as well as spotify music, for the most part. However it seems to be indexing a number of spotify tracks that aren't playable. I was trying to manually remove them from the sqlite3 DB after looking at the queries in db.c but I'm having a collation sequence error I can't figure out.

Branch: master

sqlite> DELETE FROM files WHERE path = 'spotify:local:%%';
Error: no such collation sequence: DAAP

Here is a debug log snippet of when one of these ghost songs is played via Apple Remote. It tries and fails returning back to the song list. No artwork is found for these songs. I'm just guessing but from looking at select id, path from files where path like 'spotify:%'; I suspect all spotify:local:% songs are broken/unplayable. In fact I know these songs haven't even been played on my spotify account before because some of them are home ripped on my iTunes app. They had to have come from there, not spotify.

Here is a sqlite files record of one of the spotify:local songs coming from iTunes:

sqlite> select * from files where id = '243';
243|spotify:local::Kid+Songs:02+I+Had+But+Fifty+Cents:136|spotify:local::Kid+Songs:02+I+Had+But+Fifty+Cents:136|02 I Had But Fifty Cents|Unknown artist|Kid Songs|Unknown genre||spotify||||||0|0|136000|0|0|0|0|0|0|0|0|6|0|0|0|2|2|Spotify audio|1495353453|1495353453|0|1495359057|0|0|wav|0|0|0|0|Unknown artist|1||||0|0|3032167492714513953|71127602110966156|00002 I Had But Fifty Cents|Unknown artist|Kid Songs||Unknown artist|/spotify:/(null)/Kid Songs/02 I Had But Fifty Cents|231|0
[2017-05-21 23:26:38] [DEBUG]   player: Start playback of 'spotify:local:Regina+Spektor:Begin+To+Hope:Apr%C3%A8s+Moi:310' (id=220, item-id=27)
[2017-05-21 23:26:38] [DEBUG]       db: Running query 'SELECT f.* FROM files f WHERE f.id = 220;'
[2017-05-21 23:26:38] [ INFO]   player: Opening 'spotify:local:Regina+Spektor:Begin+To+Hope:Apr%C3%A8s+Moi:310' (id=220, item-id=27)
[2017-05-21 23:26:38] [DEBUG]   player: Action is setup
[2017-05-21 23:26:38] [DEBUG]  spotify: Playback setup request
[2017-05-21 23:26:38] [DEBUG]  spotify: Setting up for playback
[2017-05-21 23:26:38] [  LOG]  spotify: Playback setup failed: The track cannot be played
[2017-05-21 23:26:38] [  LOG]   player: Failed to open 'spotify:local:Regina+Spektor:Begin+To+Hope:Apr%C3%A8s+Moi:310' (id=220, item-id=27)
[2017-05-21 23:26:38] [DEBUG]       db: Running query 'BEGIN TRANSACTION;'
[2017-05-21 23:26:38] [DEBUG]       db: Running query 'DELETE FROM queue where id <> 0;'
[2017-05-21 23:26:38] [DEBUG]       db: Running query 'END TRANSACTION;'
[2017-05-21 23:26:39] [DEBUG]       db: Running query 'BEGIN TRANSACTION;'
[2017-05-21 23:26:39] [DEBUG]       db: Running query 'SELECT value FROM admin a WHERE a.key = 'queue_version';'
[2017-05-21 23:26:39] [DEBUG]       db: Running query 'INSERT OR REPLACE INTO admin (key, value) VALUES ('queue_version', '94');'
[2017-05-21 23:26:39] [DEBUG]       db: Running query 'END TRANSACTION;'
[2017-05-21 23:26:39] [DEBUG]      mpd: Listener callback called with event type 2.
[2017-05-21 23:26:39] [DEBUG]      mpd: Listener callback called with event type 1.
[2017-05-21 23:26:39] [DEBUG]      mpd: Notify clients waiting for idle results: 2
[2017-05-21 23:26:39] [  LOG]     dacp: Could not start playback
[2017-05-21 23:26:39] [DEBUG]      mpd: Notify clients waiting for idle results: 1
[2017-05-21 23:26:39] [DEBUG]   player: Player status: stopped
[2017-05-21 23:26:39] [DEBUG]     dacp: DACP request: /ctrl-int/1/getproperty?properties=dacp.playerstate,dacp.nowplaying,dacp.playingtime,dmcp.volume,dacp.volumecontrollable,dacp.availableshufflestates,dacp.availablerepeatstates,dacp.shufflestate,dacp.repeatstate,dacp.fullscreenenabled,dacp.fullscreen,dacp.visualizerenabled,dacp.visualizer,com.apple.itunes.itms-songid,com.apple.itunes.has-chapter-data,com.apple.itunes.mediakind,com.apple.itunes.extended-media-kind&session-id=151868616
[2017-05-21 23:26:39] [DEBUG]   player: Player status: stopped
[2017-05-21 23:26:39] [DEBUG]     dacp: DACP request: /ctrl-int/1/getspeakers?session-id=151868616
[2017-05-21 23:26:39] [DEBUG]     dacp: DACP request: /ctrl-int/1/playstatusupdate?revision-number=3&session-id=151868616
[2017-05-21 23:26:39] [DEBUG]     dacp: DACP request: /ctrl-int/1/playqueue-contents?span=50&session-id=151868616
[2017-05-21 23:26:39] [DEBUG]     dacp: Fetching playqueue contents
[2017-05-21 23:26:39] [DEBUG]   player: Player status: stopped
[2017-05-21 23:26:39] [DEBUG]       db: Running query 'BEGIN TRANSACTION;'
[2017-05-21 23:26:39] [DEBUG]       db: Starting enum 'SELECT * FROM queue WHERE 1=1 ORDER BY pos ASC;'
[2017-05-21 23:26:39] [DEBUG]       db: End of queue enum results
[2017-05-21 23:26:39] [DEBUG]       db: Running query 'END TRANSACTION;'
[2017-05-21 23:26:39] [DEBUG]     dacp: DACP request: /ctrl-int/1/getproperty?properties=dmcp.volume&session-id=151868616
[2017-05-21 23:26:39] [DEBUG]   player: Player status: stopped
[2017-05-21 23:26:40] [DEBUG]     daap: DAAP request: /databases/1/items/220/extra_data/artwork?mw=100&mh=100&session-id=151868616
[2017-05-21 23:26:40] [DEBUG]  artwork: Artwork request for item 220
[2017-05-21 23:26:40] [DEBUG]       db: Running query 'SELECT COUNT(*) FROM files f WHERE f.disabled = 0 AND id = 220;'
[2017-05-21 23:26:40] [DEBUG]       db: Starting query 'SELECT f.* FROM files f WHERE f.disabled = 0 AND id = 220  ;'
[2017-05-21 23:26:40] [DEBUG]    cache: Running query 'SELECT a.format, a.data FROM artwork a WHERE a.type = 0 AND a.persistentid = 9095775672202378763 AND a.max_w = 100 AND a.max_h = 100;'
[2017-05-21 23:26:40] [DEBUG]    cache: Cache hit: SELECT a.format, a.data FROM artwork a WHERE a.type = 0 AND a.persistentid = 9095775672202378763 AND a.max_w = 100 AND a.max_h = 100;
[2017-05-21 23:26:40] [DEBUG]  artwork: Source 'cache' stopped search for artwork for group 9095775672202378763
[2017-05-21 23:26:40] [DEBUG]  artwork: No artwork found for item 220
[2017-05-21 23:26:40] [DEBUG]     daap: DAAP request handled in 4 milliseconds
[2017-05-21 23:26:40] [DEBUG]     daap: DAAP request: /databases/1/items/484/extra_data/artwork?mw=100&mh=100&session-id=151868616
[2017-05-21 23:26:40] [DEBUG]  artwork: Artwork request for item 484
[2017-05-21 23:26:40] [DEBUG]       db: Running query 'SELECT COUNT(*) FROM files f WHERE f.disabled = 0 AND id = 484;'
[2017-05-21 23:26:40] [DEBUG]       db: Starting query 'SELECT f.* FROM files f WHERE f.disabled = 0 AND id = 484  ;'
[2017-05-21 23:26:40] [DEBUG]    cache: Running query 'SELECT a.format, a.data FROM artwork a WHERE a.type = 0 AND a.persistentid = 9095775672202378763 AND a.max_w = 100 AND a.max_h = 100;'
[2017-05-21 23:26:40] [DEBUG]    cache: Cache hit: SELECT a.format, a.data FROM artwork a WHERE a.type = 0 AND a.persistentid = 9095775672202378763 AND a.max_w = 100 AND a.max_h = 100;
[2017-05-21 23:26:40] [DEBUG]  artwork: Source 'cache' stopped search for artwork for group 9095775672202378763
[2017-05-21 23:26:40] [DEBUG]  artwork: No artwork found for item 484
[2017-05-21 23:26:40] [DEBUG]     daap: DAAP request handled in 4 milliseconds
[2017-05-21 23:26:40] [DEBUG]     daap: DAAP request: /databases/1/items/220/extra_data/artwork?mw=100&mh=100&session-id=151868616
[2017-05-21 23:26:40] [DEBUG]  artwork: Artwork request for item 220
[2017-05-21 23:26:40] [DEBUG]       db: Running query 'SELECT COUNT(*) FROM files f WHERE f.disabled = 0 AND id = 220;'
[2017-05-21 23:26:40] [DEBUG]       db: Starting query 'SELECT f.* FROM files f WHERE f.disabled = 0 AND id = 220  ;'
[2017-05-21 23:26:40] [DEBUG]    cache: Running query 'SELECT a.format, a.data FROM artwork a WHERE a.type = 0 AND a.persistentid = 9095775672202378763 AND a.max_w = 100 AND a.max_h = 100;'
[2017-05-21 23:26:40] [DEBUG]    cache: Cache hit: SELECT a.format, a.data FROM artwork a WHERE a.type = 0 AND a.persistentid = 9095775672202378763 AND a.max_w = 100 AND a.max_h = 100;
[2017-05-21 23:26:40] [DEBUG]  artwork: Source 'cache' stopped search for artwork for group 9095775672202378763
[2017-05-21 23:26:40] [DEBUG]  artwork: No artwork found for item 220
[2017-05-21 23:26:40] [DEBUG]     daap: DAAP request handled in 4 milliseconds
[2017-05-21 23:26:40] [DEBUG]     daap: DAAP request: /databases/1/items/484/extra_data/artwork?mw=100&mh=100&session-id=151868616
[2017-05-21 23:26:40] [DEBUG]  artwork: Artwork request for item 484
[2017-05-21 23:26:40] [DEBUG]       db: Running query 'SELECT COUNT(*) FROM files f WHERE f.disabled = 0 AND id = 484;'
[2017-05-21 23:26:40] [DEBUG]       db: Starting query 'SELECT f.* FROM files f WHERE f.disabled = 0 AND id = 484  ;'
[2017-05-21 23:26:40] [DEBUG]    cache: Running query 'SELECT a.format, a.data FROM artwork a WHERE a.type = 0 AND a.persistentid = 9095775672202378763 AND a.max_w = 100 AND a.max_h = 100;'
[2017-05-21 23:26:40] [DEBUG]    cache: Cache hit: SELECT a.format, a.data FROM artwork a WHERE a.type = 0 AND a.persistentid = 9095775672202378763 AND a.max_w = 100 AND a.max_h = 100;
[2017-05-21 23:26:40] [DEBUG]  artwork: Source 'cache' stopped search for artwork for group 9095775672202378763
[2017-05-21 23:26:40] [DEBUG]  artwork: No artwork found for item 484
[2017-05-21 23:26:40] [DEBUG]     daap: DAAP request handled in 5 milliseconds
BIAndrews commented 7 years ago

Correction: I didn't know it but iTunes songs are showing up in the spotify app so that is where the cross contamination is coming from. forked-daapd is not mislabeling anything.

ejurgensen commented 7 years ago

Just to be sure I understand this: The "spotify:local:*" files somehow came from iTunes, and cannot be played back by forked-daapd. Right?

So I guess a fix for this would be that forked-daapd just ignores "spotify:local:*" when it gets the track lists from Spotify - true?

Also pinging @chme on this.

ejurgensen commented 7 years ago

Closing, no feedback