balbuze / volumio-plugins

volumio's plugins from balbuze
190 stars 60 forks source link

Can't handle multiple spotify accounts, 100% repro #259

Closed illtrick closed 4 years ago

illtrick commented 4 years ago

Context: This issue has been haunting myself and my wife for a long time. So much so that we jumped ship on Volumio and went to Roopiee XL. I had chocked it up to a bad integration with the allo boss I had at the time and since Roopiee XL didn't have this issue I didn't give it a second thought. I've since purchased a new usb dac (Topping D50s) and thought I'd give Volumio and this plugin another shot because I'd much prefer to use Volumio. Bummer. Same issue, but this time I spent the time to get repro steps and logs.

Expected behavior: Be able to play music on one system while swapping between two or more Spotify users on different devices.

Observed behavior: First user (doesn't matter which user) connects and it works as expected. Second user tries to connect and is stuck at "connecting" status.

Plugin Configuration: image

Repro Steps:

  1. Any user connects (tested and works with either user) and plays track.
  2. First user can stop track or continue playing track, results are the same.
  3. Second user attempts to connect.

Notes:

Full Logs: [Vollibrespot] vollibrespot::meta_pipe: Load { track_id: SpotifyId { id: 117310924387342975591297438004363832889, audio_type: Track } } [Vollibrespot] librespot_playback::player: command=Load(SpotifyId { id: 117310924387342975591297438004363832889, audio_type: Track }, false, 63228) [Vollibrespot] : Loading <From Trunch to Stromness> with Spotify URI <spotify:track:2Gx9hoFSvLApiHdZcR9yuB> [Vollibrespot] librespot_core::audio_key: new AudioKeyManager [Vollibrespot] librespot_audio::fetch: Downloading file 1f166d394848f9f6a2c3c7480c149aa54c80d7ca [Vollibrespot] librespot_core::channel: new ChannelManager [Vollibrespot] librespot_audio::fetch: AudioFileOpen::len 27774548[u64] 211.903[chunks] => 212[chunks] [Vollibrespot] librespot_playback::player: Normalisation Data: NormalisationData { track_gain_db: -4.580002, track_peak: 1.073539, album_gain_db: -5.290001, album_peak: 1.073539 } [Vollibrespot] librespot_playback::player: Applied normalisation factor: 0.59020096 [Vollibrespot] vollibrespot::meta_pipe: GotToken { token: Token { access_token: "BQBHQgawm8ZYdcZmGOYNJvUNnuFVhZ8o2GkaYH_ZYFvKzP7hou1EkqeJISNgDSsayCgGq8vJIwgIJlRfJANGjdoyVbBSowyLxobthcqq_-zRA-Qt3WJBknVxOXUM96KPQGvhxWMC0NvWbyroWSvgYfFzJQ2YibQCbWs6tFWVOrtEKsBKAn7D4eMEmQ", expires_in: 3600, token_type: "Bearer", scope: ["streaming", "user-read-playback-state", "user-modify-playback-state", "user-read-currently-playing", "user-read-private"] } } [Vollibrespot] vollibrespot::meta_pipe: ApiToken::<Token { access_token: "BQBHQgawm8ZYdcZmGOYNJvUNnuFVhZ8o2GkaYH_ZYFvKzP7hou1EkqeJISNgDSsayCgGq8vJIwgIJlRfJANGjdoyVbBSowyLxobthcqq_-zRA-Qt3WJBknVxOXUM96KPQGvhxWMC0NvWbyroWSvgYfFzJQ2YibQCbWs6tFWVOrtEKsBKAn7D4eMEmQ", expires_in: 3600, token_type: "Bearer", scope: ["streaming", "user-read-playback-state", "user-modify-playback-state", "user-read-currently-playing", "user-read-private"] }> [Vollibrespot] : <From Trunch to Stromness> loaded [Vollibrespot] vollibrespot::meta_pipe: PlaybackStopped { track_id: SpotifyId { id: 117310924387342975591297438004363832889, audio_type: Track } } [Vollibrespot] librespot_connect::spirc: kMessageTypePlay "iPhone" 106e2a6599da26b75373043a9b0fcb46eb042b59 609313477 1585452241079 [Vollibrespot] librespot_playback::player: command=Play [Vollibrespot] vollibrespot::meta_pipe: Play { track_id: SpotifyId { id: 117310924387342975591297438004363832889, audio_type: Track }, position_ms: 63228 } [Vollibrespot] vollibrespot::meta_pipe: PlaybackStarted { track_id: SpotifyId { id: 117310924387342975591297438004363832889, audio_type: Track } } [Vollibrespot] vollibrespot::meta_pipe: SinkActive [Vollibrespot] librespot_connect::spirc: kMessageTypePause "iPhone" 106e2a6599da26b75373043a9b0fcb46eb042b59 609318116 1585452245070 [Vollibrespot] vollibrespot::meta_pipe: Pause { track_id: SpotifyId { id: 117310924387342975591297438004363832889, audio_type: Track }, position_ms: 63228 } [Vollibrespot] librespot_playback::player: command=Pause [Vollibrespot] vollibrespot::meta_pipe: SinkInactive [Vollibrespot] vollibrespot::meta_pipe: PlaybackStopped { track_id: SpotifyId { id: 117310924387342975591297438004363832889, audio_type: Track } } [Vollibrespot] librespot_connect::spirc: kMessageTypePause "" webapi-4ced2e7c73484127be5d36015752eb43 609318994 1585452249738 [Vollibrespot] : volStop [Vollibrespot] : ConnectRequest: "Spotify/8.5.51 iOS/13.3.1 (iPhone11,2)" [Vollibrespot] librespot_connect::discovery: ConnectRequest: Some("action=getInfo") [Vollibrespot] : ConnectRequest: "Spotify/8.5.51 iOS/13.3.1 (iPhone11,2)" [Vollibrespot] librespot_connect::discovery: ConnectRequest: None [Vollibrespot] librespot_connect::discovery: POST "/" {} [Vollibrespot] : Connecting to AP "guc3-accesspoint-b-x7vf.ap.spotify.com:4070" [Vollibrespot] librespot_connect::spirc: drop Spirc[0] [Vollibrespot] librespot_playback::player: Shutting down player thread ... [Vollibrespot] librespot_playback::player: drop Player[0] [Vollibrespot] : EventSender disconnected [Vollibrespot] vollibrespot::meta_pipe: drop MetaPipeThread[0] [Vollibrespot] : Exiting Vollibrespot volspotconnect2.service: main process exited, code=exited, status=1/FAILURE Unit volspotconnect2.service entered failed state. volspotconnect2.service holdoff time over, scheduling restart. Stopping Volspotconnect2 Daemon... Starting Volspotconnect2 Daemon... Started Volspotconnect2 Daemon. vollibrespot v0.1.9 c98fd5d 2019-11-08 (librespot 4674946 2019-11-08) -- Built On 2019-11-08 [Vollibrespot] librespot_connect::discovery: Zeroconf server listening on 0.0.0.0:39569 [Vollibrespot] : Failed to register IPv6 receiver: Os { code: 19, kind: Other, message: "No such device" } [Vollibrespot] : ConnectRequest: "Spotify/8.5.46 iOS/12.3.2 (iPhone10,5)" [Vollibrespot] librespot_connect::discovery: ConnectRequest: Some("action=getInfo") [Vollibrespot] : ConnectRequest: "Spotify/8.5.46 iOS/12.3.2 (iPhone10,5)" [Vollibrespot] librespot_connect::discovery: ConnectRequest: None [Vollibrespot] librespot_connect::discovery: POST "/" {} [Vollibrespot] : Connecting to AP "guc3-accesspoint-b-j027.ap.spotify.com:4070" [Vollibrespot] : Authenticated as "81djbs4ws3dk6ftrm2u8u7na1" ! [Vollibrespot] librespot_core::session: new Session[0] [Vollibrespot] : Setting up new mixer: card:hw:5 mixer:D50s index:0 [Vollibrespot] : Alsa min: 0 (MilliBel(-12700)[dB]) -- max: 127 (MilliBel(0)[dB]) HW: true [Vollibrespot] : Alsa min-db is not SND_CTL_TLV_DB_GAIN_MUTE!! [Vollibrespot] librespot_connect::spirc: new Spirc[0] [Vollibrespot] librespot_core::mercury: new MercuryManager [Vollibrespot] librespot_playback::player: new Player[0] [Vollibrespot] : Using alsa sink [Vollibrespot] librespot_connect::spirc: linear volume: 22937 [Vollibrespot] : Current alsa volume: 99[i64] MilliBel(-2800) [Vollibrespot] : Mapping volume [35.000%] 22937 [u16] ->> Alsa [-2154.331%] -27.36 [dB] - -2736 [i64] [Vollibrespot] vollibrespot::meta_pipe: Starting new MetaPipe[0] [Vollibrespot] : Metadata pipe established [Vollibrespot] librespot_core::session: Session[0] strong=5 weak=2 [Vollibrespot] : Country: "US" [Vollibrespot] vollibrespot::meta_pipe: Volume { volume_to_mixer: 22937 } [Vollibrespot] vollibrespot::meta_pipe: Event::Volume(34.99961852445258) [Vollibrespot] librespot_core::mercury: unknown subscription uri=hm://remote/user/81djbs4ws3dk6ftrm2u8u7na1/ [Vollibrespot] librespot_core::mercury: subscribed uri=hm://remote/user/81djbs4ws3dk6ftrm2u8u7na1/ count=0 [Vollibrespot] librespot_connect::spirc: kMessageTypeLoad "iPhone" 106e2a6599da26b75373043a9b0fcb46eb042b59 609368128 1585452299501 [Vollibrespot] librespot_connect::spirc: Requesting API access token [Vollibrespot] librespot_connect::spirc: State: context_uri: "spotify:album:60PDbOYjrrWtanyMSWQamA" index: 0 position_ms: 67876 status: kPlayStatusPause position_measured_at: 1585452299638 context_description: "" shuffle: true repeat: false playing_from_fallback: true row: 0 playing_track_index: 0 track {gid: "XAC \022|F}\2419\237\027\"\n\2569"} track {gid: "\250\317\037\005K\276Hv\255\356\014yW\276\314'"} track {gid: "f\372yA=\003H\251\251Ef,Q\304\263\374"} track {gid: "vin\366\003BE\236\275\233\215{\335\021vC"} track {gid: "\213H\343Pv=C\017\233\t\303\322;eZa"} track {gid: "@\344\004\032\276\021BN\276/\355\215\037\275X\336"} track {gid: "\334Q\314\215Z\353C\344\241\364\276\266\240f\356\217"} track {gid: "_\224\234V\201\373NZ\262\257\242\2453\232'\371"} [Vollibrespot] librespot_connect::spirc: Frame has 8 tracks [Vollibrespot] librespot_connect::spirc: Loading context: <spotify:album:60PDbOYjrrWtanyMSWQamA> index: [0] of 8 [Vollibrespot] librespot_playback::player: command=Load(SpotifyId { id: 117310924387342975591297438004363832889, audio_type: Track }, false, 67876) [Vollibrespot] vollibrespot::meta_pipe: SessionActive { became_active_at: 1585452299739 } [Vollibrespot] : SessionActive! [Vollibrespot] vollibrespot::meta_pipe: Load { track_id: SpotifyId { id: 117310924387342975591297438004363832889, audio_type: Track } } [Vollibrespot] : Loading <From Trunch to Stromness> with Spotify URI <spotify:track:2Gx9hoFSvLApiHdZcR9yuB> [Vollibrespot] librespot_core::audio_key: new AudioKeyManager [Vollibrespot] librespot_audio::fetch: Downloading file 1f166d394848f9f6a2c3c7480c149aa54c80d7ca [Vollibrespot] librespot_core::channel: new ChannelManager [Vollibrespot] librespot_audio::fetch: AudioFileOpen::len 27774548[u64] 211.903[chunks] => 212[chunks] [Vollibrespot] librespot_playback::player: Normalisation Data: NormalisationData { track_gain_db: -4.580002, track_peak: 1.073539, album_gain_db: -5.290001, album_peak: 1.073539 } [Vollibrespot] librespot_playback::player: Applied normalisation factor: 0.59020096 [Vollibrespot] vollibrespot::meta_pipe: GotToken { token: Token { access_token: "BQDdlzVfK6ubxi7zMytUCt54IUlgBCArc9GdyC7EjASsJGwC7ol1RwQOB6JPx2zVMMjXB9hHt8JxlN0o2DiM0lw50octV8ssbzMymgkTE5I-wa9g3QkRCJWEuvSRptyb4Jg5h1suMBS2B-ej1jHfSIecsnxyNPDu9lvEAPls8XLZVgKvT6FRkxSODA", expires_in: 3600, token_type: "Bearer", scope: ["streaming", "user-read-playback-state", "user-modify-playback-state", "user-read-currently-playing", "user-read-private"] } } [Vollibrespot] vollibrespot::meta_pipe: ApiToken::<Token { access_token: "BQDdlzVfK6ubxi7zMytUCt54IUlgBCArc9GdyC7EjASsJGwC7ol1RwQOB6JPx2zVMMjXB9hHt8JxlN0o2DiM0lw50octV8ssbzMymgkTE5I-wa9g3QkRCJWEuvSRptyb4Jg5h1suMBS2B-ej1jHfSIecsnxyNPDu9lvEAPls8XLZVgKvT6FRkxSODA", expires_in: 3600, token_type: "Bearer", scope: ["streaming", "user-read-playback-state", "user-modify-playback-state", "user-read-currently-playing", "user-read-private"] }> [Vollibrespot] : <From Trunch to Stromness> loaded [Vollibrespot] vollibrespot::meta_pipe: PlaybackStopped { track_id: SpotifyId { id: 117310924387342975591297438004363832889, audio_type: Track } } [Vollibrespot] librespot_connect::spirc: kMessageTypePlay "iPhone" 106e2a6599da26b75373043a9b0fcb46eb042b59 609375740 1585452299780 [Vollibrespot] librespot_playback::player: command=Play [Vollibrespot] vollibrespot::meta_pipe: PlaybackStarted { track_id: SpotifyId { id: 117310924387342975591297438004363832889, audio_type: Track } } [Vollibrespot] vollibrespot::meta_pipe: Play { track_id: SpotifyId { id: 117310924387342975591297438004363832889, audio_type: Track }, position_ms: 67876 } [Vollibrespot] vollibrespot::meta_pipe: SinkActive [Vollibrespot] : ConnectRequest: "Spotify/8.5.51 iOS/13.3.1 (iPhone11,2)" [Vollibrespot] librespot_connect::discovery: ConnectRequest: Some("action=getInfo") [Vollibrespot] : ConnectRequest: "Spotify/8.5.51 iOS/13.3.1 (iPhone11,2)" [Vollibrespot] librespot_connect::discovery: ConnectRequest: None [Vollibrespot] librespot_connect::discovery: POST "/" {} [Vollibrespot] librespot_connect::spirc: drop Spirc[0] [Vollibrespot] librespot_playback::player: Shutting down player thread ... [Vollibrespot] librespot_playback::player: drop Player[0] [Vollibrespot] : EventSender disconnected [Vollibrespot] vollibrespot::meta_pipe: drop MetaPipeThread[0] [Vollibrespot] : Exiting Vollibrespot volspotconnect2.service: main process exited, code=exited, status=1/FAILURE Unit volspotconnect2.service entered failed state. volspotconnect2.service holdoff time over, scheduling restart. Stopping Volspotconnect2 Daemon... Starting Volspotconnect2 Daemon... Started Volspotconnect2 Daemon. vollibrespot v0.1.9 c98fd5d 2019-11-08 (librespot 4674946 2019-11-08) -- Built On 2019-11-08 [Vollibrespot] librespot_connect::discovery: Zeroconf server listening on 0.0.0.0:38121 [Vollibrespot] : Failed to register IPv6 receiver: Os { code: 19, kind: Other, message: "No such device" }

illtrick commented 4 years ago

No love for multiple users? 😢 I'll hook someone up with a second premium account for a month if that's what's preventing them from digging into this.

ashthespy commented 4 years ago

This is in-fact the case for me.. Run out of premium trials with my second test account ;-)

illtrick commented 4 years ago

@ashthespy I think github removed the ability to send private messages but if you can somehow get me an email address I'll do the rest.

ashthespy commented 4 years ago

Catch me on gitter/forums via PM? I just glanced quickly at the code and see the problem, will try and fix it in the meantime..

ashthespy commented 4 years ago

Fixed, should be in the next version, for people (with armv7 devices) willing to help test and iron out the new version:

mkdir volspotconnect2
apt-get install bzip2
wget https://files.gitter.im/ashthespy/ABCG/Volspotconnect2_0.10.0.zip
miniunzip Volspotconnect2_0.10.0-beta.zip -d volspotconnect2/
cd volspotconnect2/
wget https://files.gitter.im/ashthespy/ZCnx/vollibrespot-armv7l.tar.xz
killall node 
volumio plugin install
illtrick commented 4 years ago

Marking this as closed. Huge thanks to @ashthespy you made it possible to keep Volumio in my house!