chore: add trace logging for duplicate email diagnosis #214

crates/core/src/cache/imap/download/flow.rs

@@ -630,6 +630,13 @@ async fn perform_incremental_sync(
 ) -> BichonResult<()> {
     if remote_mailbox.exists > 0 {
         let local_max_uid = ENVELOPE_MANAGER.get_max_uid(account.id, local_mailbox.id)?;
+        tracing::info!(
+            "[account {}][mailbox {}] perform_incremental_sync: local_max_uid={:?}, remote.exists={}",
+            account.id,
+            local_mailbox.name,
+            local_max_uid,
+            remote_mailbox.exists
+        );
         match local_max_uid {
             Some(max_uid) => {
                 let mut session = ImapExecutor::create_connection(account.id).await?;

crates/core/src/envelope/extractor.rs

@@ -256,6 +256,14 @@ async fn extract_envelope_core(
         attachments: Some(attachments),
     };
     let doc = ea.to_document(&body_text, 0)?;
+    tracing::debug!(
+        "[account {}][mailbox {}] extract: uid={} msg_id={} content_hash={}",
+        account_id,
+        mailbox_id,
+        uid,
+        &ea.envelope.message_id,
+        &ea.envelope.content_hash,
+    );
     ENVELOPE_MANAGER.queue(doc).await;
     for doc in attachment_docs {
         ATTACHMENT_MANAGER.queue(doc).await;

crates/core/src/imap/executor.rs

@@ -129,8 +129,16 @@ impl ImapExecutor {
             return Ok(());
         }
         info!(
-            "[account {}][mailbox {}] {} envelopes need to be fetched",
+            "[account {}][mailbox {}] {} envelopes need to be fetched (start_uid={})",
-            account.id, mailbox.name, len
+            account.id, mailbox.name, len, start_uid
+        );
+        tracing::debug!(
+            "[account {}][mailbox {}] fetch_new_mail UID range: {}..{} ({} uids)",
+            account.id,
+            mailbox.name,
+            start_uid,
+            uid_list.iter().max().unwrap_or(&0),
+            len
         );
 
         let mut uid_vec: Vec<u32> = uid_list.into_iter().collect();

crates/core/src/store/tantivy/attachment.rs

@@ -155,6 +155,10 @@ impl IndexManager {
                                         pending_count
                                     );
                                     tokio::task::block_in_place(|| fatal_commit(&mut writer));
+                                    tracing::debug!(
+                                        "Tantivy attach: committed {} docs, pending reset to 0",
+                                        pending_count
+                                    );
                                     pending_count = 0;
                                     commit_interval.reset();
                                 }
@@ -172,9 +176,12 @@ impl IndexManager {
                     _ = commit_interval.tick() => {
                         if pending_count > 0 {
                             let mut writer = writer.lock().await;
+                            tracing::debug!(
+                                "Tantivy attach: periodic commit ({} docs pending)",
+                                pending_count
+                            );
                             tokio::task::block_in_place(|| fatal_commit(&mut writer));
                             pending_count = 0;
-                            tracing::debug!("Tantivy: Periodic commit finished.");
                         }
                     }
                     _ = shutdown.recv() => {

crates/core/src/store/tantivy/dedup.rs

@@ -255,11 +255,22 @@ fn dedup_account(
         // uidvalidity, which is required for correct incremental sync.
         entries.sort_by_key(|e| std::cmp::Reverse(e.ingest_at));
 
-        eprintln!(
+        tracing::debug!(
-            "DEBUG Phase2: key={_key:?} kept={} deleting={}",
+            "dedup: account={} mailbox={} hash={}: {} copies, keeping eid={} ingest_at={}, deleting {}",
-            entries[0].email_id,
+            account_id,
+            _key.0,
+            &_key.1,
+            entries.len(),
+            &entries[0].email_id,
+            entries[0].ingest_at,
             entries.len() - 1
         );
+
+        // eprintln!(
+        //     "DEBUG Phase2: key={_key:?} kept={} deleting={}",
+        //     entries[0].email_id,
+        //     entries.len() - 1
+        // );
         // Keep entries[0], soft-delete everything else via term query on f_id
         for entry in &entries[1..] {
             eprintln!(

crates/core/src/store/tantivy/envelope.rs

@@ -170,6 +170,10 @@ impl IndexManager {
                                         pending_count
                                     );
                                     tokio::task::block_in_place(|| fatal_commit(&mut writer));
+                                    tracing::debug!(
+                                        "Tantivy: committed {} docs, pending reset to 0",
+                                        pending_count
+                                    );
                                     pending_count = 0;
                                     commit_interval.reset();
                                 }
@@ -187,9 +191,12 @@ impl IndexManager {
                     _ = commit_interval.tick() => {
                         if pending_count > 0 {
                             let mut writer = writer.lock().await;
+                            tracing::debug!(
+                                "Tantivy: periodic commit ({} docs pending)",
+                                pending_count
+                            );
                             tokio::task::block_in_place(|| fatal_commit(&mut writer));
                             pending_count = 0;
-                            tracing::debug!("Tantivy: Periodic commit finished.");
                         }
                     }
                     _ = shutdown.recv() => {
@@ -690,7 +697,15 @@ impl IndexManager {
         let agg_res = searcher
             .search(query.as_ref(), &collector)
             .map_err(|e| raise_error!(format!("{:#?}", e), ErrorCode::InternalError))?;
-        Ok(Self::extract_max_uid(&agg_res))
+        let result = Self::extract_max_uid(&agg_res);
+        tracing::debug!(
+            "[account {}][mailbox {}] get_max_uid = {:?} (num_docs in searcher = {})",
+            account_id,
+            mailbox_id,
+            result,
+            searcher.num_docs()
+        );
+        Ok(result)
     }
 
     pub fn get_account_stats(&self, account_id: u64) -> BichonResult<AccountStats> {