[GH-ISSUE #603] Player got stuck in one song #1286

Open
opened 2026-03-14 14:14:38 +03:00 by kerem · 18 comments
Owner

Originally created by @xd-mau5 on GitHub (Nov 6, 2024).
Original GitHub issue: https://github.com/aome510/spotify-player/issues/603

Describe the bug
After using spotify-player for like 15 minutes listening a playlist the player gets stuck on a song, even if you select previous or next, it stays on the same song, if you try to place another song by selecting it directly, it does not play the one you have chosen.

To Reproduce

  1. start listening
  2. wait at least 15 minutes
  3. notice that one song got stuck

Expected behaviour
continue playing without issues

Log and backtrace
spotify-player-24-11-06-11-21.log

Screenshots
Video

Environment

  • OS: Windows 11 (Pro) 23H2 22631.4391
  • Application version: spotify_player 0.20.1
Originally created by @xd-mau5 on GitHub (Nov 6, 2024). Original GitHub issue: https://github.com/aome510/spotify-player/issues/603 **Describe the bug** After using spotify-player for like 15 minutes listening a playlist the player gets stuck on a song, even if you select previous or next, it stays on the same song, if you try to place another song by selecting it directly, it does not play the one you have chosen. **To Reproduce** 1. start listening 2. wait at least 15 minutes 3. notice that one song got stuck **Expected behaviour** continue playing without issues **Log and backtrace** [spotify-player-24-11-06-11-21.log](https://github.com/user-attachments/files/17651186/spotify-player-24-11-06-11-21.log) **Screenshots** [Video](https://files.catbox.moe/25zeyw.mp4) **Environment** - OS: Windows 11 (Pro) 23H2 22631.4391 - Application version: spotify_player 0.20.1
Author
Owner

@dhgwilliam commented on GitHub (Nov 19, 2024):

been happening to me to, i'm working on trying to predict it. one possibility on my mind is that when unpausing a song after a long idle, the player loses the context of the playlist? but i'm not 100% on that. the rest of the issue described above is the same for me, although i'm on a mac

Hardware Overview:

  Model Name: MacBook Pro
  Model Identifier: MacBookPro14,3
  Processor Name: Quad-Core Intel Core i7
  Processor Speed: 3.1 GHz
  Number of Processors: 1
  Total Number of Cores: 4
  L2 Cache (per Core): 256 KB
  L3 Cache: 8 MB
  Hyper-Threading Technology: Enabled
  Memory: 16 GB
  System Firmware Version: 529.140.2.0.0
  OS Loader Version: 577.140.2~30
  SMC Version (system): 2.45f5
      brew info spotify_player
==> spotify_player: stable 0.20.1 (bottled)
Command driven spotify player
https://github.com/aome510/spotify-player
Installed
/usr/local/Cellar/spotify_player/0.20.1 (8 files, 32.4MB) *
  Poured from bottle using the formulae.brew.sh API on 2024-11-11 at 19:02:22
<!-- gh-comment-id:2486949966 --> @dhgwilliam commented on GitHub (Nov 19, 2024): been happening to me to, i'm working on trying to predict it. one possibility on my mind is that when unpausing a song after a long idle, the player loses the context of the playlist? but i'm not 100% on that. the rest of the issue described above is the same for me, although i'm on a mac Hardware Overview: Model Name: MacBook Pro Model Identifier: MacBookPro14,3 Processor Name: Quad-Core Intel Core i7 Processor Speed: 3.1 GHz Number of Processors: 1 Total Number of Cores: 4 L2 Cache (per Core): 256 KB L3 Cache: 8 MB Hyper-Threading Technology: Enabled Memory: 16 GB System Firmware Version: 529.140.2.0.0 OS Loader Version: 577.140.2~30 SMC Version (system): 2.45f5 ``` brew info spotify_player ==> spotify_player: stable 0.20.1 (bottled) Command driven spotify player https://github.com/aome510/spotify-player Installed /usr/local/Cellar/spotify_player/0.20.1 (8 files, 32.4MB) * Poured from bottle using the formulae.brew.sh API on 2024-11-11 at 19:02:22 ```
Author
Owner

@avastmick commented on GitHub (Jan 6, 2025):

I get the same on MacOs - M2 MBP. Installed via cargo install spotify_player --features image.

After about 10 tracks it hangs on one track. If another is selected and played, it does so silently. Only a restart will recover.

Looking at the logs I get a failure on starting a new track until it loops through the playlist to get to the track it was playing previously and can play and starts again:

2025-01-06T07:00:49.552742Z  WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([125, 99, 24, 109, 205, 177, 67, 90, 158, 58, 130, 59, 87, 104, 72, 232]), uri: None, queued: None, contex
       │ t: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [2] of 30
 603   │ 2025-01-06T07:00:49.552760Z  WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([204, 75, 245, 84, 11, 181, 74, 25, 175, 197, 167, 225, 42, 94, 93, 118]), uri: None, queued: None, contex
       │ t: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [3] of 30
 604   │ 2025-01-06T07:00:49.552779Z  WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([7, 96, 156, 167, 171, 64, 69, 197, 191, 54, 141, 198, 145, 81, 173, 184]), uri: None, queued: None, conte
       │ xt: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [4] of 30
 605   │ 2025-01-06T07:00:49.552798Z  WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([103, 171, 177, 223, 188, 223, 76, 2, 162, 176, 150, 47, 112, 17, 13, 247]), uri: None, queued: None, cont
       │ ext: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [5] of 30
 606   │ 2025-01-06T07:00:49.552828Z  WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([252, 183, 214, 23, 224, 149, 68, 47, 168, 236, 184, 27, 13, 66, 88, 186]), uri: None, queued: None, conte
       │ xt: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [6] of 30
 607   │ 2025-01-06T07:00:49.552848Z  WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([53, 216, 17, 196, 66, 213, 76, 80, 157, 165, 240, 36, 25, 104, 145, 184]), uri: None, queued: None, conte
       │ xt: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [7] of 30
 608   │ 2025-01-06T07:00:49.552866Z  WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([240, 226, 191, 135, 217, 151, 79, 192, 141, 153, 5, 112, 80, 111, 15, 169]), uri: None, queued: None, con
       │ text: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [8] of 30
 609   │ 2025-01-06T07:00:49.554594Z  INFO spotify_player::streaming: Got a new player event: Changed { playable_id: Track(TrackId("31CYUJj5f9lbQ0Qqm9PzK5")) }
 610   │ 2025-01-06T07:00:49.554661Z  INFO spotify_player::streaming: Got a new player event: Playing { playable_id: Track(TrackId("31CYUJj5f9lbQ0Qqm9PzK5")), position_ms: 0 }
 611   │ 2025-01-06T07:00:50.075805Z  INFO client_request{request=GetCurrentPlayback}: spotify_player::client: Successfully handled the client request, took: 419ms
 612   │ 2025-01-06T07:01:08.254304Z  INFO spotify_player::media_control: Got a media control event: Next
 613   │ 2025-01-06T07:01:08.480349Z  WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([65, 148, 3, 216, 235, 165, 76, 114, 156, 223, 41, 78, 133, 67, 189, 196]), uri: None, queued: None, conte
       │ xt: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [10] of 30
 614   │ 2025-01-06T07:01:08.480521Z  WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([43, 199, 91, 58, 27, 18, 74, 188, 134, 237, 5, 238, 199, 48, 20, 251]), uri: None, queued: None, context:
       │  Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [11] of 30
 615   │ 2025-01-06T07:01:08.480557Z  WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([160, 18, 235, 79, 76, 204, 76, 94, 161, 230, 65, 232, 26, 116, 115, 203]), uri: None, queued: None, conte
       │ xt: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [12] of 30
<!-- gh-comment-id:2572479617 --> @avastmick commented on GitHub (Jan 6, 2025): I get the same on MacOs - M2 MBP. Installed via `cargo install spotify_player --features image`. After about 10 tracks it hangs on one track. If another is selected and played, it does so silently. Only a restart will recover. Looking at the logs I get a failure on starting a new track until it loops through the playlist to get to the track it was playing previously and can play and starts again: ``` 2025-01-06T07:00:49.552742Z WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([125, 99, 24, 109, 205, 177, 67, 90, 158, 58, 130, 59, 87, 104, 72, 232]), uri: None, queued: None, contex │ t: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [2] of 30 603 │ 2025-01-06T07:00:49.552760Z WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([204, 75, 245, 84, 11, 181, 74, 25, 175, 197, 167, 225, 42, 94, 93, 118]), uri: None, queued: None, contex │ t: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [3] of 30 604 │ 2025-01-06T07:00:49.552779Z WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([7, 96, 156, 167, 171, 64, 69, 197, 191, 54, 141, 198, 145, 81, 173, 184]), uri: None, queued: None, conte │ xt: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [4] of 30 605 │ 2025-01-06T07:00:49.552798Z WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([103, 171, 177, 223, 188, 223, 76, 2, 162, 176, 150, 47, 112, 17, 13, 247]), uri: None, queued: None, cont │ ext: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [5] of 30 606 │ 2025-01-06T07:00:49.552828Z WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([252, 183, 214, 23, 224, 149, 68, 47, 168, 236, 184, 27, 13, 66, 88, 186]), uri: None, queued: None, conte │ xt: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [6] of 30 607 │ 2025-01-06T07:00:49.552848Z WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([53, 216, 17, 196, 66, 213, 76, 80, 157, 165, 240, 36, 25, 104, 145, 184]), uri: None, queued: None, conte │ xt: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [7] of 30 608 │ 2025-01-06T07:00:49.552866Z WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([240, 226, 191, 135, 217, 151, 79, 192, 141, 153, 5, 112, 80, 111, 15, 169]), uri: None, queued: None, con │ text: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [8] of 30 609 │ 2025-01-06T07:00:49.554594Z INFO spotify_player::streaming: Got a new player event: Changed { playable_id: Track(TrackId("31CYUJj5f9lbQ0Qqm9PzK5")) } 610 │ 2025-01-06T07:00:49.554661Z INFO spotify_player::streaming: Got a new player event: Playing { playable_id: Track(TrackId("31CYUJj5f9lbQ0Qqm9PzK5")), position_ms: 0 } 611 │ 2025-01-06T07:00:50.075805Z INFO client_request{request=GetCurrentPlayback}: spotify_player::client: Successfully handled the client request, took: 419ms 612 │ 2025-01-06T07:01:08.254304Z INFO spotify_player::media_control: Got a media control event: Next 613 │ 2025-01-06T07:01:08.480349Z WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([65, 148, 3, 216, 235, 165, 76, 114, 156, 223, 41, 78, 133, 67, 189, 196]), uri: None, queued: None, conte │ xt: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [10] of 30 614 │ 2025-01-06T07:01:08.480521Z WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([43, 199, 91, 58, 27, 18, 74, 188, 134, 237, 5, 238, 199, 48, 20, 251]), uri: None, queued: None, context: │ Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [11] of 30 615 │ 2025-01-06T07:01:08.480557Z WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([160, 18, 235, 79, 76, 204, 76, 94, 161, 230, 65, 232, 26, 116, 115, 203]), uri: None, queued: None, conte │ xt: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [12] of 30 ```
Author
Owner

@avastmick commented on GitHub (Jan 6, 2025):

Update. I am looking at the logs (as per my earlier comment) and thinking about the issue. I have now tried the following:

  • Playing a playlist of about 30 songs (~1 hour 45). Fails after about 10 tracks, as per the above errors
  • Play the same playlist but also connect via phone Spotify App (watcher), and the whole playlist completes

Not ideal, but I can now play for longer than ~30 minutes. It seems as if it is an authorization error. It used to work fine, so maybe it's an upstream issue with librespot?

<!-- gh-comment-id:2574027192 --> @avastmick commented on GitHub (Jan 6, 2025): Update. I am looking at the logs (as per my earlier comment) and thinking about the issue. I have now tried the following: - Playing a playlist of about 30 songs (~1 hour 45). Fails after about 10 tracks, as per the above errors - Play the same playlist but also connect via phone Spotify App (watcher), and the whole playlist completes Not ideal, but I can now play for longer than ~30 minutes. It seems as if it is an authorization error. It used to work fine, so maybe it's an upstream issue with `librespot`?
Author
Owner

@alexjyong commented on GitHub (Jan 24, 2025):

I wonder if a temporary fix would be reloading the start up of the application or the authorization or whatever restarting the application does to "fix" it when the error is detected (which seems to be from librespot)

<!-- gh-comment-id:2613136856 --> @alexjyong commented on GitHub (Jan 24, 2025): I wonder if a temporary fix would be reloading the start up of the application or the authorization or whatever restarting the application does to "fix" it when the error is detected (which seems to be from librespot)
Author
Owner

@alexjyong commented on GitHub (Jan 24, 2025):

I wonder if this is related to here: https://github.com/librespot-org/librespot/issues/1101

<!-- gh-comment-id:2613357164 --> @alexjyong commented on GitHub (Jan 24, 2025): I wonder if this is related to here: https://github.com/librespot-org/librespot/issues/1101
Author
Owner

@alexjyong commented on GitHub (Jan 29, 2025):

Got some logs to help out.

It got to this song, and just started playing it on repeat.

Looks like something is busted with librespot.

spotify_player version 0.20.4
MacOS Sequoia 15.2

2025-01-29T18:42:40.500884Z  INFO librespot_playback::player: Loading <Parasite Eve> with Spotify URI <spotify:track:36xBFaVGjqm7le8CTHytUj>    
2025-01-29T18:42:40.986714Z  INFO librespot_playback::player: <Parasite Eve> (291812 ms) loaded    
2025-01-29T18:43:10.327336Z  INFO spotify_player::streaming: Got a new player event: EndOfTrack { playable_id: Track(TrackId("4oiUXa6wYoykN9K0RgXIo9")) }
2025-01-29T18:43:10.328868Z  INFO spotify_player::streaming: Got a new player event: Changed { playable_id: Track(TrackId("36xBFaVGjqm7le8CTHytUj")) }
2025-01-29T18:43:10.328914Z  INFO spotify_player::streaming: Got a new player event: Playing { playable_id: Track(TrackId("36xBFaVGjqm7le8CTHytUj")), position_ms: 0 }
2025-01-29T18:43:11.302758Z  INFO client_request{request=GetCurrentPlayback}: spotify_player::client: Successfully handled the client request, took: 463ms
2025-01-29T18:43:12.173237Z  INFO client_request{request=GetCurrentUserQueue}: spotify_player::client: Successfully handled the client request, took: 332ms
2025-01-29T18:47:33.113028Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) }    
2025-01-29T18:47:33.129700Z  WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([173, 243, 171, 150, 188, 62, 78, 155, 141, 35, 12, 186, 238, 89, 221, 248]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [9] of 50    
2025-01-29T18:47:33.240393Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) }    
2025-01-29T18:47:33.246455Z  WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([173, 243, 171, 150, 188, 62, 78, 155, 141, 35, 12, 186, 238, 89, 221, 248]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [9] of 50    
2025-01-29T18:47:33.246531Z  WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([186, 209, 27, 161, 155, 105, 74, 71, 133, 225, 152, 107, 2, 211, 214, 73]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [10] of 50    
2025-01-29T18:47:33.354517Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) }    
2025-01-29T18:47:33.358450Z  WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([173, 243, 171, 150, 188, 62, 78, 155, 141, 35, 12, 186, 238, 89, 221, 248]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [9] of 50    

And after a ton of those logs, eventually loads the last song played

025-01-29T18:48:02.387691Z  INFO spotify_player::streaming: Got a new player event: EndOfTrack { playable_id: Track(TrackId("36xBFaVGjqm7le8CTHytUj")) }

And just keeps doing that over and over.

<!-- gh-comment-id:2622637583 --> @alexjyong commented on GitHub (Jan 29, 2025): Got some logs to help out. It got to this song, and just started playing it on repeat. Looks like something is busted with librespot. spotify_player version `0.20.4` MacOS Sequoia 15.2 ```bash 2025-01-29T18:42:40.500884Z INFO librespot_playback::player: Loading <Parasite Eve> with Spotify URI <spotify:track:36xBFaVGjqm7le8CTHytUj> 2025-01-29T18:42:40.986714Z INFO librespot_playback::player: <Parasite Eve> (291812 ms) loaded 2025-01-29T18:43:10.327336Z INFO spotify_player::streaming: Got a new player event: EndOfTrack { playable_id: Track(TrackId("4oiUXa6wYoykN9K0RgXIo9")) } 2025-01-29T18:43:10.328868Z INFO spotify_player::streaming: Got a new player event: Changed { playable_id: Track(TrackId("36xBFaVGjqm7le8CTHytUj")) } 2025-01-29T18:43:10.328914Z INFO spotify_player::streaming: Got a new player event: Playing { playable_id: Track(TrackId("36xBFaVGjqm7le8CTHytUj")), position_ms: 0 } 2025-01-29T18:43:11.302758Z INFO client_request{request=GetCurrentPlayback}: spotify_player::client: Successfully handled the client request, took: 463ms 2025-01-29T18:43:12.173237Z INFO client_request{request=GetCurrentUserQueue}: spotify_player::client: Successfully handled the client request, took: 332ms 2025-01-29T18:47:33.113028Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) } 2025-01-29T18:47:33.129700Z WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([173, 243, 171, 150, 188, 62, 78, 155, 141, 35, 12, 186, 238, 89, 221, 248]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [9] of 50 2025-01-29T18:47:33.240393Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) } 2025-01-29T18:47:33.246455Z WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([173, 243, 171, 150, 188, 62, 78, 155, 141, 35, 12, 186, 238, 89, 221, 248]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [9] of 50 2025-01-29T18:47:33.246531Z WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([186, 209, 27, 161, 155, 105, 74, 71, 133, 225, 152, 107, 2, 211, 214, 73]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [10] of 50 2025-01-29T18:47:33.354517Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) } 2025-01-29T18:47:33.358450Z WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([173, 243, 171, 150, 188, 62, 78, 155, 141, 35, 12, 186, 238, 89, 221, 248]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [9] of 50 ``` And after a ton of those logs, eventually loads the last song played ```bash 025-01-29T18:48:02.387691Z INFO spotify_player::streaming: Got a new player event: EndOfTrack { playable_id: Track(TrackId("36xBFaVGjqm7le8CTHytUj")) } ``` And just keeps doing that over and over.
Author
Owner

@alexjyong commented on GitHub (Jan 29, 2025):

Also when the bug happens, I noticed this:

Hitting next track button or whatever just plays the same song over and over.

Selecting a new playlist and starting that will cause the player to show it "playing" but it's silent.

Logs from that are:

2025-01-29T20:21:23.091439Z  INFO spotify_player::streaming: Got a new player event: Changed { playable_id: Track(TrackId("0ubdTEsfanQa7FZ0tpmUQS")) }
2025-01-29T20:21:23.091509Z  INFO spotify_player::streaming: Got a new player event: Playing { playable_id: Track(TrackId("0ubdTEsfanQa7FZ0tpmUQS")), position_ms: 0 }
2025-01-29T20:21:23.099226Z  INFO client_request{request=Player(NextTrack)}: spotify_player::client: Successfully handled the client request, took: 172ms
2025-01-29T20:21:28.672575Z  INFO spotify_player::client::handlers: Current context ID (None) is different from the expected ID (Some(Tracks(TracksId { uri: "tracks:user-liked-tracks", kind: "Liked Tracks" }))), update the context state
2025-01-29T20:21:33.744591Z  INFO client_request{request=GetUserSavedTracks}: spotify_player::client: Successfully handled the client request, took: 5165ms
2025-01-29T20:21:37.467263Z  INFO client_request{request=Player(ResumePause)}: spotify_player::client: Successfully handled the client request, took: 161ms
2025-01-29T20:21:37.736437Z  INFO spotify_player::streaming: Got a new player event: Paused { playable_id: Track(TrackId("0ubdTEsfanQa7FZ0tpmUQS")), position_ms: 14152 }
2025-01-29T20:21:39.091813Z  INFO spotify_player::streaming: Got a new player event: Playing { playable_id: Track(TrackId("0ubdTEsfanQa7FZ0tpmUQS")), position_ms: 14152 }
2025-01-29T20:21:39.109898Z  INFO client_request{request=Player(ResumePause)}: spotify_player::client: Successfully handled the client request, took: 154ms
2025-01-29T20:21:40.193838Z ERROR librespot_connect::spirc: ContextError: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) }    
2025-01-29T20:21:40.229752Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) }    
2025-01-29T20:21:40.229820Z ERROR librespot_playback::player: Skipping to next track, unable to load track <SpotifyId("spotify:track:2q3X0uc2XpGruqitKOm3xa")>: ()    
2025-01-29T20:21:40.314118Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) }    
2025-01-29T20:21:40.314117Z  INFO client_request{request=Player(StartPlayback(URIs([Track(TrackId("2q3X0uc2XpGruqitKOm3xa")), Track(TrackId("25XKxXQy5AhBZ2uOizLQGw")), Track(TrackId("1HIa0liEraMyLrtgmW3xt9")), Track(TrackId("3buDoGEwFbwS8ozgA5o3lA")), Track(TrackId("5m2hTL0rNlQRMV56KjWCuS")), Track(TrackId("3akkA8iMHlemz2PRtTvqXp")), Track(TrackId("58NXzeA8zItIXVswwmfZC7")), Track(TrackId("0ICNCIl4m3g4xC8zvxCq5f")), Track(TrackId("6DpcY8DLvDyMjJri97HNFy")), Track(TrackId("2sk775aCajRMi5P1Y7iZxH")), Track(TrackId("6shny2UVkpaLc7jEKEoePa")), Track(TrackId("4g5ruCCmwecyY7ByndAFlJ")), Track(TrackId("6JH9yWhgbm0y9iAJhCslNc")), Track(TrackId("4oiUXa6wYoykN9K0RgXIo9")), Track(TrackId("0fsgieABBLYkx6rk5N3JUD")), Track(TrackId("5Fp1utsvyFfjmdA6eUVbiK")), Track(TrackId("5jwoygernfGvAuIxFSqxHp")), Track(TrackId("2JJ5h2I1S0UR4tyD0U1I7K")), Track(TrackId("5toE2GI4iMIpelQtzKNT9Q")), Track(TrackId("5Gw8owErJLfkNxWCSwPQKJ")), Track(TrackId("6StYvRLBf8wZPng4WO6buh")), Track(TrackId("2St4KVc4VtQgw99dnrcAnl")), Track(TrackId("2rAMEH9r80J7vGtT2ZVuwn")), Track(TrackId("5W8iKSFnp8N38ERrcLtpO1")), Track(TrackId("1IcRnn7NNkCsPsAGV8xKHB")), Track(TrackId("4Hw9NiMaUNbTYDKE3qeptO")), Track(TrackId("32Wy13eItx5ym93GYRpXWt")), Track(TrackId("0F4FejjWi3bf5vGOkuQwPS")), Track(TrackId("0K8F4CSsccQwvrJUGoa5Rh")), Track(TrackId("3WATWS2Ywo5HeHtG0bE2iZ")), Track(TrackId("36xBFaVGjqm7le8CTHytUj")), Track(TrackId("5if1S3Mum2rNsxrV1v85vi")), Track(TrackId("0Hh9uHCNBP8520LWT78QUt")), Track(TrackId("1g5ZApGqk4w8za1VOhe732")), Track(TrackId("6vIguoUNGW50bed58QaHrq")), Track(TrackId("6MzofobZt2dm0Kf1hTThFz")), Track(TrackId("2QksEBgHuU55xEwAXkHoXl")), Track(TrackId("3Pyb7rYWBsRL24vmdlzlxk")), Track(TrackId("4rUTAkOU7OkVGeQuyQCHhF")), Track(TrackId("1azxOUjt2VSjhqRvgRDryg")), Track(TrackId("4dmnMLxnELfEWTpbOXnw3Z")), Track(TrackId("5QL21dLxEx7JozlRlPX5Qa")), Track(TrackId("0ubdTEsfanQa7FZ0tpmUQS")), Track(TrackId("0142jVxzJD3y7W3uRJoYJz")), Track(TrackId("3OvxVobtv3tUBIA0ed7gPC")), Track(TrackId("7IS0GcLwLTbo8Xy96wFLCt")), Track(TrackId("3DiJ8j1HEqosI3b20DmLrk")), Track(TrackId("2gT72HL4Y84K2Mle3miAMJ")), Track(TrackId("1Vl4ESWb6U7gKSPfK4qenq")), Track(TrackId("3B7qUC4XyS3MgSCy6GmR8s"))], Some(Uri("spotify:track:2q3X0uc2XpGruqitKOm3xa"))), None))}: spotify_player::client: Successfully handled the client request, took: 427ms
2025-01-29T20:21:42.092378Z  INFO client_request{request=GetCurrentUserQueue}: spotify_player::client: Successfully handled the client request, took: 391ms
2025-01-29T20:21:47.095102Z ERROR librespot_connect::spirc: ContextError: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) }    
2025-01-29T20:21:47.140935Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) }    
2025-01-29T20:21:47.141010Z ERROR librespot_playback::player: Skipping to next track, unable to load track <SpotifyId("spotify:track:3akkA8iMHlemz2PRtTvqXp")>: ()    
2025-01-29T20:21:47.206563Z  INFO client_request{request=Player(StartPlayback(URIs([Track(TrackId("2q3X0uc2XpGruqitKOm3xa")), Track(TrackId("25XKxXQy5AhBZ2uOizLQGw")), Track(TrackId("1HIa0liEraMyLrtgmW3xt9")), Track(TrackId("3buDoGEwFbwS8ozgA5o3lA")), Track(TrackId("5m2hTL0rNlQRMV56KjWCuS")), Track(TrackId("3akkA8iMHlemz2PRtTvqXp")), Track(TrackId("58NXzeA8zItIXVswwmfZC7")), Track(TrackId("0ICNCIl4m3g4xC8zvxCq5f")), Track(TrackId("6DpcY8DLvDyMjJri97HNFy")), Track(TrackId("2sk775aCajRMi5P1Y7iZxH")), Track(TrackId("6shny2UVkpaLc7jEKEoePa")), Track(TrackId("4g5ruCCmwecyY7ByndAFlJ")), Track(TrackId("6JH9yWhgbm0y9iAJhCslNc")), Track(TrackId("4oiUXa6wYoykN9K0RgXIo9")), Track(TrackId("0fsgieABBLYkx6rk5N3JUD")), Track(TrackId("5Fp1utsvyFfjmdA6eUVbiK")), Track(TrackId("5jwoygernfGvAuIxFSqxHp")), Track(TrackId("2JJ5h2I1S0UR4tyD0U1I7K")), Track(TrackId("5toE2GI4iMIpelQtzKNT9Q")), Track(TrackId("5Gw8owErJLfkNxWCSwPQKJ")), Track(TrackId("6StYvRLBf8wZPng4WO6buh")), Track(TrackId("2St4KVc4VtQgw99dnrcAnl")), Track(TrackId("2rAMEH9r80J7vGtT2ZVuwn")), Track(TrackId("5W8iKSFnp8N38ERrcLtpO1")), Track(TrackId("1IcRnn7NNkCsPsAGV8xKHB")), Track(TrackId("4Hw9NiMaUNbTYDKE3qeptO")), Track(TrackId("32Wy13eItx5ym93GYRpXWt")), Track(TrackId("0F4FejjWi3bf5vGOkuQwPS")), Track(TrackId("0K8F4CSsccQwvrJUGoa5Rh")), Track(TrackId("3WATWS2Ywo5HeHtG0bE2iZ")), Track(TrackId("36xBFaVGjqm7le8CTHytUj")), Track(TrackId("5if1S3Mum2rNsxrV1v85vi")), Track(TrackId("0Hh9uHCNBP8520LWT78QUt")), Track(TrackId("1g5ZApGqk4w8za1VOhe732")), Track(TrackId("6vIguoUNGW50bed58QaHrq")), Track(TrackId("6MzofobZt2dm0Kf1hTThFz")), Track(TrackId("2QksEBgHuU55xEwAXkHoXl")), Track(TrackId("3Pyb7rYWBsRL24vmdlzlxk")), Track(TrackId("4rUTAkOU7OkVGeQuyQCHhF")), Track(TrackId("1azxOUjt2VSjhqRvgRDryg")), Track(TrackId("4dmnMLxnELfEWTpbOXnw3Z")), Track(TrackId("5QL21dLxEx7JozlRlPX5Qa")), Track(TrackId("0ubdTEsfanQa7FZ0tpmUQS")), Track(TrackId("0142jVxzJD3y7W3uRJoYJz")), Track(TrackId("3OvxVobtv3tUBIA0ed7gPC")), Track(TrackId("7IS0GcLwLTbo8Xy96wFLCt")), Track(TrackId("3DiJ8j1HEqosI3b20DmLrk")), Track(TrackId("2gT72HL4Y84K2Mle3miAMJ")), Track(TrackId("1Vl4ESWb6U7gKSPfK4qenq")), Track(TrackId("3B7qUC4XyS3MgSCy6GmR8s"))], Some(Uri("spotify:track:3akkA8iMHlemz2PRtTvqXp"))), None))}: spotify_player::client: Successfully handled the client request, took: 479ms
2025-01-29T20:21:47.222875Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) }    
2025-01-29T20:21:49.015309Z  INFO client_request{request=GetCurrentUserQueue}: spotify_player::client: Successfully handled the client request, took: 300ms
2025-01-29T20:22:16.938442Z  INFO client_request{request=Player(ResumePause)}: spotify_player::client: Successfully handled the client request, took: 166ms
2025-01-29T20:22:17.795377Z  INFO client_request{request=Player(ResumePause)}: spotify_player::client: Successfully handled the client request, took: 181ms
2025-01-29T20:22:18.229576Z ERROR librespot_connect::spirc: ContextError: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) }    
2025-01-29T20:22:18.270957Z  INFO client_request{request=Player(StartPlayback(URIs([Track(TrackId("2q3X0uc2XpGruqitKOm3xa")), Track(TrackId("25XKxXQy5AhBZ2uOizLQGw")), Track(TrackId("1HIa0liEraMyLrtgmW3xt9")), Track(TrackId("3buDoGEwFbwS8ozgA5o3lA")), Track(TrackId("5m2hTL0rNlQRMV56KjWCuS")), Track(TrackId("3akkA8iMHlemz2PRtTvqXp")), Track(TrackId("58NXzeA8zItIXVswwmfZC7")), Track(TrackId("0ICNCIl4m3g4xC8zvxCq5f")), Track(TrackId("6DpcY8DLvDyMjJri97HNFy")), Track(TrackId("2sk775aCajRMi5P1Y7iZxH")), Track(TrackId("6shny2UVkpaLc7jEKEoePa")), Track(TrackId("4g5ruCCmwecyY7ByndAFlJ")), Track(TrackId("6JH9yWhgbm0y9iAJhCslNc")), Track(TrackId("4oiUXa6wYoykN9K0RgXIo9")), Track(TrackId("0fsgieABBLYkx6rk5N3JUD")), Track(TrackId("5Fp1utsvyFfjmdA6eUVbiK")), Track(TrackId("5jwoygernfGvAuIxFSqxHp")), Track(TrackId("2JJ5h2I1S0UR4tyD0U1I7K")), Track(TrackId("5toE2GI4iMIpelQtzKNT9Q")), Track(TrackId("5Gw8owErJLfkNxWCSwPQKJ")), Track(TrackId("6StYvRLBf8wZPng4WO6buh")), Track(TrackId("2St4KVc4VtQgw99dnrcAnl")), Track(TrackId("2rAMEH9r80J7vGtT2ZVuwn")), Track(TrackId("5W8iKSFnp8N38ERrcLtpO1")), Track(TrackId("1IcRnn7NNkCsPsAGV8xKHB")), Track(TrackId("4Hw9NiMaUNbTYDKE3qeptO")), Track(TrackId("32Wy13eItx5ym93GYRpXWt")), Track(TrackId("0F4FejjWi3bf5vGOkuQwPS")), Track(TrackId("0K8F4CSsccQwvrJUGoa5Rh")), Track(TrackId("3WATWS2Ywo5HeHtG0bE2iZ")), Track(TrackId("36xBFaVGjqm7le8CTHytUj")), Track(TrackId("5if1S3Mum2rNsxrV1v85vi")), Track(TrackId("0Hh9uHCNBP8520LWT78QUt")), Track(TrackId("1g5ZApGqk4w8za1VOhe732")), Track(TrackId("6vIguoUNGW50bed58QaHrq")), Track(TrackId("6MzofobZt2dm0Kf1hTThFz")), Track(TrackId("2QksEBgHuU55xEwAXkHoXl")), Track(TrackId("3Pyb7rYWBsRL24vmdlzlxk")), Track(TrackId("4rUTAkOU7OkVGeQuyQCHhF")), Track(TrackId("1azxOUjt2VSjhqRvgRDryg")), Track(TrackId("4dmnMLxnELfEWTpbOXnw3Z")), Track(TrackId("5QL21dLxEx7JozlRlPX5Qa")), Track(TrackId("0ubdTEsfanQa7FZ0tpmUQS")), Track(TrackId("0142jVxzJD3y7W3uRJoYJz")), Track(TrackId("3OvxVobtv3tUBIA0ed7gPC")), Track(TrackId("7IS0GcLwLTbo8Xy96wFLCt")), Track(TrackId("3DiJ8j1HEqosI3b20DmLrk")), Track(TrackId("2gT72HL4Y84K2Mle3miAMJ")), Track(TrackId("1Vl4ESWb6U7gKSPfK4qenq")), Track(TrackId("3B7qUC4XyS3MgSCy6GmR8s"))], Some(Uri("spotify:track:58NXzeA8zItIXVswwmfZC7"))), None))}: spotify_player::client: Successfully handled the client request, took: 283ms
2025-01-29T20:22:18.271009Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) }    
2025-01-29T20:22:18.271091Z ERROR librespot_playback::player: Skipping to next track, unable to load track <SpotifyId("spotify:track:58NXzeA8zItIXVswwmfZC7")>: ()    
2025-01-29T20:22:18.350277Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) }    
2025-01-29T20:22:20.028697Z  INFO client_request{request=GetCurrentUserQueue}: spotify_player::client: Successfully handled the client request, took: 241ms

Only restarting the player completely fixes this.

<!-- gh-comment-id:2622766803 --> @alexjyong commented on GitHub (Jan 29, 2025): Also when the bug happens, I noticed this: Hitting next track button or whatever just plays the same song over and over. Selecting a new playlist and starting that will cause the player to show it "playing" but it's silent. Logs from that are: ```bash 2025-01-29T20:21:23.091439Z INFO spotify_player::streaming: Got a new player event: Changed { playable_id: Track(TrackId("0ubdTEsfanQa7FZ0tpmUQS")) } 2025-01-29T20:21:23.091509Z INFO spotify_player::streaming: Got a new player event: Playing { playable_id: Track(TrackId("0ubdTEsfanQa7FZ0tpmUQS")), position_ms: 0 } 2025-01-29T20:21:23.099226Z INFO client_request{request=Player(NextTrack)}: spotify_player::client: Successfully handled the client request, took: 172ms 2025-01-29T20:21:28.672575Z INFO spotify_player::client::handlers: Current context ID (None) is different from the expected ID (Some(Tracks(TracksId { uri: "tracks:user-liked-tracks", kind: "Liked Tracks" }))), update the context state 2025-01-29T20:21:33.744591Z INFO client_request{request=GetUserSavedTracks}: spotify_player::client: Successfully handled the client request, took: 5165ms 2025-01-29T20:21:37.467263Z INFO client_request{request=Player(ResumePause)}: spotify_player::client: Successfully handled the client request, took: 161ms 2025-01-29T20:21:37.736437Z INFO spotify_player::streaming: Got a new player event: Paused { playable_id: Track(TrackId("0ubdTEsfanQa7FZ0tpmUQS")), position_ms: 14152 } 2025-01-29T20:21:39.091813Z INFO spotify_player::streaming: Got a new player event: Playing { playable_id: Track(TrackId("0ubdTEsfanQa7FZ0tpmUQS")), position_ms: 14152 } 2025-01-29T20:21:39.109898Z INFO client_request{request=Player(ResumePause)}: spotify_player::client: Successfully handled the client request, took: 154ms 2025-01-29T20:21:40.193838Z ERROR librespot_connect::spirc: ContextError: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) } 2025-01-29T20:21:40.229752Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) } 2025-01-29T20:21:40.229820Z ERROR librespot_playback::player: Skipping to next track, unable to load track <SpotifyId("spotify:track:2q3X0uc2XpGruqitKOm3xa")>: () 2025-01-29T20:21:40.314118Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) } 2025-01-29T20:21:40.314117Z INFO client_request{request=Player(StartPlayback(URIs([Track(TrackId("2q3X0uc2XpGruqitKOm3xa")), Track(TrackId("25XKxXQy5AhBZ2uOizLQGw")), Track(TrackId("1HIa0liEraMyLrtgmW3xt9")), Track(TrackId("3buDoGEwFbwS8ozgA5o3lA")), Track(TrackId("5m2hTL0rNlQRMV56KjWCuS")), Track(TrackId("3akkA8iMHlemz2PRtTvqXp")), Track(TrackId("58NXzeA8zItIXVswwmfZC7")), Track(TrackId("0ICNCIl4m3g4xC8zvxCq5f")), Track(TrackId("6DpcY8DLvDyMjJri97HNFy")), Track(TrackId("2sk775aCajRMi5P1Y7iZxH")), Track(TrackId("6shny2UVkpaLc7jEKEoePa")), Track(TrackId("4g5ruCCmwecyY7ByndAFlJ")), Track(TrackId("6JH9yWhgbm0y9iAJhCslNc")), Track(TrackId("4oiUXa6wYoykN9K0RgXIo9")), Track(TrackId("0fsgieABBLYkx6rk5N3JUD")), Track(TrackId("5Fp1utsvyFfjmdA6eUVbiK")), Track(TrackId("5jwoygernfGvAuIxFSqxHp")), Track(TrackId("2JJ5h2I1S0UR4tyD0U1I7K")), Track(TrackId("5toE2GI4iMIpelQtzKNT9Q")), Track(TrackId("5Gw8owErJLfkNxWCSwPQKJ")), Track(TrackId("6StYvRLBf8wZPng4WO6buh")), Track(TrackId("2St4KVc4VtQgw99dnrcAnl")), Track(TrackId("2rAMEH9r80J7vGtT2ZVuwn")), Track(TrackId("5W8iKSFnp8N38ERrcLtpO1")), Track(TrackId("1IcRnn7NNkCsPsAGV8xKHB")), Track(TrackId("4Hw9NiMaUNbTYDKE3qeptO")), Track(TrackId("32Wy13eItx5ym93GYRpXWt")), Track(TrackId("0F4FejjWi3bf5vGOkuQwPS")), Track(TrackId("0K8F4CSsccQwvrJUGoa5Rh")), Track(TrackId("3WATWS2Ywo5HeHtG0bE2iZ")), Track(TrackId("36xBFaVGjqm7le8CTHytUj")), Track(TrackId("5if1S3Mum2rNsxrV1v85vi")), Track(TrackId("0Hh9uHCNBP8520LWT78QUt")), Track(TrackId("1g5ZApGqk4w8za1VOhe732")), Track(TrackId("6vIguoUNGW50bed58QaHrq")), Track(TrackId("6MzofobZt2dm0Kf1hTThFz")), Track(TrackId("2QksEBgHuU55xEwAXkHoXl")), Track(TrackId("3Pyb7rYWBsRL24vmdlzlxk")), Track(TrackId("4rUTAkOU7OkVGeQuyQCHhF")), Track(TrackId("1azxOUjt2VSjhqRvgRDryg")), Track(TrackId("4dmnMLxnELfEWTpbOXnw3Z")), Track(TrackId("5QL21dLxEx7JozlRlPX5Qa")), Track(TrackId("0ubdTEsfanQa7FZ0tpmUQS")), Track(TrackId("0142jVxzJD3y7W3uRJoYJz")), Track(TrackId("3OvxVobtv3tUBIA0ed7gPC")), Track(TrackId("7IS0GcLwLTbo8Xy96wFLCt")), Track(TrackId("3DiJ8j1HEqosI3b20DmLrk")), Track(TrackId("2gT72HL4Y84K2Mle3miAMJ")), Track(TrackId("1Vl4ESWb6U7gKSPfK4qenq")), Track(TrackId("3B7qUC4XyS3MgSCy6GmR8s"))], Some(Uri("spotify:track:2q3X0uc2XpGruqitKOm3xa"))), None))}: spotify_player::client: Successfully handled the client request, took: 427ms 2025-01-29T20:21:42.092378Z INFO client_request{request=GetCurrentUserQueue}: spotify_player::client: Successfully handled the client request, took: 391ms 2025-01-29T20:21:47.095102Z ERROR librespot_connect::spirc: ContextError: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) } 2025-01-29T20:21:47.140935Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) } 2025-01-29T20:21:47.141010Z ERROR librespot_playback::player: Skipping to next track, unable to load track <SpotifyId("spotify:track:3akkA8iMHlemz2PRtTvqXp")>: () 2025-01-29T20:21:47.206563Z INFO client_request{request=Player(StartPlayback(URIs([Track(TrackId("2q3X0uc2XpGruqitKOm3xa")), Track(TrackId("25XKxXQy5AhBZ2uOizLQGw")), Track(TrackId("1HIa0liEraMyLrtgmW3xt9")), Track(TrackId("3buDoGEwFbwS8ozgA5o3lA")), Track(TrackId("5m2hTL0rNlQRMV56KjWCuS")), Track(TrackId("3akkA8iMHlemz2PRtTvqXp")), Track(TrackId("58NXzeA8zItIXVswwmfZC7")), Track(TrackId("0ICNCIl4m3g4xC8zvxCq5f")), Track(TrackId("6DpcY8DLvDyMjJri97HNFy")), Track(TrackId("2sk775aCajRMi5P1Y7iZxH")), Track(TrackId("6shny2UVkpaLc7jEKEoePa")), Track(TrackId("4g5ruCCmwecyY7ByndAFlJ")), Track(TrackId("6JH9yWhgbm0y9iAJhCslNc")), Track(TrackId("4oiUXa6wYoykN9K0RgXIo9")), Track(TrackId("0fsgieABBLYkx6rk5N3JUD")), Track(TrackId("5Fp1utsvyFfjmdA6eUVbiK")), Track(TrackId("5jwoygernfGvAuIxFSqxHp")), Track(TrackId("2JJ5h2I1S0UR4tyD0U1I7K")), Track(TrackId("5toE2GI4iMIpelQtzKNT9Q")), Track(TrackId("5Gw8owErJLfkNxWCSwPQKJ")), Track(TrackId("6StYvRLBf8wZPng4WO6buh")), Track(TrackId("2St4KVc4VtQgw99dnrcAnl")), Track(TrackId("2rAMEH9r80J7vGtT2ZVuwn")), Track(TrackId("5W8iKSFnp8N38ERrcLtpO1")), Track(TrackId("1IcRnn7NNkCsPsAGV8xKHB")), Track(TrackId("4Hw9NiMaUNbTYDKE3qeptO")), Track(TrackId("32Wy13eItx5ym93GYRpXWt")), Track(TrackId("0F4FejjWi3bf5vGOkuQwPS")), Track(TrackId("0K8F4CSsccQwvrJUGoa5Rh")), Track(TrackId("3WATWS2Ywo5HeHtG0bE2iZ")), Track(TrackId("36xBFaVGjqm7le8CTHytUj")), Track(TrackId("5if1S3Mum2rNsxrV1v85vi")), Track(TrackId("0Hh9uHCNBP8520LWT78QUt")), Track(TrackId("1g5ZApGqk4w8za1VOhe732")), Track(TrackId("6vIguoUNGW50bed58QaHrq")), Track(TrackId("6MzofobZt2dm0Kf1hTThFz")), Track(TrackId("2QksEBgHuU55xEwAXkHoXl")), Track(TrackId("3Pyb7rYWBsRL24vmdlzlxk")), Track(TrackId("4rUTAkOU7OkVGeQuyQCHhF")), Track(TrackId("1azxOUjt2VSjhqRvgRDryg")), Track(TrackId("4dmnMLxnELfEWTpbOXnw3Z")), Track(TrackId("5QL21dLxEx7JozlRlPX5Qa")), Track(TrackId("0ubdTEsfanQa7FZ0tpmUQS")), Track(TrackId("0142jVxzJD3y7W3uRJoYJz")), Track(TrackId("3OvxVobtv3tUBIA0ed7gPC")), Track(TrackId("7IS0GcLwLTbo8Xy96wFLCt")), Track(TrackId("3DiJ8j1HEqosI3b20DmLrk")), Track(TrackId("2gT72HL4Y84K2Mle3miAMJ")), Track(TrackId("1Vl4ESWb6U7gKSPfK4qenq")), Track(TrackId("3B7qUC4XyS3MgSCy6GmR8s"))], Some(Uri("spotify:track:3akkA8iMHlemz2PRtTvqXp"))), None))}: spotify_player::client: Successfully handled the client request, took: 479ms 2025-01-29T20:21:47.222875Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) } 2025-01-29T20:21:49.015309Z INFO client_request{request=GetCurrentUserQueue}: spotify_player::client: Successfully handled the client request, took: 300ms 2025-01-29T20:22:16.938442Z INFO client_request{request=Player(ResumePause)}: spotify_player::client: Successfully handled the client request, took: 166ms 2025-01-29T20:22:17.795377Z INFO client_request{request=Player(ResumePause)}: spotify_player::client: Successfully handled the client request, took: 181ms 2025-01-29T20:22:18.229576Z ERROR librespot_connect::spirc: ContextError: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) } 2025-01-29T20:22:18.270957Z INFO client_request{request=Player(StartPlayback(URIs([Track(TrackId("2q3X0uc2XpGruqitKOm3xa")), Track(TrackId("25XKxXQy5AhBZ2uOizLQGw")), Track(TrackId("1HIa0liEraMyLrtgmW3xt9")), Track(TrackId("3buDoGEwFbwS8ozgA5o3lA")), Track(TrackId("5m2hTL0rNlQRMV56KjWCuS")), Track(TrackId("3akkA8iMHlemz2PRtTvqXp")), Track(TrackId("58NXzeA8zItIXVswwmfZC7")), Track(TrackId("0ICNCIl4m3g4xC8zvxCq5f")), Track(TrackId("6DpcY8DLvDyMjJri97HNFy")), Track(TrackId("2sk775aCajRMi5P1Y7iZxH")), Track(TrackId("6shny2UVkpaLc7jEKEoePa")), Track(TrackId("4g5ruCCmwecyY7ByndAFlJ")), Track(TrackId("6JH9yWhgbm0y9iAJhCslNc")), Track(TrackId("4oiUXa6wYoykN9K0RgXIo9")), Track(TrackId("0fsgieABBLYkx6rk5N3JUD")), Track(TrackId("5Fp1utsvyFfjmdA6eUVbiK")), Track(TrackId("5jwoygernfGvAuIxFSqxHp")), Track(TrackId("2JJ5h2I1S0UR4tyD0U1I7K")), Track(TrackId("5toE2GI4iMIpelQtzKNT9Q")), Track(TrackId("5Gw8owErJLfkNxWCSwPQKJ")), Track(TrackId("6StYvRLBf8wZPng4WO6buh")), Track(TrackId("2St4KVc4VtQgw99dnrcAnl")), Track(TrackId("2rAMEH9r80J7vGtT2ZVuwn")), Track(TrackId("5W8iKSFnp8N38ERrcLtpO1")), Track(TrackId("1IcRnn7NNkCsPsAGV8xKHB")), Track(TrackId("4Hw9NiMaUNbTYDKE3qeptO")), Track(TrackId("32Wy13eItx5ym93GYRpXWt")), Track(TrackId("0F4FejjWi3bf5vGOkuQwPS")), Track(TrackId("0K8F4CSsccQwvrJUGoa5Rh")), Track(TrackId("3WATWS2Ywo5HeHtG0bE2iZ")), Track(TrackId("36xBFaVGjqm7le8CTHytUj")), Track(TrackId("5if1S3Mum2rNsxrV1v85vi")), Track(TrackId("0Hh9uHCNBP8520LWT78QUt")), Track(TrackId("1g5ZApGqk4w8za1VOhe732")), Track(TrackId("6vIguoUNGW50bed58QaHrq")), Track(TrackId("6MzofobZt2dm0Kf1hTThFz")), Track(TrackId("2QksEBgHuU55xEwAXkHoXl")), Track(TrackId("3Pyb7rYWBsRL24vmdlzlxk")), Track(TrackId("4rUTAkOU7OkVGeQuyQCHhF")), Track(TrackId("1azxOUjt2VSjhqRvgRDryg")), Track(TrackId("4dmnMLxnELfEWTpbOXnw3Z")), Track(TrackId("5QL21dLxEx7JozlRlPX5Qa")), Track(TrackId("0ubdTEsfanQa7FZ0tpmUQS")), Track(TrackId("0142jVxzJD3y7W3uRJoYJz")), Track(TrackId("3OvxVobtv3tUBIA0ed7gPC")), Track(TrackId("7IS0GcLwLTbo8Xy96wFLCt")), Track(TrackId("3DiJ8j1HEqosI3b20DmLrk")), Track(TrackId("2gT72HL4Y84K2Mle3miAMJ")), Track(TrackId("1Vl4ESWb6U7gKSPfK4qenq")), Track(TrackId("3B7qUC4XyS3MgSCy6GmR8s"))], Some(Uri("spotify:track:58NXzeA8zItIXVswwmfZC7"))), None))}: spotify_player::client: Successfully handled the client request, took: 283ms 2025-01-29T20:22:18.271009Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) } 2025-01-29T20:22:18.271091Z ERROR librespot_playback::player: Skipping to next track, unable to load track <SpotifyId("spotify:track:58NXzeA8zItIXVswwmfZC7")>: () 2025-01-29T20:22:18.350277Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) } 2025-01-29T20:22:20.028697Z INFO client_request{request=GetCurrentUserQueue}: spotify_player::client: Successfully handled the client request, took: 241ms ``` Only restarting the player completely fixes this.
Author
Owner

@cmorgannorris commented on GitHub (Feb 6, 2025):

Same thing is happening to me. Restart fixes it for me, but it happens again pretty soon thereafter.

==> spotify_player: stable 0.20.4 (bottled)
Command driven spotify player
https://github.com/aome510/spotify-player
Installed
/opt/homebrew/Cellar/spotify_player/0.20.4 (8 files, 28.5MB) *
  Poured from bottle using the formulae.brew.sh API on 2025-01-17 at 16:35:45
    Hardware Overview:

      Model Name: MacBook Pro
      Model Identifier: MacBookPro18,1
      Model Number: Z14Z00105LL/A
      Chip: Apple M1 Pro
      Total Number of Cores: 10 (8 performance and 2 efficiency)
      Memory: 32 GB
      System Firmware Version: 11881.81.2
      OS Loader Version: 11881.81.2
      Activation Lock Status: Enabled
<!-- gh-comment-id:2641156030 --> @cmorgannorris commented on GitHub (Feb 6, 2025): Same thing is happening to me. Restart fixes it for me, but it happens again pretty soon thereafter. ``` ==> spotify_player: stable 0.20.4 (bottled) Command driven spotify player https://github.com/aome510/spotify-player Installed /opt/homebrew/Cellar/spotify_player/0.20.4 (8 files, 28.5MB) * Poured from bottle using the formulae.brew.sh API on 2025-01-17 at 16:35:45 ``` ``` Hardware Overview: Model Name: MacBook Pro Model Identifier: MacBookPro18,1 Model Number: Z14Z00105LL/A Chip: Apple M1 Pro Total Number of Cores: 10 (8 performance and 2 efficiency) Memory: 32 GB System Firmware Version: 11881.81.2 OS Loader Version: 11881.81.2 Activation Lock Status: Enabled ```
Author
Owner

@alexjyong commented on GitHub (Feb 6, 2025):

Yeah barring a proper fix either on spotify-player or librespot my vote for a temp fix would be having the application detecting when it's in a loop like this and restarting itself (but saving what playlist, song, etc) it's in to seamlessly recover itself.

I remember seeing somewhere in the code getting a new token with certain errors. No idea off hand how that's triggered. I am curious as to how it's able to recover fully with a restart.

@cmorgannorris what do the logs say on your end?

<!-- gh-comment-id:2641356953 --> @alexjyong commented on GitHub (Feb 6, 2025): Yeah barring a proper fix either on `spotify-player` or `librespot` my vote for a temp fix would be having the application detecting when it's in a loop like this and restarting itself (but saving what playlist, song, etc) it's in to seamlessly recover itself. I remember seeing somewhere in the code getting a new token with certain errors. No idea off hand how that's triggered. I am curious as to how it's able to recover fully with a restart. @cmorgannorris what do the logs say on your end?
Author
Owner

@cmorgannorris commented on GitHub (Feb 7, 2025):

@cmorgannorris what do the logs say on your end?

Here are a few lines from where it starts throwing errors, to where it gets caught in a loop of access token expired. It goes on for thousands of lines.

2025-02-06T22:23:55.313220Z ERROR librespot_connect::spirc: connection ID update selected, but none received    
2025-02-06T23:07:14.581486Z  INFO spotify_player::media_control: Got a media control event: Pause
2025-02-06T23:07:14.583530Z  INFO spotify_player::client: Client's current session is invalid, creating a new session...
2025-02-06T23:07:14.583745Z  INFO spotify_player::auth: Using cached credentials
2025-02-06T23:07:14.583923Z  INFO spotify_player::streaming: Application's connect configurations: ConnectConfig { name: "spotify-player", device_type: Speaker, is_group: false, initial_volume: Some(45875), has_volume_ctrl: true }
2025-02-06T23:07:14.583946Z  INFO librespot_playback::mixer::softmixer: Mixing with softvol and volume control: Log(60.0)    
2025-02-06T23:07:14.583963Z  INFO spotify_player::streaming: Initializing a new integrated player with device_id=07f47820-373e-4414-9fb5-9146c3f1945e
2025-02-06T23:07:14.584031Z  INFO spotify_player::streaming: Starting an integrated Spotify player using librespot's spirc protocol
2025-02-06T23:07:14.584401Z  INFO librespot_playback::convert: Converting with ditherer: tpdf    
2025-02-06T23:07:14.584436Z  INFO librespot_playback::audio_backend::rodio: Using Rodio sink with format S16 and cpal host: CoreAudio    
2025-02-06T23:07:14.584558Z ERROR librespot_core::session: Can't assign requested address (os error 49)    
2025-02-06T23:07:14.584985Z  INFO librespot_playback::audio_backend::rodio: Using audio device: MacBook Pro Speakers    
2025-02-06T23:07:14.948105Z ERROR spotify_player::client::handlers: create new client session: new streaming connection: initialize spirc: Service unavailable { client error (Connect) }: dns error: failed to lookup address information: nodename nor servname provided, or not known: failed to lookup address information: nodename nor servname provided, or not known
2025-02-07T14:35:50.252053Z  INFO client_request{request=GetContext(Playlist(PlaylistId("3WV2oEbXAEFot6iH9Bjzwg")))}: spotify_player::client: Get playlist context: spotify:playlist:3WV2oEbXAEFot6iH9Bjzwg
2025-02-07T14:35:50.252717Z  INFO client_request{request=GetContext(Playlist(PlaylistId("3WV2oEbXAEFot6iH9Bjzwg")))}: spotify_player::token: Getting a new authentication token...
2025-02-07T14:35:50.252824Z ERROR client_request{request=GetContext(Playlist(PlaylistId("3WV2oEbXAEFot6iH9Bjzwg")))}: spotify_player::client::spotify: Failed to get a new token: failed to get the token: Service unavailable { Session is not connected }
2025-02-07T14:35:50.401532Z ERROR client_request{request=GetContext(Playlist(PlaylistId("3WV2oEbXAEFot6iH9Bjzwg")))}: spotify_player::client::handlers: Failed to handle client request: failed to send a Spotify API request https://api.spotify.com/v1/playlists/3WV2oEbXAEFot6iH9Bjzwg: {
  "error": {
    "status": 401,
    "message": "The access token expired"
  }
}
2025-02-07T14:35:55.264702Z  INFO client_request{request=GetContext(Playlist(PlaylistId("3WV2oEbXAEFot6iH9Bjzwg")))}: spotify_player::client: Get playlist context: spotify:playlist:3WV2oEbXAEFot6iH9Bjzwg
2025-02-07T14:35:55.264854Z  INFO client_request{request=GetContext(Playlist(PlaylistId("3WV2oEbXAEFot6iH9Bjzwg")))}: spotify_player::token: Getting a new authentication token...
2025-02-07T14:35:55.264920Z ERROR client_request{request=GetContext(Playlist(PlaylistId("3WV2oEbXAEFot6iH9Bjzwg")))}: spotify_player::client::spotify: Failed to get a new token: failed to get the token: Service unavailable { Session is not connected }
2025-02-07T14:35:55.304049Z ERROR client_request{request=GetContext(Playlist(PlaylistId("3WV2oEbXAEFot6iH9Bjzwg")))}: spotify_player::client::handlers: Failed to handle client request: failed to send a Spotify API request https://api.spotify.com/v1/playlists/3WV2oEbXAEFot6iH9Bjzwg: {
  "error": {
    "status": 401,
    "message": "The access token expired"
  }
}
<!-- gh-comment-id:2643479468 --> @cmorgannorris commented on GitHub (Feb 7, 2025): > [@cmorgannorris](https://github.com/cmorgannorris) what do the logs say on your end? Here are a few lines from where it starts throwing errors, to where it gets caught in a loop of access token expired. It goes on for thousands of lines. ``` 2025-02-06T22:23:55.313220Z ERROR librespot_connect::spirc: connection ID update selected, but none received 2025-02-06T23:07:14.581486Z INFO spotify_player::media_control: Got a media control event: Pause 2025-02-06T23:07:14.583530Z INFO spotify_player::client: Client's current session is invalid, creating a new session... 2025-02-06T23:07:14.583745Z INFO spotify_player::auth: Using cached credentials 2025-02-06T23:07:14.583923Z INFO spotify_player::streaming: Application's connect configurations: ConnectConfig { name: "spotify-player", device_type: Speaker, is_group: false, initial_volume: Some(45875), has_volume_ctrl: true } 2025-02-06T23:07:14.583946Z INFO librespot_playback::mixer::softmixer: Mixing with softvol and volume control: Log(60.0) 2025-02-06T23:07:14.583963Z INFO spotify_player::streaming: Initializing a new integrated player with device_id=07f47820-373e-4414-9fb5-9146c3f1945e 2025-02-06T23:07:14.584031Z INFO spotify_player::streaming: Starting an integrated Spotify player using librespot's spirc protocol 2025-02-06T23:07:14.584401Z INFO librespot_playback::convert: Converting with ditherer: tpdf 2025-02-06T23:07:14.584436Z INFO librespot_playback::audio_backend::rodio: Using Rodio sink with format S16 and cpal host: CoreAudio 2025-02-06T23:07:14.584558Z ERROR librespot_core::session: Can't assign requested address (os error 49) 2025-02-06T23:07:14.584985Z INFO librespot_playback::audio_backend::rodio: Using audio device: MacBook Pro Speakers 2025-02-06T23:07:14.948105Z ERROR spotify_player::client::handlers: create new client session: new streaming connection: initialize spirc: Service unavailable { client error (Connect) }: dns error: failed to lookup address information: nodename nor servname provided, or not known: failed to lookup address information: nodename nor servname provided, or not known 2025-02-07T14:35:50.252053Z INFO client_request{request=GetContext(Playlist(PlaylistId("3WV2oEbXAEFot6iH9Bjzwg")))}: spotify_player::client: Get playlist context: spotify:playlist:3WV2oEbXAEFot6iH9Bjzwg 2025-02-07T14:35:50.252717Z INFO client_request{request=GetContext(Playlist(PlaylistId("3WV2oEbXAEFot6iH9Bjzwg")))}: spotify_player::token: Getting a new authentication token... 2025-02-07T14:35:50.252824Z ERROR client_request{request=GetContext(Playlist(PlaylistId("3WV2oEbXAEFot6iH9Bjzwg")))}: spotify_player::client::spotify: Failed to get a new token: failed to get the token: Service unavailable { Session is not connected } 2025-02-07T14:35:50.401532Z ERROR client_request{request=GetContext(Playlist(PlaylistId("3WV2oEbXAEFot6iH9Bjzwg")))}: spotify_player::client::handlers: Failed to handle client request: failed to send a Spotify API request https://api.spotify.com/v1/playlists/3WV2oEbXAEFot6iH9Bjzwg: { "error": { "status": 401, "message": "The access token expired" } } 2025-02-07T14:35:55.264702Z INFO client_request{request=GetContext(Playlist(PlaylistId("3WV2oEbXAEFot6iH9Bjzwg")))}: spotify_player::client: Get playlist context: spotify:playlist:3WV2oEbXAEFot6iH9Bjzwg 2025-02-07T14:35:55.264854Z INFO client_request{request=GetContext(Playlist(PlaylistId("3WV2oEbXAEFot6iH9Bjzwg")))}: spotify_player::token: Getting a new authentication token... 2025-02-07T14:35:55.264920Z ERROR client_request{request=GetContext(Playlist(PlaylistId("3WV2oEbXAEFot6iH9Bjzwg")))}: spotify_player::client::spotify: Failed to get a new token: failed to get the token: Service unavailable { Session is not connected } 2025-02-07T14:35:55.304049Z ERROR client_request{request=GetContext(Playlist(PlaylistId("3WV2oEbXAEFot6iH9Bjzwg")))}: spotify_player::client::handlers: Failed to handle client request: failed to send a Spotify API request https://api.spotify.com/v1/playlists/3WV2oEbXAEFot6iH9Bjzwg: { "error": { "status": 401, "message": "The access token expired" } } ```
Author
Owner

@alexjyong commented on GitHub (Feb 7, 2025):

Running the RestartIntegratedClient command helps get the player unstuck; although you have to go back into the playlist, queue or whatever you were playing.

<!-- gh-comment-id:2644179140 --> @alexjyong commented on GitHub (Feb 7, 2025): Running the `RestartIntegratedClient` command helps get the player unstuck; although you have to go back into the playlist, queue or whatever you were playing.
Author
Owner

@cmorgannorris commented on GitHub (Feb 11, 2025):

Here are some more logs. I made a note to look right after it got stuck this time. At the top you can see a successful transition from Need You Tonight to Meditate but then it's stuck. It repeats the BAD_REQUEST error and attempts to skip track repeatedly in a just a matter of seconds; I didn't include all of the repeats.

2025-02-10T16:33:31.714415Z  INFO librespot_playback::player: <Need You Tonight - 2017 Remaster> (181240 ms) loaded
2025-02-10T16:34:00.785606Z  INFO spotify_player::streaming: Got a new player event: EndOfTrack { playable_id: Track(TrackId("6MzQ7XYONDIxelWtYXUD66")) }
2025-02-10T16:34:00.787722Z  INFO spotify_player::streaming: Got a new player event: Changed { playable_id: Track(TrackId("2rnPKXJqNJe9fsnj4Sco0y")) }
2025-02-10T16:34:00.787874Z  INFO spotify_player::streaming: Got a new player event: Playing { playable_id: Track(TrackId("2rnPKXJqNJe9fsnj4Sco0y")), position_ms: 0 }
2025-02-10T16:34:02.493506Z  INFO client_request{request=GetCurrentUserQueue}: spotify_player::client: Successfully handled the client request, took: 189ms
2025-02-10T16:36:32.676717Z  INFO librespot_playback::player: Loading <Mediate - 2017 Remaster> with Spotify URI <spotify:track:6yEUfaMzYeSswYo2wxz2Cp>
2025-02-10T16:36:33.137512Z  INFO librespot_playback::player: <Mediate - 2017 Remaster> (155813 ms) loaded
2025-02-10T16:37:02.067231Z  INFO spotify_player::streaming: Got a new player event: EndOfTrack { playable_id: Track(TrackId("2rnPKXJqNJe9fsnj4Sco0y")) }
2025-02-10T16:37:02.069928Z  INFO spotify_player::streaming: Got a new player event: Changed { playable_id: Track(TrackId("6yEUfaMzYeSswYo2wxz2Cp")) }
2025-02-10T16:37:02.070079Z  INFO spotify_player::streaming: Got a new player event: Playing { playable_id: Track(TrackId("6yEUfaMzYeSswYo2wxz2Cp")), position_ms: 0 }
2025-02-10T16:37:02.930205Z  INFO client_request{request=GetCurrentPlayback}: spotify_player::client: Successfully handled the client request, took: 283ms
2025-02-10T16:37:03.785144Z  INFO client_request{request=GetCurrentUserQueue}: spotify_player::client: Successfully handled the client request, took: 136ms
2025-02-10T16:39:08.196398Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) }
2025-02-10T16:39:08.204445Z  WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([221, 8, 155, 2, 183, 111, 69, 129, 160, 189, 40, 187, 75, 22, 165, 224]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [5] of 39
2025-02-10T16:39:08.270998Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) }
2025-02-10T16:39:08.286735Z  WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([221, 8, 155, 2, 183, 111, 69, 129, 160, 189, 40, 187, 75, 22, 165, 224]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [5] of 39
2025-02-10T16:39:08.286912Z  WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([178, 250, 47, 114, 156, 253, 79, 75, 147, 27, 38, 145, 173, 239, 84, 86]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [6] of 39
2025-02-10T16:39:08.331924Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) }
2025-02-10T16:39:08.337627Z  WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([221, 8, 155, 2, 183, 111, 69, 129, 160, 189, 40, 187, 75, 22, 165, 224]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [5] of 39
2025-02-10T16:39:08.337863Z  WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([178, 250, 47, 114, 156, 253, 79, 75, 147, 27, 38, 145, 173, 239, 84, 86]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [6] of 39
2025-02-10T16:39:08.337892Z  WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([61, 22, 127, 121, 108, 143, 78, 77, 188, 38, 157, 129, 59, 113, 140, 28]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [7] of 39
2025-02-10T16:39:08.400585Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) }
2025-02-10T16:39:08.401154Z  WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([221, 8, 155, 2, 183, 111, 69, 129, 160, 189, 40, 187, 75, 22, 165, 224]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [5] of 39

Then at some point it finally gets a new token. I believe I restarted the integrated client, but I can't remember; I was in a hurry to get to the logs and see what was up.

2025-02-10T16:39:37.832467Z  WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([68, 108, 2, 35, 184, 224, 67, 68, 160, 95, 161, 157, 96, 38, 183, 134]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [36] of 39
2025-02-10T16:39:37.832475Z  WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([139, 118, 189, 126, 13, 190, 74, 196, 142, 70, 118, 5, 67, 234, 51, 101]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [37] of 39
2025-02-10T16:39:37.832483Z  WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([140, 191, 15, 3, 35, 136, 79, 64, 137, 80, 104, 146, 202, 21, 209, 213]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [38] of 39
2025-02-10T16:39:37.832492Z  WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([181, 38, 137, 227, 214, 241, 76, 19, 163, 238, 69, 145, 129, 65, 40, 109]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [0] of 39
2025-02-10T16:39:37.832500Z  WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([2, 28, 127, 95, 162, 44, 77, 44, 147, 197, 48, 75, 20, 15, 69, 194]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [1] of 39
2025-02-10T16:39:37.832508Z  WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([222, 226, 146, 181, 255, 100, 64, 214, 139, 169, 108, 104, 71, 100, 140, 198]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [2] of 39
2025-02-10T16:39:37.832516Z  WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([80, 57, 223, 211, 143, 234, 71, 38, 183, 76, 170, 168, 103, 4, 74, 66]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [3] of 39
2025-02-10T16:39:37.833570Z  INFO spotify_player::streaming: Got a new player event: Changed { playable_id: Track(TrackId("6yEUfaMzYeSswYo2wxz2Cp")) }
2025-02-10T16:39:37.833590Z  INFO spotify_player::streaming: Got a new player event: Playing { playable_id: Track(TrackId("6yEUfaMzYeSswYo2wxz2Cp")), position_ms: 0 }
2025-02-10T16:39:37.972651Z  INFO client_request{request=GetCurrentPlayback}: spotify_player::token: Getting a new authentication token...
2025-02-10T16:39:38.016850Z  INFO client_request{request=GetCurrentPlayback}: spotify_player::token: Got new token: Token { access_token: "BQDKxp06MAPW7HdGl-_ZLZd_lSILRtvR_FGWotPF58iJCkfn0LkUI4dXdgR3gyHFhjt9jan3q_zWrLk5pz8RzwlcUCGjl0Vi4vR6Potm4UDkZE0bBzzrrGmj6CEt6Ox7VI0UF0xWwylo2a2u3WpC3dVvBPCgDHNNB4Y9BKtL0pZkt78Ca4NTTjkEh19H5LSowDHm0cdCFL9o2PbSd5HCHuc4fXTAMum7yq2l8-cz9L1eHESOn0uGPLRGgrFZ37uaDAhpqhd-iCIh6XV0-BphxHJ-Epuej9xVy-l8Ie01P0CxK2R3Dgok29A33s7ZWhdb9c21fYFRawo-j5DtZZjpBY9yJPrvyN52v3fF42J_W3qBJMGfjhw2dt_SCYU8pkJ043quMbPyvGmzS0a11oH5bQ", expires_in: TimeDelta { secs: 3600, nanos: 0 }, expires_at: Some(2025-02-10T17:39:38.016844Z), refresh_token: None, scopes: {} }
2025-02-10T16:39:38.278847Z  INFO client_request{request=GetCurrentPlayback}: spotify_player::client: Successfully handled the client request, took: 306ms

Not sure if any of this helps. It's all probably just more of the same but I figured I'd dump it here just so we have the data.

<!-- gh-comment-id:2651035709 --> @cmorgannorris commented on GitHub (Feb 11, 2025): Here are some more logs. I made a note to look right after it got stuck this time. At the top you can see a successful transition from _Need You Tonight_ to _Meditate_ but then it's stuck. It repeats the BAD_REQUEST error and attempts to skip track repeatedly in a just a matter of seconds; I didn't include all of the repeats. ``` 2025-02-10T16:33:31.714415Z INFO librespot_playback::player: <Need You Tonight - 2017 Remaster> (181240 ms) loaded 2025-02-10T16:34:00.785606Z INFO spotify_player::streaming: Got a new player event: EndOfTrack { playable_id: Track(TrackId("6MzQ7XYONDIxelWtYXUD66")) } 2025-02-10T16:34:00.787722Z INFO spotify_player::streaming: Got a new player event: Changed { playable_id: Track(TrackId("2rnPKXJqNJe9fsnj4Sco0y")) } 2025-02-10T16:34:00.787874Z INFO spotify_player::streaming: Got a new player event: Playing { playable_id: Track(TrackId("2rnPKXJqNJe9fsnj4Sco0y")), position_ms: 0 } 2025-02-10T16:34:02.493506Z INFO client_request{request=GetCurrentUserQueue}: spotify_player::client: Successfully handled the client request, took: 189ms 2025-02-10T16:36:32.676717Z INFO librespot_playback::player: Loading <Mediate - 2017 Remaster> with Spotify URI <spotify:track:6yEUfaMzYeSswYo2wxz2Cp> 2025-02-10T16:36:33.137512Z INFO librespot_playback::player: <Mediate - 2017 Remaster> (155813 ms) loaded 2025-02-10T16:37:02.067231Z INFO spotify_player::streaming: Got a new player event: EndOfTrack { playable_id: Track(TrackId("2rnPKXJqNJe9fsnj4Sco0y")) } 2025-02-10T16:37:02.069928Z INFO spotify_player::streaming: Got a new player event: Changed { playable_id: Track(TrackId("6yEUfaMzYeSswYo2wxz2Cp")) } 2025-02-10T16:37:02.070079Z INFO spotify_player::streaming: Got a new player event: Playing { playable_id: Track(TrackId("6yEUfaMzYeSswYo2wxz2Cp")), position_ms: 0 } 2025-02-10T16:37:02.930205Z INFO client_request{request=GetCurrentPlayback}: spotify_player::client: Successfully handled the client request, took: 283ms 2025-02-10T16:37:03.785144Z INFO client_request{request=GetCurrentUserQueue}: spotify_player::client: Successfully handled the client request, took: 136ms 2025-02-10T16:39:08.196398Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) } 2025-02-10T16:39:08.204445Z WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([221, 8, 155, 2, 183, 111, 69, 129, 160, 189, 40, 187, 75, 22, 165, 224]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [5] of 39 2025-02-10T16:39:08.270998Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) } 2025-02-10T16:39:08.286735Z WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([221, 8, 155, 2, 183, 111, 69, 129, 160, 189, 40, 187, 75, 22, 165, 224]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [5] of 39 2025-02-10T16:39:08.286912Z WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([178, 250, 47, 114, 156, 253, 79, 75, 147, 27, 38, 145, 173, 239, 84, 86]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [6] of 39 2025-02-10T16:39:08.331924Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) } 2025-02-10T16:39:08.337627Z WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([221, 8, 155, 2, 183, 111, 69, 129, 160, 189, 40, 187, 75, 22, 165, 224]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [5] of 39 2025-02-10T16:39:08.337863Z WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([178, 250, 47, 114, 156, 253, 79, 75, 147, 27, 38, 145, 173, 239, 84, 86]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [6] of 39 2025-02-10T16:39:08.337892Z WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([61, 22, 127, 121, 108, 143, 78, 77, 188, 38, 157, 129, 59, 113, 140, 28]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [7] of 39 2025-02-10T16:39:08.400585Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) } 2025-02-10T16:39:08.401154Z WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([221, 8, 155, 2, 183, 111, 69, 129, 160, 189, 40, 187, 75, 22, 165, 224]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [5] of 39 ``` Then at some point it finally gets a new token. I believe I restarted the integrated client, but I can't remember; I was in a hurry to get to the logs and see what was up. ``` 2025-02-10T16:39:37.832467Z WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([68, 108, 2, 35, 184, 224, 67, 68, 160, 95, 161, 157, 96, 38, 183, 134]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [36] of 39 2025-02-10T16:39:37.832475Z WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([139, 118, 189, 126, 13, 190, 74, 196, 142, 70, 118, 5, 67, 234, 51, 101]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [37] of 39 2025-02-10T16:39:37.832483Z WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([140, 191, 15, 3, 35, 136, 79, 64, 137, 80, 104, 146, 202, 21, 209, 213]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [38] of 39 2025-02-10T16:39:37.832492Z WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([181, 38, 137, 227, 214, 241, 76, 19, 163, 238, 69, 145, 129, 65, 40, 109]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [0] of 39 2025-02-10T16:39:37.832500Z WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([2, 28, 127, 95, 162, 44, 77, 44, 147, 197, 48, 75, 20, 15, 69, 194]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [1] of 39 2025-02-10T16:39:37.832508Z WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([222, 226, 146, 181, 255, 100, 64, 214, 139, 169, 108, 104, 71, 100, 140, 198]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [2] of 39 2025-02-10T16:39:37.832516Z WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([80, 57, 223, 211, 143, 234, 71, 38, 183, 76, 170, 168, 103, 4, 74, 66]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [3] of 39 2025-02-10T16:39:37.833570Z INFO spotify_player::streaming: Got a new player event: Changed { playable_id: Track(TrackId("6yEUfaMzYeSswYo2wxz2Cp")) } 2025-02-10T16:39:37.833590Z INFO spotify_player::streaming: Got a new player event: Playing { playable_id: Track(TrackId("6yEUfaMzYeSswYo2wxz2Cp")), position_ms: 0 } 2025-02-10T16:39:37.972651Z INFO client_request{request=GetCurrentPlayback}: spotify_player::token: Getting a new authentication token... 2025-02-10T16:39:38.016850Z INFO client_request{request=GetCurrentPlayback}: spotify_player::token: Got new token: Token { access_token: "BQDKxp06MAPW7HdGl-_ZLZd_lSILRtvR_FGWotPF58iJCkfn0LkUI4dXdgR3gyHFhjt9jan3q_zWrLk5pz8RzwlcUCGjl0Vi4vR6Potm4UDkZE0bBzzrrGmj6CEt6Ox7VI0UF0xWwylo2a2u3WpC3dVvBPCgDHNNB4Y9BKtL0pZkt78Ca4NTTjkEh19H5LSowDHm0cdCFL9o2PbSd5HCHuc4fXTAMum7yq2l8-cz9L1eHESOn0uGPLRGgrFZ37uaDAhpqhd-iCIh6XV0-BphxHJ-Epuej9xVy-l8Ie01P0CxK2R3Dgok29A33s7ZWhdb9c21fYFRawo-j5DtZZjpBY9yJPrvyN52v3fF42J_W3qBJMGfjhw2dt_SCYU8pkJ043quMbPyvGmzS0a11oH5bQ", expires_in: TimeDelta { secs: 3600, nanos: 0 }, expires_at: Some(2025-02-10T17:39:38.016844Z), refresh_token: None, scopes: {} } 2025-02-10T16:39:38.278847Z INFO client_request{request=GetCurrentPlayback}: spotify_player::client: Successfully handled the client request, took: 306ms ``` Not sure if any of this helps. It's all probably just more of the same but I figured I'd dump it here just so we have the data.
Author
Owner

@alexjyong commented on GitHub (Feb 11, 2025):

I am getting a lot of theses in my logs now

2025-02-11T21:45:31.147190Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(INVALID_CREDENTIALS) }    
2025-02-11T21:45:31.165698Z  WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([48, 211, 97, 157, 5, 1, 64, 195, 187, 167, 13, 197, 157, 172, 114, 156]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [14] of 50    
2025-02-11T21:45:31.285648Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(INVALID_CREDENTIALS) }    

I did notice in the logs the original token's expiration was around the same time the songs started looping.

I'm guessing when tokens expire, we aren't handling getting new tokens properly or something? I need to test more.

<!-- gh-comment-id:2652152829 --> @alexjyong commented on GitHub (Feb 11, 2025): I am getting a lot of theses in my logs now ``` 2025-02-11T21:45:31.147190Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(INVALID_CREDENTIALS) } 2025-02-11T21:45:31.165698Z WARN librespot_connect::spirc: Skipping track <TrackRef { gid: Some([48, 211, 97, 157, 5, 1, 64, 195, 187, 167, 13, 197, 157, 172, 114, 156]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at position [14] of 50 2025-02-11T21:45:31.285648Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(INVALID_CREDENTIALS) } ``` I did notice in the logs the original token's expiration was around the same time the songs started looping. I'm guessing when tokens expire, we aren't handling getting new tokens properly or something? I need to test more.
Author
Owner

@alexjyong commented on GitHub (Feb 12, 2025):

Just saw this again now

2025-02-12T15:47:34.233796Z  INFO spotify_player::token: Got new token: Token { access_token: "<REDACTED>", expires_in: TimeDelta { secs: 3600, nanos: 0 }, expires_at: Some(2025-02-12T16:47:34.233779Z), refresh_token: None, scopes: {} }

That timestamp converts to 2025-02-12 11:47:34 AM EST which is right around where the songs started looping.

Expiry time matches with logs where error starts happening.

2025-02-12T16:48:49.502040Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(INVALID_CREDENTIALS) }   

My hypothesis is that the tokens expire and we aren't refreshing for a new one.

Looks like we have code to handle this? Wonder what's going on with it not catching this or whatever.

github.com/aome510/spotify-player@78edb10e15/spotify_player/src/client/spotify.rs (L74-L89)

<!-- gh-comment-id:2654311872 --> @alexjyong commented on GitHub (Feb 12, 2025): Just saw this again now ``` 2025-02-12T15:47:34.233796Z INFO spotify_player::token: Got new token: Token { access_token: "<REDACTED>", expires_in: TimeDelta { secs: 3600, nanos: 0 }, expires_at: Some(2025-02-12T16:47:34.233779Z), refresh_token: None, scopes: {} } ``` That timestamp converts to `2025-02-12 11:47:34 AM EST` which is right around where the songs started looping. Expiry time matches with logs where error starts happening. ``` 2025-02-12T16:48:49.502040Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(INVALID_CREDENTIALS) } ``` My hypothesis is that the tokens expire and we aren't refreshing for a new one. Looks like we have code to handle this? Wonder what's going on with it not catching this or whatever. https://github.com/aome510/spotify-player/blob/78edb10e15ddcd8c67e6807bd951e976c8c7b19d/spotify_player/src/client/spotify.rs#L74-L89
Author
Owner

@alexjyong commented on GitHub (Feb 12, 2025):

More logs. Looks like we do refresh the token but we do it multiple times.

2025-02-12T20:09:55.382490Z  INFO spotify_player::streaming: Got a new player event: Changed { playable_id: Track(TrackId("2r1yo1u0PHegpetacdrHh2")) }
2025-02-12T20:09:55.382751Z  INFO spotify_player::streaming: Got a new player event: Playing { playable_id: Track(TrackId("2r1yo1u0PHegpetacdrHh2")), position_ms: 0 }
2025-02-12T20:09:55.384359Z  INFO client_request{request=GetCurrentPlayback}: spotify_player::token: Getting a new authentication token...
2025-02-12T20:09:56.382140Z  INFO spotify_player::token: Getting a new authentication token...
2025-02-12T20:09:56.390039Z  INFO spotify_player::token: Getting a new authentication token...
2025-02-12T20:09:56.390306Z  INFO spotify_player::token: Getting a new authentication token...
2025-02-12T20:09:56.396655Z  INFO client_request{request=GetCurrentPlayback}: spotify_player::token: Getting a new authentication token...
2025-02-12T20:09:57.399376Z  INFO client_request{request=GetCurrentPlayback}: spotify_player::token: Getting a new authentication token...
2025-02-12T20:09:57.588273Z  INFO client_request{request=GetCurrentPlayback}: spotify_player::token: Got new token: Token { access_token: "<REDACTED>", expires_in: TimeDelta { secs: 3600, nanos: 0 }, expires_at: Some(2025-02-12T21:09:57.588264Z), refresh_token: None, scopes: {} }
2025-02-12T20:09:57.598970Z  INFO spotify_player::token: Got new token: Token { access_token: "<REDACTED>", expires_in: TimeDelta { secs: 3600, nanos: 0 }, expires_at: Some(2025-02-12T21:09:57.598963Z), refresh_token: None, scopes: {} }
2025-02-12T20:09:57.599449Z  INFO spotify_player::token: Got new token: Token { access_token: "<REDACTED>", expires_in: TimeDelta { secs: 3600, nanos: 0 }, expires_at: Some(2025-02-12T21:09:57.599449Z), refresh_token: None, scopes: {} }
2025-02-12T20:09:57.599559Z  INFO client_request{request=GetCurrentPlayback}: spotify_player::token: Got new token: Token { access_token: "<REDACTED>", expires_in: TimeDelta { secs: 3600, nanos: 0 }, expires_at: Some(2025-02-12T21:09:57.599558Z), refresh_token: None, scopes: {} }
2025-02-12T20:09:57.599657Z  INFO client_request{request=GetCurrentPlayback}: spotify_player::token: Got new token: Token { access_token: "<REDACTED>", expires_in: TimeDelta { secs: 3600, nanos: 0 }, expires_at: Some(2025-02-12T21:09:57.599657Z), refresh_token: None, scopes: {} }
2025-02-12T20:09:57.599747Z  INFO spotify_player::token: Got new token: Token { access_token: "<REDATED>", expires_in: TimeDelta { secs: 3600, nanos: 0 }, expires_at: Some(2025-02-12T21:09:57.599747Z), refresh_token: None, scopes: {} }

Either way later, it still doesn't work and we get INVALID_CREDENTIALS

2025-02-12T20:13:37.908839Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(INVALID_CREDENTIALS) }    
2025-02-12T20:13:37.909028Z ERROR librespot_playback::player: Skipping to next track, unable to load track <SpotifyId("spotify:track:7Gms5d2KYbWOGLIIJK3kD9")>: ()    
2025-02-12T20:13:37.912692Z ERROR librespot_connect::spirc: ContextError: Error { kind: FailedPrecondition, error: FaultyRequest(INVALID_CREDENTIALS) }    
2025-02-12T20:13:38.032243Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(INVALID_CREDENTIALS) }    
2025-02-12T20:13:39.046414Z  INFO spotify_player::client: Saving the retrieved image into /Users/ajyong/.cache/spotify-player/image/RAT WARS-HEALTH-cover-6tkuHF.jpg

Wonder if the old token is still in play?

Either way, what has been consistent is that after an hour (the token's lifespan) the songs start repeating, and I have to restart the application or RestartIntegratedPlayer

<!-- gh-comment-id:2654851753 --> @alexjyong commented on GitHub (Feb 12, 2025): More logs. Looks like we do refresh the token but we do it multiple times. ``` 2025-02-12T20:09:55.382490Z INFO spotify_player::streaming: Got a new player event: Changed { playable_id: Track(TrackId("2r1yo1u0PHegpetacdrHh2")) } 2025-02-12T20:09:55.382751Z INFO spotify_player::streaming: Got a new player event: Playing { playable_id: Track(TrackId("2r1yo1u0PHegpetacdrHh2")), position_ms: 0 } 2025-02-12T20:09:55.384359Z INFO client_request{request=GetCurrentPlayback}: spotify_player::token: Getting a new authentication token... 2025-02-12T20:09:56.382140Z INFO spotify_player::token: Getting a new authentication token... 2025-02-12T20:09:56.390039Z INFO spotify_player::token: Getting a new authentication token... 2025-02-12T20:09:56.390306Z INFO spotify_player::token: Getting a new authentication token... 2025-02-12T20:09:56.396655Z INFO client_request{request=GetCurrentPlayback}: spotify_player::token: Getting a new authentication token... 2025-02-12T20:09:57.399376Z INFO client_request{request=GetCurrentPlayback}: spotify_player::token: Getting a new authentication token... 2025-02-12T20:09:57.588273Z INFO client_request{request=GetCurrentPlayback}: spotify_player::token: Got new token: Token { access_token: "<REDACTED>", expires_in: TimeDelta { secs: 3600, nanos: 0 }, expires_at: Some(2025-02-12T21:09:57.588264Z), refresh_token: None, scopes: {} } 2025-02-12T20:09:57.598970Z INFO spotify_player::token: Got new token: Token { access_token: "<REDACTED>", expires_in: TimeDelta { secs: 3600, nanos: 0 }, expires_at: Some(2025-02-12T21:09:57.598963Z), refresh_token: None, scopes: {} } 2025-02-12T20:09:57.599449Z INFO spotify_player::token: Got new token: Token { access_token: "<REDACTED>", expires_in: TimeDelta { secs: 3600, nanos: 0 }, expires_at: Some(2025-02-12T21:09:57.599449Z), refresh_token: None, scopes: {} } 2025-02-12T20:09:57.599559Z INFO client_request{request=GetCurrentPlayback}: spotify_player::token: Got new token: Token { access_token: "<REDACTED>", expires_in: TimeDelta { secs: 3600, nanos: 0 }, expires_at: Some(2025-02-12T21:09:57.599558Z), refresh_token: None, scopes: {} } 2025-02-12T20:09:57.599657Z INFO client_request{request=GetCurrentPlayback}: spotify_player::token: Got new token: Token { access_token: "<REDACTED>", expires_in: TimeDelta { secs: 3600, nanos: 0 }, expires_at: Some(2025-02-12T21:09:57.599657Z), refresh_token: None, scopes: {} } 2025-02-12T20:09:57.599747Z INFO spotify_player::token: Got new token: Token { access_token: "<REDATED>", expires_in: TimeDelta { secs: 3600, nanos: 0 }, expires_at: Some(2025-02-12T21:09:57.599747Z), refresh_token: None, scopes: {} } ``` Either way later, it still doesn't work and we get INVALID_CREDENTIALS ``` 2025-02-12T20:13:37.908839Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(INVALID_CREDENTIALS) } 2025-02-12T20:13:37.909028Z ERROR librespot_playback::player: Skipping to next track, unable to load track <SpotifyId("spotify:track:7Gms5d2KYbWOGLIIJK3kD9")>: () 2025-02-12T20:13:37.912692Z ERROR librespot_connect::spirc: ContextError: Error { kind: FailedPrecondition, error: FaultyRequest(INVALID_CREDENTIALS) } 2025-02-12T20:13:38.032243Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(INVALID_CREDENTIALS) } 2025-02-12T20:13:39.046414Z INFO spotify_player::client: Saving the retrieved image into /Users/ajyong/.cache/spotify-player/image/RAT WARS-HEALTH-cover-6tkuHF.jpg ``` Wonder if the old token is still in play? Either way, what has been consistent is that after an hour (the token's lifespan) the songs start repeating, and I have to restart the application or RestartIntegratedPlayer
Author
Owner

@alexjyong commented on GitHub (Mar 3, 2025):

So I made a PR (against my local branch) that sometimes works, but other times, runs into the same issue.

https://github.com/alexjyong/spotify-player/pull/1

Logs

2025-03-03T17:32:00.905532Z  INFO client_request{request=GetCurrentPlayback}: spotify_player::client::spotify: Attempting to refresh token. Current token is: Some("<REDACTED>")
2025-03-03T17:32:00.905965Z  INFO client_request{request=GetCurrentPlayback}: spotify_player::token: Getting a new authentication token...
2025-03-03T17:32:00.973105Z  INFO client_request{request=GetCurrentPlayback}: spotify_player::token: Got new token: Token { access_token: "<REDACTED>", expires_in: TimeDelta { secs: 3600, nanos: 0 }, expires_at: Some(2025-03-03T18:32:00.973101Z), refresh_token: None, scopes: {} }
2025-03-03T17:32:00.973563Z  INFO client_request{request=GetCurrentPlayback}: spotify_player::client::spotify: Got new token: Token { access_token: "<REDACTED>", expires_in: TimeDelta { secs: 3600, nanos: 0 }, expires_at: Some(2025-03-03T18:32:00.973101Z), refresh_token: None, scopes: {} }

Image

One side effect is when the token expires (which happens on the code at the time of writing) is the list of playable items fading away, although navigating to another page, or back to the page you are on fixes it. Would be nice if that could be automated, but this is all new to me.

<!-- gh-comment-id:2695221627 --> @alexjyong commented on GitHub (Mar 3, 2025): So I made a PR (against my local branch) that _sometimes_ works, but other times, runs into the same issue. https://github.com/alexjyong/spotify-player/pull/1 Logs ``` 2025-03-03T17:32:00.905532Z INFO client_request{request=GetCurrentPlayback}: spotify_player::client::spotify: Attempting to refresh token. Current token is: Some("<REDACTED>") 2025-03-03T17:32:00.905965Z INFO client_request{request=GetCurrentPlayback}: spotify_player::token: Getting a new authentication token... 2025-03-03T17:32:00.973105Z INFO client_request{request=GetCurrentPlayback}: spotify_player::token: Got new token: Token { access_token: "<REDACTED>", expires_in: TimeDelta { secs: 3600, nanos: 0 }, expires_at: Some(2025-03-03T18:32:00.973101Z), refresh_token: None, scopes: {} } 2025-03-03T17:32:00.973563Z INFO client_request{request=GetCurrentPlayback}: spotify_player::client::spotify: Got new token: Token { access_token: "<REDACTED>", expires_in: TimeDelta { secs: 3600, nanos: 0 }, expires_at: Some(2025-03-03T18:32:00.973101Z), refresh_token: None, scopes: {} } ``` ![Image](https://github.com/user-attachments/assets/ed6712ac-30ce-4ab3-8a63-c1ab8cb60a74) One side effect is when the token expires (which happens on the code at the time of writing) is the list of playable items fading away, although navigating to another page, or back to the page you are on fixes it. Would be nice if that could be automated, but this is all new to me.
Author
Owner

@alexjyong commented on GitHub (Mar 3, 2025):

Update, while my changes appear to be more stable that whats in master at present, eventually, we run into an error where the song will play silently. You can navigate between different pages, load up different lists, and logs show that we are getting a new token and loading it as expected.

But eventually we end up with

2025-03-03T21:42:27.960859Z ERROR librespot_connect::spirc: ContextError: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) }    
2025-03-03T21:42:28.000041Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) }    
2025-03-03T21:42:28.000302Z ERROR librespot_playback::player: Skipping to next track, unable to load track <SpotifyId("spotify:track:1MFjsV9fhHGgz93rW6a2JB")>: ()    
2025-03-03T21:42:28.001350Z  INFO client_request{request=Player(StartPlayback(Context(Playlist(PlaylistId("37i9dQZF1DZ06evO3s43Jg")), Some(Uri("spotify:track:1MFjsV9fhHGgz93rW6a2JB"))), None))}: spotify_player::client: Successfully handled the client request, took: 357ms
2025-03-03T21:42:28.080505Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) }    
2025-03-03T21:42:30.330794Z  INFO client_request{request=GetCurrentUserQueue}: spotify_player::client: Successfully handled the client request, took: 284ms
2025-03-03T21:42:32.768199Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) }    
2025-03-03T21:42:32.768291Z ERROR librespot_playback::player: Skipping to next track, unable to load track <SpotifyId("spotify:track:4wY4wXTHpQ2fY1T7Nb3IZt")>: ()    
2025-03-03T21:42:32.769625Z ERROR librespot_connect::spirc: ContextError: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) }    
2025-03-03T21:42:32.809402Z  INFO client_request{request=Player(StartPlayback(Context(Playlist(PlaylistId("37i9dQZF1DZ06evO3s43Jg")), Some(Uri("spotify:track:4wY4wXTHpQ2fY1T7Nb3IZt"))), None))}: spotify_player::client: Successfully handled the client request, took: 335ms
2025-03-03T21:42:32.883078Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) }    
2025-03-03T21:42:34.258567Z  INFO client_request{request=GetCurrentUserQueue}: spotify_player::client: Successfully handled the client request, took: 201ms
2025-03-03T21:43:45.948402Z  INFO client_request{request=GetBrowseCategories}: spotify_player::client: Successfully handled the client request, took: 120ms
<!-- gh-comment-id:2695633928 --> @alexjyong commented on GitHub (Mar 3, 2025): Update, while my changes appear to be more stable that whats in master at present, eventually, we run into an error where the song will play silently. You can navigate between different pages, load up different lists, and logs show that we are getting a new token and loading it as expected. But eventually we end up with ``` 2025-03-03T21:42:27.960859Z ERROR librespot_connect::spirc: ContextError: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) } 2025-03-03T21:42:28.000041Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) } 2025-03-03T21:42:28.000302Z ERROR librespot_playback::player: Skipping to next track, unable to load track <SpotifyId("spotify:track:1MFjsV9fhHGgz93rW6a2JB")>: () 2025-03-03T21:42:28.001350Z INFO client_request{request=Player(StartPlayback(Context(Playlist(PlaylistId("37i9dQZF1DZ06evO3s43Jg")), Some(Uri("spotify:track:1MFjsV9fhHGgz93rW6a2JB"))), None))}: spotify_player::client: Successfully handled the client request, took: 357ms 2025-03-03T21:42:28.080505Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) } 2025-03-03T21:42:30.330794Z INFO client_request{request=GetCurrentUserQueue}: spotify_player::client: Successfully handled the client request, took: 284ms 2025-03-03T21:42:32.768199Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) } 2025-03-03T21:42:32.768291Z ERROR librespot_playback::player: Skipping to next track, unable to load track <SpotifyId("spotify:track:4wY4wXTHpQ2fY1T7Nb3IZt")>: () 2025-03-03T21:42:32.769625Z ERROR librespot_connect::spirc: ContextError: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) } 2025-03-03T21:42:32.809402Z INFO client_request{request=Player(StartPlayback(Context(Playlist(PlaylistId("37i9dQZF1DZ06evO3s43Jg")), Some(Uri("spotify:track:4wY4wXTHpQ2fY1T7Nb3IZt"))), None))}: spotify_player::client: Successfully handled the client request, took: 335ms 2025-03-03T21:42:32.883078Z ERROR librespot_playback::player: Unable to load audio item: Error { kind: FailedPrecondition, error: FaultyRequest(BAD_REQUEST) } 2025-03-03T21:42:34.258567Z INFO client_request{request=GetCurrentUserQueue}: spotify_player::client: Successfully handled the client request, took: 201ms 2025-03-03T21:43:45.948402Z INFO client_request{request=GetBrowseCategories}: spotify_player::client: Successfully handled the client request, took: 120ms ```
Author
Owner

@alexjyong commented on GitHub (Mar 4, 2025):

I went and made a PR against upstream master with what I have so far. At this point, I figure it's better than nothing, as it does partially fix it. The bug still comes back here and there, but not always.

<!-- gh-comment-id:2698871463 --> @alexjyong commented on GitHub (Mar 4, 2025): I went and made a PR against upstream master with what I have so far. At this point, I figure it's better than nothing, as it does partially fix it. The bug still comes back here and there, but not always.
Sign in to join this conversation.
No milestone
No project
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set.

Reference
starred/spotify-player#1286
No description provided.