librespot crashes if volume is not changed first

[nrwiersma]

Describe the bug
I am running librespot via raspotify. When I connect using Spotify Connect and play a song, it instantly crashes. If I change the volume first, it does not crash.

To reproduce
Steps to reproduce the behavior:

1. Run librespot
2. Connect with Spotify Connect
3. In the client click on play
4. librespot crashes

Log

Nov 24 06:05:18 veranda-speakers systemd[1]: raspotify.service: Deactivated successfully.
Nov 24 06:05:18 veranda-speakers systemd[1]: Stopped raspotify.service - Raspotify (Spotify Connect Client).
Nov 24 06:05:18 veranda-speakers systemd[1]: Started raspotify.service - Raspotify (Spotify Connect Client).
Nov 24 06:05:19 veranda-speakers librespot[6225]: [2023-11-24T04:05:19Z WARN  librespot] `--verbose` and `--quiet` are mutually exclusive. Logging can not be both verbose and quiet. Using verbose mode.
Nov 24 06:05:19 veranda-speakers librespot[6225]: [2023-11-24T04:05:19Z INFO  librespot] librespot 0.4.2 a6e1258 (Built on 2023-06-21, Build ID: zuwVQKTQ, Profile: release)
Nov 24 06:05:19 veranda-speakers librespot[6225]: [2023-11-24T04:05:19Z TRACE librespot] Environment variable(s):
Nov 24 06:05:19 veranda-speakers librespot[6225]: [2023-11-24T04:05:19Z TRACE librespot]                 LIBRESPOT_NAME="Veranda Speakers"
Nov 24 06:05:19 veranda-speakers librespot[6225]: [2023-11-24T04:05:19Z TRACE librespot]                 LIBRESPOT_BACKEND="alsa"
Nov 24 06:05:19 veranda-speakers librespot[6225]: [2023-11-24T04:05:19Z TRACE librespot]                 LIBRESPOT_CACHE="/var/cache/raspotify"
Nov 24 06:05:19 veranda-speakers librespot[6225]: [2023-11-24T04:05:19Z TRACE librespot]                 LIBRESPOT_SYSTEM_CACHE="/var/lib/raspotify"
Nov 24 06:05:19 veranda-speakers librespot[6225]: [2023-11-24T04:05:19Z TRACE librespot]                 LIBRESPOT_QUIET=
Nov 24 06:05:19 veranda-speakers librespot[6225]: [2023-11-24T04:05:19Z TRACE librespot]                 LIBRESPOT_AUTOPLAY=
Nov 24 06:05:19 veranda-speakers librespot[6225]: [2023-11-24T04:05:19Z TRACE librespot]                 LIBRESPOT_DISABLE_AUDIO_CACHE=
Nov 24 06:05:19 veranda-speakers librespot[6225]: [2023-11-24T04:05:19Z TRACE librespot]                 LIBRESPOT_DISABLE_CREDENTIAL_CACHE=
Nov 24 06:05:19 veranda-speakers librespot[6225]: [2023-11-24T04:05:19Z TRACE librespot]                 LIBRESPOT_ENABLE_VOLUME_NORMALISATION=
Nov 24 06:05:19 veranda-speakers librespot[6225]: [2023-11-24T04:05:19Z TRACE librespot]                 LIBRESPOT_VERBOSE=
Nov 24 06:05:19 veranda-speakers librespot[6225]: [2023-11-24T04:05:19Z TRACE librespot]                 LIBRESPOT_INITIAL_VOLUME="50"
Nov 24 06:05:19 veranda-speakers librespot[6225]: [2023-11-24T04:05:19Z TRACE librespot]                 LIBRESPOT_VOLUME_RANGE="80.0"
Nov 24 06:05:19 veranda-speakers librespot[6225]: [2023-11-24T04:05:19Z DEBUG librespot_discovery::server] Zeroconf server listening on 0.0.0.0:36009
Nov 24 06:05:19 veranda-speakers librespot[6225]: [2023-11-24T04:05:19Z DEBUG librespot_discovery::server] Shutting down discovery server
Nov 24 06:05:28 veranda-speakers librespot[6225]: [2023-11-24T04:05:28Z DEBUG librespot_discovery::server] POST "/" {}
Nov 24 06:05:28 veranda-speakers librespot[6225]: [2023-11-24T04:05:28Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:4070
Nov 24 06:05:28 veranda-speakers librespot[6225]: [2023-11-24T04:05:28Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gue1.spotify.com:80
Nov 24 06:05:28 veranda-speakers librespot[6225]: [2023-11-24T04:05:28Z INFO  librespot_core::session] Connecting to AP "ap-gew1.spotify.com:4070"
Nov 24 06:05:29 veranda-speakers librespot[6225]: [2023-11-24T04:05:29Z INFO  librespot_core::session] Authenticated as "nrwiersma" !
Nov 24 06:05:29 veranda-speakers librespot[6225]: [2023-11-24T04:05:29Z DEBUG librespot_core::session] new Session[0]
Nov 24 06:05:29 veranda-speakers librespot[6225]: [2023-11-24T04:05:29Z INFO  librespot_playback::mixer::softmixer] Mixing with softvol and volume control: Log(80.0)
Nov 24 06:05:29 veranda-speakers librespot[6225]: [2023-11-24T04:05:29Z DEBUG librespot_playback::player] Created <PlayerInternal> [player:0] thread
Nov 24 06:05:29 veranda-speakers librespot[6225]: [2023-11-24T04:05:29Z DEBUG librespot_connect::spirc] new Spirc[0]
Nov 24 06:05:29 veranda-speakers librespot[6225]: [2023-11-24T04:05:29Z DEBUG librespot_connect::spirc] canonical_username: nrwiersma
Nov 24 06:05:29 veranda-speakers librespot[6225]: [2023-11-24T04:05:29Z DEBUG librespot::component] new MercuryManager
Nov 24 06:05:29 veranda-speakers librespot[6225]: [2023-11-24T04:05:29Z DEBUG librespot_playback::mixer::mappings] Input volume 32767 mapped to: 1.00%
Nov 24 06:05:29 veranda-speakers librespot[6225]: [2023-11-24T04:05:29Z INFO  librespot_playback::audio_backend::alsa] Using AlsaSink with format: S16, sample rate: 44100
Nov 24 06:05:29 veranda-speakers librespot[6225]: [2023-11-24T04:05:29Z DEBUG librespot_playback::resampler] Sample Rate: 44.1kHz
Nov 24 06:05:29 veranda-speakers librespot[6225]: [2023-11-24T04:05:29Z DEBUG librespot_playback::resampler] Interpolation Type: Bypass
Nov 24 06:05:29 veranda-speakers librespot[6225]: [2023-11-24T04:05:29Z DEBUG librespot_playback::resampler] No <ResampleWorker> threads required
Nov 24 06:05:29 veranda-speakers librespot[6225]: [2023-11-24T04:05:29Z DEBUG librespot_playback::normaliser] Normalisation Type: Auto
Nov 24 06:05:29 veranda-speakers librespot[6225]: [2023-11-24T04:05:29Z DEBUG librespot_playback::normaliser] Normalisation Pregain: 0.0 dB
Nov 24 06:05:29 veranda-speakers librespot[6225]: [2023-11-24T04:05:29Z DEBUG librespot_playback::normaliser] Normalisation Threshold: -2.0 dBFS
Nov 24 06:05:29 veranda-speakers librespot[6225]: [2023-11-24T04:05:29Z DEBUG librespot_playback::normaliser] Normalisation Method: Dynamic
Nov 24 06:05:29 veranda-speakers librespot[6225]: [2023-11-24T04:05:29Z DEBUG librespot_playback::normaliser] Normalisation Attack: 5 ms
Nov 24 06:05:29 veranda-speakers librespot[6225]: [2023-11-24T04:05:29Z DEBUG librespot_playback::normaliser] Normalisation Release: 100 ms
Nov 24 06:05:29 veranda-speakers librespot[6225]: [2023-11-24T04:05:29Z INFO  librespot_playback::convert] Converting with ditherer: tpdf
Nov 24 06:05:29 veranda-speakers librespot[6225]: [2023-11-24T04:05:29Z DEBUG librespot_playback::player] command=AddEventSender
Nov 24 06:05:29 veranda-speakers librespot[6225]: [2023-11-24T04:05:29Z DEBUG librespot_playback::player] command=VolumeSet(32767)
Nov 24 06:05:29 veranda-speakers librespot[6225]: [2023-11-24T04:05:29Z DEBUG librespot_core::session] Session[0] strong=3 weak=2
Nov 24 06:05:29 veranda-speakers librespot[6225]: [2023-11-24T04:05:29Z INFO  librespot_core::session] Country: "ZA"
Nov 24 06:05:30 veranda-speakers librespot[6225]: [2023-11-24T04:05:30Z DEBUG librespot_core::mercury] subscribed uri=hm://remote/user/nrwiersma/ count=0
Nov 24 06:05:30 veranda-speakers librespot[6225]: [2023-11-24T04:05:30Z DEBUG librespot_connect::spirc] kMessageTypeNotify "nick-laptop" f4ea63729b8268f5e807eb7ad37eb941e0a06584 2139165168 1700798729945 kPlayStatusStop
Nov 24 06:05:30 veranda-speakers librespot[6225]: [2023-11-24T04:05:30Z DEBUG librespot_connect::spirc] kMessageTypeNotify "Kitchen Speakers" 0dcb10f2f91b17950310ecff447c71020fb9ec9c 2139165168 1700798729945 kPlayStatusStop
Nov 24 06:05:30 veranda-speakers librespot[6225]: [2023-11-24T04:05:30Z DEBUG librespot_connect::spirc] kMessageTypeNotify "1c4a4011-4efc-4dc4-9c86-da60fc8da057" 1c4a4011-4efc-4dc4-9c86-da60fc8da057 2139165168 1700798729945 kPlayStatusStop
Nov 24 06:05:30 veranda-speakers librespot[6225]: [2023-11-24T04:05:30Z DEBUG librespot_connect::spirc] kMessageTypeNotify "Bar Speakers" 6d9bf24cf9fbabdf81df77dbce67764a5d76d65f 2139165168 1700798729945 kPlayStatusStop
Nov 24 06:05:30 veranda-speakers librespot[6225]: [2023-11-24T04:05:30Z DEBUG librespot_connect::spirc] kMessageTypeNotify "ecc5316c-4811-4da4-a2a3-bd7c7bfb7411" ecc5316c-4811-4da4-a2a3-bd7c7bfb7411 2139165168 1700798729945 kPlayStatusStop
Nov 24 06:05:30 veranda-speakers librespot[6225]: [2023-11-24T04:05:30Z DEBUG librespot_connect::spirc] kMessageTypeNotify "Nicholas’s MacBook Pro" fa26b61482bbad6d0af0b6c655650d556f6d2e91 2139165168 1700798729945 kPlayStatusStop
Nov 24 06:05:30 veranda-speakers librespot[6225]: [2023-11-24T04:05:30Z DEBUG librespot_connect::spirc] kMessageTypeLoad "nick-laptop" f4ea63729b8268f5e807eb7ad37eb941e0a06584 2139165453 1700798729945 kPlayStatusPause
Nov 24 06:05:30 veranda-speakers librespot[6225]: [2023-11-24T04:05:30Z DEBUG librespot_connect::spirc] State: context_uri: "spotify:playlist:37i9dQZF1DWTcEjayzrZ4x" index: 0 position_ms: 77922 status: kPlayStatusPause position_measured_at: 1700798730265 context_description: "" shuffle: false repeat: false playing_from_fallback: true row: 0 playing_track_index: 0 track {gid: "\262\351\2235\235OD\026\244P\351\216\265\262\t\010"} track {gid: "\203\032\350EY\367NK\226\353\002xf\242T\324" queued: true} track {gid: "Z\241c\247\231\311Iw\2413;b\"\234\325\226" queued: true} track {gid: "\367\232\217\252sJJ\212\2738\322\263\303)O#" queued: true} track {gid: "P@\202L\257(F\313\277\362\360\027l\267\337k" queued: true} track {gid: "\207\022\274\\3\343K\210\271\\b\023\351\312\244\206" queued: true} track {gid: "\210\024\360~d]J/\223\353<3\262\222\347\363" queued: true} track {gid: "\250\345_8\300\314Ar\271\274O\237\014\023\002e" queued: true} track {gid: "F\325\203\255\335\355E\223\277\035\2507^\262\310\214" queued: true} track {gid: "\366E5}\235XF\375\274y-am\216\242\213" queued: true} track {gid: "y&\036\273?\371H\226\264z\345s\336\034\316*" queued: true} track {gid: "\254b\257$\254eLd\204\204\275\274\320>\365\253"} track {gid: "8\202\215\016UyO\240\211.\301R;g\237S"} track {gid: "h\014\330\352BEDA\230&+\252\036\\g\""} track {gid: "\201=\002S\360\223M\353\221f\002\\sD\222\253"} track {gid: "<\266\251U\221\226H6\200\341\316\372\3277\2268"} track {gid: "[\253\030\276\323\201L\311\225\220\213\236O\253,i"} track {gid: "<Q\267\372\334SM\002\266n\246\353\347<\330["} track {gid: "tF\0058\372\356HI\263\023X\340\342\233\366\303"} track {gid: "\276\2226)\321zF\207\272&eI\315\270\364\340"} track {gid: "9\300\303\032\022\332E\234\273\353I\257\332\264\375\324"} track {gid: "\302&\252\235\030\024H\275\227=\350\254\333@\301\323"} track {gid: "WY\304T\200\036J\212\237\364\243O\314\rw\003"} track {gid: "V5\303$\034YAi\276ZC\031\027\010n\237"} track {gid: "\371\276\3372\302\tF\205\243\376\345`]\207\335\203"} track {gid: "[e\210\324\223\253J\313\250\304\251\233\335\317\224\316"} track {gid: "\273o\324\374\311}K\377\226\372\237\367\337EZf"} track {gid: "n}\241\017\304\262I\263\262\2647\232\211\307&\214"} track {gid: "f;\212\314\234\375C=\207d\325\267]\211\234m"} track {gid: "\230d\277\013\251[G/\251)\020\327\263\376\027\372"} track {gid: "\257C\\\241\261xE6\221\227\236nF\312\275\272"} track {gid: "V\342\275:#`H\252\262 \310\242\277\220\240|"} track {gid: "\311/\363\2250\375M\211\217\355\351x\002\000}\020"} track {gid: "\3270\245:\3238A\177\257u*\322\241\313w\304"} track {gid: "t\343+5\221\265E\203\217\237\215\304\376\3421\013"} track {gid: "\002\200P\250LkD4\235\010?\310\033<\254\366"} track {gid: "\261\224\010T|}A\227\202\224\345\246_\311\342r"} track {gid: "\375\264\362\212<PN\245\211\251\203:D\323\2616"} track {gid: "wa=\337X\323C\361\226\323/\310\376\\\035\205"} track {gid: "\247JR\177\275\346F&\241\213\316\240z\361<D"} track {gid: "\253\375m\257\234\tM\263\265\004G\250\367/\003\352"} track {gid: "\270\310\003j\331nEl\224\032/\254U\231M\223"} track {gid: "1\362\360\373\023\370D\366\207\312\352\222\223i\213w"} track {gid: "B\371\325\307w\013F:\216\261v\350\225\373\020."} track {gid: "0\250\242LX\331O\274\2478\035\235\225\010T\270"} track {gid: "\336/\r\253\027\013O+\230K\020\021D\327\203\362"} track {gid: "f\322Y\210\271kJ\030\242\342\032\250u\200\214\260"} track {gid: "\261E\221\017n\260J\252\202\316\212?z`Z\327"} track {gid: "\263\2154\366\262\017K\255\255\253rtQ\003\333z"} track {gid: "\034R\215\355\3741C\370\216).\325bPb\307"} track {gid: "9m\261\242\267\265C\007\222\025\034\025\232\265\\\030"} track {gid: "\020l\234_.\363O\365\225\321F#\302>O\360"} track {gid: "\021\357\325T\227\243NV\234\323\023h5jQ\311"} track {gid: "5\313m\225\202vE5\2149s\226\024\204O\323"} track {gid: "G`l\026C\313J\201\275B\271w{\037\266~"} track {gid: " <\2523U\244BN\202\362!\326\237\177\217)"} track {gid: "\242\025\037\372O\rN\222\244\2502\025:\334V\036"} track {gid: "\355\314p\212l\202A}\277\374P\341\031G\006M"} track {gid: "\272\036\333\334SMEY\212\177\346\311\311\370\333%"} track {gid: "\233K\207\363\016\251Df\214Cpx\334\315\223\251"} track {gid: "\374\326\304\343V\017A\345\223\245Fo|d\272\315"} track {gid: "Fb\223\302\345*N\372\250\270{fDo\320:"} track {gid: "\034\275W\322\300XF6\214t\355U\310\201\360\223"} track {gid: "\335P\177\220\242\207J~\204T\3612M\231\205n"} track {gid: "\371\275\306m\214\230@6\225\261\177O\266\316h\""} track {gid: "P\367\242\007\027UK\221\212\rtd\017\216q\314"} track {gid: "\223I\205\222\327BKt\232\017\034\343n\305D\363"} track {gid: "U\244\210\226\"\274H\216\216\022\352\272n\023Ka"} track {gid: "\025\321~\364\303\301I\340\232\251\2108T\2035O"} track {gid: "\216x\177\312Y9L\016\236\033u\223^\340\241e"} track {gid: "Z+\301\200RLH>\271Ox7@\2577W"} track {gid: "\332\340\322\325\314\317C\222\277:2_h\376\230\306"} track {gid: "\363gO\331\306^E\304\235\245zDe7\264<"} track {gid: "\2424\261\326b0O\341\253\213D\377&\376X\016"} track {gid: "\327\235\305\311\244\303G\342\233\335\2310\370\334:\364"} track {gid: ".1\304+r\322D\377\276|\363\n\235\373\262\245"} track {gid: "$\352ic\3076J\302\230\250\362m\331\313X\000"} track {gid: "n\311\213w2\"M\263\260\221E\030\261\300\216\235"} track {gid: "q\346\245\31659A\234\271sBI\007\2078\216"} track {gid: "\373\314\336\202\310\312Fa\247\006]S\014\020\034s"} track {gid: "\332N\317\037\003\352IV\271\214\264h\271\037\326\'"} track {gid: "u\356\340\271\271\255G\n\242s:\334\345\203\220\213"} track {gid: "\351\315}EH\251G\341\272\001\204\034\247}\235\225"} track {gid: "x\204\325\310\341^N\355\253\003r-\317m^y"} track {gid: "\217\266,\332\032\256@\362\217$h\222*\274\020\026"} track {gid: "\205\266\355t\037YF\327\213\315\010\203n9\204\006"} track {gid: "H\231\010\r\024!O\312\217wo6\331\230o\031"} track {gid: "\"\376\'\234]\346I\247\232\"u\236\222\305\250\223"} track {gid: "|\3244B\226\346I\213\252Hg\264\212L\312\331"} track {gid: "6~\021\261\370EIu\2066\3411G\237k("} track {gid: "-\257\031\342l\350H\255\267\271W\374\025X\017e"}
Nov 24 06:05:30 veranda-speakers librespot[6225]: [2023-11-24T04:05:30Z DEBUG librespot_connect::spirc] Frame has 91 tracks
Nov 24 06:05:30 veranda-speakers librespot[6225]: [2023-11-24T04:05:30Z INFO  librespot_connect::spirc] Fetching autoplay context uri
Nov 24 06:05:30 veranda-speakers librespot[6225]: [2023-11-24T04:05:30Z DEBUG librespot_playback::player] command=SetAutoNormaliseAsAlbum(false)
Nov 24 06:05:30 veranda-speakers librespot[6225]: [2023-11-24T04:05:30Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPause]
Nov 24 06:05:30 veranda-speakers librespot[6225]: [2023-11-24T04:05:30Z DEBUG librespot_playback::player] command=Load(SpotifyId { id: 237815374179742963486177631549955115272, audio_type: Track }, false, 77922)
Nov 24 06:05:30 veranda-speakers librespot[6225]: [2023-11-24T04:05:30Z DEBUG librespot_playback::player] Created <PlayerInternal> [loader:spotify:track:5rBnsa0pkuIndZ3vGW95vq] thread
Nov 24 06:05:30 veranda-speakers librespot[6225]: [2023-11-24T04:05:30Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPause]
Nov 24 06:05:30 veranda-speakers librespot[6225]: [2023-11-24T04:05:30Z INFO  librespot_playback::player] Loading <You're All I Can Think Of> with Spotify URI <spotify:track:5rBnsa0pkuIndZ3vGW95vq>
Nov 24 06:05:30 veranda-speakers librespot[6225]: [2023-11-24T04:05:30Z DEBUG librespot_audio::fetch] Downloading file b14e0af1e7871c4bb4cdeb94741ca7f3fffda89f
Nov 24 06:05:30 veranda-speakers librespot[6225]: [2023-11-24T04:05:30Z DEBUG librespot::component] new ChannelManager
Nov 24 06:05:30 veranda-speakers librespot[6225]: [2023-11-24T04:05:30Z INFO  librespot_connect::spirc] Autoplay uri resolved to <"spotify:playlist:37i9dQZF1DWV7EzJMK2FUI">
Nov 24 06:05:30 veranda-speakers librespot[6225]: [2023-11-24T04:05:30Z DEBUG librespot::component] new AudioKeyManager
Nov 24 06:05:31 veranda-speakers librespot[6225]: [2023-11-24T04:05:31Z INFO  librespot_connect::spirc] Resolved 50 tracks from <"spotify:playlist:37i9dQZF1DWTcEjayzrZ4x">
Nov 24 06:05:32 veranda-speakers librespot[6225]: [2023-11-24T04:05:32Z DEBUG librespot_connect::spirc] kMessageTypePlay "nick-laptop" f4ea63729b8268f5e807eb7ad37eb941e0a06584 2139167155 1700798730550 kPlayStatusPause
Nov 24 06:05:32 veranda-speakers librespot[6225]: [2023-11-24T04:05:32Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPause]
Nov 24 06:05:32 veranda-speakers librespot[6225]: [2023-11-24T04:05:32Z DEBUG librespot_playback::player] command=Play
Nov 24 06:05:32 veranda-speakers librespot[6225]: [2023-11-24T04:05:32Z ERROR librespot_playback::player] Player::play called from invalid state
Nov 24 06:05:32 veranda-speakers systemd[1]: raspotify.service: Main process exited, code=exited, status=1/FAILURE
Nov 24 06:05:32 veranda-speakers systemd[1]: raspotify.service: Failed with result 'exit-code'.
Nov 24 06:05:32 veranda-speakers systemd[1]: raspotify.service: Triggering OnFailure= dependencies.

-- Config --

LIBRESPOT_QUIET=
LIBRESPOT_AUTOPLAY=
LIBRESPOT_DISABLE_AUDIO_CACHE=
LIBRESPOT_DISABLE_CREDENTIAL_CACHE=
LIBRESPOT_ENABLE_VOLUME_NORMALISATION=
LIBRESPOT_VERBOSE=
LIBRESPOT_NAME="Veranda Speakers"
LIBRESPOT_INITIAL_VOLUME="50"
LIBRESPOT_VOLUME_RANGE="80.0"

Host (what you are running librespot on):

• OS: Raspberry Pi OS Bookworm
• Platform: Raspberry Pi Zero 2 WH

[nrwiersma]

I have been running through the versions to see where things break. It seems this is the last "working" version before I see the issue: librespot 0.4.2 70997e9 (Built on 2023-03-16, Build ID: flowgGlc, Profile: release)

[roderickvd]

There aren't any different 0.4.2 releases of librespot. But maybe there are different releases of raspotify?
Please try a vanilla librespot here (so not packaged with raspotify).

[nrwiersma]

Hi. I am aware that vanilla 0.4.2 does not have this issue. Raspotify has its own builds. But the issue remains the same on the dev branch I guess. It seems if I dont change the volume first, I end up here when I first press play:

https://github.com/librespot-org/librespot/blob/dev/playback/src/player.rs#L1509C26-L1509C64

On 0.4.2, I end up in the same place:

https://github.com/librespot-org/librespot/blob/v0.4.2/playback/src/player.rs#L1284

but in this case it is just a warning, so it does not play but also does not exit.