From 14a146d65f08b61308948ba660374be72c77cc12 Mon Sep 17 00:00:00 2001 From: "Nathan.fooo" <86001920+appflowy@users.noreply.github.com> Date: Sat, 3 Feb 2024 07:40:18 +0800 Subject: [PATCH] chore: add logs (#286) * chore: add logs * chore: add logs * chore: add logs --- libs/client-api/src/http.rs | 3 ++- libs/client-api/src/notify.rs | 11 +++++++-- libs/gotrue-entity/src/dto.rs | 10 ++++++++ libs/gotrue-entity/src/gotrue_jwt.rs | 24 ++++++++++++++++---- libs/gotrue/src/api.rs | 18 +++++++++++---- src/biz/casbin/access_control.rs | 34 +++++++++++++++++----------- src/biz/user.rs | 2 +- src/component/auth/jwt.rs | 14 ++++++++++-- src/main.rs | 1 + 9 files changed, 89 insertions(+), 28 deletions(-) diff --git a/libs/client-api/src/http.rs b/libs/client-api/src/http.rs index 96109bbf..7a751b1d 100644 --- a/libs/client-api/src/http.rs +++ b/libs/client-api/src/http.rs @@ -40,7 +40,7 @@ use shared_entity::response::{AppResponse, AppResponseError}; use std::sync::atomic::AtomicBool; use std::sync::Arc; use std::time::Duration; -use tracing::{error, event, instrument, trace, warn}; +use tracing::{error, event, info, instrument, trace, warn}; use url::Url; use gotrue_entity::dto::SignUpResponse::{Authenticated, NotAuthenticated}; @@ -1158,6 +1158,7 @@ impl Client { let expires_at = self.token_expires_at()?; if ts + 30 > expires_at { + info!("token is about to expire, refreshing token"); // Add 30 seconds buffer self.refresh_token().await?; } diff --git a/libs/client-api/src/notify.rs b/libs/client-api/src/notify.rs index 06394b64..7a827ed4 100644 --- a/libs/client-api/src/notify.rs +++ b/libs/client-api/src/notify.rs @@ -46,10 +46,17 @@ impl ClientToken { /// /// - `token`: The new `AccessTokenResponse` to be set. pub(crate) fn set(&mut self, new_token: GotrueTokenResponse) { - event!(tracing::Level::DEBUG, "Did set token: {:?}", new_token); let is_new = match &self.token { None => true, - Some(old_token) => old_token.access_token != new_token.access_token, + Some(old_token) => { + event!( + tracing::Level::INFO, + "old token:{}, new token:{}", + old_token, + new_token + ); + old_token.access_token != new_token.access_token + }, }; self.token = Some(new_token); diff --git a/libs/gotrue-entity/src/dto.rs b/libs/gotrue-entity/src/dto.rs index 5bebbd74..707ff264 100644 --- a/libs/gotrue-entity/src/dto.rs +++ b/libs/gotrue-entity/src/dto.rs @@ -1,5 +1,6 @@ use serde::{Deserialize, Serialize}; use std::collections::BTreeMap; +use std::fmt::{Display, Formatter}; #[derive(Debug, Serialize, Deserialize, Clone)] pub struct Identity { @@ -88,6 +89,15 @@ pub struct GotrueTokenResponse { pub provider_refresh_token: Option, } +impl Display for GotrueTokenResponse { + fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result { + f.debug_struct("GotrueTokenResponse") + .field("expires_at", &self.expires_at) + .field("token_type", &self.token_type) + .finish() + } +} + #[derive(Serialize, Deserialize, Debug)] pub struct GoTrueSettings { pub external: GoTrueOAuthProviderSettings, diff --git a/libs/gotrue-entity/src/gotrue_jwt.rs b/libs/gotrue-entity/src/gotrue_jwt.rs index a8893a78..95842976 100644 --- a/libs/gotrue-entity/src/gotrue_jwt.rs +++ b/libs/gotrue-entity/src/gotrue_jwt.rs @@ -1,5 +1,6 @@ use jsonwebtoken::{decode, Algorithm, DecodingKey, Validation}; use serde::{Deserialize, Serialize}; +use std::fmt::{Display, Formatter}; #[derive(Debug, Serialize, Deserialize)] pub struct GoTrueJWTClaims { @@ -22,6 +23,15 @@ pub struct GoTrueJWTClaims { pub session_id: Option, } +impl Display for GoTrueJWTClaims { + fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result { + f.debug_struct("GoTrueJWTClaims") + .field("exp", &self.exp) + .field("email", &self.email) + .finish() + } +} + #[derive(Debug, Serialize, Deserialize)] pub struct Amr { pub method: String, @@ -34,17 +44,21 @@ lazy_static::lazy_static! { } impl GoTrueJWTClaims { - pub fn verify(token: &str, secret: &[u8]) -> Result { - let claims = decode::(token, &DecodingKey::from_secret(secret), &VALIDATION)?.claims; + pub fn decode(token: &str, secret: &[u8]) -> Result { + let token_data = decode::(token, &DecodingKey::from_secret(secret), &VALIDATION)?; + Ok(token_data.claims) + } + pub fn verify_claim(claims: &GoTrueJWTClaims) -> Result<(), jsonwebtoken::errors::Error> { let ts_expiry = claims.exp.ok_or_else(|| { jsonwebtoken::errors::ErrorKind::MissingRequiredClaim("expect exp but not found".to_owned()) })?; let ts_now = chrono::Utc::now().timestamp(); - match ts_now > ts_expiry { - true => Err(jsonwebtoken::errors::ErrorKind::ExpiredSignature.into()), - false => Ok(claims), + if ts_now > ts_expiry { + Err(jsonwebtoken::errors::ErrorKind::ExpiredSignature.into()) + } else { + Ok(()) } } } diff --git a/libs/gotrue/src/api.rs b/libs/gotrue/src/api.rs index 8df34e39..562acbb0 100644 --- a/libs/gotrue/src/api.rs +++ b/libs/gotrue/src/api.rs @@ -12,6 +12,7 @@ use gotrue_entity::error::{GoTrueError, GoTrueErrorSerde, GotrueClientError}; use gotrue_entity::sso::{SSOProvider, SSOProviders}; use infra::reqwest::{check_response, from_body, from_response}; use reqwest::{Method, RequestBuilder}; +use tracing::event; #[derive(Clone)] pub struct Client { @@ -70,7 +71,6 @@ impl Client { "password": password, }); let url: String = format!("{}/signup", self.base_url); - let mut req_builder = self.client.post(&url).json(&payload); if let Some(redirect_to) = redirect_to { req_builder = req_builder.header("redirect_to", redirect_to); @@ -109,11 +109,21 @@ impl Client { #[tracing::instrument(skip_all, err)] pub async fn user_info(&self, access_token: &str) -> Result { let url = format!("{}/user", self.base_url); - let resp = self + match self .http_client_with_auth(Method::GET, &url, access_token) .send() - .await?; - to_gotrue_result(resp).await + .await + { + Ok(resp) => to_gotrue_result(resp).await, + Err(err) => { + event!( + tracing::Level::ERROR, + "fail to get user info with access token: {}", + access_token + ); + Err(err.into()) + }, + } } pub async fn update_user( diff --git a/src/biz/casbin/access_control.rs b/src/biz/casbin/access_control.rs index 2262b9dd..3296fa3e 100644 --- a/src/biz/casbin/access_control.rs +++ b/src/biz/casbin/access_control.rs @@ -7,8 +7,8 @@ use casbin::{CoreApi, MgmtApi}; use database::user::select_uid_from_uuid; use sqlx::PgPool; use tokio::sync::{broadcast, RwLock}; -use tracing::instrument; use tracing::log::warn; +use tracing::{error, instrument}; use uuid::Uuid; @@ -272,26 +272,34 @@ impl CollabAccessControl for CasbinCollabAccessControl { .map(AFAccessLevel::from); if access_level.is_none() { - if let Ok(member) = self + match self .casbin_access_control .get_collab_member(&uid, oid) .await { - access_level = Some(member.permission.access_level); - self - .casbin_access_control - .update( - &uid, - &ObjectType::Collab(oid), - &ActionType::Level(member.permission.access_level), - ) - .await?; + Ok(member) => { + access_level = Some(member.permission.access_level); + self + .casbin_access_control + .update( + &uid, + &ObjectType::Collab(oid), + &ActionType::Level(member.permission.access_level), + ) + .await?; + }, + Err(err) => { + error!( + "Failed to get member:{} in collab:{}, error: {}", + uid, oid, err + ); + }, } } access_level.ok_or(AppError::RecordNotFound(format!( - "collab:{} does not exist or user:{} is not a member", - oid, uid + "user:{} is not a member of collab:{}", + uid, oid ))) } diff --git a/src/biz/user.rs b/src/biz/user.rs index bddeffc7..c341d8b2 100644 --- a/src/biz/user.rs +++ b/src/biz/user.rs @@ -67,7 +67,7 @@ where let is_new = !is_user_exist(txn.deref_mut(), &user_uuid).await?; if is_new { let new_uid = id_gen.write().await.next_id(); - event!(tracing::Level::DEBUG, "create new user:{}", new_uid); + event!(tracing::Level::INFO, "create new user:{}", new_uid); let workspace_id = create_user(txn.deref_mut(), new_uid, &user_uuid, &user.email, &name).await?; diff --git a/src/component/auth/jwt.rs b/src/component/auth/jwt.rs index 9bb45187..78cb8552 100644 --- a/src/component/auth/jwt.rs +++ b/src/component/auth/jwt.rs @@ -144,9 +144,19 @@ fn gotrue_jwt_claims_from_token( token: &str, state: &Data, ) -> Result { - GoTrueJWTClaims::verify( + let claims = GoTrueJWTClaims::decode( token, state.config.gotrue.jwt_secret.expose_secret().as_bytes(), ) - .map_err(actix_web::error::ErrorUnauthorized) + .map_err(|err| { + actix_web::error::ErrorUnauthorized(format!("fail to decode token:{}, error:{}", token, err)) + })?; + + GoTrueJWTClaims::verify_claim(&claims).map_err(|err| { + actix_web::error::ErrorUnauthorized(format!( + "fail to verify token:{}, claims:{}, error:{}", + token, claims, err + )) + })?; + Ok(claims) } diff --git a/src/main.rs b/src/main.rs index 1dde1649..f204777c 100644 --- a/src/main.rs +++ b/src/main.rs @@ -16,6 +16,7 @@ async fn main() -> anyhow::Result<()> { filters.push(format!("realtime={}", level)); filters.push(format!("database={}", level)); filters.push(format!("storage={}", level)); + filters.push(format!("gotrue={}", level)); let conf = get_configuration().map_err(|e| anyhow::anyhow!("Failed to read configuration: {}", e))?; init_subscriber(&conf.app_env, filters);