Putting a song in queue and pressing next crashes librespot with IllegalArgumentException #226
Description
Describe the bug
When I play music from a Spotify playlist, I put a song from a different playlist or from search in queue. Pressing next on the previous playing song reliably crashes librespot for me, even if I wait ten seconds or so.
(This was also the exception seen in #225, but the issue there is about the error handling, not the exception seen)
To Reproduce
- Play any spotify playlist, i used "motivation mix"
- Put a song in queue that isn't in the playlist, I used one from a different playlist and also one that I searched for
- Press next on the currently playing song
- Librespot crashes with
java.lang.IllegalArgumentException
Managed to reproduce with shuffle on and with shuffle off.
Screenshots/Stracktraces/Logs
You can see there that I first did some successful queuing and pressing next for songs in the same playlist, but as soon as I put an external one in, it crashed.
May 06 11:21:36 raspi-server java[14655]: 2020-05-06 11:21:36,800 INFO Session:124 - Created new session! {deviceId: 8bf84159a7db52d4d242631487924938b125b2d8, ap: guc3-accesspoint-b-6vt5.ap.spotify.com:80, proxy: false}
May 06 11:21:36 raspi-server java[14655]: 2020-05-06 11:21:36,801 INFO ZeroconfServer:350 - Accepted new user from S7. {deviceId: 8bf84159a7db52d4d242631487924938b125b2d8}
May 06 11:21:37 raspi-server java[14655]: 2020-05-06 11:21:37,699 INFO Session:322 - Connected successfully!
May 06 11:21:38 raspi-server java[14655]: 2020-05-06 11:21:38,251 INFO Session:1171 - Skipping SecretBlock
May 06 11:21:38 raspi-server java[14655]: 2020-05-06 11:21:38,253 INFO Session:1143 - Received LicenseVersion: 0
May 06 11:21:38 raspi-server java[14655]: 2020-05-06 11:21:38,255 INFO Session:1133 - Received CountryCode: DE
May 06 11:21:38 raspi-server java[14655]: 2020-05-06 11:21:38,292 DEBUG TokenProvider:49 - Token expired or not suitable, requesting again. {scopes: [playlist-read], oldToken: null}
May 06 11:21:38 raspi-server java[14655]: 2020-05-06 11:21:38,314 INFO CacheManager:72 - There are 380 cached entries.
May 06 11:21:38 raspi-server java[14655]: 2020-05-06 11:21:38,383 INFO Session:1171 - Skipping LegacyWelcome
May 06 11:21:38 raspi-server java[14655]: 2020-05-06 11:21:38,384 INFO Session:1171 - Skipping UnknownData_AllZeros
May 06 11:21:38 raspi-server java[14655]: 2020-05-06 11:21:38,398 DEBUG MercuryClient:214 - Couldn't dispatch Mercury event {seq: 930565069098450944, uri: hm://pusher/v1/connections/OGJmODQxNTlhN2RiNTJkNGQyNDI2MzE0ODc5MjQ5MzhiMTI1YjJkOCtBUCt0Y3A6Ly9ndWMzLWFjY2Vzc3BvaW50LWItNnZ0NS5ndWMzLnNwb3RpZnkubmV0OjUwMTIrODk2MzZEMEEzQjk2QjJCQzY4NTZDNjJEODI2MTNBMjE4MzRGOTExNEE4MzU1ODhEQzNERTExODg5OEUxRjhGMw%3D%3D, code: 200, payload: []}
May 06 11:21:38 raspi-server java[14655]: 2020-05-06 11:21:38,440 DEBUG Session:1147 - Received 0x10: 8813DBDBBCE212A976802CBD579BDFB059C5FEEC
May 06 11:21:38 raspi-server java[14655]: 2020-05-06 11:21:38,595 INFO Session:1098 - Skipping unknown command {cmd: 0x75, payload: 000000}
May 06 11:21:38 raspi-server java[14655]: 2020-05-06 11:21:38,728 DEBUG TokenProvider:53 - Updated token successfully! {scopes: [playlist-read], newToken: StoredToken{expiresIn=3600, accessToken='BQAmQA7AbI[truncated]', scopes=[playlist-read], timestamp=1588756898729}}
May 06 11:21:39 raspi-server java[14655]: 2020-05-06 11:21:39,377 INFO Session:355 - Authenticated as myusername!
May 06 11:21:39 raspi-server java[14655]: 2020-05-06 11:21:39,724 DEBUG EventService:48 - Event sent. {body: 812|1|de, result: 200}
May 06 11:21:40 raspi-server java[14655]: 2020-05-06 11:21:40,159 DEBUG DealerClient:316 - Dealer connected! {host: gae-dealer.spotify.com}
May 06 11:21:40 raspi-server java[14655]: 2020-05-06 11:21:40,399 DEBUG DeviceStateHandler:136 - Updated Spotify-Connection-Id: OGJmODQxNTlhN2RiNTJkNGQyNDI2MzE0ODc5MjQ5MzhiMTI1YjJkOCtkZWFsZXIrdGNwOi8vZ2FlMi1kZWFsZXItY2FuYXJ5LTVoOHEuZ2FlMi5zcG90aWZ5Lm5ldDo1NzAwKzBBNjA1NDFCRTk0REFCQTkzMjI4OUY3NjhGQjg5ODBERTU2RkI4Mjk5NDU1RDI3QTZDNTk1QTkyRDc3RjZCNDc=
May 06 11:21:40 raspi-server java[14655]: 2020-05-06 11:21:40,442 INFO StateWrapper:305 - Notified new device (us)!
May 06 11:21:41 raspi-server java[14655]: 2020-05-06 11:21:41,088 INFO DeviceStateHandler:255 - Put state. {ts: 1588756900433, connId: OGJmOD[truncated], reason: NEW_DEVICE}
May 06 11:21:41 raspi-server java[14655]: 2020-05-06 11:21:41,657 DEBUG Player:244 - Received command: Transfer
May 06 11:21:42 raspi-server java[14655]: 2020-05-06 11:21:42,182 DEBUG Player:316 - Loading context (transfer), uri: spotify:playlist:37i9dQZF1DXdxcBWuJkbcy
May 06 11:21:42 raspi-server java[14655]: 2020-05-06 11:21:42,217 DEBUG DeviceStateHandler:199 - Device is now active. {ts: 1588756902219}
May 06 11:21:42 raspi-server java[14655]: 2020-05-06 11:21:42,338 INFO PlayerSession:48 - Created new session. {id: BrcWpY6wzed2Kd5zPifuFw}
May 06 11:21:42 raspi-server java[14655]: 2020-05-06 11:21:42,383 DEBUG PlayerSession:263 - PlayerQueueEntry{0184a231188bbee8627f0d363f565b15} has been added to the output. {sessionId: BrcWpY6wzed2Kd5zPifuFw, pos: 69, reason: CLICK_ROW}
May 06 11:21:42 raspi-server java[14655]: 2020-05-06 11:21:42,441 DEBUG DealerClient:108 - Handled request. {key: 8376b5ce-5ea6-472b-ab15-554ababc95ed, result: SUCCESS}
May 06 11:21:42 raspi-server java[14655]: 2020-05-06 11:21:42,666 INFO DeviceStateHandler:255 - Put state. {ts: 1588756902409, connId: OGJmOD[truncated], reason: PLAYER_STATE_CHANGED}
May 06 11:21:42 raspi-server java[14655]: 2020-05-06 11:21:42,679 DEBUG EventService:48 - Event sent. {body: 557|3|BrcWpY6wzed2Kd5zPifuFw|spotify:playlist:37i9dQZF1DXdxcBWuJkbcy|spotify:playlist:37i9dQZF1DXdxcBWuJkbcy|1588756902374||81|, result: 200}
May 06 11:21:42 raspi-server java[14655]: 2020-05-06 11:21:42,976 DEBUG EventService:48 - Event sent. {body: 558|1|0184a231188bbee8627f0d363f565b15|BrcWpY6wzed2Kd5zPifuFw|1588756902394, result: 200}
May 06 11:21:43 raspi-server java[14655]: 2020-05-06 11:21:43,235 DEBUG EventService:48 - Event sent. {body: 274|3|2|2|a1c6802d2984f8be0d038d915bd41fc8956ce326|spotify:track:4aebBr4JAihzJQR0CiIZJv|1|2|2, result: 200}
May 06 11:21:43 raspi-server java[14655]: 2020-05-06 11:21:43,427 INFO PlayerQueueEntry:100 - Loaded track. {name: 'Hello', artists: 'Adele', uri: spotify:track:4aebBr4JAihzJQR0CiIZJv, id: 0184a231188bbee8627f0d363f565b15}
May 06 11:21:43 raspi-server java[14655]: 2020-05-06 11:21:43,434 DEBUG CrossfadeController:42 - Loaded crossfade intervals {id: 0184a231188bbee8627f0d363f565b15, in: {}, out: {}}
May 06 11:21:43 raspi-server java[14655]: 2020-05-06 11:21:43,850 INFO DeviceStateHandler:255 - Put state. {ts: 1588756903688, connId: OGJmOD[truncated], reason: PLAYER_STATE_CHANGED}
May 06 11:21:45 raspi-server java[14655]: 2020-05-06 11:21:45,785 DEBUG Player:244 - Received command: Play
May 06 11:21:45 raspi-server java[14655]: 2020-05-06 11:21:45,790 DEBUG Player:297 - Loading context (play), uri: spotify:playlist:37i9dQZF1DXdxcBWuJkbcy
May 06 11:21:45 raspi-server java[14655]: 2020-05-06 11:21:45,886 INFO StateWrapper:207 - Context has transforming! {url: https://spclient.wg.spotify.com/cuepoints-transitions/v2/decorate, shuffle: true, willRequest: true}
May 06 11:21:46 raspi-server java[14655]: 2020-05-06 11:21:46,327 DEBUG StateWrapper:221 - Updated context with transforming information!
May 06 11:21:46 raspi-server java[14655]: 2020-05-06 11:21:46,333 DEBUG PlayerQueueEntry:210 - PlayerQueueEntry{0184a231188bbee8627f0d363f565b15} has been removed from output.
May 06 11:21:46 raspi-server java[14655]: 2020-05-06 11:21:46,335 INFO PlayerSession:48 - Created new session. {id: 56+oErLh+nTKQTxxoItV4w}
May 06 11:21:46 raspi-server java[14655]: 2020-05-06 11:21:46,339 DEBUG PlayerSession:263 - PlayerQueueEntry{01218a140c8b9ac8b09072234a0acbfe} has been added to the output. {sessionId: 56+oErLh+nTKQTxxoItV4w, pos: 453, reason: PLAY_BTN}
May 06 11:21:46 raspi-server java[14655]: 2020-05-06 11:21:46,393 DEBUG DealerClient:108 - Handled request. {key: f2e0b716-12f7-49f6-8de5-2f39d31dc0b5, result: SUCCESS}
May 06 11:21:46 raspi-server java[14655]: 2020-05-06 11:21:46,593 INFO DeviceStateHandler:255 - Put state. {ts: 1588756906356, connId: OGJmOD[truncated], reason: PLAYER_STATE_CHANGED}
May 06 11:21:46 raspi-server java[14655]: 2020-05-06 11:21:46,703 DEBUG EventService:48 - Event sent. {body: 12|37|1|8bf84159a7db52d4d242631487924938b125b2d8|0184a231188bbee8627f0d363f565b15|00000000000000000000000000000000|com.spotify.gaia|clickrow|playlist|endplay|655360|3174136|444|444|295502|0|0|0|0|1|120|0|-1|context|262|0|0|0|0|0|444|444|0|176400|spotify:playlist:37i9dQZF1DXdxcBWuJkbcy|vorbis|88d922669b954a74829582b0dc381979||0|1588756902438|0|context|||com.spotify|crossfade|none|422307f82d79a8f76a4f795002fe9c3ac0294a7e|na|none, result: 200}
May 06 11:21:46 raspi-server java[14655]: 2020-05-06 11:21:46,833 INFO DeviceStateHandler:255 - Put state. {ts: 1588756906368, connId: OGJmOD[truncated], reason: PLAYER_STATE_CHANGED}
May 06 11:21:46 raspi-server java[14655]: 2020-05-06 11:21:46,964 DEBUG EventService:48 - Event sent. {body: 10|20|a1c6802d2984f8be0d038d915bd41fc8956ce326|0184a231188bbee8627f0d363f565b15|0|0|0|0|0|0|655360|3174136|music|-1|-1|-1|-1.000000|-1|-1.000000|-1|-1|-1|-1.000000|-1|-1|-1|-1|-1.000000|-1|0.000000|-1.000000|||unknown|0|0|0|0|0|interactive|0|176400|0|0, result: 200}
May 06 11:21:47 raspi-server java[14655]: 2020-05-06 11:21:47,271 DEBUG EventService:48 - Event sent. {body: 372|1|0184a231188bbee8627f0d363f565b15|spotify:track:4aebBr4JAihzJQR0CiIZJv|0|[[120,444]], result: 200}
May 06 11:21:47 raspi-server java[14655]: 2020-05-06 11:21:47,599 DEBUG EventService:48 - Event sent. {body: 557|3|56+oErLh+nTKQTxxoItV4w|spotify:playlist:37i9dQZF1DXdxcBWuJkbcy|spotify:playlist:37i9dQZF1DXdxcBWuJkbcy|1588756906340||80|context://spotify:playlist:37i9dQZF1DXdxcBWuJkbcy, result: 200}
May 06 11:21:47 raspi-server java[14655]: 2020-05-06 11:21:47,638 INFO PlayerQueueEntry:100 - Loaded track. {name: 'Lights Go Down', artists: 'Mike Candys', uri: spotify:track:2shD8wlebq8fDg6ChqOPkC, id: 01218a140c8b9ac8b09072234a0acbfe}
May 06 11:21:47 raspi-server java[14655]: 2020-05-06 11:21:47,661 DEBUG CrossfadeController:42 - Loaded crossfade intervals {id: 01218a140c8b9ac8b09072234a0acbfe, in: {FORWARD_BTN=FadeInterval{start=0, duration=500, interpolator=xyz.gianlu.librespot.player.crossfade.LinearIncreasingInterpolator@1c9b6fc}, BACK_BTN=FadeInterval{start=0, duration=500, interpolator=xyz.gianlu.librespot.player.crossfade.LinearIncreasingInterpolator@1f8e2e3}}, out: {TRACK_DONE=FadeInterval{start=149730, duration=990, interpolator=LookupInterpolator{tx=[0.0, 0.08, 0.192, 0.448, 0.999], ty=[1.0, 0.9773715, 0.9158691, 0.7001406, 0.0014996249]}}, FORWARD_BTN=PartialFadeInterval{duration=500, interpolator=xyz.gianlu.librespot.player.crossfade.LinearDecreasingInterpolator@1a30e16}, BACK_BTN=PartialFadeInterval{duration=500, interpolator=xyz.gianlu.librespot.player.crossfade.LinearDecreasingInterpolator@18b32c8}}}
May 06 11:21:47 raspi-server java[14655]: 2020-05-06 11:21:47,993 DEBUG EventService:48 - Event sent. {body: 558|1|01218a140c8b9ac8b09072234a0acbfe|56+oErLh+nTKQTxxoItV4w|1588756906342, result: 200}
May 06 11:21:48 raspi-server java[14655]: 2020-05-06 11:21:48,268 INFO DeviceStateHandler:255 - Put state. {ts: 1588756907786, connId: OGJmOD[truncated], reason: PLAYER_STATE_CHANGED}
May 06 11:21:48 raspi-server java[14655]: 2020-05-06 11:21:48,353 DEBUG EventService:48 - Event sent. {body: 274|3|2|2|412636d9c0edfa1699d7ea901d49385b6a578978|spotify:track:2shD8wlebq8fDg6ChqOPkC|1|2|2, result: 200}
May 06 11:21:54 raspi-server java[14655]: 2020-05-06 11:21:54,889 DEBUG Player:244 - Received command: UpdateContext
May 06 11:21:54 raspi-server java[14655]: 2020-05-06 11:21:54,989 DEBUG DealerClient:108 - Handled request. {key: ca747ca2-61c2-453b-bac7-b45baf146d28, result: SUCCESS}
May 06 11:21:55 raspi-server java[14655]: 2020-05-06 11:21:55,159 INFO DeviceStateHandler:255 - Put state. {ts: 1588756914989, connId: OGJmOD[truncated], reason: PLAYER_STATE_CHANGED}
May 06 11:22:01 raspi-server java[14655]: 2020-05-06 11:22:01,361 DEBUG Player:244 - Received command: UpdateContext
May 06 11:22:01 raspi-server java[14655]: 2020-05-06 11:22:01,447 DEBUG DealerClient:108 - Handled request. {key: 8b005f16-83a7-46a3-8835-7a1e0a3efc5d, result: SUCCESS}
May 06 11:22:01 raspi-server java[14655]: 2020-05-06 11:22:01,582 INFO DeviceStateHandler:255 - Put state. {ts: 1588756921446, connId: OGJmOD[truncated], reason: PLAYER_STATE_CHANGED}
May 06 11:22:03 raspi-server java[14655]: 2020-05-06 11:22:03,169 DEBUG Player:244 - Received command: UpdateContext
May 06 11:22:03 raspi-server java[14655]: 2020-05-06 11:22:03,261 DEBUG DealerClient:108 - Handled request. {key: 07d9d7fc-8e9c-46b0-b562-95114eb5242b, result: SUCCESS}
May 06 11:22:03 raspi-server java[14655]: 2020-05-06 11:22:03,362 INFO DeviceStateHandler:255 - Put state. {ts: 1588756923257, connId: OGJmOD[truncated], reason: PLAYER_STATE_CHANGED}
May 06 11:22:07 raspi-server java[14655]: 2020-05-06 11:22:07,028 DEBUG Player:244 - Received command: UpdateContext
May 06 11:22:07 raspi-server java[14655]: 2020-05-06 11:22:07,087 DEBUG DealerClient:108 - Handled request. {key: cbe3e306-ddfc-42dd-b190-55eba83f3da7, result: SUCCESS}
May 06 11:22:07 raspi-server java[14655]: 2020-05-06 11:22:07,233 INFO DeviceStateHandler:255 - Put state. {ts: 1588756927086, connId: OGJmOD[truncated], reason: PLAYER_STATE_CHANGED}
May 06 11:22:08 raspi-server java[14655]: 2020-05-06 11:22:08,585 DEBUG Player:244 - Received command: AddToQueue
May 06 11:22:08 raspi-server java[14655]: 2020-05-06 11:22:08,644 DEBUG DealerClient:108 - Handled request. {key: 0bc13325-de90-4368-8c7f-d86c55e028db, result: SUCCESS}
May 06 11:22:08 raspi-server java[14655]: 2020-05-06 11:22:08,844 INFO DeviceStateHandler:255 - Put state. {ts: 1588756928641, connId: OGJmOD[truncated], reason: PLAYER_STATE_CHANGED}
May 06 11:22:19 raspi-server java[14655]: 2020-05-06 11:22:19,481 DEBUG Player:244 - Received command: SkipNext
May 06 11:22:19 raspi-server java[14655]: 2020-05-06 11:22:19,507 DEBUG CrossfadeController:171 - Cleared fade out because custom fade doesn't apply. {id: 01218a140c8b9ac8b09072234a0acbfe}
May 06 11:22:19 raspi-server java[14655]: 2020-05-06 11:22:19,508 DEBUG CrossfadeController:176 - Changed fade out. {curr: PartialFadeInterval{duration=500, interpolator=xyz.gianlu.librespot.player.crossfade.LinearDecreasingInterpolator@1a30e16}, custom: false, why: FORWARD_BTN, id: 01218a140c8b9ac8b09072234a0acbfe}
May 06 11:22:19 raspi-server java[14655]: 2020-05-06 11:22:19,510 DEBUG PlayerSession:263 - PlayerQueueEntry{015998af6ee2387d6673fdfa6d64f321} has been added to the output. {sessionId: 56+oErLh+nTKQTxxoItV4w, pos: 4, reason: FORWARD_BTN}
May 06 11:22:19 raspi-server java[14655]: 2020-05-06 11:22:19,518 DEBUG DealerClient:108 - Handled request. {key: e5fdd4b7-a37c-45e6-b1ca-c099628d49f5, result: SUCCESS}
May 06 11:22:19 raspi-server java[14655]: 2020-05-06 11:22:19,676 INFO DeviceStateHandler:255 - Put state. {ts: 1588756939515, connId: OGJmOD[truncated], reason: PLAYER_STATE_CHANGED}
May 06 11:22:19 raspi-server java[14655]: 2020-05-06 11:22:19,801 DEBUG EventService:48 - Event sent. {body: 12|37|2|8bf84159a7db52d4d242631487924938b125b2d8|01218a140c8b9ac8b09072234a0acbfe|00000000000000000000000000000000|playlist|playbtn|playlist|fwdbtn|1048576|1948472|33160|33160|155520|0|0|0|0|1|52|0|-1|context|240|0|0|0|0|0|33160|33160|0|176400|spotify:playlist:37i9dQZF1DXdxcBWuJkbcy|vorbis|50b3f784e5d243b9a3b9221b9e429f3a||0|1588756906394|0|context|your-library|8.5.56.1186|com.spotify|crossfade|none|422307f82d79a8f76a4f795002fe9c3ac0294a7e|na|none, result: 200}
May 06 11:22:20 raspi-server java[14655]: 2020-05-06 11:22:20,107 DEBUG EventService:48 - Event sent. {body: 10|20|412636d9c0edfa1699d7ea901d49385b6a578978|01218a140c8b9ac8b09072234a0acbfe|0|0|0|0|0|0|1048576|1948472|music|-1|-1|-1|-1.000000|-1|-1.000000|-1|-1|-1|-1.000000|-1|-1|-1|-1|-1.000000|-1|0.000000|-1.000000|||unknown|0|0|0|0|0|interactive|0|176400|0|0, result: 200}
May 06 11:22:20 raspi-server java[14655]: 2020-05-06 11:22:20,407 DEBUG EventService:48 - Event sent. {body: 372|1|01218a140c8b9ac8b09072234a0acbfe|spotify:track:2shD8wlebq8fDg6ChqOPkC|0|[[52,33160]], result: 200}
May 06 11:22:20 raspi-server java[14655]: 2020-05-06 11:22:20,701 DEBUG EventService:48 - Event sent. {body: 558|1|015998af6ee2387d6673fdfa6d64f321|56+oErLh+nTKQTxxoItV4w|1588756939512, result: 200}
May 06 11:22:20 raspi-server java[14655]: 2020-05-06 11:22:20,796 INFO PlayerQueueEntry:100 - Loaded track. {name: 'Every Battle', artists: 'Hallman', uri: spotify:track:1LzCBjvOTj1vKFo8GduP3h, id: 015998af6ee2387d6673fdfa6d64f321}
May 06 11:22:20 raspi-server java[14655]: 2020-05-06 11:22:20,807 DEBUG CrossfadeController:42 - Loaded crossfade intervals {id: 015998af6ee2387d6673fdfa6d64f321, in: {TRACK_DONE=FadeInterval{start=25214, duration=937, interpolator=LookupInterpolator{tx=[0.0, 0.024, 0.138, 0.48, 0.999], ty=[0.0, 0.3266236, 0.5520289, 0.8023654, 0.9996999]}}, FORWARD_BTN=FadeInterval{start=0, duration=500, interpolator=xyz.gianlu.librespot.player.crossfade.LinearIncreasingInterpolator@53e986}, BACK_BTN=FadeInterval{start=0, duration=500, interpolator=xyz.gianlu.librespot.player.crossfade.LinearIncreasingInterpolator@bf0ab7}}, out: {TRACK_DONE=FadeInterval{start=208334, duration=1120, interpolator=LookupInterpolator{tx=[0.0, 0.08, 0.192, 0.448, 0.999], ty=[1.0, 0.9773715, 0.9158691, 0.7001406, 0.0014996249]}}, FORWARD_BTN=PartialFadeInterval{duration=500, interpolator=xyz.gianlu.librespot.player.crossfade.LinearDecreasingInterpolator@147c33c}, BACK_BTN=PartialFadeInterval{duration=500, interpolator=xyz.gianlu.librespot.player.crossfade.LinearDecreasingInterpolator@471d0b}}}
May 06 11:22:20 raspi-server java[14655]: 2020-05-06 11:22:20,988 INFO DeviceStateHandler:255 - Put state. {ts: 1588756940829, connId: OGJmOD[truncated], reason: PLAYER_STATE_CHANGED}
May 06 11:22:21 raspi-server java[14655]: 2020-05-06 11:22:20,999 DEBUG EventService:48 - Event sent. {body: 274|3|2|2|8ecdc36c9702b0bc51c65cffaeb0a520333260d2|spotify:track:1LzCBjvOTj1vKFo8GduP3h|1|2|2, result: 200}
May 06 11:22:21 raspi-server java[14655]: 2020-05-06 11:22:21,112 DEBUG PlayerQueueEntry:210 - PlayerQueueEntry{01218a140c8b9ac8b09072234a0acbfe} has been removed from output.
May 06 11:22:30 raspi-server java[14655]: 2020-05-06 11:22:30,672 DEBUG Player:244 - Received command: UpdateContext
May 06 11:22:30 raspi-server java[14655]: 2020-05-06 11:22:30,715 DEBUG DealerClient:108 - Handled request. {key: 3593301b-fe93-41f8-bbed-986025b4ee66, result: SUCCESS}
May 06 11:22:30 raspi-server java[14655]: 2020-05-06 11:22:30,850 INFO DeviceStateHandler:255 - Put state. {ts: 1588756950714, connId: OGJmOD[truncated], reason: PLAYER_STATE_CHANGED}
May 06 11:22:32 raspi-server java[14655]: 2020-05-06 11:22:32,429 DEBUG Player:244 - Received command: AddToQueue
May 06 11:22:32 raspi-server java[14655]: 2020-05-06 11:22:32,445 DEBUG DealerClient:108 - Handled request. {key: 324c2caf-e6a7-4691-b10e-67c6625e0822, result: SUCCESS}
May 06 11:22:32 raspi-server java[14655]: 2020-05-06 11:22:32,604 INFO DeviceStateHandler:255 - Put state. {ts: 1588756952445, connId: OGJmOD[truncated], reason: PLAYER_STATE_CHANGED}
May 06 11:22:39 raspi-server java[14655]: 2020-05-06 11:22:39,808 DEBUG Player:244 - Received command: SkipNext
May 06 11:22:39 raspi-server java[14655]: 2020-05-06 11:22:39,842 DEBUG CrossfadeController:171 - Cleared fade out because custom fade doesn't apply. {id: 015998af6ee2387d6673fdfa6d64f321}
May 06 11:22:39 raspi-server java[14655]: 2020-05-06 11:22:39,844 DEBUG CrossfadeController:176 - Changed fade out. {curr: PartialFadeInterval{duration=500, interpolator=xyz.gianlu.librespot.player.crossfade.LinearDecreasingInterpolator@147c33c}, custom: false, why: FORWARD_BTN, id: 015998af6ee2387d6673fdfa6d64f321}
May 06 11:22:39 raspi-server java[14655]: 2020-05-06 11:22:39,846 DEBUG PlayerSession:263 - PlayerQueueEntry{01ae795cc941dd8d5f1decd72bd9d436} has been added to the output. {sessionId: 56+oErLh+nTKQTxxoItV4w, pos: 7, reason: FORWARD_BTN}
May 06 11:22:39 raspi-server java[14655]: 2020-05-06 11:22:39,860 DEBUG DealerClient:108 - Handled request. {key: 00157f02-e199-47cb-bb34-ddfd6dc5449e, result: SUCCESS}
May 06 11:22:39 raspi-server java[14655]: 2020-05-06 11:22:39,994 INFO DeviceStateHandler:255 - Put state. {ts: 1588756959851, connId: OGJmOD[truncated], reason: PLAYER_STATE_CHANGED}
May 06 11:22:40 raspi-server java[14655]: 2020-05-06 11:22:40,127 DEBUG EventService:48 - Event sent. {body: 12|37|3|8bf84159a7db52d4d242631487924938b125b2d8|015998af6ee2387d6673fdfa6d64f321|00000000000000000000000000000000|playlist|fwdbtn|playlist|fwdbtn|786432|2572420|20334|20334|212181|0|0|0|0|1|17|0|-1|context|299|0|0|0|0|0|20334|20334|0|176400|spotify:playlist:37i9dQZF1DXdxcBWuJkbcy|vorbis|3a11a747ef60402398d6b5cee3787a37||0|1588756939519|0|context|your-library|8.5.56.1186|com.spotify|crossfade|none|422307f82d79a8f76a4f795002fe9c3ac0294a7e|na|none, result: 200}
May 06 11:22:40 raspi-server java[14655]: 2020-05-06 11:22:40,386 DEBUG EventService:48 - Event sent. {body: 10|20|8ecdc36c9702b0bc51c65cffaeb0a520333260d2|015998af6ee2387d6673fdfa6d64f321|0|0|0|0|0|0|786432|2572420|music|-1|-1|-1|-1.000000|-1|-1.000000|-1|-1|-1|-1.000000|-1|-1|-1|-1|-1.000000|-1|0.000000|-1.000000|||unknown|0|0|0|0|0|interactive|0|176400|0|0, result: 200}
May 06 11:22:40 raspi-server java[14655]: 2020-05-06 11:22:40,547 INFO PlayerQueueEntry:100 - Loaded track. {name: 'Day 'N' Nite - Martin Jensen Edit', artists: 'Stefy De Cicco, Ben Hamilton, Martin Jensen', uri: spotify:track:0ou367q5bmco9pZNxq80iD, id: 01ae795cc941dd8d5f1decd72bd9d436}
May 06 11:22:40 raspi-server java[14655]: 2020-05-06 11:22:40,555 DEBUG CrossfadeController:42 - Loaded crossfade intervals {id: 01ae795cc941dd8d5f1decd72bd9d436, in: {TRACK_DONE=FadeInterval{start=4876, duration=2956, interpolator=LookupInterpolator{tx=[0.0, 0.024, 0.138, 0.48, 0.999], ty=[0.0, 0.3266236, 0.5520289, 0.8023654, 0.9996999]}}, FORWARD_BTN=FadeInterval{start=0, duration=500, interpolator=xyz.gianlu.librespot.player.crossfade.LinearIncreasingInterpolator@18ce930}, BACK_BTN=FadeInterval{start=0, duration=500, interpolator=xyz.gianlu.librespot.player.crossfade.LinearIncreasingInterpolator@112bcf}}, out: {TRACK_DONE=FadeInterval{start=160934, duration=468, interpolator=LookupInterpolator{tx=[0.0, 0.08, 0.192, 0.448, 0.999], ty=[1.0, 0.9773715, 0.9158691, 0.7001406, 0.0014996249]}}, FORWARD_BTN=PartialFadeInterval{duration=500, interpolator=xyz.gianlu.librespot.player.crossfade.LinearDecreasingInterpolator@1b2c8d6}, BACK_BTN=PartialFadeInterval{duration=500, interpolator=xyz.gianlu.librespot.player.crossfade.LinearDecreasingInterpolator@1457df9}}}
May 06 11:22:40 raspi-server java[14655]: 2020-05-06 11:22:40,675 DEBUG PlayerQueueEntry:210 - PlayerQueueEntry{015998af6ee2387d6673fdfa6d64f321} has been removed from output.
May 06 11:22:40 raspi-server java[14655]: 2020-05-06 11:22:40,687 DEBUG EventService:48 - Event sent. {body: 372|1|015998af6ee2387d6673fdfa6d64f321|spotify:track:1LzCBjvOTj1vKFo8GduP3h|0|[[17,20334]], result: 200}
May 06 11:22:40 raspi-server java[14655]: 2020-05-06 11:22:40,779 INFO DeviceStateHandler:255 - Put state. {ts: 1588756960594, connId: OGJmOD[truncated], reason: PLAYER_STATE_CHANGED}
May 06 11:22:41 raspi-server java[14655]: 2020-05-06 11:22:40,995 DEBUG EventService:48 - Event sent. {body: 558|1|01ae795cc941dd8d5f1decd72bd9d436|56+oErLh+nTKQTxxoItV4w|1588756959848, result: 200}
May 06 11:22:41 raspi-server java[14655]: 2020-05-06 11:22:41,373 DEBUG EventService:48 - Event sent. {body: 274|3|2|2|6b419204fa5c061abf9e239ba2a9165038e3daa5|spotify:track:0ou367q5bmco9pZNxq80iD|1|2|2, result: 200}
May 06 11:22:56 raspi-server java[14655]: 2020-05-06 11:22:56,378 DEBUG Player:244 - Received command: UpdateContext
May 06 11:22:56 raspi-server java[14655]: 2020-05-06 11:22:56,432 DEBUG DealerClient:108 - Handled request. {key: 17f9e5b5-f643-4169-9cf0-e6b4a65e8985, result: SUCCESS}
May 06 11:22:56 raspi-server java[14655]: 2020-05-06 11:22:56,583 INFO DeviceStateHandler:255 - Put state. {ts: 1588756976429, connId: OGJmOD[truncated], reason: PLAYER_STATE_CHANGED}
May 06 11:23:05 raspi-server java[14655]: 2020-05-06 11:23:05,026 DEBUG Player:244 - Received command: AddToQueue
May 06 11:23:05 raspi-server java[14655]: 2020-05-06 11:23:05,061 DEBUG DealerClient:108 - Handled request. {key: a9a1a2fc-bf08-4de7-a36d-da0ec42f9e34, result: SUCCESS}
May 06 11:23:05 raspi-server java[14655]: 2020-05-06 11:23:05,228 INFO DeviceStateHandler:255 - Put state. {ts: 1588756985059, connId: OGJmOD[truncated], reason: PLAYER_STATE_CHANGED}
May 06 11:23:06 raspi-server java[14655]: 2020-05-06 11:23:06,909 DEBUG Player:244 - Received command: SkipNext
May 06 11:23:06 raspi-server java[14655]: 2020-05-06 11:23:06,920 DEBUG CrossfadeController:171 - Cleared fade out because custom fade doesn't apply. {id: 01ae795cc941dd8d5f1decd72bd9d436}
May 06 11:23:06 raspi-server java[14655]: 2020-05-06 11:23:06,921 DEBUG CrossfadeController:176 - Changed fade out. {curr: PartialFadeInterval{duration=500, interpolator=xyz.gianlu.librespot.player.crossfade.LinearDecreasingInterpolator@1b2c8d6}, custom: false, why: FORWARD_BTN, id: 01ae795cc941dd8d5f1decd72bd9d436}
May 06 11:23:06 raspi-server java[14655]: 2020-05-06 11:23:06,922 DEBUG PlayerSession:263 - PlayerQueueEntry{0146e08ce247a1400cd61239d90cc4d6} has been added to the output. {sessionId: 56+oErLh+nTKQTxxoItV4w, pos: 2, reason: FORWARD_BTN}
May 06 11:23:06 raspi-server java[14655]: 2020-05-06 11:23:06,928 DEBUG DealerClient:108 - Handled request. {key: eb946ea4-e0c9-4763-99ae-2b38525c1a04, result: SUCCESS}
May 06 11:23:07 raspi-server java[14655]: 2020-05-06 11:23:07,126 INFO DeviceStateHandler:255 - Put state. {ts: 1588756986926, connId: OGJmOD[truncated], reason: PLAYER_STATE_CHANGED}
May 06 11:23:07 raspi-server java[14655]: 2020-05-06 11:23:07,209 DEBUG EventService:48 - Event sent. {body: 12|37|4|8bf84159a7db52d4d242631487924938b125b2d8|01ae795cc941dd8d5f1decd72bd9d436|00000000000000000000000000000000|playlist|fwdbtn|playlist|fwdbtn|917504|2145516|27083|27083|166200|0|0|0|0|1|23|0|-1|context|225|0|0|0|0|0|27083|27083|0|176400|spotify:playlist:37i9dQZF1DXdxcBWuJkbcy|vorbis|0cf9c35a74e642e09b33bc30d56dd283||0|1588756959860|0|context|your-library|8.5.56.1186|com.spotify|crossfade|none|422307f82d79a8f76a4f795002fe9c3ac0294a7e|na|none, result: 200}
May 06 11:23:07 raspi-server java[14655]: 2020-05-06 11:23:07,500 DEBUG EventService:48 - Event sent. {body: 10|20|6b419204fa5c061abf9e239ba2a9165038e3daa5|01ae795cc941dd8d5f1decd72bd9d436|0|0|0|0|0|0|917504|2145516|music|-1|-1|-1|-1.000000|-1|-1.000000|-1|-1|-1|-1.000000|-1|-1|-1|-1|-1.000000|-1|0.000000|-1.000000|||unknown|0|0|0|0|0|interactive|0|176400|0|0, result: 200}
May 06 11:23:07 raspi-server java[14655]: 2020-05-06 11:23:07,737 INFO PlayerQueueEntry:100 - Loaded track. {name: 'Bang Bang - Extended Mix', artists: 'Neelix', uri: spotify:track:2VKWhoUTw53RCrsxzfD4vf, id: 0146e08ce247a1400cd61239d90cc4d6}
May 06 11:23:07 raspi-server java[14655]: 2020-05-06 11:23:07,744 FATAL Log4JUncaughtExceptionHandler:15 - [player-queue-28236902]
May 06 11:23:07 raspi-server java[14655]: java.lang.IllegalArgumentException: TrackId{spotify:track:2VKWhoUTw53RCrsxzfD4vf}
May 06 11:23:07 raspi-server java[14655]: at xyz.gianlu.librespot.player.StateWrapper.metadataFor(StateWrapper.java:600) ~[librespot_neu.jar:1.4.0-SNAPSHOT]
May 06 11:23:07 raspi-server java[14655]: at xyz.gianlu.librespot.player.Player.metadataFor(Player.java:721) ~[librespot_neu.jar:1.4.0-SNAPSHOT]
May 06 11:23:07 raspi-server java[14655]: at xyz.gianlu.librespot.player.playback.PlayerSession.metadataFor(PlayerSession.java:180) ~[librespot_neu.jar:1.4.0-SNAPSHOT]
May 06 11:23:07 raspi-server java[14655]: at xyz.gianlu.librespot.player.playback.PlayerQueueEntry.load(PlayerQueueEntry.java:104) ~[librespot_neu.jar:1.4.0-SNAPSHOT]
May 06 11:23:07 raspi-server java[14655]: at xyz.gianlu.librespot.player.playback.PlayerQueueEntry.run(PlayerQueueEntry.java:245) ~[librespot_neu.jar:1.4.0-SNAPSHOT]
May 06 11:23:07 raspi-server java[14655]: at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167) ~[?:?]
May 06 11:23:07 raspi-server java[14655]: at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641) ~[?:?]
May 06 11:23:07 raspi-server java[14655]: at java.lang.Thread.run(Thread.java:844) [?:?]
May 06 11:23:07 raspi-server java[14655]: 2020-05-06 11:23:07,821 DEBUG EventService:48 - Event sent. {body: 372|1|01ae795cc941dd8d5f1decd72bd9d436|spotify:track:0ou367q5bmco9pZNxq80iD|0|[[23,27083]], result: 200}
May 06 11:23:08 raspi-server java[14655]: 2020-05-06 11:23:08,121 DEBUG EventService:48 - Event sent. {body: 558|1|0146e08ce247a1400cd61239d90cc4d6|56+oErLh+nTKQTxxoItV4w|1588756986924, result: 200}
May 06 11:23:08 raspi-server java[14655]: 2020-05-06 11:23:08,427 DEBUG EventService:48 - Event sent. {body: 274|3|2|2|dcd364b6d6a118fc4158e5f2216fa129b246ca33|spotify:track:2VKWhoUTw53RCrsxzfD4vf|1|2|2, result: 200}
Version/Commit
8ba96df