search

xou816 / spot

Native Spotify client for the GNOME desktop
MIT License
2.27k stars 119 forks source link

Autologin doesn't work #596

Closed samsapti closed 1 year ago

samsapti commented 1 year ago

Describe the bug Autologin doesn't work. Every time I open Spot it prompts me to log back in. If I close the login prompt, it refuses to play saying that the player isn't responding. GNOME Keyring is unlocked and the "Spotify Credentials" entry is present.

To Reproduce Steps to reproduce the behavior:

  1. Open Spot and log in
  2. Close Spot
  3. Open Spot again
  4. See the login prompt
  5. If you close the login prompt without logging in, you can't play any tracks

Expected behavior Autologin should work.

General information:

Stack trace:

There's no stack trace, but this is the output when running spot from the terminal (although it doesn't look relevant):

(process:8927): Adwaita-CRITICAL **: 21:43:21.017: adw_leaflet_set_visible_child: assertion 'contains_child' failed

Additional context I'm not using Flatpak.

On a Fedora installation, it works fine with the latest Flatpak version.

xou816 commented 1 year ago

if you're able to test, do you have the issue before 59953e2026c84a62451969c5bb68e2a0a6b20515 ?

samsapti commented 1 year ago

Yes, I compiled the parent commit of the one you linked to (https://github.com/xou816/spot/commit/653aec8c808e8d5edcf051fb5cd2f18fe1859464), the issue is still there.

samsapti commented 1 year ago

Running with RUST_LOG="debug" spot gives me the following:

(process:14031): Adwaita-CRITICAL **: 22:53:16.633: adw_leaflet_set_visible_child: assertion 'contains_child' failed
[2023-02-16T21:53:16Z DEBUG isahc::agent] agent_thread; id=0
[2023-02-16T21:53:16Z DEBUG isahc::agent] agent took 152.831µs to start up
[2023-02-16T21:53:16Z INFO  tracing::span] socket reader;
[2023-02-16T21:53:16Z INFO  zbus::connection] {}; obj_server_task_name="ObjectServer task"
[2023-02-16T21:53:16Z DEBUG spot] activate
[2023-02-16T21:53:16Z DEBUG spot::app::models::songs::song_list_model] pos 0, removed 0, added 50
[2023-02-16T21:53:18Z DEBUG spot::app::components::window] saving geometry
xou816 commented 1 year ago

ok thanks!! this at least rules out a recent change

I'm surprised that it works okay with the flatpak version but doesnt otherwise

samsapti commented 1 year ago

@xou816 note that the Flatpak version that works for me is the latest stable version, 0.3.1, not the latest git-commit. The non-Flatpak version is the latest commit, the one that doesn't work. If I get some time in the coming days, I can try to git bisect it and find the offending commit.

samsapti commented 1 year ago

I tried running the Flatpak version with RUST_LOG=debug as well, which corretly logs in automatically:

(process:2): Adwaita-CRITICAL **: 16:02:49.410: adw_leaflet_set_visible_child: assertion 'contains_child' failed
[2023-02-17T15:02:49Z DEBUG isahc::agent] agent_thread; id=0
[2023-02-17T15:02:49Z DEBUG isahc::agent] agent took 372.944µs to start up
[2023-02-17T15:02:49Z DEBUG spot] activate
[2023-02-17T15:02:49Z DEBUG hyper::client::connect::dns] resolving host="apresolve.spotify.com"
[2023-02-17T15:02:49Z DEBUG hyper::client::connect::http] connecting to 34.98.74.57:80
[2023-02-17T15:02:49Z DEBUG hyper::client::connect::http] connected to 34.98.74.57:80
[2023-02-17T15:02:49Z DEBUG hyper::proto::h1::io] flushed 47 bytes
[2023-02-17T15:02:49Z DEBUG hyper::proto::h1::io] parsed 5 headers
[2023-02-17T15:02:49Z DEBUG hyper::proto::h1::conn] incoming body is content-length (169 bytes)
[2023-02-17T15:02:49Z DEBUG hyper::proto::h1::conn] incoming body completed
[2023-02-17T15:02:49Z DEBUG hyper::client::pool] pooling idle connection for ("http", apresolve.spotify.com:80)
[2023-02-17T15:02:49Z INFO  librespot_core::session] Connecting to AP "ap-gew4.spotify.com:4070"
[2023-02-17T15:02:49Z DEBUG spot::app::models::songs::song_list_model] pos 0, removed 0, added 50
[2023-02-17T15:02:49Z INFO  librespot_core::session] Authenticated as "username" !
[2023-02-17T15:02:49Z DEBUG librespot_core::session] new Session[0]
[2023-02-17T15:02:49Z INFO  spot::player::player] bitrate: Bitrate320
[2023-02-17T15:02:49Z INFO  librespot_playback::mixer::softmixer] Mixing with softvol and volume control: Log(30.0)
[2023-02-17T15:02:49Z DEBUG librespot_core::session] Session[0] strong=3 weak=1
[2023-02-17T15:02:49Z INFO  librespot_core::session] Country: "DK"
[2023-02-17T15:02:49Z DEBUG librespot_playback::player] new Player[0]
[2023-02-17T15:02:49Z INFO  librespot_playback::convert] Converting with ditherer: tpdf
[2023-02-17T15:02:49Z INFO  spot::player::player] using pulseaudio
[2023-02-17T15:02:49Z INFO  librespot_playback::audio_backend::pulseaudio] Using PulseAudioSink with format: S16
[2023-02-17T15:02:49Z DEBUG isahc::client] send_async; method=GET uri=https://api.spotify.com/v1/me/albums?offset=0&limit=30
[2023-02-17T15:02:49Z DEBUG isahc::handler] handler
[2023-02-17T15:02:49Z DEBUG isahc::handler] handler; id=0
[2023-02-17T15:02:49Z DEBUG isahc::handler]   Trying 35.186.224.25:443...
[2023-02-17T15:02:49Z DEBUG isahc::handler] Connected to api.spotify.com (35.186.224.25) port 443 (#0)
[2023-02-17T15:02:49Z DEBUG isahc::handler] ALPN, offering h2
[2023-02-17T15:02:49Z DEBUG isahc::handler] ALPN, offering http/1.1
[2023-02-17T15:02:49Z DEBUG isahc::handler]  CAfile: /etc/pki/ca-trust/extracted/pem/tls-ca-bundle.pem
[2023-02-17T15:02:49Z DEBUG isahc::handler]  CApath: /etc/pki/tls/certs
[2023-02-17T15:02:49Z DEBUG isahc::handler] TLSv1.3 (OUT), TLS handshake, Client hello (1):
[2023-02-17T15:02:49Z DEBUG isahc::handler] TLSv1.3 (IN), TLS handshake, Server hello (2):
[2023-02-17T15:02:49Z DEBUG isahc::handler] TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
[2023-02-17T15:02:49Z DEBUG isahc::handler] TLSv1.3 (IN), TLS handshake, Certificate (11):
[2023-02-17T15:02:49Z DEBUG isahc::handler] TLSv1.3 (IN), TLS handshake, CERT verify (15):
[2023-02-17T15:02:49Z DEBUG isahc::handler] TLSv1.3 (IN), TLS handshake, Finished (20):
[2023-02-17T15:02:49Z DEBUG isahc::handler] TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
[2023-02-17T15:02:49Z DEBUG isahc::handler] TLSv1.3 (OUT), TLS handshake, Finished (20):
[2023-02-17T15:02:49Z DEBUG isahc::handler] SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
[2023-02-17T15:02:49Z DEBUG isahc::handler] ALPN, server accepted to use h2
[2023-02-17T15:02:49Z DEBUG isahc::handler] Server certificate:
[2023-02-17T15:02:49Z DEBUG isahc::handler]  subject: C=SE; L=Stockholm; O=Spotify AB; CN=*.spotify.com
[2023-02-17T15:02:49Z DEBUG isahc::handler]  start date: Apr  6 00:00:00 2022 GMT
[2023-02-17T15:02:49Z DEBUG isahc::handler]  expire date: Apr  6 23:59:59 2023 GMT
[2023-02-17T15:02:49Z DEBUG isahc::handler]  subjectAltName: host "api.spotify.com" matched cert's "*.spotify.com"
[2023-02-17T15:02:49Z DEBUG isahc::handler]  issuer: C=US; O=DigiCert Inc; CN=DigiCert TLS RSA SHA256 2020 CA1
[2023-02-17T15:02:49Z DEBUG isahc::handler]  SSL certificate verify ok.
[2023-02-17T15:02:49Z DEBUG isahc::handler] Using HTTP2, server supports multiplexing
[2023-02-17T15:02:49Z DEBUG isahc::handler] Connection state changed (HTTP/2 confirmed)
[2023-02-17T15:02:49Z DEBUG isahc::handler] Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
[2023-02-17T15:02:49Z DEBUG isahc::handler] Using Stream ID: 1 (easy handle 0x559391467000)
[2023-02-17T15:02:50Z DEBUG isahc::handler] TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
[2023-02-17T15:02:50Z DEBUG isahc::handler] TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
[2023-02-17T15:02:50Z DEBUG isahc::handler] old SSL session ID is stale, removing
[2023-02-17T15:02:50Z DEBUG isahc::handler] Connection #0 to host api.spotify.com left intact
[2023-02-17T15:02:50Z DEBUG isahc::client] send_async; method=GET uri=https://api.spotify.com/v1/me/playlists?offset=0&limit=30
[2023-02-17T15:02:50Z DEBUG isahc::handler] handler
[2023-02-17T15:02:50Z DEBUG isahc::handler] handler; id=0
[2023-02-17T15:02:50Z DEBUG isahc::handler] Found bundle for host api.spotify.com: 0x7fd090007930 [can multiplex]
[2023-02-17T15:02:50Z DEBUG isahc::handler] Re-using existing connection! (#0) with host api.spotify.com
[2023-02-17T15:02:50Z DEBUG isahc::handler] Connected to api.spotify.com (35.186.224.25) port 443 (#0)
[2023-02-17T15:02:50Z DEBUG isahc::handler] Using Stream ID: 3 (easy handle 0x559391467000)
[2023-02-17T15:02:50Z DEBUG isahc::handler] Connection #0 to host api.spotify.com left intact
[2023-02-17T15:02:50Z DEBUG isahc::client] send_async; method=GET uri=https://api.spotify.com/v1/me/tracks?offset=0&limit=50
[2023-02-17T15:02:50Z DEBUG isahc::handler] handler
[2023-02-17T15:02:50Z DEBUG isahc::handler] handler; id=0
[2023-02-17T15:02:50Z DEBUG isahc::handler] Found bundle for host api.spotify.com: 0x7fd090007930 [can multiplex]
[2023-02-17T15:02:50Z DEBUG isahc::handler] Re-using existing connection! (#0) with host api.spotify.com
[2023-02-17T15:02:50Z DEBUG isahc::handler] Connected to api.spotify.com (35.186.224.25) port 443 (#0)
[2023-02-17T15:02:50Z DEBUG isahc::handler] Using Stream ID: 5 (easy handle 0x559391467000)
[2023-02-17T15:02:50Z DEBUG isahc::handler] Connection #0 to host api.spotify.com left intact
[2023-02-17T15:02:50Z DEBUG spot::app::models::songs::song_list_model] pos 0, removed 50, added 50
[2023-02-17T15:04:49Z DEBUG librespot_core::session] Session[0] strong=3 weak=1
xou816 commented 1 year ago

I wonder if it's not related somehow to https://github.com/xou816/spot/issues/558 maybe there is a login failure happening for some reason that would wipe your credentials

I'll think about it and push a temporary build with some additional logging maybe

xou816 commented 1 year ago

if you're able to add a dbg! like so for instance 

diff --git a/src/app/state/login_state.rs b/src/app/state/login_state.rs
index 366458b..3b9cfa7 100644
--- a/src/app/state/login_state.rs
+++ b/src/app/state/login_state.rs
@@ -83,7 +83,7 @@ impl UpdatableState for LoginState {
     type Event = AppEvent;

     fn update_with(&mut self, action: Cow<Self::Action>) -> Vec<Self::Event> {
-        match action.into_owned() {
+        match dbg!(action).into_owned() {
             LoginAction::TryLogin(TryLoginAction::Password { username, password }) => {
                 vec![
                     LoginEvent::LoginStarted(LoginStartedEvent::Password { username, password })

it would help to see if you have a log similar to

[src/app/state/login_state.rs:86] action = TryLogin(
    Token {
        username: "username",
        token: "some token",
    },
)

before you attempt to login manually!

samsapti commented 1 year ago

@xou816 there's no such log entry, even after adding dbg().

xou816 commented 1 year ago

were you logged in at least once before?

also worth trying: this PR fixes a couple issues with login #598 (handles connectivity issues more gracefully)

samsapti commented 1 year ago

were you logged in at least once before?

Yes, I also tried logging in manually, closing the app and repoening.

also worth trying: this PR fixes a couple issues with login https://github.com/xou816/spot/pull/598

I was just about to do that :)

samsapti commented 1 year ago

Nope, still not working:

(process:10503): Adwaita-CRITICAL **: 18:12:27.400: adw_leaflet_set_visible_child: assertion 'contains_child' failed
[2023-02-18T17:12:27Z DEBUG isahc::agent] agent_thread; id=0
[2023-02-18T17:12:27Z DEBUG isahc::agent] agent took 127.6µs to start up
[2023-02-18T17:12:27Z INFO  tracing::span] socket reader;
[2023-02-18T17:12:27Z INFO  zbus::connection] {}; obj_server_task_name="ObjectServer task"
[2023-02-18T17:12:27Z DEBUG spot] activate
[2023-02-18T17:12:27Z DEBUG spot::app::models::songs::song_list_model] pos 0, removed 0, added 50
[2023-02-18T17:12:45Z DEBUG spot::app::components::window] saving geometry
xou816 commented 1 year ago

I updated one of the dependencies related to credentials management and added some extra logs along with that, its on the development branch if you want to give it a try! (sorry to have you build dozens of different versions...)

samsapti commented 1 year ago

It still doesn't work, but now I get this error log:

(process:16790): Adwaita-CRITICAL **: 19:01:04.279: adw_leaflet_set_visible_child: assertion 'contains_child' failed
[2023-02-21T18:01:04Z DEBUG isahc::agent] agent_thread; id=0
[2023-02-21T18:01:04Z DEBUG isahc::agent] agent took 155.213µs to start up
[2023-02-21T18:01:04Z INFO  tracing::span] socket reader;
[2023-02-21T18:01:04Z INFO  zbus::connection] {}; obj_server_task_name="ObjectServer task"
[2023-02-21T18:01:04Z DEBUG spot] activate
[2023-02-21T18:01:04Z INFO  tracing::span] socket reader;
[2023-02-21T18:01:04Z WARN  spot::app::components::login::login_model] Could not retrieve credentials: no secret service provider or dbus session found
[2023-02-21T18:01:04Z DEBUG spot::app::models::songs::song_list_model] pos 0, removed 0, added 50

It seems it can't find the secret service or the DBUS session, even though my DBUS_SESSION_BUS_ADDRESS env var is set, and the secret service is indeed available and accessible by other programs.

(sorry to have you build dozens of different versions...)

No problem :)

samsapti commented 1 year ago

Running dbus-monitor --session destination=org.freedesktop.secrets sender=org.freedesktop.secrets does give me some output when running Spot. Specifically, this seems to be of relevance:

method call time=1677003737.780224 sender=:1.80 -> destination=org.freedesktop.secrets serial=4 path=/org/freedesktop/secrets/collection/Default_5fkeyring; interface=org.freedesktop.DBus.Properties; member=Get
   string "org.freedesktop.Secret.Collection"
   string "Locked"
method return time=1677003737.780277 sender=:1.19 -> destination=:1.80 serial=79 reply_serial=4
   variant       boolean false
method call time=1677003737.780332 sender=:1.80 -> destination=org.freedesktop.secrets serial=5 path=/org/freedesktop/secrets/collection/Default_5fkeyring; interface=org.freedesktop.Secret.Collection; member=SearchItems
   array [
      dict entry(
         string "spot_credentials"
         string "yes"
      )
   ]
method return time=1677003737.780410 sender=:1.19 -> destination=:1.80 serial=80 reply_serial=5
   array [
      object path "/org/freedesktop/secrets/collection/Default_5fkeyring/6"
   ]
method call time=1677003737.780471 sender=:1.80 -> destination=org.freedesktop.secrets serial=6 path=/org/freedesktop/secrets/collection/Default_5fkeyring/6; interface=org.freedesktop.Secret.Item; member=GetSecret
   object path "/org/freedesktop/secrets/session/s11"
method return time=1677003737.780546 sender=:1.19 -> destination=:1.80 serial=81 reply_serial=6
   struct {
      object path "/org/freedesktop/secrets/session/s11"
      array of bytes [
         7c [REDACTED] b0
      ]
      array of bytes [
         [REDACTED] [REDACTED] [REDACTED] [REDACTED] [REDACTED] [REDACTED]
         [REDACTED] [REDACTED] [REDACTED] [REDACTED] [REDACTED] [REDACTED]
         [REDACTED] [REDACTED] [REDACTED] [REDACTED] [REDACTED] [REDACTED]
         ...
         [REDACTED] [REDACTED] [REDACTED] [REDACTED]
      ]
      string "text/plain"
   }
xou816 commented 1 year ago

Thanks! I do have pretty much the same output. So DBUS messages are being sent... but something happens on the way back?

Out of curiosity, are the MPRIS features working properly for you?

samsapti commented 1 year ago

Yes, MPRIS works fine.

samsapti commented 1 year ago

@xou816 I found the cause of the bug!

Turns out, that the JSON deserialization fails if the password contains (what would look like) invalid escape characters. In my case, my randomly generated Spotify password contains the substring \&, which causes this error message:

[src/app/credentials.rs:38] serde_json::from_slice(&item) = Err(
    Error("invalid escape", line: 1, column: 114),
)
[src/app/components/login/login_model.rs:21] Credentials::retrieve().await = Err(
    Unavailable,
)

which I got by adding some dbg!()s. Due to .map_err(|_| Error::Unavailable) in src/app/credentials.rs:38, it incorrectly reports it as an error due to the secret service being unavailable.

Here are the added dbg!()s:

diff --git a/src/app/components/login/login_model.rs b/src/app/components/login/login_model.rs
index 033468f..897ba4d 100644
--- a/src/app/components/login/login_model.rs
+++ b/src/app/components/login/login_model.rs
@@ -18,7 +18,7 @@ impl LoginModel {

     pub fn try_autologin(&self) {
         self.dispatcher.dispatch_async(Box::pin(async {
-            let action = match Credentials::retrieve().await {
+            let action = match dbg!(Credentials::retrieve().await) {
                 Ok(creds) => LoginAction::TryLogin(if creds.token_expired() {
                     TryLoginAction::Password {
                         username: creds.username,
diff --git a/src/app/credentials.rs b/src/app/credentials.rs
index 50867f8..560c313 100644
--- a/src/app/credentials.rs
+++ b/src/app/credentials.rs
@@ -35,7 +35,7 @@ impl Credentials {
         }
         let items = collection.search_items(make_attributes()).await?;
         let item = items.get(0).ok_or(Error::NoResult)?.get_secret().await?;
-        serde_json::from_slice(&item).map_err(|_| Error::Unavailable)
+        dbg!(serde_json::from_slice(&item)).map_err(|_| Error::Unavailable)
     }

     pub async fn logout() -> Result<(), Error> {

I'll try to come up with a way to handle backslashes in the password.

Edit: I have a fix ready, coming up with a PR!

xou816 commented 1 year ago

oh wow nice find!! I had not thought it could be an issue with deserialization -- and whatever login and error management I have in place certainly didnt help... thanks a lot, I'll have a look at the PR!

xou816 commented 1 year ago

Wait so I'm curious where the issues lies exactly -- I've changed my password so that it starts with "\5..." (I assumed the issue is with the backslash and double quotes too, probably, I don't think \& is anything special, or is it?) It's properly escaped by serde and ends up stored as {"username":"xou816","password":"\\5..."} And then properly deserializes it too. If I apply the additional escaping logic I get a login failure :/

Could you confirm that you don't have the issue with flatpak? That was weird. I'm wondering if it's possible that the issue lies somewhere else (a faulty version of dbus that would mess with escaping?)

samsapti commented 1 year ago

Well, mine ends up stored as {"username":"...","password":"...\&..."}, which is why it fails to deserialize. I can check the Flatpak version tomorrow on Fedora, but I was using it two days ago and it didn't have the issue. Though I can see that the DBUS version is the same on both my systems (1.14.6-1).

samsapti commented 1 year ago

I don't think \& is anything special, or is it?

Exactly, it isn't, which is why serde fails to deserialize it. Why it doesn't escape the backslash when serializing tho, I can't say.

xou816 commented 1 year ago

Great, thanks, I appreciate it if we can run a couple more tests with your setup first! :)

samsapti commented 1 year ago

@xou816 still no issues with the Flatpak version (0.3.1), but I noticed that my password is stored as {"username":"...","password":"...\\&..."} in my keyring on Fedora, so somehow it's correctly escaped. Could it be an issue with the serde_json version, as it has been updated since that release? Perhaps I can try building that version on Artix and see if the issue persists.

xou816 commented 1 year ago

It's worth a try yes! If you don't mind!

samsapti commented 1 year ago

@xou816 I just upgraded the Flatpak version to 0.4.0, it correctly escapes and stores the password as {"username":"...","password":"...\\&..."}. I don't know why it fails on Artix.

I haven't yet tried to downgrade to 0.3.1 on Artix, but I tried only downgrading the serde_json dependency to the version used in 0.3.1.

xou816 commented 1 year ago

sounds like it's definitely not serde if both 0.3 and 0.4 are okay. I suspect a dbus related dependency on your Artix install but I have no clue which it could be :/

samsapti commented 1 year ago

@xou816 I think you're right. I just tried adding:

diff --git a/src/app/credentials.rs b/src/app/credentials.rs
index 50867f8..3ff3125 100644
--- a/src/app/credentials.rs
+++ b/src/app/credentials.rs
@@ -58,6 +58,8 @@ impl Credentials {
             collection.unlock().await?;
         }
         let encoded = serde_json::to_vec(&self).unwrap();
+        let p: Credentials = serde_json::from_slice(&encoded).unwrap();
+        dbg!(p);
         collection
             .create_item(
                 "Spotify Credentials",

and it indeed prints it as ...\\&..., but stores it in my keyring as ...\&....

samsapti commented 1 year ago

I think this is unrelated to Spot. Saving a password manually with secret-tool from the shell, pasting the password as ...\\&..., saves it as ...\&.... Should we close this?

xou816 commented 1 year ago

I think we should close it for now yes :/ thanks for taking the time to investigate this and even suggest a fix!!

samsapti commented 1 year ago

@xou816 no problem :)

After investigating some more, I noticed that it works fine on my other Artix system. The difference between them turns out to be that the faulty one uses an unencrypted secret service keyring (without password), and the working one uses an encrypted one. When unencrypted, the keyring is stored as a plaintext file, as opposed to an encrypted one which is in binary format.

I tested both encrypted and unencrypted keyrings with secret-tool storing passwords like \n\t\&\\..., and as I suspected, escape characters are interpreted before they're stored ONLY IF the keyring is UNENCRYPTED. If it's encrypted, it stores secrets AS IS, \n like \n, not like an actual line break making the keyring file invalid. That's weird. I should probably file a bug report with gnome-keyring.

Rants aside, Spot works fine now after switching to encrypted keyring :D