add debugs logs for enrollment process (#708)

* add debugs logs for enrollment process * add more debug logs for desktop activation, enrollment and create device * comment arm build * cargo fmt * add more debug logs v2 * uncomment arm build and change defguard version from 0.11.1 to 1.0.0 * Apply suggestions from code review Co-authored-by: Aleksander <[email protected]> * apply cargo fmt --------- Co-authored-by: Aleksander <[email protected]> Co-authored-by: Robert Olejnik <[email protected]>
DefGuard · Aug 13, 2024 · 17307d6 · 17307d6
1 parent 8aa3d23
commit 17307d6
Show file tree

Hide file tree

Showing 7 changed files with 211 additions and 47 deletions.
diff --git a/.github/workflows/release.yml b/.github/workflows/release.yml
@@ -6,7 +6,7 @@ on:
 
 jobs:
   publish-docker:
-    runs-on: [self-hosted, Linux]
+    runs-on: [self-hosted, Linux, X64]
     steps:
       - name: Checkout
         uses: actions/checkout@v4

diff --git a/src/db/models/enrollment.rs b/src/db/models/enrollment.rs
@@ -77,7 +77,7 @@ impl From<TokenError> for Status {
 }
 
 // Representation of a user enrollment session
-#[derive(Clone)]
+#[derive(Clone, Debug)]
 pub struct Token {
     pub id: String,
     pub user_id: i64,
@@ -161,16 +161,22 @@ impl Token {
         session_timeout_seconds: u64,
     ) -> Result<NaiveDateTime, TokenError> {
         // check if token can be used
+        debug!("Creating a new session.");
         if self.is_expired() {
+            debug!("Token is already expired. Cannot establish a new session.");
             return Err(TokenError::TokenExpired);
         }
         match self.used_at {
             // session started but still valid
             Some(used_at) if self.is_session_valid(session_timeout_seconds) => {
+                debug!("Session already exists yet it is still valid.");
                 Ok(used_at + Duration::seconds(session_timeout_seconds as i64))
             }
             // session expired
-            Some(_) => Err(TokenError::TokenUsed),
+            Some(_) => {
+                debug!("Session has expired.");
+                Err(TokenError::TokenUsed)
+            }
             // session not yet started
             None => {
                 let now = Utc::now().naive_utc();
@@ -179,6 +185,7 @@ impl Token {
                     .await?;
                 self.used_at = Some(now);
 
+                debug!("Generate a new session successfully.");
                 Ok(now + Duration::seconds(session_timeout_seconds as i64))
             }
         }
@@ -194,8 +201,14 @@ impl Token {
         .fetch_optional(pool)
         .await?
         {
-            Some(enrollment) => Ok(enrollment),
-            None => Err(TokenError::NotFound),
+            Some(enrollment) => {
+                debug!("Fetch token {enrollment:?} from database.");
+                Ok(enrollment)
+            }
+            None => {
+                debug!("Token with id {} does not exist in database.", id);
+                Err(TokenError::NotFound)
+            }
         }
     }
 
@@ -214,34 +227,37 @@ impl Token {
     where
         E: PgExecutor<'e>,
     {
-        debug!("Fetching user for enrollment");
+        debug!("Find user by id {}.", self.user_id);
         let Some(user) = User::find_by_id(executor, self.user_id).await? else {
             error!("User not found for enrollment token {}", self.id);
             return Err(TokenError::UserNotFound);
         };
+        debug!("Fetched user {user:?}.");
         Ok(user)
     }
 
     pub async fn fetch_admin<'e, E>(&self, executor: E) -> Result<Option<User>, TokenError>
     where
         E: PgExecutor<'e>,
     {
-        debug!("Fetching admin for enrollment");
+        debug!("Fetch admin data.");
         if self.admin_id.is_none() {
+            debug!("Admin don't have id. Stop fetching data...");
             return Ok(None);
         }
 
         let admin_id = self.admin_id.unwrap();
+        debug!("Trying to find admin using id {admin_id}");
         let user = User::find_by_id(executor, admin_id).await?;
-        info!("Fetched admin id {} for enrollment", admin_id);
+        debug!("Fetched admin {user:?}.");
         Ok(user)
     }
 
     pub async fn delete_unused_user_tokens(
         transaction: &mut PgConnection,
         user_id: i64,
     ) -> Result<(), TokenError> {
-        debug!("Deleting unused enrollment tokens for user {user_id}");
+        debug!("Deleting unused tokens for the user.");
         let result = query!(
             "DELETE FROM token \
             WHERE user_id = $1 \
@@ -251,7 +267,7 @@ impl Token {
         .execute(transaction)
         .await?;
         info!(
-            "Deleted {} unused enrollment tokens for user {user_id}",
+            "Deleted {} unused enrollment tokens for the user.",
             result.rows_affected()
         );
 
@@ -376,13 +392,23 @@ impl User {
         mail_tx: UnboundedSender<Mail>,
     ) -> Result<String, TokenError> {
         info!(
-            "User {} starting enrollment for user {}, notification enabled: {send_user_notification}",
+            "User {} started a new enrollment process for user {}.",
             admin.username, self.username
         );
+        debug!(
+            "Notify user by mail about the enrollment process: {}",
+            send_user_notification
+        );
+        debug!("Check if {} has a password.", self.username);
         if self.has_password() {
+            debug!(
+                "User {} that you want to start enrollment process for already has a password.",
+                self.username
+            );
             return Err(TokenError::AlreadyActive);
         }
 
+        debug!("Verify that {} is an active user.", self.username);
         if !self.is_active {
             warn!(
                 "Can't create enrollment token for disabled user {}",
@@ -397,19 +423,25 @@ impl User {
         self.clear_unused_enrollment_tokens(&mut *transaction)
             .await?;
 
+        debug!("Create a new enrollment token for user {}.", self.username);
         let enrollment = Token::new(
             user_id,
             Some(admin_id),
             email.clone(),
             token_timeout_seconds,
             Some(ENROLLMENT_TOKEN_TYPE.to_string()),
         );
+        debug!("Saving a new enrollment token...");
         enrollment.save(&mut *transaction).await?;
+        debug!(
+            "Saved a new enrollment token with id {} for user {}.",
+            enrollment.id, self.username
+        );
 
         if send_user_notification {
             if let Some(email) = email {
                 debug!(
-                    "Sending enrollment start mail for user {} to {email}",
+                    "Sending an enrollment mail for user {} to {email}.",
                     self.username
                 );
                 let base_message_context = enrollment
@@ -423,7 +455,14 @@ impl User {
                         enrollment_service_url,
                         &enrollment.id,
                     )
-                    .map_err(|err| TokenError::NotificationError(err.to_string()))?,
+                    .map_err(|err| {
+                        debug!(
+                            "Cannot send an email to the user {} due to the error {}.",
+                            self.username,
+                            err.to_string()
+                        );
+                        TokenError::NotificationError(err.to_string())
+                    })?,
                     attachments: Vec::new(),
                     result_tx: None,
                 };
@@ -441,6 +480,10 @@ impl User {
                 }
             }
         }
+        info!(
+            "New enrollment token has been generated for {}.",
+            self.username
+        );
 
         Ok(enrollment.id)
     }
@@ -458,40 +501,55 @@ impl User {
         mail_tx: UnboundedSender<Mail>,
     ) -> Result<String, TokenError> {
         info!(
-            "User {} starting desktop configuration for user {}, notification enabled: {send_user_notification}",
+            "User {} starting a new desktop activation for user {}",
             admin.username, self.username
         );
+        debug!(
+            "Notify {} by mail about the enrollment process: {}",
+            self.username, send_user_notification
+        );
 
         let user_id = self.id.expect("User without ID");
         let admin_id = admin.id.expect("Admin user without ID");
 
+        debug!("Verify that {} is an active user.", self.username);
         if !self.is_active {
             warn!(
-                "Can't create desktop configuration enrollment token for disabled user {}",
+                "Can't create desktop activation token for disabled user {}.",
                 self.username
             );
             return Err(TokenError::UserDisabled);
         }
 
         self.clear_unused_enrollment_tokens(&mut *transaction)
             .await?;
+        debug!("Cleared unused tokens for {}.", self.username);
 
-        let enrollment = Token::new(
+        debug!(
+            "Create a new desktop activation token for user {}.",
+            self.username
+        );
+        let desktop_configuration = Token::new(
             user_id,
             Some(admin_id),
             email.clone(),
             token_timeout_seconds,
             Some(ENROLLMENT_TOKEN_TYPE.to_string()),
         );
-        enrollment.save(&mut *transaction).await?;
+        debug!("Saving a new desktop configuration token...");
+        desktop_configuration.save(&mut *transaction).await?;
+        debug!(
+            "Saved a new desktop activation token with id {} for user {}.",
+            desktop_configuration.id, self.username
+        );
 
         if send_user_notification {
             if let Some(email) = email {
                 debug!(
-                    "Sending desktop configuration start mail for user {} to {email}",
+                    "Sending a desktop configuration mail for user {} to {email}",
                     self.username
                 );
-                let base_message_context = enrollment
+                let base_message_context = desktop_configuration
                     .get_welcome_message_context(&mut *transaction)
                     .await?;
                 let mail = Mail {
@@ -500,9 +558,16 @@ impl User {
                     content: templates::desktop_start_mail(
                         base_message_context,
                         &enrollment_service_url,
-                        &enrollment.id,
+                        &desktop_configuration.id,
                     )
-                    .map_err(|err| TokenError::NotificationError(err.to_string()))?,
+                    .map_err(|err| {
+                        debug!(
+                            "Cannot send an email to the user {} due to the error {}.",
+                            self.username,
+                            err.to_string()
+                        );
+                        TokenError::NotificationError(err.to_string())
+                    })?,
                     attachments: Vec::new(),
                     result_tx: None,
                 };
@@ -519,19 +584,20 @@ impl User {
                 }
             }
         }
+        info!(
+            "New desktop activation token has been generated for {}.",
+            self.username
+        );
 
-        Ok(enrollment.id)
+        Ok(desktop_configuration.id)
     }
 
     // Remove unused tokens when triggering user enrollment
     async fn clear_unused_enrollment_tokens(
         &self,
         transaction: &mut PgConnection,
     ) -> Result<(), TokenError> {
-        info!(
-            "Removing unused enrollment tokens for user {}",
-            self.username
-        );
+        info!("Removing unused tokens for user {}.", self.username);
         Token::delete_unused_user_tokens(transaction, self.id.expect("Missing user ID")).await
     }