diff --git a/Cargo.lock b/Cargo.lock index b4131eb..0e23603 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2626,6 +2626,7 @@ dependencies = [ "tokio-rustls", "tokio-stream", "tracing", + "tracing-test", "webpki-roots", "wiremock", ] @@ -4744,6 +4745,27 @@ dependencies = [ "tracing-serde", ] +[[package]] +name = "tracing-test" +version = "0.2.6" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "19a4c448db514d4f24c5ddb9f73f2ee71bfb24c526cf0c570ba142d1119e0051" +dependencies = [ + "tracing-core", + "tracing-subscriber", + "tracing-test-macro", +] + +[[package]] +name = "tracing-test-macro" +version = "0.2.6" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ad06847b7afb65c7866a36664b75c40b895e318cea4f71299f013fb22965329d" +dependencies = [ + "quote", + "syn 2.0.119", +] + [[package]] name = "try-lock" version = "0.2.5" diff --git a/crates/nuncio-mail/Cargo.toml b/crates/nuncio-mail/Cargo.toml index 644a401..1045a59 100644 --- a/crates/nuncio-mail/Cargo.toml +++ b/crates/nuncio-mail/Cargo.toml @@ -31,6 +31,7 @@ reqwest.workspace = true [dev-dependencies] tempfile.workspace = true wiremock.workspace = true +tracing-test = "0.2" # `test-util` (not in tokio's `full`) enables paused-clock tests so the # bounded per-item FETCH timeout can be asserted without a real-time wait. tokio = { workspace = true, features = ["test-util"] } diff --git a/crates/nuncio-mail/src/imap.rs b/crates/nuncio-mail/src/imap.rs index e022380..2de83f7 100644 --- a/crates/nuncio-mail/src/imap.rs +++ b/crates/nuncio-mail/src/imap.rs @@ -716,6 +716,11 @@ impl ImapEngine { /// 2. Each queue is drained in explicit UID-set batches of at most /// `batch_size`, so the full bodies held in memory at once never exceed /// one batch. + #[tracing::instrument( + skip(self, session), + fields(account_id = %self.account_id, folder_id = %folder_id), + err + )] async fn sync_folder_messages_batched( &self, folder_id: &str, @@ -770,10 +775,12 @@ impl ImapEngine { let mut max_uid_seen: u32 = 0; let mut body_uids: Vec = Vec::new(); let mut oversized_uids: Vec = Vec::new(); + let mut skipped_no_uid: usize = 0; for item in &enumeration { // A message with no UID cannot be addressed by a follow-up fetch, // so it is skipped rather than issued a UID-less request. let Some(uid) = item.uid.filter(|u| *u >= 1) else { + skipped_no_uid += 1; continue; }; max_uid_seen = max_uid_seen.max(uid); @@ -857,6 +864,15 @@ impl ImapEngine { .unwrap_or_else(|| "full-resync-required".to_string()), }; + tracing::info!( + account_id = %self.account_id, + folder_id, + fetched = emails.len(), + oversized = oversized_uids.len(), + skipped = skipped_no_uid, + "imap folder sync complete" + ); + Ok((emails, new_checkpoint)) } @@ -1066,19 +1082,50 @@ impl ImapEngine { // Refuse to act unless the mailbox's current UIDVALIDITY provably // matches the one the stored UID was captured under. let stored_validity = parse_uid_validity(&spec.uid_validity); - match (stored_validity, mailbox.uid_validity) { - (Some(stored), Some(current)) if stored == current => {} - (stored, current) => { - return Err(MailError::ImapError(format!( - "refusing to mutate message '{}' in folder '{}': UIDVALIDITY guard failed \ - (stored {stored:?}, current {current:?}); the stored UID may no longer \ - address the intended message", - spec.message_id, spec.folder_id - ))); - } - } + let guard_passed = matches!( + (stored_validity, mailbox.uid_validity), + (Some(stored), Some(current)) if stored == current + ); let uid_set = uid.to_string(); + + // Every destructive op (MOVE, DELETE -- which issues STORE \Deleted + // followed by a UID-scoped EXPUNGE) is logged BEFORE any command is + // sent to the server, so an audit trail exists even when the + // UIDVALIDITY guard below then refuses to proceed. + match &spec.kind { + RemoteMutationKind::Move { to_folder } => { + tracing::info!( + op = "MOVE", + folder_id = %spec.folder_id, + to_folder = %to_folder, + uid_set = %uid_set, + uidvalidity_guard_passed = guard_passed, + "issuing destructive IMAP MOVE" + ); + } + RemoteMutationKind::Delete => { + tracing::warn!( + op = "DELETE", + folder_id = %spec.folder_id, + uid_set = %uid_set, + uidvalidity_guard_passed = guard_passed, + "issuing destructive IMAP DELETE (STORE \\Deleted + UID-scoped EXPUNGE)" + ); + } + RemoteMutationKind::SetFlagged { .. } | RemoteMutationKind::Copy { .. } => {} + } + + if !guard_passed { + let current_validity = mailbox.uid_validity; + return Err(MailError::ImapError(format!( + "refusing to mutate message '{}' in folder '{}': UIDVALIDITY guard failed \ + (stored {stored_validity:?}, current {current_validity:?}); the stored UID may \ + no longer address the intended message", + spec.message_id, spec.folder_id + ))); + } + match &spec.kind { RemoteMutationKind::SetFlagged { value } => { let op = if *value { "+FLAGS" } else { "-FLAGS" }; @@ -1336,6 +1383,7 @@ impl ImapEngine { #[async_trait] impl MailBackend for ImapEngine { + #[tracing::instrument(skip(self), fields(account_id = %self.account_id), err)] async fn sync_folders(&self) -> Result, MailError> { let (u, p) = match (&self.username, &self.password) { (Some(u), Some(p)) => (u.as_str(), p.as_str()), @@ -1365,6 +1413,11 @@ impl MailBackend for ImapEngine { } drop(mailboxes); let _ = session.logout().await; + tracing::info!( + account_id = %self.account_id, + folders = folders.len(), + "imap folder list sync complete" + ); // An empty mailbox is a genuine result, not a signal to fall back to // placeholder folders -- the caller gets exactly what the server reported. Ok(folders) @@ -1386,6 +1439,7 @@ impl MailBackend for ImapEngine { #[cfg(test)] mod tests { use super::*; + use tracing_test::traced_test; #[tokio::test] async fn imap_dual_socket_manager_lifecycle() -> Result<(), MailError> { @@ -2510,6 +2564,121 @@ mod tests { Ok(()) } + #[traced_test] + #[tokio::test] + async fn imap_destructive_delete_logs_before_issuing_even_when_uidvalidity_guard_fails() { + // The stored checkpoint's UIDVALIDITY (1) does not match the scripted + // server's current UIDVALIDITY (2), so the UIDVALIDITY guard MUST + // refuse the mutation and no protocol command may reach the server + // (proven below via `commands`). A WARN log naming the op, the target + // UID set, and the failed guard result must still exist -- proving the + // pre-log fires before dispatch, not merely on a successful path. + let (result, commands) = run_scripted_mutation( + &imap_spec(RemoteMutationKind::Delete, Some("1:105")), + false, + true, + 2, + ) + .await; + + let err = result.expect_err("a UIDVALIDITY mismatch must be refused"); + assert!(matches!(err, MailError::ImapError(_))); + assert!( + !commands.iter().any(|c| { + let u = c.to_ascii_uppercase(); + u.contains("STORE") || u.contains("EXPUNGE") || u.contains("COPY") + }), + "no mutating command may be issued on a guard failure, got: {commands:?}" + ); + + assert!(logs_contain("issuing destructive IMAP DELETE")); + assert!(logs_contain("uid_set=42")); + assert!(logs_contain("uidvalidity_guard_passed=false")); + } + + #[traced_test] + #[tokio::test] + async fn imap_destructive_move_logs_before_issuing_with_uid_set_and_passing_guard() { + // A guard-passing MOVE still logs before the command is issued, at + // INFO (MOVE is reversible/non-permanent, unlike DELETE/EXPUNGE). + let (result, _commands) = run_scripted_mutation( + &imap_spec( + RemoteMutationKind::Move { + to_folder: "Archive".to_string(), + }, + Some("1:105"), + ), + true, + true, + 1, + ) + .await; + result.expect("move mutation succeeds"); + + assert!(logs_contain("issuing destructive IMAP MOVE")); + assert!(logs_contain("uid_set=42")); + assert!(logs_contain("uidvalidity_guard_passed=true")); + } + + #[traced_test] + #[tokio::test] + async fn imap_folder_sync_logs_completion_counts() { + // A folder sync run must log its completion counts (fetched, and by + // extension the oversized/skipped counters this run does not + // exercise), so an operator can see sync outcomes without a debugger. + let (client_io, server_io) = tokio::io::duplex(8192); + let server = tokio::spawn(async move { + let mut io = server_io; + while let Some(line) = read_scripted_line(&mut io).await { + let tag = line.split_whitespace().next().unwrap_or("").to_string(); + let upper = line.to_ascii_uppercase(); + if upper.contains("LOGIN") { + let _ = io + .write_all(format!("{tag} OK Logged in\r\n").as_bytes()) + .await; + } else if upper.contains("SELECT") { + let resp = format!( + "* FLAGS (\\Seen)\r\n* 0 EXISTS\r\n* 0 RECENT\r\n\ + * OK [UIDVALIDITY 1] ok\r\n* OK [UIDNEXT 1] ok\r\n\ + {tag} OK [READ-WRITE] SELECT done\r\n" + ); + let _ = io.write_all(resp.as_bytes()).await; + } else if upper.contains("UID FETCH") { + let _ = io + .write_all(format!("{tag} OK FETCH completed\r\n").as_bytes()) + .await; + } else if upper.contains("LOGOUT") { + let _ = io + .write_all(format!("* BYE\r\n{tag} OK LOGOUT\r\n").as_bytes()) + .await; + break; + } + } + }); + + let client = async_imap::Client::new(client_io); + let mut session = client + .login("user", "pass") + .await + .map_err(|(e, _)| e) + .expect("scripted login succeeds"); + let engine = ImapEngine::new("acct-completion", "example.test", 993); + + let (emails, _checkpoint) = engine + .sync_folder_messages_with_session("INBOX", None, &mut session) + .await + .expect("sync succeeds"); + assert!(emails.is_empty()); + + drop(session); + let _ = server.await; + + assert!(logs_contain("imap folder sync complete")); + assert!(logs_contain("fetched=0")); + assert!(logs_contain("oversized=0")); + assert!(logs_contain("skipped=0")); + } + #[test] fn imap_fetch_command_query_construction() { let query = build_fetch_command_query(); diff --git a/crates/nuncio-mail/src/jmap.rs b/crates/nuncio-mail/src/jmap.rs index cfbc0fa..80319b7 100644 --- a/crates/nuncio-mail/src/jmap.rs +++ b/crates/nuncio-mail/src/jmap.rs @@ -524,6 +524,7 @@ impl JmapEngine { #[async_trait] impl MailBackend for JmapEngine { + #[tracing::instrument(skip(self), fields(account_id = %self.account_id), err)] async fn sync_folders(&self) -> Result, MailError> { if !self.has_credentials() { return Err(MailError::AuthError( @@ -536,7 +537,7 @@ impl MailBackend for JmapEngine { let raw = self.post_jmap(&session.api_url, &request).await?; let mailboxes = Self::parse_mailbox_get_response(&raw)?; - Ok(mailboxes + let folders: Vec = mailboxes .into_iter() .map(|mb| Folder { id: mb.id, @@ -544,9 +545,22 @@ impl MailBackend for JmapEngine { total_messages: mb.total_emails as usize, unread_messages: mb.unread_emails as usize, }) - .collect()) + .collect(); + + tracing::info!( + account_id = %self.account_id, + folders = folders.len(), + "jmap folder list sync complete" + ); + + Ok(folders) } + #[tracing::instrument( + skip(self, _since_state), + fields(account_id = %self.account_id, folder_id = %folder_id), + err + )] async fn sync_messages( &self, folder_id: &str, @@ -566,15 +580,50 @@ impl MailBackend for JmapEngine { let get_request = Self::build_email_get_request(&account_id, Some(ids)); let get_raw = self.post_jmap(&session.api_url, &get_request).await?; - self.parse_email_get_response(&get_raw) + let (emails, state) = self.parse_email_get_response(&get_raw)?; + + tracing::info!( + account_id = %self.account_id, + folder_id, + fetched = emails.len(), + "jmap message sync complete" + ); + + Ok((emails, state)) } + #[tracing::instrument(skip(self), fields(account_id = %self.account_id), err)] async fn apply_mutation(&self, spec: &RemoteMutationSpec) -> Result<(), MailError> { if !self.has_credentials() { return Err(MailError::AuthError( "JMAP remote mutation requires credentials".to_string(), )); } + + // JMAP has no UIDVALIDITY-equivalent guard (an `Email/set` targets a + // stable object id per RFC 8621), but a destructive mutation is still + // logged BEFORE the request is issued, mirroring the IMAP audit trail. + match &spec.kind { + RemoteMutationKind::Move { to_folder } => { + tracing::info!( + op = "MOVE", + folder_id = %spec.folder_id, + to_folder = %to_folder, + remote_id = %spec.remote_id, + "issuing destructive JMAP mailbox move (Email/set update)" + ); + } + RemoteMutationKind::Delete => { + tracing::warn!( + op = "DELETE", + folder_id = %spec.folder_id, + remote_id = %spec.remote_id, + "issuing destructive JMAP delete (Email/set destroy)" + ); + } + RemoteMutationKind::SetFlagged { .. } | RemoteMutationKind::Copy { .. } => {} + } + let session = self.discover_session().await?; let account_id = self.resolve_account_id(&session); diff --git a/crates/nuncio-mail/src/smtp.rs b/crates/nuncio-mail/src/smtp.rs index 9cef1f0..894ae6c 100644 --- a/crates/nuncio-mail/src/smtp.rs +++ b/crates/nuncio-mail/src/smtp.rs @@ -88,21 +88,49 @@ impl SmtpTransportEngine { /// Send a composed [`OutboundMessage`] using the inner transport client. /// Returns `Ok(())` only when the transport genuinely accepted the - /// message. + /// message. Logs the send attempt and outcome with the recipient COUNT + /// only (`to` plus `cc` when present) -- never the addresses themselves. pub async fn send_message(&self, message: &OutboundMessage) -> Result<(), MailError> { + let recipient_count = + 1 + usize::from(message.cc.as_ref().is_some_and(|cc| !cc.trim().is_empty())); + tracing::info!(recipient_count, "smtp send attempt"); + let msg = Self::build_outbound_mime_message(message)?; - self.transport.send(msg).await.map_err(MailError::from)?; - Ok(()) + match self.transport.send(msg).await { + Ok(_) => { + tracing::info!(recipient_count, "smtp send succeeded"); + Ok(()) + } + Err(e) => { + let err = MailError::from(e); + tracing::warn!(recipient_count, error = %err, "smtp send failed"); + Err(err) + } + } } - /// Send an email message using a provided [`AsyncSmtpTransport`] client instance. + /// Send an email message using a provided [`AsyncSmtpTransport`] client + /// instance. Logs the send attempt and outcome with the recipient COUNT + /// only -- never the address itself. pub async fn send_email_with_transport( transport: &AsyncSmtpTransport, email: &Email, ) -> Result<(), MailError> { + let recipient_count = 1; + tracing::info!(recipient_count, "smtp send attempt"); + let msg = Self::build_mime_message(email)?; - transport.send(msg).await.map_err(MailError::from)?; - Ok(()) + match transport.send(msg).await { + Ok(_) => { + tracing::info!(recipient_count, "smtp send succeeded"); + Ok(()) + } + Err(e) => { + let err = MailError::from(e); + tracing::warn!(recipient_count, error = %err, "smtp send failed"); + Err(err) + } + } } /// Build an RFC 5322 [`lettre::Message`] from a Nuncio [`Email`] entity. @@ -323,6 +351,7 @@ mod tests { use super::*; use bytes::Bytes; use nuncio_core::model::Attachment; + use tracing_test::traced_test; fn sample_email() -> Email { Email { @@ -608,6 +637,28 @@ mod tests { )); } + #[traced_test] + #[tokio::test] + async fn send_message_logs_attempt_and_failure_with_recipient_count_never_addresses() { + let engine = SmtpTransportEngine::new("127.0.0.1", 1, TlsMode::ImplicitTls, "user", "pass") + .expect("valid config"); + let mut message = sample_outbound_message(); + message.cc = Some("carol@nuncio.mx".to_string()); + let _ = engine + .send_message(&message) + .await + .expect_err("delivery to port 1 should fail"); + + assert!(logs_contain("smtp send attempt")); + assert!(logs_contain("recipient_count=2")); + assert!(logs_contain("smtp send failed")); + + assert!(!logs_contain("alice@nuncio.mx")); + assert!(!logs_contain("bob@nuncio.mx")); + assert!(!logs_contain("carol@nuncio.mx")); + assert!(!logs_contain("Status Update")); + } + #[tokio::test] async fn message_sender_trait_impl_delegates_to_send_message() { // Proves `SmtpTransportEngine`'s `MessageSender` trait impl is wired