chore: add logs (#286)

* chore: add logs

* chore: add logs

* chore: add logs

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?;
     }

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);
 

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<String>,
 }
 
+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,

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<String>,
 }
 
+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<Self, jsonwebtoken::errors::Error> {
-    let claims = decode::<Self>(token, &DecodingKey::from_secret(secret), &VALIDATION)?.claims;
+  pub fn decode(token: &str, secret: &[u8]) -> Result<Self, jsonwebtoken::errors::Error> {
+    let token_data = decode::<Self>(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(())
     }
   }
 }

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<User, GoTrueError> {
     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(

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
     )))
   }
 

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?;
 

src/component/auth/jwt.rs

@@ -144,9 +144,19 @@ fn gotrue_jwt_claims_from_token(
   token: &str,
   state: &Data<AppState>,
 ) -> Result<GoTrueJWTClaims, actix_web::Error> {
-  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)
 }

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);