Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

update librespot to 0.6 #1317

Open
wants to merge 18 commits into
base: master
Choose a base branch
from
Open

update librespot to 0.6 #1317

wants to merge 18 commits into from

Conversation

eladyn
Copy link
Member

@eladyn eladyn commented Dec 27, 2024

This upgrades librespot to version 0.6 and reworks the dbus logic to no longer rely on the web API but just use local method calls.

This should hopefully fix #891, reports welcome.

It supersedes and closes #1309.

Note, that it does not yet fix the issue #1293, since OAuth is still not implemented.

TBD:

  • re-implement OpenUri with Spirc::load
  • implement OAuth (probably new PR)

Some of the long-standing librespot issues that are fixed with this upgrade:
Fixes #1246, fixes #522, fixes #788, fixes #1285.

@klh
Copy link

klh commented Dec 30, 2024

Looks good to me +1

@mietzen
Copy link
Contributor

mietzen commented Jan 2, 2025

@eladyn I couldn't give code suggestions on files you didn't edit. So I sent you a PR: eladyn#1

I updated the docker cross compile guide.

* Update docker cross compile guide for librespot 0.6.0 upgrade

- Enhanced log output
- Use latest GH Release
- Corrected compose filename

* use latest rust 1 image
@clstrickland
Copy link

I was testing this PR to see if it solved #706 (which it seems like it did!) but I noticed some issues that I didn't see with the master build.

I noticed that the shuffle status gets "stuck" in a certain state. The Spotify client on another device like my phone or the web player will show Spotify has shuffle on, but mpris will still report it is off:

method call time=1735980483.723316 sender=:1.18 -> destination=org.mpris.MediaPlayer2.spotifyd.instance27084 serial=716 path=/org/mpris/MediaPlayer2; interface=org.freedesktop.DBus.Properties; member=Get
   string "org.mpris.MediaPlayer2.Player"
   string "Shuffle"
method return time=1735980483.723758 sender=:1.11 -> destination=:1.18 serial=1432 reply_serial=716
   variant       boolean false

In spite of my phone and web player showing shuffle is on, it seems like it is not shuffling, as when I send the next song command via mpris, it goes through my playlist in order. This issue is a little hit or miss for me, but it seems like more often than not shuffle is messed up.

The other issue (I guess whether or not this behavior is desired is an opinion since technically there is a period of no audio) I saw is that, when going to the next song, there is a brief period where the mpris metadata returns "NoTrack", which is causing my mpris controller to show as "not playing" for a few seconds every time the next song starts.

Note the timestamps

method call time=1735980046.906653 sender=:1.18 -> destination=org.mpris.MediaPlayer2.spotifyd.instance27084 serial=369 path=/org/mpris/MediaPlayer2; interface=org.freedesktop.DBus.Properties; member=Get
   string "org.mpris.MediaPlayer2.Player"
   string "Metadata"
method return time=1735980046.907190 sender=:1.11 -> destination=:1.18 serial=1030 reply_serial=369
   variant       array [
         dict entry(
            string "mpris:length"
            variant                int64 182479000
         )
         dict entry(
            string "xesam:artist"
            variant                array [
                  string "Angrybaby"
               ]
         )
         dict entry(
            string "xesam:trackNumber"
            variant                uint32 1
         )
         dict entry(
            string "mpris:artUrl"
            variant                string "https://i.scdn.co/image/ab67616d0000b273a9c1761e9a1fc148466390c2"
         )
         dict entry(
            string "xesam:albumArtist"
            variant                array [
                  string "Angrybaby"
               ]
         )
         dict entry(
            string "mpris:trackid"
            variant                object path "/spotify/track/6tXebnSmy1ZEZANFRHRoCO"
         )
         dict entry(
            string "xesam:title"
            variant                string "WASTED ON ME"
         )
         dict entry(
            string "xesam:discNumber"
            variant                uint32 1
         )
         dict entry(
            string "xesam:album"
            variant                string "WASTED ON ME"
         )
         dict entry(
            string "xesam:autoRating"
            variant                double 0.5
         )
      ]
signal time=1735980046.914352 sender=:1.11 -> destination=(null destination) serial=1031 path=/org/mpris/MediaPlayer2; interface=org.freedesktop.DBus.Properties; member=PropertiesChanged
   string "org.mpris.MediaPlayer2.Player"
   array [
      dict entry(
         string "Metadata"
         variant             array [
               dict entry(
                  string "mpris:trackid"
                  variant                      object path "/org/mpris/MediaPlayer2/TrackList/NoTrack"
               )
            ]
      )
   ]
   array [
   ]
signal time=1735980047.186702 sender=:1.11 -> destination=(null destination) serial=1032 path=/org/mpris/MediaPlayer2; interface=org.freedesktop.DBus.Properties; member=PropertiesChanged
   string "org.mpris.MediaPlayer2.Player"
   array [
      dict entry(
         string "Metadata"
         variant             array [
               dict entry(
                  string "xesam:title"
                  variant                      string "Wicked"
               )
               dict entry(
                  string "xesam:album"
                  variant                      string "Good Will Prevail"
               )
               dict entry(
                  string "xesam:autoRating"
                  variant                      double 0.3
               )
               dict entry(
                  string "xesam:trackNumber"
                  variant                      uint32 1
               )
               dict entry(
                  string "xesam:artist"
                  variant                      array [
                        string "GRiZ"
                        string "Eric Krasno"
                     ]
               )
               dict entry(
                  string "mpris:length"
                  variant                      int64 354286000
               )
               dict entry(
                  string "xesam:albumArtist"
                  variant                      array [
                        string "GRiZ"
                     ]
               )
               dict entry(
                  string "xesam:discNumber"
                  variant                      uint32 1
               )
               dict entry(
                  string "mpris:trackid"
                  variant                      object path "/spotify/track/5Kn5DgKUYMmSWpD6XTVtww"
               )
               dict entry(
                  string "mpris:artUrl"
                  variant                      string "https://i.scdn.co/image/ab67616d0000b273bb2fccfc1c079ec32e9b817d"
               )
            ]
      )
   ]
   array [
   ]

It is only for a fraction of a second, but it still throws off my mpris client.

Let me know if there is any more info I can try to gather to help figure this out.

@eladyn
Copy link
Member Author

eladyn commented Jan 4, 2025

@clstrickland Thank you for giving the updated MPRIS implementation a little more testing, that is really helpful.

Regarding the shuffle, I can confirm that setting shuffle through MPRIS did not actually shuffle songs, which is however more of an upstream problem which seems to have been fixed there in dev.
To work around this, I disallowed setting shuffle through the MPRIS interface for now, until it actually works. This should hopefully prevent the shuffle button from showing up in MPRIS consumers?

Regarding the other issue, I'm not entirely sure what is happening there, maybe it was one minor thing I missed and added now. If it's still happening I added some debug logging, could you possibly try to gather some debug logs? (in particular, the lines with handling event ... would be of interest, combined with the corresponding PropertiesChanged signals) That would be great!

@clstrickland
Copy link

That's too bad about shuffle, but I'd rather not have shuffle on a client that doesn't crash than how it was before.

Jan 04 12:23:29 superserver-mini spotifyd[160329]: [DEBUG symphonia_format_ogg::demuxer] seek: bisect step: page={ start_ts=1508032, end_ts=1513152 } byte_range=[4026, 1355768, 2707511]
Jan 04 12:23:29 superserver-mini spotifyd[160329]: [DEBUG symphonia_format_ogg::demuxer] seek: bisect step: page={ start_ts=741824, end_ts=746944 } byte_range=[4026, 679897, 1355768]
Jan 04 12:23:29 superserver-mini spotifyd[160329]: [DEBUG symphonia_format_ogg::demuxer] seek: bisect step: page={ start_ts=373184, end_ts=376448 } byte_range=[4026, 341961, 679897]
Jan 04 12:23:29 superserver-mini spotifyd[160329]: [DEBUG symphonia_format_ogg::demuxer] seek: bisect step: page={ start_ts=189760, end_ts=193856 } byte_range=[4026, 172993, 341961]
Jan 04 12:23:29 superserver-mini spotifyd[160329]: [DEBUG symphonia_format_ogg::demuxer] seek: bisect step: page={ start_ts=95808, end_ts=99904 } byte_range=[4026, 88509, 172993]
Jan 04 12:23:29 superserver-mini spotifyd[160329]: [DEBUG symphonia_format_ogg::demuxer] seeked track=0x0 to packet_ts=0 (delta=0)
Jan 04 12:23:29 superserver-mini spotifyd[160329]: [DEBUG spotifyd::dbus_mpris] handling event Preloading { track_id: SpotifyId("spotify:track:6Kvoubt8zigmnFWLMRWu6U") }
Jan 04 12:23:59 superserver-mini spotifyd[160329]: [DEBUG spotifyd::dbus_mpris] handling event EndOfTrack { play_request_id: 1, track_id: SpotifyId("spotify:track:5qM4xXjaE3XDmv86oFCRoj") }
Jan 04 12:23:59 superserver-mini spotifyd[160329]: [DEBUG librespot_connect::spirc] At track 12 of 81 <"spotify:user:***:collection"> update [false]
Jan 04 12:23:59 superserver-mini spotifyd[160329]: [DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:6Kvoubt8zigmnFWLMRWu6U"), true, 0)
Jan 04 12:23:59 superserver-mini spotifyd[160329]: [DEBUG librespot_playback::player] Normalisation Data: NormalisationData { track_gain_db: -7.082057952880859, track_peak: 1.158416986465454, album_gain_db: -7.082057952880859, album_peak: 1.158416986465454 }
Jan 04 12:23:59 superserver-mini spotifyd[160329]: [DEBUG librespot_playback::player] Calculated Normalisation Factor for Track: 31.33%
Jan 04 12:23:59 superserver-mini spotifyd[160329]: [DEBUG spotifyd::dbus_mpris] handling event PlayRequestIdChanged { play_request_id: 2 }
Jan 04 12:23:59 superserver-mini spotifyd[160329]: [DEBUG spotifyd::dbus_mpris] handling event TrackChanged { audio_item: AudioItem { track_id: SpotifyId("spotify:track:6Kvoubt8zigmnFWLMRWu6U"), uri: "spotify:track:6Kvoubt8zigmnFWLMRWu6U", files: AudioFiles({OTHER5: FileId(Ok("1260a2fb12a0515e90f5fdc94d055749ad545bf9")), AAC_160: FileId(Ok("0186b95de84042ee21b1a4e392dc14b1df573a17")), AAC_24: FileId(Ok("e94ec3395bedf90ead066fa79c82958f67195d30")), MP4_128: FileId(Ok("28ec7d86f27f972235fc1593c385969697cfdeef")), OGG_VORBIS_96: FileId(Ok("5bf2dc3990dcc8a18e4d2e02876a0659cb124d96")), AAC_320: FileId(Ok("9c9483f2e8bfd4367fbf1c8f5d0aca0803fc4e12")), OGG_VORBIS_320: FileId(Ok("80c9ad5526d60ba74a15a7ef2d89afbbe57790e5")), OGG_VORBIS_160: FileId(Ok("05b41c884e3872eca62f59c87a8fa33d37197790"))}), name: "Fly (Original Mix) - Fly (Original Mix)", covers: [CoverImage { url: "https://i.scdn.co/image/ab67616d0000b2733244626bd980e551203b6be6", size: LARGE, width: 640, height: 640 }, CoverImage { url: "https://i.scdn.co/image/ab67616d00001e023244626bd980e551203b6be6", size: DEFAULT, width: 300, height: 300 }, CoverImage { url: "https://i.scdn.co/image/ab67616d000048513244626bd980e551203b6be6", size: SMALL, width: 64, height: 64 }], language: ["en"], duration_ms: 265717, is_explicit: false, availability: Ok(()), alternatives: None, unique_fields: Track { artists: ArtistsWithRole([ArtistWithRole { id: SpotifyId("spotify:artist:0jNDKefhfSbLR9sFvcPLHo"), name: "San Holo", role: ARTIST_ROLE_MAIN_ARTIST }]), album: "Cosmos", album_artists: ["San Holo"], popularity: 38, number: 2, disc_number: 1 } } }
Jan 04 12:23:59 superserver-mini spotifyd[160329]: [DEBUG spotifyd::dbus_mpris] handling event Playing { play_request_id: 2, track_id: SpotifyId("spotify:track:6Kvoubt8zigmnFWLMRWu6U"), position_ms: 0 }
Jan 04 12:23:59 superserver-mini spotifyd[160329]: [DEBUG librespot_audio::fetch] Downloading file 80c9ad5526d60ba74a15a7ef2d89afbbe57790e5 complete
Jan 04 12:24:05 superserver-mini spotifyd[160329]: [DEBUG libmdns::fsm] received question: IN mantle lights._hap._tcp.local
Jan 04 12:24:07 superserver-mini spotifyd[160329]: [DEBUG librespot_connect::spirc] At track 13 of 81 <"spotify:user:***:collection"> update [false]
Jan 04 12:24:07 superserver-mini spotifyd[160329]: [DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:6KfGL6Lo2goJvcTd5Tpm0j"), true, 0)
Jan 04 12:24:07 superserver-mini spotifyd[160329]: [DEBUG spotifyd::dbus_mpris] handling event PlayRequestIdChanged { play_request_id: 3 }
Jan 04 12:24:07 superserver-mini spotifyd[160329]: [DEBUG spotifyd::dbus_mpris] handling event Loading { play_request_id: 3, track_id: SpotifyId("spotify:track:6KfGL6Lo2goJvcTd5Tpm0j"), position_ms: 0 }
Jan 04 12:24:07 superserver-mini spotifyd[160329]: [DEBUG librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/metadata/4/track/dda72514f94d4d6eb6b1abb263d6ad33?product=0&country=US&salt=1215114130
Jan 04 12:24:08 superserver-mini spotifyd[160329]: [DEBUG librespot_audio::fetch] Downloading file 77df15e854394c8177ef95ef693e485811556fb4
Jan 04 12:24:08 superserver-mini spotifyd[160329]: [DEBUG librespot_core::http_client] Requesting https://guc3-spclient.spotify.com:443/storage-resolve/files/audio/interactive/77df15e854394c8177ef95ef693e485811556fb4?product=0&country=US&salt=2656314572
Jan 04 12:24:08 superserver-mini spotifyd[160329]: [DEBUG symphonia_format_ogg::page] grow page buffer to 8192 bytes
Jan 04 12:24:08 superserver-mini spotifyd[160329]: [DEBUG symphonia_codec_vorbis] vorbis: leftover bits in setup head extra data
Jan 04 12:24:08 superserver-mini spotifyd[160329]: [DEBUG symphonia_format_ogg::demuxer] seeking track=0x0 to frame_ts=0
Jan 04 12:24:08 superserver-mini spotifyd[160329]: [DEBUG symphonia_format_ogg::demuxer] seek: bisect step: page={ start_ts=5057920, end_ts=5061568 } byte_range=[4026, 4998936, 9993847]
Jan 04 12:24:08 superserver-mini spotifyd[160329]: [DEBUG symphonia_format_ogg::demuxer] seek: bisect step: page={ start_ts=2759232, end_ts=2762752 } byte_range=[4026, 2501481, 4998936]
Jan 04 12:24:08 superserver-mini spotifyd[160329]: [DEBUG symphonia_format_ogg::demuxer] seek: bisect step: page={ start_ts=1587456, end_ts=1592256 } byte_range=[4026, 1252753, 2501481]
Jan 04 12:24:08 superserver-mini spotifyd[160329]: [DEBUG symphonia_format_ogg::demuxer] seek: bisect step: page={ start_ts=901568, end_ts=905984 } byte_range=[4026, 628389, 1252753]
Jan 04 12:24:08 superserver-mini spotifyd[160329]: [DEBUG symphonia_format_ogg::demuxer] seek: bisect step: page={ start_ts=502336, end_ts=508480 } byte_range=[4026, 316207, 628389]
Jan 04 12:24:08 superserver-mini spotifyd[160329]: [DEBUG symphonia_format_ogg::demuxer] seek: bisect step: page={ start_ts=248384, end_ts=254528 } byte_range=[4026, 160116, 316207]
Jan 04 12:24:08 superserver-mini spotifyd[160329]: [DEBUG symphonia_format_ogg::demuxer] seek: bisect step: page={ start_ts=129728, end_ts=135872 } byte_range=[4026, 82071, 160116]
Jan 04 12:24:08 superserver-mini spotifyd[160329]: [DEBUG symphonia_format_ogg::demuxer] seeked track=0x0 to packet_ts=0 (delta=0)
Jan 04 12:24:08 superserver-mini spotifyd[160329]: [DEBUG librespot_playback::player] Normalisation Data: NormalisationData { track_gain_db: -9.029998779296875, track_peak: 1.0864760875701904, album_gain_db: -10.430000305175781, album_peak: 1.1233508586883545 }
Jan 04 12:24:08 superserver-mini spotifyd[160329]: [DEBUG librespot_playback::player] Calculated Normalisation Factor for Track: 25.03%
Jan 04 12:24:08 superserver-mini spotifyd[160329]: [DEBUG spotifyd::dbus_mpris] handling event TrackChanged { audio_item: AudioItem { track_id: SpotifyId("spotify:track:6KfGL6Lo2goJvcTd5Tpm0j"), uri: "spotify:track:6KfGL6Lo2goJvcTd5Tpm0j", files: AudioFiles({AAC_24: FileId(Ok("4f932d112a8b66e7e4b38703d72d37402e7457af")), OTHER5: FileId(Ok("2f551394dbbb0634bd9680acadd8532152e6d6d9")), MP4_128: FileId(Ok("5e0bac156b5b1d749ca685a296e6e40c5c5505b6")), AAC_320: FileId(Ok("8528e3152d93e5b291da27ee70b4f632b2a7b1f6")), OGG_VORBIS_320: FileId(Ok("77df15e854394c8177ef95ef693e485811556fb4")), OGG_VORBIS_160: FileId(Ok("32b4dae9903b1443dbc99e3201ebbcf989281e39")), AAC_160: FileId(Ok("acf0f31d03d9c971a36b2717bd8f0f36a0ca763d")), OGG_VORBIS_96: FileId(Ok("2dd245309661224ab24c14d5424d5712634e7187"))}), name: "Push Through", covers: [CoverImage { url: "https://i.scdn.co/image/ab67616d0000b2735f1f1c836f2519b6579ae4df", size: LARGE, width: 640, height: 640 }, CoverImage { url: "https://i.scdn.co/image/ab67616d00001e025f1f1c836f2519b6579ae4df", size: DEFAULT, width: 300, height: 300 }, CoverImage { url: "https://i.scdn.co/image/ab67616d000048515f1f1c836f2519b6579ae4df", size: SMALL, width: 64, height: 64 }], language: ["en"], duration_ms: 232941, is_explicit: false, availability: Ok(()), alternatives: None, unique_fields: Track { artists: ArtistsWithRole([ArtistWithRole { id: SpotifyId("spotify:artist:0u18Cq5stIQLUoIaULzDmA"), name: "DROELOE", role: ARTIST_ROLE_MAIN_ARTIST }]), album: "A Matter Of Perspective", album_artists: ["DROELOE"], popularity: 28, number: 10, disc_number: 4 } } }
Jan 04 12:24:08 superserver-mini spotifyd[160329]: [DEBUG spotifyd::dbus_mpris] handling event Playing { play_request_id: 3, track_id: SpotifyId("spotify:track:6KfGL6Lo2goJvcTd5Tpm0j"), position_ms: 0 }
Jan 04 12:24:08 superserver-mini spotifyd[160329]: [DEBUG rustls::client::hs] Resuming session
Jan 04 12:24:08 superserver-mini spotifyd[160329]: [DEBUG rustls::client::hs] Using ciphersuite TLS13_AES_256_GCM_SHA384
Jan 04 12:24:08 superserver-mini spotifyd[160329]: [DEBUG rustls::client::tls13] Resuming using PSK
Jan 04 12:24:08 superserver-mini spotifyd[160329]: [DEBUG rustls::client::tls13] TLS1.3 encrypted extensions: [ServerNameAck, Unknown(UnknownExtension { typ: EllipticCurves, payload: 00040017001d }), Protocols([ProtocolName(687474702f312e31)])]
Jan 04 12:24:08 superserver-mini spotifyd[160329]: [DEBUG rustls::client::hs] ALPN protocol is Some(b"http/1.1")
Jan 04 12:24:08 superserver-mini spotifyd[160329]: [DEBUG librespot_audio::fetch] Downloading file 77df15e854394c8177ef95ef693e485811556fb4 complete

The issue happened on the transition from "Fly (Original Mix) - Fly (Original Mix)" to "Push Through".

@eladyn
Copy link
Member Author

eladyn commented Jan 4, 2025

Thanks for the log, that probably makes sense, it's erasing the previous metadata when loading a new song, which probably happens when the track hasn't been preloaded entirely beforehand. I'll push a fix later...

@eladyn
Copy link
Member Author

eladyn commented Jan 5, 2025

@clstrickland Should hopefully be fixed now. :)

@clstrickland
Copy link

That is fixed now!
...but I found a new issue (I'm sorry)

For the sake of not blowing up this thread, I'm attaching the logs as files.
dbus-monitor.txt
spotifyd.txt

Mpris starts reporting NoTrack nonstop until the song is changed. I created this issue by skipping back about 3 songs using mpris controls. In the logs, it happened once I got to "Sleepy Eyes".

@eladyn
Copy link
Member Author

eladyn commented Jan 5, 2025

Don't worry, the more testing the better!

I didn't really think that could happen, but it turns out that one track can have multiple track_ids, in this case spotify:track:1Wvzo4EotLEh4W3OVcQoDO and spotify:track:3EMp6kj0bAkU7OYh1Lh3fA, which both point to "Sleepy Eyes". I guess, I'll just remove the check, whether the track id matches then, it was only meant as a safeguard against weird librespot behaviour anyway.

@clstrickland
Copy link

@eladyn I just checked, and that issue is resolved. I have not noticed any other problems, I hope this gets merged soon!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
5 participants