Cargo.lock

@@ -2507,6 +2507,7 @@ dependencies = [
  "thiserror 1.0.69",
  "tokio",
  "tracing",
+ "tracing-subscriber",
  "wiremock",
 ]
 
@@ -2552,6 +2553,7 @@ dependencies = [
  "thiserror 1.0.69",
  "tokio",
  "tracing",
+ "tracing-subscriber",
  "wiremock",
 ]
 

crates/nuncio-cal/Cargo.toml

@@ -26,3 +26,4 @@ quick-xml.workspace = true
 [dev-dependencies]
 tempfile.workspace = true
 wiremock.workspace = true
+tracing-subscriber.workspace = true

crates/nuncio-cal/src/caldav.rs

@@ -3,6 +3,7 @@
 use async_trait::async_trait;
 use nuncio_core::model::CalendarEvent;
 use serde::{Deserialize, Serialize};
+use tracing::{debug, info, instrument, warn};
 
 use crate::backend::CalendarBackend;
 use crate::parser::{CalendarError, IcalParserAdapter};
@@ -13,7 +14,7 @@ use crate::parser::{CalendarError, IcalParserAdapter};
 /// `caldav_url` must already resolve to a specific calendar collection (e.g.
 /// `https://caldav.example.com/dav/calendars/user/jmaes/work/`) -- PROPFIND-based
 /// `calendar-home-set` auto-discovery is out of scope for this client.
-#[derive(Debug, Clone, Serialize, Deserialize)]
+#[derive(Clone, Serialize, Deserialize)]
 pub struct CalDavAccountConfig {
     /// Nuncio account identifier this calendar collection belongs to.
     pub account_id: String,
@@ -26,6 +27,36 @@ pub struct CalDavAccountConfig {
     pub auth_token: String,
 }
 
+impl std::fmt::Debug for CalDavAccountConfig {
+    /// Manual `Debug` impl that redacts `auth_token` -- a derived impl would print the raw
+    /// secret verbatim the moment anything (a `debug!` log, an assertion failure message,
+    /// a panic payload) formats this config with `{:?}`.
+    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+        f.debug_struct("CalDavAccountConfig")
+            .field("account_id", &self.account_id)
+            .field("caldav_url", &self.caldav_url)
+            .field("username", &self.username)
+            .field("auth_token", &"<redacted>")
+            .finish()
+    }
+}
+
+/// Best-effort extraction of the `UID` property from a raw (possibly malformed) VEVENT/
+/// VCALENDAR block, used only to correlate a dropped-VEVENT log line with the source event --
+/// never returns the summary, attendees, description, or any other calendar content.
+fn extract_vevent_uid(raw_ics: &str) -> Option<String> {
+    raw_ics.lines().find_map(|line| {
+        let line = line.trim();
+        let (name, value) = line.split_once(':')?;
+        let bare_name = name.split(';').next().unwrap_or(name);
+        if bare_name.eq_ignore_ascii_case("UID") {
+            Some(value.trim().to_string())
+        } else {
+            None
+        }
+    })
+}
+
 /// CalDAV client protocol engine managing WebDAV REPORT queries against a real server.
 pub struct CalDavClient {
     config: CalDavAccountConfig,
@@ -66,32 +97,59 @@ impl CalDavClient {
     }
 
     /// Parse CalDAV WebDAV XML `<multistatus>` response containing embedded VEVENT data.
+    ///
+    /// A VEVENT block that fails to parse is dropped from the returned events but never
+    /// silently: it is logged at `warn` (with its UID, if extractable, and a short parse-error
+    /// reason -- never the raw VEVENT body) so a sync that quietly lost calendar data is
+    /// visible in telemetry instead of just showing up as a smaller-than-expected event count.
     pub fn parse_multistatus_response(
         &self,
         calendar_id: &str,
         raw_xml: &str,
     ) -> Result<Vec<CalendarEvent>, CalendarError> {
+        let (events, _dropped) = self.parse_multistatus_response_counted(calendar_id, raw_xml);
+        Ok(events)
+    }
+
+    /// Same parse as [`Self::parse_multistatus_response`], additionally reporting how many
+    /// VEVENT blocks were dropped as unparseable so callers can log round-trip counts.
+    fn parse_multistatus_response_counted(
+        &self,
+        calendar_id: &str,
+        raw_xml: &str,
+    ) -> (Vec<CalendarEvent>, usize) {
         let mut events = Vec::new();
+        let mut dropped = 0usize;
 
         // Extract <c:calendar-data> or <calendar-data> text blocks
         for block in raw_xml.split("<c:calendar-data>") {
             if let Some((ics_data, _)) = block.split_once("</c:calendar-data>") {
                 let clean_ics = ics_data.trim();
                 if !clean_ics.is_empty() {
-                    let event_id = format!("caldav-evt-{}", events.len() + 1);
-                    if let Ok(event) = IcalParserAdapter::parse_ical(
+                    let event_id = format!("caldav-evt-{}", events.len() + dropped + 1);
+                    match IcalParserAdapter::parse_ical(
                         &event_id,
                         &self.config.account_id,
                         calendar_id,
                         clean_ics,
                     ) {
-                        events.push(event);
+                        Ok(event) => events.push(event),
+                        Err(err) => {
+                            dropped += 1;
+                            warn!(
+                                account_id = %self.config.account_id,
+                                calendar_id = %calendar_id,
+                                uid = %extract_vevent_uid(clean_ics).unwrap_or_else(|| "unknown".to_string()),
+                                reason = %err,
+                                "dropped unparseable VEVENT"
+                            );
+                        }
                     }
                 }
             }
         }
 
-        Ok(events)
+        (events, dropped)
     }
 
     /// Format a unix timestamp as the `YYYYMMDDTHHMMSSZ` form RFC 4791's
@@ -113,6 +171,11 @@ impl CalDavClient {
     /// returned. A server or network failure surfaces as [`CalendarError::TransportFailed`];
     /// a malformed TZID inside a returned VEVENT surfaces as
     /// [`CalendarError::UnresolvableTimezone`] via [`IcalParserAdapter::parse_ical`].
+    #[instrument(
+        name = "caldav_sync",
+        skip(self),
+        fields(account_id = %self.config.account_id, calendar_id = %calendar_id)
+    )]
     pub async fn fetch_remote_events(
         &self,
         calendar_id: &str,
@@ -128,6 +191,12 @@ impl CalDavClient {
         let report_method = reqwest::Method::from_bytes(b"REPORT")
             .map_err(|e| CalendarError::TransportFailed(format!("invalid HTTP method: {e}")))?;
 
+        debug!(
+            account_id = %self.config.account_id,
+            calendar_id = %calendar_id,
+            "issuing CalDAV REPORT calendar-query"
+        );
+
         let response = self
             .http
             .request(report_method, &self.config.caldav_url)
@@ -153,7 +222,17 @@ impl CalDavClient {
             .await
             .map_err(|e| CalendarError::TransportFailed(e.to_string()))?;
 
-        self.parse_multistatus_response(calendar_id, &raw_xml)
+        let (events, dropped) = self.parse_multistatus_response_counted(calendar_id, &raw_xml);
+        info!(
+            account_id = %self.config.account_id,
+            calendar_id = %calendar_id,
+            fetched = events.len() + dropped,
+            parsed = events.len(),
+            dropped,
+            "completed CalDAV sync"
+        );
+
+        Ok(events)
     }
 }
 
@@ -221,10 +300,165 @@ END:VCALENDAR</c:calendar-data>
         assert_eq!(events[0].location, Some("Boardroom".to_string()));
     }
 
+    #[test]
+    fn parse_multistatus_response_surfaces_a_warn_for_a_dropped_vevent_instead_of_silence() {
+        use crate::test_tracing::with_recorder;
+
+        let client = CalDavClient::new(test_config());
+        // A TZID that cannot be resolved to a real IANA zone; the VEVENT fails to parse but
+        // the one alongside it (plain UTC) must still come through.
+        let xml_response = r#"<?xml version="1.0" encoding="utf-8"?>
+        <d:multistatus xmlns:d="DAV:" xmlns:c="urn:ietf:params:xml:ns:caldav">
+            <d:response>
+                <d:propstat>
+                    <d:prop>
+                        <c:calendar-data>BEGIN:VCALENDAR
+VERSION:2.0
+BEGIN:VEVENT
+UID:evt-unresolvable-tzid
+SUMMARY:Confidential Merger Talks
+DTSTART;TZID=Not/ARealZone:20240101T090000
+DTEND;TZID=Not/ARealZone:20240101T100000
+END:VEVENT
+END:VCALENDAR</c:calendar-data>
+                    </d:prop>
+                </d:propstat>
+            </d:response>
+            <d:response>
+                <d:propstat>
+                    <d:prop>
+                        <c:calendar-data>BEGIN:VCALENDAR
+VERSION:2.0
+BEGIN:VEVENT
+SUMMARY:Good Event
+DTSTART:20240301T120000Z
+DTEND:20240301T130000Z
+END:VEVENT
+END:VCALENDAR</c:calendar-data>
+                    </d:prop>
+                </d:propstat>
+            </d:response>
+        </d:multistatus>"#;
+
+        let (recorder, result) =
+            with_recorder(|| client.parse_multistatus_response("cal-work", xml_response));
+        let events = result.expect("the unparseable VEVENT is dropped, not fatal");
+        assert_eq!(events.len(), 1);
+        assert_eq!(events[0].summary, "Good Event");
+
+        let warnings: Vec<_> = recorder
+            .events()
+            .into_iter()
+            .filter(|e| e.level == tracing::Level::WARN)
+            .collect();
+        assert_eq!(warnings.len(), 1, "exactly one VEVENT should be dropped");
+        assert_eq!(
+            warnings[0].fields.get("uid").map(String::as_str),
+            Some("evt-unresolvable-tzid")
+        );
+        assert!(warnings[0].message().contains("dropped"));
+
+        // The dropped VEVENT's summary (potential PII) must never appear in telemetry.
+        for value in recorder.all_field_values() {
+            assert!(!value.contains("Confidential Merger Talks"));
+        }
+    }
+
     #[test]
     fn format_query_timestamp_produces_ical_utc_form() {
         let formatted =
             CalDavClient::format_query_timestamp(1_704_067_200).expect("valid timestamp");
         assert_eq!(formatted, "20240101T000000Z");
     }
+
+    #[test]
+    fn debug_impl_redacts_auth_token() {
+        let config = test_config();
+        let rendered = format!("{config:?}");
+        assert!(!rendered.contains("app-token-secret"));
+        assert!(rendered.contains("<redacted>"));
+    }
+
+    #[test]
+    fn fetch_remote_events_logs_completion_counts_including_a_drop() {
+        use crate::test_tracing::with_recorder;
+        use wiremock::matchers::{method, path};
+        use wiremock::{Mock, MockServer, ResponseTemplate};
+
+        let runtime = tokio::runtime::Builder::new_current_thread()
+            .enable_all()
+            .build()
+            .expect("current-thread runtime");
+
+        let (recorder, result) = with_recorder(|| {
+            runtime.block_on(async {
+                let mock_server = MockServer::start().await;
+                let xml_response = r#"<?xml version="1.0" encoding="utf-8"?>
+        <d:multistatus xmlns:d="DAV:" xmlns:c="urn:ietf:params:xml:ns:caldav">
+            <d:response>
+                <d:propstat>
+                    <d:prop>
+                        <c:calendar-data>BEGIN:VCALENDAR
+VERSION:2.0
+BEGIN:VEVENT
+UID:evt-bad
+DTSTART;TZID=Not/ARealZone:20240101T090000
+END:VEVENT
+END:VCALENDAR</c:calendar-data>
+                    </d:prop>
+                </d:propstat>
+            </d:response>
+            <d:response>
+                <d:propstat>
+                    <d:prop>
+                        <c:calendar-data>BEGIN:VCALENDAR
+VERSION:2.0
+BEGIN:VEVENT
+SUMMARY:Good Event
+DTSTART:20240301T120000Z
+DTEND:20240301T130000Z
+END:VEVENT
+END:VCALENDAR</c:calendar-data>
+                    </d:prop>
+                </d:propstat>
+            </d:response>
+        </d:multistatus>"#;
+
+                Mock::given(method("REPORT"))
+                    .and(path("/calendars/work/"))
+                    .respond_with(ResponseTemplate::new(207).set_body_string(xml_response))
+                    .mount(&mock_server)
+                    .await;
+
+                let mut config = test_config();
+                config.caldav_url = format!("{}/calendars/work/", mock_server.uri());
+                let client = CalDavClient::new(config);
+
+                client
+                    .fetch_remote_events("cal-work", 1_700_000_000, 1_800_000_000)
+                    .await
+            })
+        });
+
+        let events = result.expect("one good VEVENT still comes through");
+        assert_eq!(events.len(), 1);
+
+        let completion = recorder
+            .events()
+            .into_iter()
+            .find(|e| e.message().contains("completed CalDAV sync"))
+            .expect("a completion event is logged");
+        assert_eq!(
+            completion.fields.get("fetched").map(String::as_str),
+            Some("2")
+        );
+        assert_eq!(
+            completion.fields.get("parsed").map(String::as_str),
+            Some("1")
+        );
+        assert_eq!(
+            completion.fields.get("dropped").map(String::as_str),
+            Some("1")
+        );
+    }
 }

crates/nuncio-cal/src/lib.rs

@@ -11,6 +11,8 @@ pub mod nlp;
 pub mod parser;
 pub mod rrule;
 pub mod scheduling;
+#[cfg(test)]
+mod test_tracing;
 
 pub use backend::CalendarBackend;
 pub use caldav::{CalDavAccountConfig, CalDavClient};

crates/nuncio-cal/src/test_tracing.rs

@@ -0,0 +1,134 @@
+//! Shared in-test `tracing` capture helper.
+//!
+//! Installs a thread-local subscriber that records every span (with its
+//! fields) and every event (with its level, fields, and message) into an
+//! in-memory buffer, so tests can assert on what the code logged -- including
+//! the negative assertion that a secret never appears in any recorded field.
+//! Deterministic and fully offline: no global subscriber, no I/O.
+
+#![cfg(test)]
+
+use std::collections::HashMap;
+use std::sync::{Arc, Mutex};
+
+use tracing::field::{Field, Visit};
+use tracing::span::Attributes;
+use tracing::{Event, Id, Level, Subscriber};
+use tracing_subscriber::layer::Context as LayerContext;
+use tracing_subscriber::prelude::*;
+use tracing_subscriber::registry::LookupSpan;
+
+/// A captured span: its name and the string-rendered fields it opened with.
+#[derive(Debug, Clone)]
+pub(crate) struct RecordedSpan {
+    #[allow(dead_code)]
+    pub name: String,
+    pub fields: HashMap<String, String>,
+}
+
+/// A captured event: its level and its string-rendered fields (including the
+/// `message`).
+#[derive(Debug, Clone)]
+pub(crate) struct RecordedEvent {
+    pub level: Level,
+    pub fields: HashMap<String, String>,
+}
+
+impl RecordedEvent {
+    /// The event's `message` field, or the empty string if it had none.
+    pub fn message(&self) -> &str {
+        self.fields.get("message").map(String::as_str).unwrap_or("")
+    }
+}
+
+/// In-memory sink of everything the subscriber captured during a test.
+#[derive(Debug, Default)]
+pub(crate) struct Recorder {
+    spans: Mutex<Vec<RecordedSpan>>,
+    events: Mutex<Vec<RecordedEvent>>,
+}
+
+impl Recorder {
+    /// A snapshot of every captured span.
+    pub fn spans(&self) -> Vec<RecordedSpan> {
+        self.spans.lock().unwrap_or_else(|e| e.into_inner()).clone()
+    }
+
+    /// A snapshot of every captured event.
+    pub fn events(&self) -> Vec<RecordedEvent> {
+        self.events
+            .lock()
+            .unwrap_or_else(|e| e.into_inner())
+            .clone()
+    }
+
+    /// Every field value recorded across all spans and events, so a test can
+    /// assert that a secret never appears anywhere in the telemetry.
+    pub fn all_field_values(&self) -> Vec<String> {
+        let mut values = Vec::new();
+        for span in self.spans().iter() {
+            values.extend(span.fields.values().cloned());
+        }
+        for event in self.events().iter() {
+            values.extend(event.fields.values().cloned());
+        }
+        values
+    }
+}
+
+struct FieldVisitor(HashMap<String, String>);
+
+impl Visit for FieldVisitor {
+    fn record_str(&mut self, field: &Field, value: &str) {
+        self.0.insert(field.name().to_string(), value.to_string());
+    }
+    fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) {
+        self.0
+            .entry(field.name().to_string())
+            .or_insert_with(|| format!("{value:?}"));
+    }
+}
+
+struct CaptureLayer(Arc<Recorder>);
+
+impl<S> tracing_subscriber::Layer<S> for CaptureLayer
+where
+    S: Subscriber + for<'a> LookupSpan<'a>,
+{
+    fn on_new_span(&self, attrs: &Attributes<'_>, _id: &Id, _ctx: LayerContext<'_, S>) {
+        let mut visitor = FieldVisitor(HashMap::new());
+        attrs.record(&mut visitor);
+        self.0
+            .spans
+            .lock()
+            .unwrap_or_else(|e| e.into_inner())
+            .push(RecordedSpan {
+                name: attrs.metadata().name().to_string(),
+                fields: visitor.0,
+            });
+    }
+
+    fn on_event(&self, event: &Event<'_>, _ctx: LayerContext<'_, S>) {
+        let mut visitor = FieldVisitor(HashMap::new());
+        event.record(&mut visitor);
+        self.0
+            .events
+            .lock()
+            .unwrap_or_else(|e| e.into_inner())
+            .push(RecordedEvent {
+                level: *event.metadata().level(),
+                fields: visitor.0,
+            });
+    }
+}
+
+/// Runs `f` with a thread-local capturing subscriber installed and returns the
+/// recorder alongside `f`'s result. Because the subscriber is thread-local,
+/// any async work driven inside `f` must run on the calling thread (e.g. a
+/// current-thread runtime's `block_on`) for its telemetry to be captured.
+pub(crate) fn with_recorder<T>(f: impl FnOnce() -> T) -> (Arc<Recorder>, T) {
+    let recorder = Arc::new(Recorder::default());
+    let subscriber = tracing_subscriber::registry().with(CaptureLayer(recorder.clone()));
+    let value = tracing::subscriber::with_default(subscriber, f);
+    (recorder, value)
+}

crates/nuncio-contacts/Cargo.toml

@@ -26,3 +26,4 @@ async-trait = { workspace = true }
 [dev-dependencies]
 tempfile = { workspace = true }
 wiremock = { workspace = true }
+tracing-subscriber = { workspace = true }

crates/nuncio-contacts/src/carddav.rs

@@ -3,6 +3,7 @@
 use async_trait::async_trait;
 use serde::{Deserialize, Serialize};
 use thiserror::Error;
+use tracing::{debug, info, instrument};
 
 use crate::backend::ContactsBackend;
 use crate::models::Contact;
@@ -27,7 +28,7 @@ pub enum CardDavError {
 /// `carddav_url` must already resolve to a specific address book collection (e.g.
 /// `https://carddav.example.com/dav/addressbooks/user/jmaes/contacts/`) -- PROPFIND-based
 /// `addressbook-home-set` auto-discovery is out of scope for this client.
-#[derive(Debug, Clone, Serialize, Deserialize)]
+#[derive(Clone, Serialize, Deserialize)]
 pub struct CardDavAccountConfig {
     /// Nuncio account identifier this address book collection belongs to.
     pub account_id: String,
@@ -40,6 +41,20 @@ pub struct CardDavAccountConfig {
     pub auth_token: String,
 }
 
+impl std::fmt::Debug for CardDavAccountConfig {
+    /// Manual `Debug` impl that redacts `auth_token` -- a derived impl would print the raw
+    /// secret verbatim the moment anything (a `debug!` log, an assertion failure message,
+    /// a panic payload) formats this config with `{:?}`.
+    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+        f.debug_struct("CardDavAccountConfig")
+            .field("account_id", &self.account_id)
+            .field("carddav_url", &self.carddav_url)
+            .field("username", &self.username)
+            .field("auth_token", &"<redacted>")
+            .finish()
+    }
+}
+
 /// CardDAV client protocol engine managing address book `REPORT` queries against a real server.
 pub struct CardDavClient {
     config: CardDavAccountConfig,
@@ -100,6 +115,7 @@ impl CardDavClient {
     /// This performs a real network request -- no canned or fabricated data is ever
     /// returned. A server or network failure surfaces as [`CardDavError::TransportFailed`]; a
     /// malformed vCard inside a returned response surfaces as [`CardDavError::ParseFailed`].
+    #[instrument(name = "carddav_sync", skip(self), fields(account_id = %account_id))]
     pub async fn fetch_remote_vcards(
         &self,
         account_id: &str,
@@ -111,6 +127,8 @@ impl CardDavClient {
         let report_method = reqwest::Method::from_bytes(b"REPORT")
             .map_err(|e| CardDavError::TransportFailed(format!("invalid HTTP method: {e}")))?;
 
+        debug!(account_id = %account_id, "issuing CardDAV REPORT addressbook-query");
+
         let response = self
             .http
             .request(report_method, &self.config.carddav_url)
@@ -136,7 +154,19 @@ impl CardDavClient {
             .await
             .map_err(|e| CardDavError::TransportFailed(e.to_string()))?;
 
-        self.parse_multistatus_response(account_id, &raw_xml)
+        // `parse_multistatus_response` fails fast on the first unparseable vCard (unlike the
+        // CalDAV client, which drops individual bad VEVENTs), so a successful return here means
+        // every card that was fetched parsed cleanly -- `dropped` is always 0 on this path.
+        let contacts = self.parse_multistatus_response(account_id, &raw_xml)?;
+        info!(
+            account_id = %account_id,
+            fetched = contacts.len(),
+            parsed = contacts.len(),
+            dropped = 0,
+            "completed CardDAV sync"
+        );
+
+        Ok(contacts)
     }
 }
 
@@ -207,4 +237,83 @@ END:VCARD</card:address-data>
             .expect("parse succeeds");
         assert!(contacts.is_empty());
     }
+
+    #[test]
+    fn debug_impl_redacts_auth_token() {
+        let config = test_config();
+        let rendered = format!("{config:?}");
+        assert!(!rendered.contains("app-token-secret"));
+        assert!(rendered.contains("<redacted>"));
+    }
+
+    #[test]
+    fn fetch_remote_vcards_logs_completion_counts() {
+        use crate::test_tracing::with_recorder;
+        use wiremock::matchers::{method, path};
+        use wiremock::{Mock, MockServer, ResponseTemplate};
+
+        let runtime = tokio::runtime::Builder::new_current_thread()
+            .enable_all()
+            .build()
+            .expect("current-thread runtime");
+
+        let (recorder, result) = with_recorder(|| {
+            runtime.block_on(async {
+                let mock_server = MockServer::start().await;
+                let xml_response = r#"<?xml version="1.0" encoding="utf-8"?>
+        <d:multistatus xmlns:d="DAV:" xmlns:card="urn:ietf:params:xml:ns:carddav">
+            <d:response>
+                <d:propstat>
+                    <d:prop>
+                        <card:address-data>BEGIN:VCARD
+VERSION:4.0
+FN:Alice Dev
+EMAIL:alice@nuncio.mx
+END:VCARD</card:address-data>
+                    </d:prop>
+                </d:propstat>
+            </d:response>
+        </d:multistatus>"#;
+
+                Mock::given(method("REPORT"))
+                    .and(path("/addressbooks/contacts/"))
+                    .respond_with(ResponseTemplate::new(207).set_body_string(xml_response))
+                    .mount(&mock_server)
+                    .await;
+
+                let mut config = test_config();
+                config.carddav_url = format!("{}/addressbooks/contacts/", mock_server.uri());
+                let client = CardDavClient::new(config);
+
+                client.fetch_remote_vcards("acct-1").await
+            })
+        });
+
+        let contacts = result.expect("fetch succeeds against the wiremock server");
+        assert_eq!(contacts.len(), 1);
+
+        let completion = recorder
+            .events()
+            .into_iter()
+            .find(|e| e.message().contains("completed CardDAV sync"))
+            .expect("a completion event is logged");
+        assert_eq!(
+            completion.fields.get("fetched").map(String::as_str),
+            Some("1")
+        );
+        assert_eq!(
+            completion.fields.get("parsed").map(String::as_str),
+            Some("1")
+        );
+        assert_eq!(
+            completion.fields.get("dropped").map(String::as_str),
+            Some("0")
+        );
+
+        // vCard PII must never appear in telemetry.
+        for value in recorder.all_field_values() {
+            assert!(!value.contains("Alice Dev"));
+            assert!(!value.contains("alice@nuncio.mx"));
+        }
+    }
 }

crates/nuncio-contacts/src/lib.rs

@@ -10,6 +10,8 @@ pub mod db;
 pub mod mock;
 pub mod models;
 pub mod parser;
+#[cfg(test)]
+mod test_tracing;
 
 pub use backend::ContactsBackend;
 pub use carddav::{CardDavAccountConfig, CardDavClient, CardDavError};

crates/nuncio-contacts/src/test_tracing.rs

@@ -0,0 +1,135 @@
+//! Shared in-test `tracing` capture helper.
+//!
+//! Installs a thread-local subscriber that records every span (with its
+//! fields) and every event (with its level, fields, and message) into an
+//! in-memory buffer, so tests can assert on what the code logged -- including
+//! the negative assertion that a secret never appears in any recorded field.
+//! Deterministic and fully offline: no global subscriber, no I/O.
+
+#![cfg(test)]
+
+use std::collections::HashMap;
+use std::sync::{Arc, Mutex};
+
+use tracing::field::{Field, Visit};
+use tracing::span::Attributes;
+use tracing::{Event, Id, Level, Subscriber};
+use tracing_subscriber::layer::Context as LayerContext;
+use tracing_subscriber::prelude::*;
+use tracing_subscriber::registry::LookupSpan;
+
+/// A captured span: its name and the string-rendered fields it opened with.
+#[derive(Debug, Clone)]
+pub(crate) struct RecordedSpan {
+    #[allow(dead_code)]
+    pub name: String,
+    pub fields: HashMap<String, String>,
+}
+
+/// A captured event: its level and its string-rendered fields (including the
+/// `message`).
+#[derive(Debug, Clone)]
+pub(crate) struct RecordedEvent {
+    #[allow(dead_code)]
+    pub level: Level,
+    pub fields: HashMap<String, String>,
+}
+
+impl RecordedEvent {
+    /// The event's `message` field, or the empty string if it had none.
+    pub fn message(&self) -> &str {
+        self.fields.get("message").map(String::as_str).unwrap_or("")
+    }
+}
+
+/// In-memory sink of everything the subscriber captured during a test.
+#[derive(Debug, Default)]
+pub(crate) struct Recorder {
+    spans: Mutex<Vec<RecordedSpan>>,
+    events: Mutex<Vec<RecordedEvent>>,
+}
+
+impl Recorder {
+    /// A snapshot of every captured span.
+    pub fn spans(&self) -> Vec<RecordedSpan> {
+        self.spans.lock().unwrap_or_else(|e| e.into_inner()).clone()
+    }
+
+    /// A snapshot of every captured event.
+    pub fn events(&self) -> Vec<RecordedEvent> {
+        self.events
+            .lock()
+            .unwrap_or_else(|e| e.into_inner())
+            .clone()
+    }
+
+    /// Every field value recorded across all spans and events, so a test can
+    /// assert that a secret never appears anywhere in the telemetry.
+    pub fn all_field_values(&self) -> Vec<String> {
+        let mut values = Vec::new();
+        for span in self.spans().iter() {
+            values.extend(span.fields.values().cloned());
+        }
+        for event in self.events().iter() {
+            values.extend(event.fields.values().cloned());
+        }
+        values
+    }
+}
+
+struct FieldVisitor(HashMap<String, String>);
+
+impl Visit for FieldVisitor {
+    fn record_str(&mut self, field: &Field, value: &str) {
+        self.0.insert(field.name().to_string(), value.to_string());
+    }
+    fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) {
+        self.0
+            .entry(field.name().to_string())
+            .or_insert_with(|| format!("{value:?}"));
+    }
+}
+
+struct CaptureLayer(Arc<Recorder>);
+
+impl<S> tracing_subscriber::Layer<S> for CaptureLayer
+where
+    S: Subscriber + for<'a> LookupSpan<'a>,
+{
+    fn on_new_span(&self, attrs: &Attributes<'_>, _id: &Id, _ctx: LayerContext<'_, S>) {
+        let mut visitor = FieldVisitor(HashMap::new());
+        attrs.record(&mut visitor);
+        self.0
+            .spans
+            .lock()
+            .unwrap_or_else(|e| e.into_inner())
+            .push(RecordedSpan {
+                name: attrs.metadata().name().to_string(),
+                fields: visitor.0,
+            });
+    }
+
+    fn on_event(&self, event: &Event<'_>, _ctx: LayerContext<'_, S>) {
+        let mut visitor = FieldVisitor(HashMap::new());
+        event.record(&mut visitor);
+        self.0
+            .events
+            .lock()
+            .unwrap_or_else(|e| e.into_inner())
+            .push(RecordedEvent {
+                level: *event.metadata().level(),
+                fields: visitor.0,
+            });
+    }
+}
+
+/// Runs `f` with a thread-local capturing subscriber installed and returns the
+/// recorder alongside `f`'s result. Because the subscriber is thread-local,
+/// any async work driven inside `f` must run on the calling thread (e.g. a
+/// current-thread runtime's `block_on`) for its telemetry to be captured.
+pub(crate) fn with_recorder<T>(f: impl FnOnce() -> T) -> (Arc<Recorder>, T) {
+    let recorder = Arc::new(Recorder::default());
+    let subscriber = tracing_subscriber::registry().with(CaptureLayer(recorder.clone()));
+    let value = tracing::subscriber::with_default(subscriber, f);
+    (recorder, value)
+}

crates/nuncio-store/src/db.rs

@@ -764,12 +764,22 @@ impl DatabaseEngine {
                 .execute(&mut *tx)
                 .await
                 .map_err(DatabaseError::Query)?;
+            tracing::info!(
+                table = "messages",
+                column = "remote_id",
+                "applying schema migration"
+            );
         }
         if !existing_columns.iter().any(|c| c == "uid_validity") {
             sqlx::query("ALTER TABLE messages ADD COLUMN uid_validity TEXT NOT NULL DEFAULT ''")
                 .execute(&mut *tx)
                 .await
                 .map_err(DatabaseError::Query)?;
+            tracing::info!(
+                table = "messages",
+                column = "uid_validity",
+                "applying schema migration"
+            );
         }
 
         // Seed any legacy row still carrying the empty-string default with a
@@ -823,6 +833,11 @@ impl DatabaseEngine {
             .execute(&self.pool)
             .await
             .map_err(DatabaseError::Query)?;
+            tracing::info!(
+                table = "accounts",
+                column = "imap_tls_mode",
+                "applying schema migration"
+            );
         }
         if !existing_columns.iter().any(|c| c == "smtp_tls_mode") {
             sqlx::query(
@@ -831,6 +846,11 @@ impl DatabaseEngine {
             .execute(&self.pool)
             .await
             .map_err(DatabaseError::Query)?;
+            tracing::info!(
+                table = "accounts",
+                column = "smtp_tls_mode",
+                "applying schema migration"
+            );
         }
 
         Ok(())
@@ -865,12 +885,22 @@ impl DatabaseEngine {
                 .execute(&self.pool)
                 .await
                 .map_err(DatabaseError::Query)?;
+            tracing::info!(
+                table = "accounts",
+                column = "smtp_host",
+                "applying schema migration"
+            );
         }
         if !existing_columns.iter().any(|c| c == "smtp_port") {
             sqlx::query("ALTER TABLE accounts ADD COLUMN smtp_port INTEGER")
                 .execute(&self.pool)
                 .await
                 .map_err(DatabaseError::Query)?;
+            tracing::info!(
+                table = "accounts",
+                column = "smtp_port",
+                "applying schema migration"
+            );
         }
 
         Ok(())
@@ -902,6 +932,11 @@ impl DatabaseEngine {
                 .execute(&self.pool)
                 .await
                 .map_err(DatabaseError::Query)?;
+            tracing::info!(
+                table = "accounts",
+                column = "collection_url",
+                "applying schema migration"
+            );
         }
 
         Ok(())
@@ -3811,6 +3846,107 @@ mod tests {
         engine.close().await;
     }
 
+    /// Applying an additive column migration against a pre-existing (old-schema)
+    /// database must be visible in telemetry -- an `INFO` log naming the table and
+    /// column -- rather than only observable indirectly via the resulting schema.
+    #[tokio::test]
+    async fn migrate_logs_when_an_additive_column_migration_actually_runs() {
+        use std::sync::{Arc, Mutex};
+        use tracing_subscriber::fmt::MakeWriter;
+
+        #[derive(Clone, Default)]
+        struct CapturedLogs(Arc<Mutex<Vec<u8>>>);
+
+        impl std::io::Write for CapturedLogs {
+            fn write(&mut self, buf: &[u8]) -> std::io::Result<usize> {
+                self.0
+                    .lock()
+                    .expect("log buffer lock")
+                    .extend_from_slice(buf);
+                Ok(buf.len())
+            }
+            fn flush(&mut self) -> std::io::Result<()> {
+                Ok(())
+            }
+        }
+
+        impl<'a> MakeWriter<'a> for CapturedLogs {
+            type Writer = CapturedLogs;
+            fn make_writer(&'a self) -> Self::Writer {
+                self.clone()
+            }
+        }
+
+        let dir = tempfile::tempdir().expect("tempdir");
+        let db_path = dir.path().join("pre_dav_migration.db");
+        let secrets = crate::vault::SecretManager::mock();
+
+        // An old-schema `accounts` table predating `collection_url`.
+        {
+            let url = format!("sqlite://{}", db_path.to_string_lossy());
+            let options = sqlx::sqlite::SqliteConnectOptions::from_str(&url)
+                .expect("valid sqlite url")
+                .create_if_missing(true);
+            let pool = sqlx::SqlitePool::connect_with(options)
+                .await
+                .expect("connect to fresh old-schema db");
+
+            sqlx::query(
+                r#"
+                CREATE TABLE accounts (
+                    id TEXT PRIMARY KEY NOT NULL,
+                    name TEXT NOT NULL,
+                    email_address TEXT NOT NULL,
+                    protocol TEXT NOT NULL,
+                    server_host TEXT NOT NULL,
+                    server_port INTEGER NOT NULL,
+                    use_tls INTEGER NOT NULL,
+                    keyring_secret_key TEXT NOT NULL,
+                    sync_interval_secs INTEGER NOT NULL,
+                    smtp_host TEXT,
+                    smtp_port INTEGER,
+                    imap_tls_mode TEXT NOT NULL DEFAULT 'implicit_tls',
+                    smtp_tls_mode TEXT NOT NULL DEFAULT 'implicit_tls'
+                )
+                "#,
+            )
+            .execute(&pool)
+            .await
+            .expect("create old-schema accounts table");
+
+            pool.close().await;
+        }
+
+        let logs = CapturedLogs::default();
+        let subscriber = tracing_subscriber::fmt()
+            .with_writer(logs.clone())
+            .with_ansi(false)
+            .finish();
+
+        // `set_default` returns a guard that stays active across `.await`
+        // points as long as this test stays on the single `#[tokio::test]`
+        // current-thread executor, which is the default runtime flavor and
+        // exactly what is used here.
+        let guard = tracing::subscriber::set_default(subscriber);
+        let engine = DatabaseEngine::connect_file(&db_path, &secrets)
+            .await
+            .expect("opening an old-schema database must never error");
+        drop(guard);
+
+        let captured = String::from_utf8(logs.0.lock().expect("log buffer lock").clone())
+            .expect("captured log is valid utf8");
+        assert!(
+            captured.contains("collection_url"),
+            "expected the migrated column to be named in the INFO log, got: {captured}"
+        );
+        assert!(
+            captured.to_ascii_uppercase().contains("INFO"),
+            "expected an INFO-level log for the applied migration, got: {captured}"
+        );
+
+        engine.close().await;
+    }
+
     #[test]
     fn database_error_display() {
         let err = DatabaseError::PoolCreation("failed".to_string());

crates/nuncio-store/src/vault.rs

@@ -231,6 +231,9 @@ impl SecretManager {
                 let mut bytes = vec![0u8; len];
                 OsRng.fill_bytes(&mut bytes);
                 self.set_secret(account, &hex::encode(&bytes))?;
+                // Lifecycle visibility only: which purpose got a key minted, and how long it
+                // is, never the key material itself.
+                tracing::info!(purpose = account, len, "minted key material on first use");
                 Ok(bytes)
             }
             Err(e) => Err(e),
@@ -360,6 +363,60 @@ mod tests {
         assert!(matches!(err, VaultError::StorageFailed(_)));
     }
 
+    #[test]
+    fn get_or_create_key_bytes_logs_minting_without_leaking_the_key() {
+        use std::sync::{Arc, Mutex};
+        use tracing_subscriber::fmt::MakeWriter;
+
+        #[derive(Clone, Default)]
+        struct CapturedLogs(Arc<Mutex<Vec<u8>>>);
+
+        impl std::io::Write for CapturedLogs {
+            fn write(&mut self, buf: &[u8]) -> std::io::Result<usize> {
+                self.0
+                    .lock()
+                    .expect("log buffer lock")
+                    .extend_from_slice(buf);
+                Ok(buf.len())
+            }
+            fn flush(&mut self) -> std::io::Result<()> {
+                Ok(())
+            }
+        }
+
+        impl<'a> MakeWriter<'a> for CapturedLogs {
+            type Writer = CapturedLogs;
+            fn make_writer(&'a self) -> Self::Writer {
+                self.clone()
+            }
+        }
+
+        let manager = SecretManager::mock();
+        let logs = CapturedLogs::default();
+        let subscriber = tracing_subscriber::fmt()
+            .with_writer(logs.clone())
+            .with_ansi(false)
+            .finish();
+
+        let guard = tracing::subscriber::set_default(subscriber);
+        let key = manager
+            .get_or_create_key_bytes(WEBHOOK_SIGNING_KEY_ACCOUNT, 32)
+            .expect("key provisioned from vault");
+        drop(guard);
+
+        let captured = String::from_utf8(logs.0.lock().expect("log buffer lock").clone())
+            .expect("captured log is valid utf8");
+        assert!(
+            captured.contains(WEBHOOK_SIGNING_KEY_ACCOUNT),
+            "expected the key's purpose to be named in the INFO log, got: {captured}"
+        );
+        assert!(captured.to_ascii_uppercase().contains("INFO"));
+
+        // The minted key bytes must never appear in the log, in any encoding.
+        let hex_key = hex::encode(&key);
+        assert!(!captured.contains(&hex_key));
+    }
+
     #[test]
     fn os_keyring_provider_can_be_constructed_for_production_use() {
         // Construction alone must not touch the OS credential store (lazy `Entry` creation