search

dtcooper / raspotify

A Spotify Connect client that mostly Just Works™
https://dtcooper.github.io/raspotify
MIT License
4.66k stars 216 forks source link

Sound stops after <1 second while Spotify shows it's playing #623

Closed carlfriedrich closed 1 year ago

carlfriedrich commented 1 year ago

Due Diligence

What can we help you with?

I have just installed raspotify on a freh Raspberry PI OS 64bit. I have no external DAC connected, just using the headphone jack to play audio.

Connecting my Spotify to the raspotify worked out of the box: it showed up on Spotify Connect, I could instantly connect to it, and the sound started. It immediately stopped again, though. My Spotify app however shows it's still playing. Whenever I hit pause and then play again, the sound appears for a fraction of a second and then disappears again.

Any ideas what might cause this?

JasonLG1979 commented 1 year ago

Hard to say since you have not included any logs or any other useful information.

carlfriedrich commented 1 year ago

Hi @JasonLG1979, thanks for your quick reply and sorry for the missing logs.

I just re-installed Raspberry Pi OS, this time the 32-bit variant, in order to check if that makes a difference. Then I installed raspotify, and that's it. Behavior exactly the same like before.

Logs:

tim@rpi:~ $ sudo journalctl -u raspotify -b
-- Journal begins at Wed 2023-05-03 02:25:51 CEST, ends at Mon 2023-05-08 16:02:31 CEST. --
May 08 16:01:17 rpi systemd[1]: Started Raspotify (Spotify Connect Client).
May 08 16:01:21 rpi librespot[1293]: [2023-05-08T14:01:21Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:4070
May 08 16:01:21 rpi librespot[1293]: [2023-05-08T14:01:21Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:443
May 08 16:01:21 rpi librespot[1293]: [2023-05-08T14:01:21Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:80
May 08 16:01:21 rpi librespot[1293]: [2023-05-08T14:01:21Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gue1.spotify.com:4070
tim@rpi:~ $ sudo cat /etc/raspotify/crash_report
cat: /etc/raspotify/crash_report: No such file or directory

Does that help? Anything else I could check?

JasonLG1979 commented 1 year ago

That doesn't really show anything wrong weird. Try running librespot in debug mode (verbose logging) from the terminal. Let's see what it says.

carlfriedrich commented 1 year ago 
tim@rpi:~ $ librespot -v
[2023-05-08T14:14:14Z INFO  librespot] librespot 0.4.2 626a51a (Built on 2023-05-07, Build ID: tWZ8mek2, Profile: release)
[2023-05-08T14:14:14Z TRACE librespot] Command line argument(s):
[2023-05-08T14:14:14Z TRACE librespot]          v
[2023-05-08T14:14:14Z DEBUG librespot_discovery::server] Zeroconf server listening on 0.0.0.0:41607
[2023-05-08T14:14:14Z DEBUG librespot_discovery::server] Shutting down discovery server
[2023-05-08T14:14:17Z DEBUG librespot_discovery::server] POST "/" {}
[2023-05-08T14:14:17Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:4070
[2023-05-08T14:14:17Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:443
[2023-05-08T14:14:17Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:80
[2023-05-08T14:14:17Z WARN  librespot_core::apresolve] Ignoring blacklisted access point ap-gue1.spotify.com:4070
[2023-05-08T14:14:17Z INFO  librespot_core::session] Connecting to AP "ap-guc3.spotify.com:443"
[2023-05-08T14:14:18Z INFO  librespot_core::session] Authenticated as "carlfriedrich" !
[2023-05-08T14:14:18Z DEBUG librespot_core::session] new Session[0]
[2023-05-08T14:14:18Z INFO  librespot_playback::mixer::softmixer] Mixing with softvol and volume control: Log(60.0)
[2023-05-08T14:14:18Z DEBUG librespot_connect::spirc] new Spirc[0]
[2023-05-08T14:14:18Z DEBUG librespot_connect::spirc] canonical_username: carlfriedrich
[2023-05-08T14:14:18Z DEBUG librespot_playback::player] new Player[0]
[2023-05-08T14:14:18Z INFO  librespot_playback::convert] Converting with ditherer: tpdf
[2023-05-08T14:14:18Z INFO  librespot_playback::audio_backend::alsa] Using AlsaSink with format: S16
[2023-05-08T14:14:18Z DEBUG librespot::component] new MercuryManager
[2023-05-08T14:14:18Z DEBUG librespot_playback::player] command=AddEventSender
[2023-05-08T14:14:18Z DEBUG librespot_playback::mixer::mappings] Input volume 58958 mapped to: 49.99%
[2023-05-08T14:14:18Z DEBUG librespot_playback::player] command=VolumeSet(58958)
[2023-05-08T14:14:18Z DEBUG librespot_core::session] Session[0] strong=3 weak=2
[2023-05-08T14:14:18Z INFO  librespot_core::session] Country: "DE"
[2023-05-08T14:14:18Z DEBUG librespot_core::mercury] subscribed uri=hm://remote/user/carlfriedrich/ count=0
[2023-05-08T14:14:18Z DEBUG librespot_connect::spirc] kMessageTypeNotify "Tims Telefon" 5b99ff037188bf32c8c5c3ec47b358c796f9ca25 2075562510 1683555258111 kPlayStatusStop
[2023-05-08T14:14:18Z DEBUG librespot_connect::spirc] kMessageTypeNotify "DESKTOP-TIM" 3a5a69f294c6e6fd2b5ab5bb520fd7f6949e8dc5 2075562510 1683555258111 kPlayStatusStop
[2023-05-08T14:14:19Z DEBUG librespot_connect::spirc] kMessageTypeLoad "Tims Telefon" 5b99ff037188bf32c8c5c3ec47b358c796f9ca25 2075563079 1683555238881 kPlayStatusPause
[2023-05-08T14:14:19Z DEBUG librespot_connect::spirc] State: context_uri: "spotify:album:7GVO4vtxp0eEWsETAWk3nZ" index: 1 position_ms: 58858 status: kPlayStatusPause position_measured_at: 1683555258893 context_description: "" shuffle: false repeat: false playing_from_fallback: true row: 0 playing_track_index: 1 track {gid: "+\030J\311\r\325HS\263\250\230\242\247s\014\215"} track {gid: "\224\311\355\302Q\000I\362\267\220\022\323WA\362a"} track {gid: "\021\211\021\237D\316Iy\26211\027\206\2233\274"} track {gid: "\024\naB\325\225M6\2033\237dK\347bq"} track {gid: "|\235J\302L\275AI\244\237\232]\201\375\357^"} track {gid: "/LE)\n\214L\227\205\3542*$\251N]"} track {gid: "\337H\023\361&<D\273\252\301M\200\255\300\214\262"} track {gid: "\270\237,\327d\361C\225\206r\363\354\314\262\'2"} track {gid: "\344m\317\324\327FE\306\2603\231(7O\031W"} track {gid: ".\231\351\232\357\341GG\244&\2503\226q\377\034"} track {gid: "Y2\3365i6L\271\254\006\355\005\205\233\257\207"}
[2023-05-08T14:14:19Z DEBUG librespot_connect::spirc] Frame has 11 tracks
[2023-05-08T14:14:19Z DEBUG librespot_playback::player] command=SetAutoNormaliseAsAlbum(true)
[2023-05-08T14:14:19Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPause]
[2023-05-08T14:14:19Z DEBUG librespot_playback::player] command=Load(SpotifyId { id: 197774217371141277761891402022763229793, audio_type: Track }, false, 58858)
[2023-05-08T14:14:19Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPause]
[2023-05-08T14:14:19Z INFO  librespot_playback::player] Loading <Emmylou> with Spotify URI <spotify:track:4wL93z69Krzpbijf9TFsf7>
[2023-05-08T14:14:19Z DEBUG librespot_audio::fetch] Downloading file 852a23954670b34e76c47a6d39a1515912f9d569
[2023-05-08T14:14:19Z DEBUG librespot::component] new ChannelManager
[2023-05-08T14:14:19Z DEBUG librespot::component] new AudioKeyManager
[2023-05-08T14:14:20Z DEBUG librespot_connect::spirc] kMessageTypeNotify "Tims Telefon" 5b99ff037188bf32c8c5c3ec47b358c796f9ca25 2075564372 1683555259973 kPlayStatusStop
[2023-05-08T14:14:21Z INFO  librespot_playback::player] <Emmylou> (258000 ms) loaded
[2023-05-08T14:14:21Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPause]
[2023-05-08T14:14:21Z TRACE librespot_connect::spirc] ==> kPlayStatusPause
[2023-05-08T14:14:27Z DEBUG librespot_connect::spirc] kMessageTypePlay "Tims Telefon" 5b99ff037188bf32c8c5c3ec47b358c796f9ca25 2075571521 1683555261296 kPlayStatusPause
[2023-05-08T14:14:27Z DEBUG librespot_playback::mixer::mappings] Input volume 58958 mapped to: 49.99%
[2023-05-08T14:14:27Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
[2023-05-08T14:14:27Z DEBUG librespot_playback::player] command=VolumeSet(58958)
[2023-05-08T14:14:27Z DEBUG librespot_playback::player] command=Play
[2023-05-08T14:14:27Z TRACE librespot_playback::player] == Starting sink ==
[2023-05-08T14:14:27Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
[2023-05-08T14:14:27Z TRACE librespot_playback::audio_backend::alsa] Closest Supported Period Size to Optimal (4410): 4412
[2023-05-08T14:14:27Z TRACE librespot_playback::audio_backend::alsa] Closest Supported Buffer Size to Optimal (22050): 22060
[2023-05-08T14:14:27Z TRACE librespot_playback::audio_backend::alsa] A Buffer Size of 22060 Frames is Suboptimal
[2023-05-08T14:14:27Z TRACE librespot_playback::audio_backend::alsa] A larger than necessary Buffer Size can lead to perceivable latency (lag).
[2023-05-08T14:14:27Z TRACE librespot_playback::audio_backend::alsa] Period Buffer size in bytes: 17648
[2023-05-08T14:14:27Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
[2023-05-08T14:14:27Z DEBUG librespot_core::mercury] unknown subscription uri=social-connect/v2/session_update
[2023-05-08T14:14:31Z DEBUG librespot_connect::spirc] kMessageTypePause "Tims Telefon" 5b99ff037188bf32c8c5c3ec47b358c796f9ca25 2075575243 1683555267840 kPlayStatusPlay
[2023-05-08T14:14:31Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPause]
[2023-05-08T14:14:31Z DEBUG librespot_playback::player] command=Pause
[2023-05-08T14:14:31Z TRACE librespot_playback::player] == Stopping sink ==
[2023-05-08T14:14:31Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPause]
[2023-05-08T14:14:31Z TRACE librespot_connect::spirc] ==> kPlayStatusPause
[2023-05-08T14:14:34Z DEBUG librespot_connect::spirc] kMessageTypePlay "Tims Telefon" 5b99ff037188bf32c8c5c3ec47b358c796f9ca25 2075578255 1683555271907 kPlayStatusPause
[2023-05-08T14:14:34Z DEBUG librespot_playback::mixer::mappings] Input volume 58958 mapped to: 49.99%
[2023-05-08T14:14:34Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
[2023-05-08T14:14:34Z DEBUG librespot_playback::player] command=VolumeSet(58958)
[2023-05-08T14:14:34Z DEBUG librespot_playback::player] command=Play
[2023-05-08T14:14:34Z TRACE librespot_playback::player] == Starting sink ==
[2023-05-08T14:14:34Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
[2023-05-08T14:14:34Z TRACE librespot_playback::audio_backend::alsa] Closest Supported Period Size to Optimal (4410): 4412
[2023-05-08T14:14:34Z TRACE librespot_playback::audio_backend::alsa] Closest Supported Buffer Size to Optimal (22050): 22060
[2023-05-08T14:14:34Z TRACE librespot_playback::audio_backend::alsa] A Buffer Size of 22060 Frames is Suboptimal
[2023-05-08T14:14:34Z TRACE librespot_playback::audio_backend::alsa] A larger than necessary Buffer Size can lead to perceivable latency (lag).
[2023-05-08T14:14:34Z TRACE librespot_playback::audio_backend::alsa] Period Buffer size in bytes: 17648
[2023-05-08T14:14:34Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
[2023-05-08T14:14:40Z DEBUG librespot_connect::spirc] kMessageTypePause "Tims Telefon" 5b99ff037188bf32c8c5c3ec47b358c796f9ca25 2075584955 1683555274312 kPlayStatusPlay
[2023-05-08T14:14:40Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPause]
[2023-05-08T14:14:40Z DEBUG librespot_playback::player] command=Pause
[2023-05-08T14:14:40Z TRACE librespot_playback::player] == Stopping sink ==
[2023-05-08T14:14:41Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPause]
[2023-05-08T14:14:41Z TRACE librespot_connect::spirc] ==> kPlayStatusPause
[2023-05-08T14:14:43Z DEBUG librespot_connect::spirc] kMessageTypePlay "Tims Telefon" 5b99ff037188bf32c8c5c3ec47b358c796f9ca25 2075587462 1683555281015 kPlayStatusPause
[2023-05-08T14:14:43Z DEBUG librespot_playback::mixer::mappings] Input volume 58958 mapped to: 49.99%
[2023-05-08T14:14:43Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
[2023-05-08T14:14:43Z DEBUG librespot_playback::player] command=VolumeSet(58958)
[2023-05-08T14:14:43Z DEBUG librespot_playback::player] command=Play
[2023-05-08T14:14:43Z TRACE librespot_playback::player] == Starting sink ==
[2023-05-08T14:14:43Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
[2023-05-08T14:14:43Z TRACE librespot_playback::audio_backend::alsa] Closest Supported Period Size to Optimal (4410): 4412
[2023-05-08T14:14:43Z TRACE librespot_playback::audio_backend::alsa] Closest Supported Buffer Size to Optimal (22050): 22060
[2023-05-08T14:14:43Z TRACE librespot_playback::audio_backend::alsa] A Buffer Size of 22060 Frames is Suboptimal
[2023-05-08T14:14:43Z TRACE librespot_playback::audio_backend::alsa] A larger than necessary Buffer Size can lead to perceivable latency (lag).
[2023-05-08T14:14:43Z TRACE librespot_playback::audio_backend::alsa] Period Buffer size in bytes: 17648
[2023-05-08T14:14:43Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
[2023-05-08T14:14:52Z DEBUG librespot_connect::spirc] kMessageTypePause "Tims Telefon" 5b99ff037188bf32c8c5c3ec47b358c796f9ca25 2075596449 1683555283501 kPlayStatusPlay
[2023-05-08T14:14:52Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPause]
[2023-05-08T14:14:52Z DEBUG librespot_playback::player] command=Pause
[2023-05-08T14:14:52Z TRACE librespot_playback::player] == Stopping sink ==
[2023-05-08T14:14:52Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPause]
[2023-05-08T14:14:52Z TRACE librespot_connect::spirc] ==> kPlayStatusPause
[2023-05-08T14:14:53Z DEBUG librespot_connect::spirc] kMessageTypePlay "Tims Telefon" 5b99ff037188bf32c8c5c3ec47b358c796f9ca25 2075598089 1683555283501 kPlayStatusPause
[2023-05-08T14:14:53Z DEBUG librespot_playback::mixer::mappings] Input volume 58958 mapped to: 49.99%
[2023-05-08T14:14:53Z DEBUG librespot_playback::player] command=VolumeSet(58958)
[2023-05-08T14:14:53Z DEBUG librespot_playback::player] command=Play
[2023-05-08T14:14:53Z TRACE librespot_playback::player] == Starting sink ==
[2023-05-08T14:14:53Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
[2023-05-08T14:14:53Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
[2023-05-08T14:14:53Z TRACE librespot_playback::audio_backend::alsa] Closest Supported Period Size to Optimal (4410): 4412
[2023-05-08T14:14:53Z TRACE librespot_playback::audio_backend::alsa] Closest Supported Buffer Size to Optimal (22050): 22060
[2023-05-08T14:14:53Z TRACE librespot_playback::audio_backend::alsa] A Buffer Size of 22060 Frames is Suboptimal
[2023-05-08T14:14:53Z TRACE librespot_playback::audio_backend::alsa] A larger than necessary Buffer Size can lead to perceivable latency (lag).
[2023-05-08T14:14:53Z TRACE librespot_playback::audio_backend::alsa] Period Buffer size in bytes: 17648
[2023-05-08T14:14:53Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
[2023-05-08T14:14:55Z DEBUG librespot_audio::fetch] File 852a23954670b34e76c47a6d39a1515912f9d569 complete, saving to cache
[2023-05-08T14:14:56Z DEBUG librespot_connect::spirc] kMessageTypePause "Tims Telefon" 5b99ff037188bf32c8c5c3ec47b358c796f9ca25 2075600223 1683555294135 kPlayStatusPlay
[2023-05-08T14:14:56Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPause]
[2023-05-08T14:14:56Z DEBUG librespot_playback::player] command=Pause
[2023-05-08T14:14:56Z TRACE librespot_playback::player] == Stopping sink ==
[2023-05-08T14:14:56Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPause]
[2023-05-08T14:14:56Z TRACE librespot_connect::spirc] ==> kPlayStatusPause
JasonLG1979 commented 1 year ago

Is it just for that specific track or album?

carlfriedrich commented 1 year ago

Okay, that seemed to be related to my speaker. 🙈 Connected to my PC's line-in the playback works perfectly. Sorry for the noise!

JasonLG1979 commented 1 year ago

No worries.