diff --git a/Cargo.lock b/Cargo.lock index b4131eb..1bde572 100644 --- a/Cargo.lock +++ b/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", ] diff --git a/crates/nuncio-cal/Cargo.toml b/crates/nuncio-cal/Cargo.toml index 4696177..f329efd 100644 --- a/crates/nuncio-cal/Cargo.toml +++ b/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 diff --git a/crates/nuncio-cal/src/caldav.rs b/crates/nuncio-cal/src/caldav.rs index 3d1f888..055334e 100644 --- a/crates/nuncio-cal/src/caldav.rs +++ b/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", &"") + .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 { + 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 `` 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, 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, usize) { let mut events = Vec::new(); + let mut dropped = 0usize; // Extract or text blocks for block in raw_xml.split("") { if let Some((ics_data, _)) = block.split_once("") { 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 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#" + + + + + 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 + + + + + + + BEGIN:VCALENDAR +VERSION:2.0 +BEGIN:VEVENT +SUMMARY:Good Event +DTSTART:20240301T120000Z +DTEND:20240301T130000Z +END:VEVENT +END:VCALENDAR + + + + "#; + + 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("")); + } + + #[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#" + + + + + BEGIN:VCALENDAR +VERSION:2.0 +BEGIN:VEVENT +UID:evt-bad +DTSTART;TZID=Not/ARealZone:20240101T090000 +END:VEVENT +END:VCALENDAR + + + + + + + BEGIN:VCALENDAR +VERSION:2.0 +BEGIN:VEVENT +SUMMARY:Good Event +DTSTART:20240301T120000Z +DTEND:20240301T130000Z +END:VEVENT +END:VCALENDAR + + + + "#; + + 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") + ); + } } diff --git a/crates/nuncio-cal/src/lib.rs b/crates/nuncio-cal/src/lib.rs index 5943a0a..058ccaa 100644 --- a/crates/nuncio-cal/src/lib.rs +++ b/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}; diff --git a/crates/nuncio-cal/src/test_tracing.rs b/crates/nuncio-cal/src/test_tracing.rs new file mode 100644 index 0000000..178898c --- /dev/null +++ b/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, +} + +/// 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, +} + +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>, + events: Mutex>, +} + +impl Recorder { + /// A snapshot of every captured span. + pub fn spans(&self) -> Vec { + self.spans.lock().unwrap_or_else(|e| e.into_inner()).clone() + } + + /// A snapshot of every captured event. + pub fn events(&self) -> Vec { + 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 { + 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); + +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); + +impl tracing_subscriber::Layer 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(f: impl FnOnce() -> T) -> (Arc, 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) +} diff --git a/crates/nuncio-contacts/Cargo.toml b/crates/nuncio-contacts/Cargo.toml index c91f4c9..3f38356 100644 --- a/crates/nuncio-contacts/Cargo.toml +++ b/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 } diff --git a/crates/nuncio-contacts/src/carddav.rs b/crates/nuncio-contacts/src/carddav.rs index 0fe496b..3d6c7a1 100644 --- a/crates/nuncio-contacts/src/carddav.rs +++ b/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", &"") + .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 .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("")); + } + + #[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#" + + + + + BEGIN:VCARD +VERSION:4.0 +FN:Alice Dev +EMAIL:alice@nuncio.mx +END:VCARD + + + + "#; + + 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")); + } + } } diff --git a/crates/nuncio-contacts/src/lib.rs b/crates/nuncio-contacts/src/lib.rs index 3911bfc..15eddd9 100644 --- a/crates/nuncio-contacts/src/lib.rs +++ b/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}; diff --git a/crates/nuncio-contacts/src/test_tracing.rs b/crates/nuncio-contacts/src/test_tracing.rs new file mode 100644 index 0000000..7e7c4bf --- /dev/null +++ b/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, +} + +/// 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, +} + +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>, + events: Mutex>, +} + +impl Recorder { + /// A snapshot of every captured span. + pub fn spans(&self) -> Vec { + self.spans.lock().unwrap_or_else(|e| e.into_inner()).clone() + } + + /// A snapshot of every captured event. + pub fn events(&self) -> Vec { + 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 { + 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); + +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); + +impl tracing_subscriber::Layer 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(f: impl FnOnce() -> T) -> (Arc, 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) +} diff --git a/crates/nuncio-store/src/db.rs b/crates/nuncio-store/src/db.rs index 898bfa5..a7095d8 100644 --- a/crates/nuncio-store/src/db.rs +++ b/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>>); + + impl std::io::Write for CapturedLogs { + fn write(&mut self, buf: &[u8]) -> std::io::Result { + 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()); diff --git a/crates/nuncio-store/src/vault.rs b/crates/nuncio-store/src/vault.rs index ca60afd..26ec80c 100644 --- a/crates/nuncio-store/src/vault.rs +++ b/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>>); + + impl std::io::Write for CapturedLogs { + fn write(&mut self, buf: &[u8]) -> std::io::Result { + 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