Spotify tracks not playable - but are populated and browsable

[jappish84]

Please try to provide the following:

• version of owntone: 28.10
• platform x86 docker

Steps to reproduce:

I noticed the spotify integration got partially broken after an update - not sure exactly what update though.

I'm currently on latest version 28.10

In the WebUI, under "Settings" -> "Online Services" status for spotify is "Access granted for my_username"

I have tried:

1. logging out
2. restarting the container
3. Granting new access - This step generates errors, more info below

When trying to play a track through the browser I get:

The logs show:

[2025-01-22 10:02:10] [  LOG]  spotify: Error opening source: Cannot open media, session is invalid

[2025-01-22 10:02:10] [  LOG]  spotify: Error opening source: Cannot open media, session is invalid

[2025-01-22 10:02:10] [  LOG]  spotify: Error opening source: Cannot open media, session is invalid

[2025-01-22 10:02:10] [  LOG]      web: Failed to start playback from position '53'

[2025-01-22 10:02:10] [  LOG]      web: JSON api request failed with error code 500 (/api/queue/items/add?clear=true&playback=start&playback_from_position=53&shuffle=false&uris=library:playlist:32)

I have tried reauthenticating with spotify but that always results in a long loading time followed by the browser displaying a "500 could not connect to access point". However, the owntone webui still shows that access has been granted for the user, although, no tracks from spotify are playable BUT I can browse through spotify albums, all my tracks and playlists are loaded, just not playable.

Relevant section of logs

`[2024-10-27 13:51:05] [ INFO]     http: Making request for https://accounts.spotify.com/api/token

[2024-10-27 13:51:05] [ INFO]     http: Making request for https://api.spotify.com/v1/me

[2024-10-27 13:51:05] [ INFO]     http: Making request for https://APResolve.spotify.com/

[2024-10-27T12:53:13Z WARN  libmdns::fsm] dropping truncated packet from 192.168.1.171:5353

[2024-10-27T12:53:13Z WARN  libmdns::fsm] dropping truncated packet from 192.168.1.171:5353

[2024-10-27T12:53:13Z WARN  libmdns::fsm] dropping truncated packet from 192.168.1.171:5353

[2024-10-27 13:53:15] [  LOG]     misc: Could not connect to 'spotify' at ap-gew4.spotify.com (port 4070): Operation timed out

[2024-10-27 13:53:15] [  LOG]      web: Could not parse Spotify OAuth callback '/oauth/spotify?code=LONG_CODE_REDACTED': Could not connect to access point

[2024-10-27 13:54:12] [ INFO]     http: Making request for https://api.spotify.com/v1/albums/4SpOELLHyGJCAvRJsMYvuT

[2024-10-27 13:54:12] [ INFO]     http: Making request for https://api.spotify.com/v1/albums/4SpOELLHyGJCAvRJsMYvuT/tracks?market=SE

[2024-10-27 13:54:12] [  LOG]  spotify: Error opening source: Cannot open media, session is invalid

[2024-10-27 13:54:12] [ WARN]   player: Error starting input read loop (now 0, item_id 72485, now item_id 0)

[2024-10-27 13:54:12] [  LOG]  spotify: Error opening source: Cannot open media, session is invalid

[2024-10-27 13:54:12] [ WARN]   player: Error starting input read loop (now 0, item_id 72486, now item_id 0)

[2024-10-27 13:54:12] [  LOG]  spotify: Error opening source: Cannot open media, session is invalid

[2024-10-27 13:54:12] [ WARN]   player: Error starting input read loop (now 0, item_id 72487, now item_id 0)

[2024-10-27 13:54:12] [  LOG]  spotify: Error opening source: Cannot open media, session is invalid

[2024-10-27 13:54:12] [ WARN]   player: Error starting input read loop (now 0, item_id 72488, now item_id 0)

[2024-10-27 13:54:12] [  LOG]   player: Input start was called with an item id that has disappeared (id=72488)

[2024-10-27 13:54:12] [ WARN]   player: Error starting input read loop (now 0, item_id 72488, now item_id 0)

[2024-10-27 13:54:12] [ INFO]       db: No matching row found for query: SELECT pos FROM queue WHERE id = 72488;

[2024-10-27 13:54:12] [  LOG]       db: Error fetching queue item by pos relative to item id

[2024-10-27 13:54:12] [  LOG]   player: Error fetching next item from queue (item-id=72488, repeat=2)

[2024-10-27 13:54:12] [  LOG]      web: Failed to start playback from position '0'

[2024-10-27 13:54:12] [  LOG]      web: JSON api request failed with error code 500 (/api/queue/items/add?clear=true&playback=start&playback_from_position=0&shuffle=false&uris=spotify:album:4SpOELLHyGJCAvRJsMYvuT)`

Later I discovered that owntone tried other access points aswell, but tracks are still not playable

[2024-12-07 21:06:41] [ LOG] scan: Done processing playlist, added/modified 134 items

[2024-12-07 21:06:41] [ LOG] scan: Bulk library scan completed in 12 sec

[2024-12-07 21:06:41] [ LOG] lib: Library init scan completed in 12 sec (337 changes)

[2024-12-07T20:06:45Z WARN librespot_core::session] Try another access point...

[2024-12-07T20:06:45Z INFO librespot_core::session] Connecting to AP "ap-guc3.spotify.com:4070"

[2024-12-07T20:06:46Z INFO librespot_core::session] Authenticated as 'REDACTED' !

[2024-12-07T20:06:46Z INFO librespot_core::session] Country: "SE"

[ejurgensen]

"Could not connect to 'spotify' at ap-gew4.spotify.com"

For some reason the access point wasn't connectable, but it's working fine for me just now.

OwnTone should try another access point in that case, but I can't see from the log if it did that. Some of the logging you included is from librespot, not from OwnTone, so that's not so relevant ("[2024-12-07T20:06:45Z INFO librespot_core::session] Connecting to AP "ap-guc3.spotify.com:4070"").

[jappish84]

I just tried again. First I logged out of my account - this generated nothing in the logs. I then restarted the container and my username was gone. I then tried reauthenticating - after a long wait I was presented with 500 could not connect to access point

I reloaded the page and the webUI shows that my username is authenticated. I can browse around spotify, so I did some browsing and tried to play a song - here is the logs from the point where I try to authorize access to the point I try and play the song

[2025-01-22 12:55:52] [  LOG]     misc: Could not connect to 'spotify' at ap-gew4.spotify.com (port 4070): Operation timed out

[2025-01-22 12:55:52] [  LOG]      web: Could not parse Spotify OAuth callback '/oauth/spotify?code=REDACTED': Could not connect to access point

[2025-01-22T11:56:46Z WARN  libmdns::fsm] dropping truncated packet from 192.168.1.171:5353

[2025-01-22T11:56:46Z WARN  libmdns::fsm] dropping truncated packet from 192.168.1.171:5353

[2025-01-22 12:57:03] [  LOG]  spotify: Track not available for playback: '(null)' - '(null)' ((null)) (restrictions: (null))

[2025-01-22 12:57:03] [  LOG]  spotify: Couldn't add item at index 12 '{ "added_at": "2025-01-16T23:00:48Z", "added_by": { "external_urls": { "spotify": "https:\/\/open.spotify.com\/user\/" }, "href": "https:\/\/api.spotify.com\/v1\/users\/", "id": "", "type": "user", "uri": "spotify:user:" }, "is_local": false, "primary_color": null, "track": null, "video_thumbnail": { "url": null } }' (API endpoint: 'https://api.spotify.com/v1/playlists/37i9dQZF1DWXfgo3OOonqa/tracks')

[2025-01-22 12:57:03] [  LOG]  spotify: Track not available for playback: '(null)' - '(null)' ((null)) (restrictions: (null))

[2025-01-22 12:57:03] [  LOG]  spotify: Couldn't add item at index 87 '{ "added_at": "2025-01-16T23:00:48Z", "added_by": { "external_urls": { "spotify": "https:\/\/open.spotify.com\/user\/" }, "href": "https:\/\/api.spotify.com\/v1\/users\/", "id": "", "type": "user", "uri": "spotify:user:" }, "is_local": false, "primary_color": null, "track": null, "video_thumbnail": { "url": null } }' (API endpoint: 'https://api.spotify.com/v1/playlists/37i9dQZF1DWXfgo3OOonqa/tracks')

[2025-01-22 12:57:03] [  LOG]  spotify: Track not available for playback: '(null)' - '(null)' ((null)) (restrictions: (null))

[2025-01-22 12:57:03] [  LOG]  spotify: Couldn't add item at index 96 '{ "added_at": "2025-01-16T23:00:48Z", "added_by": { "external_urls": { "spotify": "https:\/\/open.spotify.com\/user\/" }, "href": "https:\/\/api.spotify.com\/v1\/users\/", "id": "", "type": "user", "uri": "spotify:user:" }, "is_local": false, "primary_color": null, "track": null, "video_thumbnail": { "url": null } }' (API endpoint: 'https://api.spotify.com/v1/playlists/37i9dQZF1DWXfgo3OOonqa/tracks')

[2025-01-22 12:57:03] [  LOG]  spotify: Error opening source: Cannot open media, session is invalid

[2025-01-22 12:57:03] [  LOG]  spotify: Error opening source: Cannot open media, session is invalid

[2025-01-22 12:57:03] [  LOG]  spotify: Error opening source: Cannot open media, session is invalid

[2025-01-22 12:57:03] [  LOG]  spotify: Error opening source: Cannot open media, session is invalid

[2025-01-22 12:57:03] [  LOG]  spotify: Error opening source: Cannot open media, session is invalid

[2025-01-22 12:57:03] [  LOG]  spotify: Error opening source: Cannot open media, session is invalid

[2025-01-22 12:57:03] [  LOG]  spotify: Error opening source: Cannot open media, session is invalid

[2025-01-22 12:57:03] [  LOG]  spotify: Error opening source: Cannot open media, session is invalid

[2025-01-22 12:57:03] [  LOG]  spotify: Error opening source: Cannot open media, session is invalid

[2025-01-22 12:57:03] [  LOG]  spotify: Error opening source: Cannot open media, session is invalid

[2025-01-22 12:57:03] [  LOG]  spotify: (LOGGING SKIPPED - above log message is repeating)

[2025-01-22 12:57:04] [  LOG]      web: Failed to start playback from position '5'

[2025-01-22 12:57:04] [  LOG]      web: JSON api request failed with error code 500 (/api/queue/items/add?clear=true&playback=start&playback_from_position=5&shuffle=false&uris=spotify:playlist:37i9dQZF1DWXfgo3OOonqa)

[ejurgensen]

The core error is the same "Could not connect to 'spotify' at ap-gew4.spotify.com (port 4070)". I also now had the same error. It was after playing a few songs, so maybe the access point is unstable right now.

From the logs, it looks like the mechanism to select another access point isn't kicking in, but I'm working on a new Spotify implementation, so I'm not going to dive into that.

As a temporary workaround, maybe you can add ap-gew4.spotify.com to your hosts file and give it the ip address of ap-guc3.spotify.com (if that works).

[jappish84]

Thanks, good to hear a new implementation is coming, looking forward to that.
Sorry, but I forgot to mention that I've had this issue since october, I posted the issue first here but since I never got a response I tried the official docker container and am getting the same error.

I'll try and see if I can get the workaround working, thanks

[jappish84]

Thanks for the pointer, I set up a DNS forwarding rule and also found that '/etc/hosts' file already contained an ip... can't remember I added this, but my memory can't be trusted. It's working again, thanks