Fixed token refresh.

Cargo.lock

@@ -1180,7 +1180,7 @@ checksum = "42703706b716c37f96a77aea830392ad231f44c9e9a67872fa5548707e11b11c"
 
 [[package]]
 name = "furumi_tui"
-version = "0.1.1"
+version = "0.1.2"
 dependencies = [
  "anyhow",
  "arboard",

Cargo.toml

@@ -1,6 +1,6 @@
 [package]
 name = "furumi_tui"
-version = "0.1.1"
+version = "0.1.2"
 edition = "2024"
 
 [[bin]]

src/api/auth.rs

@@ -1,4 +1,5 @@
 use std::fs;
+use std::io::ErrorKind;
 use std::path::PathBuf;
 use std::time::{SystemTime, UNIX_EPOCH};
 
@@ -44,6 +45,10 @@ impl AuthSession {
     pub fn access_token_expired(&self) -> bool {
         now_epoch_seconds() + EXPIRY_SKEW_SECONDS >= self.expires_at_epoch_seconds
     }
+
+    pub fn seconds_until_access_expiry(&self) -> i64 {
+        self.expires_at_epoch_seconds - now_epoch_seconds()
+    }
 }
 
 pub fn now_epoch_seconds() -> i64 {
@@ -58,10 +63,34 @@ pub fn session_path() -> Option<PathBuf> {
 }
 
 pub fn load_session() -> Option<AuthSession> {
-    let path = session_path()?;
+    let Some(path) = session_path() else {
-    let text = fs::read_to_string(&path).ok()?;
+        tracing::warn!("cannot determine config directory; no stored auth session loaded");
-    match serde_json::from_str(&text) {
+        return None;
-        Ok(session) => Some(session),
+    };
+    let text = match fs::read_to_string(&path) {
+        Ok(text) => text,
+        Err(err) if err.kind() == ErrorKind::NotFound => {
+            tracing::debug!(path = %path.display(), "credentials file not found");
+            return None;
+        }
+        Err(err) => {
+            tracing::warn!(path = %path.display(), %err, "failed to read credentials file");
+            return None;
+        }
+    };
+    match serde_json::from_str::<AuthSession>(&text) {
+        Ok(session) => {
+            tracing::info!(
+                path = %path.display(),
+                user_id = session.user.id,
+                user = %session.user.name,
+                server = %session.server_base_url,
+                expires_at_epoch_seconds = session.expires_at_epoch_seconds,
+                seconds_until_expiry = session.seconds_until_access_expiry(),
+                "loaded stored auth session"
+            );
+            Some(session)
+        }
         Err(err) => {
             tracing::warn!(path = %path.display(), %err, "ignoring unreadable credentials file");
             None
@@ -75,12 +104,31 @@ pub fn save_session(session: &AuthSession) -> Result<()> {
         fs::create_dir_all(parent).with_context(|| format!("creating {}", parent.display()))?;
     }
     let text = serde_json::to_string_pretty(session)?;
-    write_private(&path, &text).with_context(|| format!("writing {}", path.display()))
+    tracing::info!(
+        path = %path.display(),
+        user_id = session.user.id,
+        user = %session.user.name,
+        server = %session.server_base_url,
+        expires_at_epoch_seconds = session.expires_at_epoch_seconds,
+        seconds_until_expiry = session.seconds_until_access_expiry(),
+        "persisting auth session"
+    );
+    write_private(&path, &text).with_context(|| format!("writing {}", path.display()))?;
+    tracing::debug!(path = %path.display(), "auth session persisted");
+    Ok(())
 }
 
 pub fn delete_session() {
     if let Some(path) = session_path() {
-        let _ = fs::remove_file(path);
+        match fs::remove_file(&path) {
+            Ok(()) => tracing::info!(path = %path.display(), "deleted stored auth session"),
+            Err(err) if err.kind() == ErrorKind::NotFound => {
+                tracing::debug!(path = %path.display(), "stored auth session already absent");
+            }
+            Err(err) => {
+                tracing::warn!(path = %path.display(), %err, "failed to delete stored auth session")
+            }
+        }
     }
 }
 

src/api/client.rs

@@ -76,21 +76,42 @@ pub async fn login_password(
     username: &str,
     password: &str,
 ) -> Result<AuthSession, ApiError> {
-    let response = http
+    let device_name = device_name();
+    tracing::info!(%base_url, %device_name, "password login request started");
+    let response = match http
         .post(format!("{base_url}/api/auth/password"))
         .json(&PasswordLoginRequest {
             username,
             password,
-            device_name: device_name(),
+            device_name,
         })
         .send()
-        .await?;
+        .await
-    let login: LoginResponse = parse_response(response).await?;
+    {
-    Ok(AuthSession::new(
+        Ok(response) => response,
-        base_url.to_string(),
+        Err(err) => {
-        login.user,
+            tracing::warn!(%base_url, %err, "password login request failed");
-        login.tokens,
+            return Err(ApiError::Network(err));
-    ))
+        }
+    };
+    let status = response.status();
+    let login: LoginResponse = match parse_response(response).await {
+        Ok(login) => login,
+        Err(err) => {
+            tracing::warn!(%base_url, %status, %err, "password login rejected");
+            return Err(err);
+        }
+    };
+    let session = AuthSession::new(base_url.to_string(), login.user, login.tokens);
+    tracing::info!(
+        %base_url,
+        user_id = session.user.id,
+        user = %session.user.name,
+        expires_at_epoch_seconds = session.expires_at_epoch_seconds,
+        seconds_until_expiry = session.seconds_until_access_expiry(),
+        "password login succeeded"
+    );
+    Ok(session)
 }
 
 pub async fn login_sso_exchange(
@@ -98,20 +119,38 @@ pub async fn login_sso_exchange(
     base_url: &str,
     code: &str,
 ) -> Result<AuthSession, ApiError> {
-    let response = http
+    let device_name = device_name();
+    tracing::info!(%base_url, %device_name, "SSO exchange request started");
+    let response = match http
         .post(format!("{base_url}/api/auth/sso/exchange"))
-        .json(&SsoExchangeRequest {
+        .json(&SsoExchangeRequest { code, device_name })
-            code,
-            device_name: device_name(),
-        })
         .send()
-        .await?;
+        .await
-    let login: LoginResponse = parse_response(response).await?;
+    {
-    Ok(AuthSession::new(
+        Ok(response) => response,
-        base_url.to_string(),
+        Err(err) => {
-        login.user,
+            tracing::warn!(%base_url, %err, "SSO exchange request failed");
-        login.tokens,
+            return Err(ApiError::Network(err));
-    ))
+        }
+    };
+    let status = response.status();
+    let login: LoginResponse = match parse_response(response).await {
+        Ok(login) => login,
+        Err(err) => {
+            tracing::warn!(%base_url, %status, %err, "SSO exchange rejected");
+            return Err(err);
+        }
+    };
+    let session = AuthSession::new(base_url.to_string(), login.user, login.tokens);
+    tracing::info!(
+        %base_url,
+        user_id = session.user.id,
+        user = %session.user.name,
+        expires_at_epoch_seconds = session.expires_at_epoch_seconds,
+        seconds_until_expiry = session.seconds_until_access_expiry(),
+        "SSO exchange succeeded"
+    );
+    Ok(session)
 }
 
 /// Browser entry point for SSO. redirect_uri is either our loopback
@@ -130,15 +169,38 @@ async fn refresh_tokens(
     base_url: &str,
     refresh_token: &str,
 ) -> Result<TokensResponse, ApiError> {
-    let response = http
+    tracing::info!(%base_url, "refresh token request started");
+    let response = match http
         .post(format!("{base_url}/api/auth/refresh"))
         .json(&RefreshRequest { refresh_token })
         .send()
-        .await?;
+        .await
+    {
+        Ok(response) => response,
+        Err(err) => {
+            tracing::warn!(%base_url, %err, "refresh token request failed");
+            return Err(ApiError::Network(err));
+        }
+    };
+    let status = response.status();
     if response.status() == reqwest::StatusCode::UNAUTHORIZED {
+        tracing::warn!(%base_url, %status, "refresh token rejected by server");
         return Err(ApiError::SessionExpired);
     }
-    parse_response(response).await
+    let tokens: TokensResponse = match parse_response(response).await {
+        Ok(tokens) => tokens,
+        Err(err) => {
+            tracing::warn!(%base_url, %status, %err, "refresh token request returned error");
+            return Err(err);
+        }
+    };
+    tracing::info!(
+        %base_url,
+        %status,
+        expires_in_seconds = tokens.expires_in_seconds,
+        "refresh token request succeeded"
+    );
+    Ok(tokens)
 }
 
 /// Mirrors the backend's PlaybackStateDto.
@@ -201,6 +263,16 @@ async fn parse_response<T: DeserializeOwned>(response: reqwest::Response) -> Res
     Err(ApiError::Server(message))
 }
 
+fn stream_error_is_auth_related(err: &ApiError) -> bool {
+    let ApiError::Server(message) = err else {
+        return false;
+    };
+    let message = message.to_ascii_lowercase();
+    message.contains("401")
+        || message.contains("unauthorized")
+        || message.contains("authentication")
+}
+
 /// Authenticated API client. Owns the session; refreshes the access token
 /// proactively (60s skew) and once more on 401, persisting rotated tokens.
 /// The session mutex makes concurrent refreshes single-flight.
@@ -258,13 +330,43 @@ impl ApiClient {
     pub async fn open_stream(
         &self,
         path: &str,
+    ) -> Result<(crate::player::TrackReader, Option<u64>), ApiError> {
+        let url: reqwest::Url = format!("{}{path}", self.base_url)
+            .parse()
+            .map_err(|err| ApiError::Server(format!("bad stream url: {err}")))?;
+        tracing::info!(path, "opening authenticated stream");
+        let token = self.fresh_access_token().await?;
+        match self.open_stream_with_token(url.clone(), &token).await {
+            Ok(stream) => {
+                tracing::debug!(path, "authenticated stream opened");
+                Ok(stream)
+            }
+            Err(err) if stream_error_is_auth_related(&err) => {
+                tracing::warn!(path, %err, "stream rejected bearer token; refreshing and retrying");
+                let retry_token = self.refresh_after_rejection(&token).await?;
+                let result = self.open_stream_with_token(url, &retry_token).await;
+                if let Err(retry_err) = &result {
+                    tracing::warn!(path, %retry_err, "stream open failed after auth refresh");
+                }
+                result
+            }
+            Err(err) => {
+                tracing::warn!(path, %err, "stream open failed");
+                Err(err)
+            }
+        }
+    }
+
+    async fn open_stream_with_token(
+        &self,
+        url: reqwest::Url,
+        token: &str,
     ) -> Result<(crate::player::TrackReader, Option<u64>), ApiError> {
         use stream_download::Settings;
         use stream_download::http::HttpStream;
         use stream_download::source::SourceStream as _;
         use stream_download::storage::temp::TempStorageProvider;
 
-        let token = self.fresh_access_token().await?;
         let mut headers = reqwest::header::HeaderMap::new();
         let value = format!("Bearer {token}")
             .parse()
@@ -275,9 +377,6 @@ impl ApiClient {
             .build()
             .map_err(ApiError::Network)?;
 
-        let url = format!("{}{path}", self.base_url)
-            .parse()
-            .map_err(|err| ApiError::Server(format!("bad stream url: {err}")))?;
         let stream = HttpStream::new(client, url)
             .await
             .map_err(|err| ApiError::Server(format!("stream open failed: {err}")))?;
@@ -480,6 +579,7 @@ impl ApiClient {
             let session = self.session.lock().await;
             (session.access_token.clone(), session.refresh_token.clone())
         };
+        tracing::info!(base_url = %self.base_url, "logout request started");
         let response = self
             .http
             .post(format!("{}/api/auth/logout", self.base_url))
@@ -489,12 +589,20 @@ impl ApiClient {
             })
             .send()
             .await?;
+        let status = response.status();
 
         #[derive(serde::Deserialize)]
         struct LogoutResponse {
             revoked: bool,
         }
-        let body: LogoutResponse = parse_response(response).await?;
+        let body: LogoutResponse = match parse_response(response).await {
+            Ok(body) => body,
+            Err(err) => {
+                tracing::warn!(base_url = %self.base_url, %status, %err, "logout request failed");
+                return Err(err);
+            }
+        };
+        tracing::info!(base_url = %self.base_url, %status, revoked = body.revoked, "logout request succeeded");
         Ok(body.revoked)
     }
 
@@ -564,15 +672,28 @@ impl ApiClient {
         let token = self.fresh_access_token().await?;
         let response = build(&self.http, url, &token).send().await?;
         if response.status() == reqwest::StatusCode::UNAUTHORIZED {
+            tracing::warn!(%url, "authenticated request returned 401; refreshing token and retrying");
             let token = self.refresh_after_rejection(&token).await?;
-            return Ok(build(&self.http, url, &token).send().await?);
+            let response = build(&self.http, url, &token).send().await?;
+            if response.status() == reqwest::StatusCode::UNAUTHORIZED {
+                tracing::warn!(%url, "authenticated request still returned 401 after token refresh");
+            }
+            return Ok(response);
         }
         Ok(response)
     }
 
     async fn fresh_access_token(&self) -> Result<String, ApiError> {
         let mut session = self.session.lock().await;
+        let seconds_until_expiry = session.seconds_until_access_expiry();
         if session.access_token_expired() {
+            tracing::info!(
+                user_id = session.user.id,
+                user = %session.user.name,
+                expires_at_epoch_seconds = session.expires_at_epoch_seconds,
+                seconds_until_expiry,
+                "access token expired or near expiry; refreshing"
+            );
             self.refresh_locked(&mut session).await?;
         }
         Ok(session.access_token.clone())
@@ -583,28 +704,75 @@ impl ApiClient {
     async fn refresh_after_rejection(&self, rejected_token: &str) -> Result<String, ApiError> {
         let mut session = self.session.lock().await;
         if session.access_token != rejected_token {
+            tracing::info!(
+                user_id = session.user.id,
+                user = %session.user.name,
+                "rejected access token was already rotated by another task"
+            );
             return Ok(session.access_token.clone());
         }
+        tracing::warn!(
+            user_id = session.user.id,
+            user = %session.user.name,
+            seconds_until_expiry = session.seconds_until_access_expiry(),
+            "access token was rejected; refreshing"
+        );
         self.refresh_locked(&mut session).await?;
         Ok(session.access_token.clone())
     }
 
     async fn refresh_locked(&self, session: &mut AuthSession) -> Result<(), ApiError> {
+        let user_id = session.user.id;
+        let user = session.user.name.clone();
+        let previous_expires_at = session.expires_at_epoch_seconds;
+        let previous_seconds_until_expiry = session.seconds_until_access_expiry();
+        tracing::info!(
+            user_id,
+            user = %user,
+            server = %self.base_url,
+            previous_expires_at_epoch_seconds = previous_expires_at,
+            previous_seconds_until_expiry,
+            "refreshing access token"
+        );
         let result = refresh_tokens(&self.http, &self.base_url, &session.refresh_token).await;
         match result {
             Ok(tokens) => {
+                let expires_in_seconds = tokens.expires_in_seconds;
                 session.apply_tokens(tokens);
                 if let Err(err) = auth::save_session(session) {
                     tracing::warn!(%err, "failed to persist rotated tokens");
                 }
-                tracing::debug!("access token refreshed");
+                tracing::info!(
+                    user_id = session.user.id,
+                    user = %session.user.name,
+                    server = %self.base_url,
+                    expires_in_seconds,
+                    expires_at_epoch_seconds = session.expires_at_epoch_seconds,
+                    seconds_until_expiry = session.seconds_until_access_expiry(),
+                    "access token refreshed"
+                );
                 Ok(())
             }
             Err(ApiError::SessionExpired) => {
+                tracing::warn!(
+                    user_id,
+                    user = %user,
+                    server = %self.base_url,
+                    "refresh token expired or rejected; clearing stored session"
+                );
                 auth::delete_session();
                 Err(ApiError::SessionExpired)
             }
-            Err(err) => Err(err),
+            Err(err) => {
+                tracing::warn!(
+                    user_id,
+                    user = %user,
+                    server = %self.base_url,
+                    %err,
+                    "access token refresh failed"
+                );
+                Err(err)
+            }
         }
     }
 }

src/app/mod.rs

@@ -637,9 +637,21 @@ fn start_current_audio(state: &mut AppState, runtime: &Runtime, position_secs: f
                 }
             }
             Err(ApiError::SessionExpired) => {
+                tracing::warn!(
+                    track_id = track.id,
+                    title = %track.title,
+                    "playback stream open reported expired session"
+                );
                 let _ = tx.send(AppEvent::SessionExpired);
             }
             Err(err) => {
+                tracing::warn!(
+                    track_id = track.id,
+                    title = %track.title,
+                    stream_url = %track.stream_url,
+                    %err,
+                    "playback stream open failed"
+                );
                 let _ = tx.send(AppEvent::StatusMessage(format!("playback failed: {err}")));
             }
         }
@@ -682,6 +694,14 @@ fn maybe_prefetch_next(state: &mut AppState, runtime: &Runtime) {
     tokio::spawn(async move {
         match api.open_stream(&next.stream_url).await {
             Ok((reader, byte_len)) => controller.enqueue(reader, byte_len),
+            Err(ApiError::SessionExpired) => {
+                tracing::warn!(
+                    track_id = next.id,
+                    title = %next.title,
+                    "prefetch reported expired session"
+                );
+                let _ = tx.send(AppEvent::SessionExpired);
+            }
             Err(err) => {
                 tracing::warn!(%err, "prefetch failed; falling back to a normal switch");
                 let _ = tx.send(AppEvent::PrefetchFailed { pos: next_pos });