Segmentation fault when selecting spoifyd as playback device and starting playback

[Witcher01]

Description Spotifyd segfault's when music should start playing.

To Reproduce

1. Start spotifyd
2. Play music selecting a different device on Spotfy
3. Segfault

Expected behavior Should play music

Logs

Click to show logs

``` Loading config from "/home/thomas/.config/spotifyd/spotifyd.conf" CliConfig { config_path: None, no_daemon: true, verbose: true, pid: None, shared_config: SharedConfigValues { username: Some("taken out for privacy"), username_cmd: None, password: None, password_cmd: Some("taken out for privacy"), use_keyring: false, use_mpris: None, on_song_change_hook: None, cache_path: None, no-audio-cache: false, backend: Some(Alsa), volume_controller: None, device: None, control: None, mixer: None, device_name: None, bitrate: None, initial_volume: None, volume_normalisation: false, normalisation_pregain: None, zeroconf_port: None, proxy: None, device_type: None, autoplay: false, max_cache_size: None } } Found user shell: Some("/bin/zsh") No password specified. Checking password_cmd Running "wait-for-creds.sh spotify password" using "/bin/zsh" No proxy specified registering event source with poller: token=Token(0), interests=READABLE | WRITABLE Using software volume controller. Connecting to AP "ap.spotify.com:443" registering event source with poller: token=Token(1), interests=READABLE | WRITABLE flushing framed transport writing; remaining=192 framed transport flushed attempting to decode a frame frame decoded from buffer Authenticated as "TODO for devs: take this out" ! new Session[0] flushing framed transport framed transport flushed new Spirc[0] attempting to decode a frame canonical_username: TODO for devs: take this out new Player[0] Using Alsa sink with format: S16 new MercuryManager frame decoded from buffer Session[0] strong=4 weak=2 attempting to decode a frame input volume:65535 to mixer: 65535 frame decoded from buffer attempting to decode a frame command=AddEventSender command=VolumeSet(65535) frame decoded from buffer attempting to decode a frame frame decoded from buffer Country: "DE" attempting to decode a frame frame decoded from buffer attempting to decode a frame frame decoded from buffer attempting to decode a frame frame decoded from buffer attempting to decode a frame flushing framed transport writing; remaining=436 framed transport flushed flushing framed transport framed transport flushed attempting to decode a frame frame decoded from buffer attempting to decode a frame flushing framed transport framed transport flushed attempting to decode a frame frame decoded from buffer attempting to decode a frame subscribed uri=hm://remote/user/TODO for devs: take this out/ count=0 frame decoded from buffer attempting to decode a frame frame decoded from buffer attempting to decode a frame kMessageTypeGoodbye "Thomas’ iPhone" fad2a5d4b7d363443d2b91defe2e17ae4959a165 1213738990 1663366081768 kPlayStatusStop flushing framed transport framed transport flushed attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame kMessageTypeHello "Thomas’ iPhone" fad2a5d4b7d363443d2b91defe2e17ae4959a165 1213743534 1663366086312 kPlayStatusStop Sending status to server: [kPlayStatusStop] frame decoded from buffer attempting to decode a frame kMessageTypeNotify "Thomas’ iPhone" fad2a5d4b7d363443d2b91defe2e17ae4959a165 1213743534 1663366086312 kPlayStatusStop flushing framed transport writing; remaining=410 framed transport flushed flushing framed transport framed transport flushed attempting to decode a frame frame decoded from buffer attempting to decode a frame flushing framed transport framed transport flushed attempting to decode a frame frame decoded from buffer attempting to decode a frame kMessageTypeLoad "Thomas’ iPhone" fad2a5d4b7d363443d2b91defe2e17ae4959a165 1213745243 1663366086312 kPlayStatusPause State: context_uri: "spotify:album:4edWR14ULxaPjBWlGGMIK1" index: 1 position_ms: 10758 status: kPlayStatusPause position_measured_at: 1663366088067 context_description: "" shuffle: false repeat: false playing_from_fallback: true row: 0 playing_track_index: 1 track {gid: "\362\367\317m\236\277O\275\207X\017)\312\204\021\307"} track {gid: "\217\025\341\334\031zA\317\201\016aY\245\266\2445"} track {gid: "\321\203\332d\034*IN\244\265\300j\2473\233H"} track {gid: "N`\371\016\2332CY\207MI\026JQ\"\215"} track {gid: "Xo@\320\317\303O[\243d{!\205\341\272\215"} track {gid: "M\037^\262\336\222G\324\227\2218k\247\250v_"} track {gid: "\355\2359\234\360\212D\275\245\001*\322!1\240\241"} track {gid: "\326\203\354z\200\010Ls\274\037\205\243\303\032\245e"} track {gid: "\230\267\002\201\017]I\345\247\307D9\211\003\340\352"} track {gid: "\0359b\240\301!J\372\226!\035\276\333,>\270"} track {gid: "vd\3066SlJ\221\276\315\017\336i+\256:"} track {gid: "\032\002\0277\230VJ%\271\271\354\024\010\205\010!"} Frame has 12 tracks Sending status to server: [kPlayStatusPause] command=Load(SpotifyId { id: 190193222611513700946566707334687925301, audio_type: Track }, false, 10758) Sending status to server: [kPlayStatusPause] flushing framed transport writing; remaining=686 framed transport flushed flushing framed transport writing; remaining=769 framed transport flushed flushing framed transport framed transport flushed attempting to decode a frame frame decoded from buffer attempting to decode a frame flushing framed transport framed transport flushed attempting to decode a frame flushing framed transport framed transport flushed attempting to decode a frame frame decoded from buffer attempting to decode a frame Loading with Spotify URI Downloading file 995f48cfda22e871fc320f75ceea1483903d1fc3 new ChannelManager flushing framed transport writing; remaining=53 framed transport flushed flushing framed transport framed transport flushed attempting to decode a frame frame decoded from buffer attempting to decode a frame flushing framed transport framed transport flushed attempting to decode a frame frame decoded from buffer attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame kMessageTypeNotify "Thomas’ iPhone" fad2a5d4b7d363443d2b91defe2e17ae4959a165 1213745548 1663366088326 kPlayStatusPlay new AudioKeyManager command=Stop frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame Ping time estimated as: 63 ms. flushing framed transport writing; remaining=49 framed transport flushed flushing framed transport framed transport flushed attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame frame decoded from buffer attempting to decode a frame flushing framed transport framed transport flushed attempting to decode a frame frame decoded from buffer attempting to decode a frame Normalisation Data: NormalisationData { track_gain_db: -10.392186, track_peak: 1.0392327, album_gain_db: -11.16839, album_peak: 1.0392327 } Normalisation Type: Album Normalisation Threshold: 0.0 Normalisation Method: Dynamic Normalisation Factor: 0.276427 Normalisation Attack: 0.005 Normalisation Release: 0.1 Normalisation Knee: 1.0 flushing framed transport writing; remaining=53 framed transport flushed flushing framed transport framed transport flushed attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame frame decoded from buffer attempting to decode a frame frame decoded from buffer attempting to decode a frame Ping time estimated as: 57 ms. flushing framed transport writing; remaining=53 framed transport flushed flushing framed transport framed transport flushed attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame frame decoded from buffer attempting to decode a frame Ping time estimated as: 39 ms. flushing framed transport writing; remaining=53 framed transport flushed flushing framed transport framed transport flushed attempting to decode a frame frame decoded from buffer attempting to decode a frame flushing framed transport framed transport flushed attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame frame decoded from buffer attempting to decode a frame Ping time estimated as: 43 ms. flushing framed transport writing; remaining=53 framed transport flushed flushing framed transport framed transport flushed attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame frame decoded from buffer attempting to decode a frame Ping time estimated as: 58 ms. flushing framed transport writing; remaining=53 framed transport flushed flushing framed transport framed transport flushed attempting to decode a frame frame decoded from buffer attempting to decode a frame flushing framed transport framed transport flushed attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame frame decoded from buffer attempting to decode a frame Ping time estimated as: 70 ms. flushing framed transport writing; remaining=53 framed transport flushed flushing framed transport framed transport flushed attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame frame decoded from buffer attempting to decode a frame Ping time estimated as: 57 ms. flushing framed transport writing; remaining=53 framed transport flushed flushing framed transport framed transport flushed attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame frame decoded from buffer attempting to decode a frame Ping time estimated as: 57 ms. flushing framed transport writing; remaining=53 framed transport flushed flushing framed transport framed transport flushed attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame frame decoded from buffer attempting to decode a frame Ping time estimated as: 59 ms. (180026 ms) loaded flushing framed transport writing; remaining=53 framed transport flushed flushing framed transport framed transport flushed attempting to decode a frame frame decoded from buffer attempting to decode a frame flushing framed transport framed transport flushed attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame frame decoded from buffer attempting to decode a frame flushing framed transport framed transport flushed attempting to decode a frame frame decoded from buffer attempting to decode a frame kMessageTypeNotify "Thomas’ iPhone" fad2a5d4b7d363443d2b91defe2e17ae4959a165 1213747179 1663366089957 kPlayStatusPlay flushing framed transport framed transport flushed attempting to decode a frame frame decoded from buffer attempting to decode a frame kMessageTypeLoad "Thomas’ iPhone" fad2a5d4b7d363443d2b91defe2e17ae4959a165 1213748012 1663366089957 kPlayStatusPlay State: context_uri: "spotify:album:4edWR14ULxaPjBWlGGMIK1" index: 1 position_ms: 13326 status: kPlayStatusPlay position_measured_at: 1663366090838 context_description: "" shuffle: false repeat: false playing_from_fallback: true row: 0 playing_track_index: 1 track {gid: "\362\367\317m\236\277O\275\207X\017)\312\204\021\307"} track {gid: "\217\025\341\334\031zA\317\201\016aY\245\266\2445"} track {gid: "\321\203\332d\034*IN\244\265\300j\2473\233H"} track {gid: "N`\371\016\2332CY\207MI\026JQ\"\215"} track {gid: "Xo@\320\317\303O[\243d{!\205\341\272\215"} track {gid: "M\037^\262\336\222G\324\227\2218k\247\250v_"} track {gid: "\355\2359\234\360\212D\275\245\001*\322!1\240\241"} track {gid: "\326\203\354z\200\010Ls\274\037\205\243\303\032\245e"} track {gid: "\230\267\002\201\017]I\345\247\307D9\211\003\340\352"} track {gid: "\0359b\240\301!J\372\226!\035\276\333,>\270"} track {gid: "vd\3066SlJ\221\276\315\017\336i+\256:"} track {gid: "\032\002\0277\230VJ%\271\271\354\024\010\205\010!"} Frame has 12 tracks Sending status to server: [kPlayStatusPlay] command=Load(SpotifyId { id: 190193222611513700946566707334687925301, audio_type: Track }, true, 13326) Sending status to server: [kPlayStatusPlay] flushing framed transport writing; remaining=1455 framed transport flushed flushing framed transport framed transport flushed attempting to decode a frame frame decoded from buffer attempting to decode a frame Loading with Spotify URI Downloading file 995f48cfda22e871fc320f75ceea1483903d1fc3 flushing framed transport writing; remaining=53 framed transport flushed flushing framed transport framed transport flushed attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame frame decoded from buffer attempting to decode a frame Ping time estimated as: 57 ms. flushing framed transport writing; remaining=49 framed transport flushed flushing framed transport framed transport flushed attempting to decode a frame frame decoded from buffer attempting to decode a frame frame decoded from buffer attempting to decode a frame flushing framed transport framed transport flushed attempting to decode a frame frame decoded from buffer unknown subscription uri=social-connect/v2/session_update attempting to decode a frame flushing framed transport framed transport flushed attempting to decode a frame frame decoded from buffer unknown subscription uri=social-connect/v2/session_update attempting to decode a frame frame decoded from buffer attempting to decode a frame Normalisation Data: NormalisationData { track_gain_db: -10.392186, track_peak: 1.0392327, album_gain_db: -11.16839, album_peak: 1.0392327 } Normalisation Type: Album Normalisation Threshold: 0.0 Normalisation Method: Dynamic Normalisation Factor: 0.276427 Normalisation Attack: 0.005 Normalisation Release: 0.1 Normalisation Knee: 1.0 flushing framed transport writing; remaining=53 framed transport flushed flushing framed transport framed transport flushed attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame Ping time estimated as: 37 ms. flushing framed transport framed transport flushed attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame frame decoded from buffer attempting to decode a frame frame decoded from buffer attempting to decode a frame flushing framed transport writing; remaining=53 framed transport flushed flushing framed transport framed transport flushed attempting to decode a frame frame decoded from buffer attempting to decode a frame flushing framed transport framed transport flushed attempting to decode a frame flushing framed transport framed transport flushed attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame frame decoded from buffer attempting to decode a frame Ping time estimated as: 63 ms. flushing framed transport writing; remaining=53 framed transport flushed flushing framed transport framed transport flushed attempting to decode a frame frame decoded from buffer attempting to decode a frame flushing framed transport framed transport flushed attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame frame decoded from buffer attempting to decode a frame Ping time estimated as: 61 ms. flushing framed transport writing; remaining=53 framed transport flushed flushing framed transport framed transport flushed attempting to decode a frame frame decoded from buffer attempting to decode a frame flushing framed transport framed transport flushed attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame frame decoded from buffer attempting to decode a frame Ping time estimated as: 59 ms. flushing framed transport framed transport flushed attempting to decode a frame frame decoded from buffer attempting to decode a frame kMessageTypeNotify "Thomas’ iPhone" fad2a5d4b7d363443d2b91defe2e17ae4959a165 1213748546 1663366091324 kPlayStatusStop flushing framed transport writing; remaining=53 framed transport flushed flushing framed transport framed transport flushed attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame frame decoded from buffer attempting to decode a frame Ping time estimated as: 57 ms. flushing framed transport writing; remaining=53 framed transport flushed flushing framed transport framed transport flushed attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame frame decoded from buffer attempting to decode a frame Ping time estimated as: 62 ms. flushing framed transport writing; remaining=53 framed transport flushed flushing framed transport framed transport flushed attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame frame decoded from buffer attempting to decode a frame Ping time estimated as: 68 ms. flushing framed transport writing; remaining=53 framed transport flushed flushing framed transport framed transport flushed attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame attempting to decode a frame frame decoded from buffer attempting to decode a frame frame decoded from buffer attempting to decode a frame Ping time estimated as: 58 ms. (180026 ms) loaded == Starting sink == zsh: segmentation fault ./target/debug/spotifyd --no-daemon --verbose ```

Compilation flags (features were not changed, using alsa)

• [ ] dbus_mpris
• [ ] dbus_keyring
• [x] alsa_backend
• [ ] portaudio_backend
• [ ] pulseaudio_backend
• [ ] rodio_backend

Versions (please complete the following information):

• OS: Alpine Linux (Edge)
• Spotifyd: 7146f64a819590a16de9991de74f8bc2fea9c2ac
• cargo: cargo 1.63.0 (fd9c4297c 2022-07-01)

Additional context

• Alsa is used for playback
• Alpine Linux is a musl-based distro (glibc is not available)

[eladyn]

Thank you for the report!

From the logs you provided, it seems that the segfault is related to starting the alsa sink (the code that logs the last message is here), but that could be wrong as well.

Would you be able to obtain a core dump from that crash? Then we might be able to see, which exact method calls caused the crash.

[Witcher01]

Hi, thanks for the quick reply! You can find the core dump here: core.27297.gz

I wanted to debug a bit myself and found out the segfault actually happens in alsa-rs, in this exact line: https://github.com/diwic/alsa-rs/blob/638dce00a9cf01d80526b23a908173ce40ee870b/src/pcm.rs#L131

I'm not sure where to go from here, partially due to gdb not being able to show me anything beyond librespot_playback::audio_backend::alsa::open_device when stepping through the code:

(gdb) s
alloc::string::{impl#37}::deref (self=0x7ffff65c3610) at /rustc/4b91a6ea7258a947e59c6522cd5898e7c0a6a88f/library/alloc/src/string.rs:2413
2413    /rustc/4b91a6ea7258a947e59c6522cd5898e7c0a6a88f/library/alloc/src/string.rs: No such file or directory.

If, by any chance, you know a solution to this, I'd be happy to hear it!

I would open an issue (or send a patch directly) in alsa-rs, but lack the context of the segfault.

[eladyn]

I don't have much experience with debugging with gdb, but I think I can't do much with the core dump without your specific configuration and binaries. (Should've thought about that before asking for one. :sweat_smile:)

Anyway, I remembered that something similar to this had also happened to me before and it turned out to be a similar issue as https://github.com/diwic/alsa-rs/issues/59. In my specific case, this just required adding compiler flags, maybe it's different in your situation, but this issue in alsa-rs might get you on the right track.

[eladyn]

@Witcher01, has this issue since been resolved? :)

[Witcher01]

I'm so sorry, it seems like I missed your previous comment on this!

In the end, I cannot say whether this is fixed or not, sorry about that. I've since switched back from Alpine to a glibc based distro where this problem doesn't show (unrelated reasons). I have not tried the suggested solution.

For the sake of my issue, you can mark this as resolved. As for if this is an issue for others you'll seem to have to find another person that also runs this on Alpine/musl (iirc this is a musl issue).

Thanks for asking if this has been resolved, and sorry again about missing your comment!

[eladyn]

No, worries! Good to hear that you found a solution for yourself. :)