| 1 | //! The background writer. |
| 2 | //! |
| 3 | //! One dedicated OS thread behind an unbounded `mpsc`. `record()` is a |
| 4 | //! non-blocking `send` and a hard no-op when the process is not armed; |
| 5 | //! everything the thread does is wrapped in `catch_unwind`, so a panic inside |
| 6 | //! telemetry costs telemetry and nothing else. |
| 7 | //! |
| 8 | //! A plain thread rather than a `tokio` task, deliberately: `init` is called |
| 9 | //! from six subcommand dispatch points, several of which have no runtime yet, |
| 10 | //! and a telemetry subsystem that only works when someone remembered to be |
| 11 | //! inside an executor is a subsystem that silently collects nothing on half its |
| 12 | //! surfaces. |
| 13 | |
| 14 | use std::panic::{AssertUnwindSafe, catch_unwind}; |
| 15 | use std::path::PathBuf; |
| 16 | use std::sync::mpsc::{Receiver, RecvTimeoutError, Sender, SyncSender, channel, sync_channel}; |
| 17 | use std::time::Duration; |
| 18 | |
| 19 | use crate::buffer; |
| 20 | use crate::client::{self, SendOutcome}; |
| 21 | use crate::decision::{self, TelemetryDecision}; |
| 22 | use crate::envelope; |
| 23 | use crate::event::{Batch, Event, SCHEMA_VERSION, Surface}; |
| 24 | |
| 25 | /// Events per batch. |
| 26 | pub const BATCH_MAX_EVENTS: usize = 200; |
| 27 | /// Byte ceiling per batch body. |
| 28 | pub const BATCH_MAX_BYTES: usize = 64 * 1024; |
| 29 | |
| 30 | pub(crate) enum Message { |
| 31 | Event(Box<Event>), |
| 32 | PersistLocal(SyncSender<FlushOutcome>), |
| 33 | Shutdown(SyncSender<FlushOutcome>), |
| 34 | } |
| 35 | |
| 36 | /// What a flush attempt did. |
| 37 | #[derive(Debug, Clone, Copy, PartialEq, Eq)] |
| 38 | pub enum FlushOutcome { |
| 39 | /// Nothing was buffered. |
| 40 | Empty, |
| 41 | /// Events remain in the local buffer for a later network flush. |
| 42 | Buffered, |
| 43 | /// A batch was written to the dry-run sink. |
| 44 | DryRun, |
| 45 | /// A batch was accepted by the endpoint. |
| 46 | Sent, |
| 47 | /// A batch was assembled and dropped — offline, refused, or contended. |
| 48 | Dropped, |
| 49 | /// Telemetry was off by the time the flush ran; nothing was sent. |
| 50 | Suppressed, |
| 51 | /// The actor did not answer inside the caller's deadline. |
| 52 | TimedOut, |
| 53 | } |
| 54 | |
| 55 | /// Facts the writer thread needs, fixed at arming time. |
| 56 | #[derive(Debug, Clone)] |
| 57 | pub(crate) struct Context { |
| 58 | pub root: PathBuf, |
| 59 | pub endpoint: Option<String>, |
| 60 | pub surface: Surface, |
| 61 | pub config_path: Option<PathBuf>, |
| 62 | pub app_version: String, |
| 63 | pub git_sha: Option<String>, |
| 64 | pub tty: bool, |
| 65 | } |
| 66 | |
| 67 | /// A handle to the writer thread. |
| 68 | #[derive(Debug)] |
| 69 | pub(crate) struct Handle { |
| 70 | tx: Sender<Message>, |
| 71 | } |
| 72 | |
| 73 | impl Handle { |
| 74 | /// Start the writer thread. |
| 75 | pub(crate) fn spawn(context: Context) -> Self { |
| 76 | let (tx, rx) = channel::<Message>(); |
| 77 | // A detached thread: nothing joins it, and the process exiting while it |
| 78 | // is mid-write is exactly the case the torn-line tolerance covers. |
| 79 | let _ = std::thread::Builder::new() |
| 80 | .name("codewhale-telemetry".to_string()) |
| 81 | .spawn(move || run(&context, &rx)); |
| 82 | Self { tx } |
| 83 | } |
| 84 | |
| 85 | /// Queue an event. Never blocks, never errors upward. |
| 86 | pub(crate) fn record(&self, event: Event) { |
| 87 | let _ = self.tx.send(Message::Event(Box::new(event))); |
| 88 | } |
| 89 | |
| 90 | /// Ask for a final flush and stop the thread. |
| 91 | pub(crate) fn shutdown(&self, deadline: Duration) -> FlushOutcome { |
| 92 | self.round_trip(deadline, Message::Shutdown) |
| 93 | } |
| 94 | |
| 95 | /// Persist queued events locally and stop without making a network request. |
| 96 | /// |
| 97 | /// Unlike [`Handle::shutdown`], this waits without a deadline: the local |
| 98 | /// path performs only bounded disk work, and racing it against a clock is |
| 99 | /// what lost dry-run receipts on slow hosts (#6269). The writer always |
| 100 | /// acknowledges — even on panic — so the only way out without an outcome |
| 101 | /// is a writer that is already gone, which fails open as `TimedOut`. |
| 102 | pub(crate) fn persist_local(&self) -> FlushOutcome { |
| 103 | let (ack_tx, ack_rx) = sync_channel::<FlushOutcome>(1); |
| 104 | if self.tx.send(Message::PersistLocal(ack_tx)).is_err() { |
| 105 | return FlushOutcome::TimedOut; |
| 106 | } |
| 107 | ack_rx.recv().unwrap_or(FlushOutcome::TimedOut) |
| 108 | } |
| 109 | |
| 110 | fn round_trip( |
| 111 | &self, |
| 112 | deadline: Duration, |
| 113 | build: impl FnOnce(SyncSender<FlushOutcome>) -> Message, |
| 114 | ) -> FlushOutcome { |
| 115 | let (ack_tx, ack_rx) = sync_channel::<FlushOutcome>(1); |
| 116 | if self.tx.send(build(ack_tx)).is_err() { |
| 117 | return FlushOutcome::TimedOut; |
| 118 | } |
| 119 | match ack_rx.recv_timeout(deadline) { |
| 120 | Ok(outcome) => outcome, |
| 121 | Err(RecvTimeoutError::Timeout | RecvTimeoutError::Disconnected) => { |
| 122 | FlushOutcome::TimedOut |
| 123 | } |
| 124 | } |
| 125 | } |
| 126 | } |
| 127 | |
| 128 | fn run(context: &Context, rx: &Receiver<Message>) { |
| 129 | while let Ok(message) = rx.recv() { |
| 130 | // Telemetry never takes the process with it. The hook has already been |
| 131 | // installed by the time this thread exists, so a panic here is caught, |
| 132 | // dropped, and the loop continues. |
| 133 | let result = catch_unwind(AssertUnwindSafe(|| match message { |
| 134 | Message::Event(event) => { |
| 135 | append(context, &event); |
| 136 | None |
| 137 | } |
| 138 | Message::PersistLocal(ack) => { |
| 139 | // The caller joins this without a deadline (#6269), so the |
| 140 | // acknowledgement must be unconditional: a panic here would |
| 141 | // otherwise hang a short CLI command at exit. The outer |
| 142 | // `catch_unwind` still guards the other arms. |
| 143 | let outcome = match catch_unwind(AssertUnwindSafe(|| persist_local(context))) { |
| 144 | Ok(outcome) => outcome, |
| 145 | Err(_) => { |
| 146 | tracing::debug!("telemetry local persist recovered from a panic"); |
| 147 | FlushOutcome::Dropped |
| 148 | } |
| 149 | }; |
| 150 | let _ = ack.send(outcome); |
| 151 | Some(()) |
| 152 | } |
| 153 | Message::Shutdown(ack) => { |
| 154 | let _ = ack.send(flush(context)); |
| 155 | Some(()) |
| 156 | } |
| 157 | })); |
| 158 | match result { |
| 159 | Ok(Some(())) => return, |
| 160 | Ok(None) => {} |
| 161 | Err(_) => { |
| 162 | tracing::debug!("telemetry writer recovered from a panic"); |
| 163 | } |
| 164 | } |
| 165 | } |
| 166 | } |
| 167 | |
| 168 | fn append(context: &Context, event: &Event) { |
| 169 | let Ok(line) = serde_json::to_string(event) else { |
| 170 | return; |
| 171 | }; |
| 172 | let path = buffer::buffer_path(&context.root); |
| 173 | let _ = buffer::append(&context.root, &path, &line); |
| 174 | } |
| 175 | |
| 176 | /// Seal every event queued before this message without reaching the network. |
| 177 | /// |
| 178 | /// The channel is FIFO, so all prior event appends have settled before this |
| 179 | /// runs. Re-deciding here preserves the same mid-session opt-out boundary as a |
| 180 | /// full flush. An explicitly empty endpoint is the local dry-run sink and can |
| 181 | /// therefore be finalized immediately; a configured endpoint leaves the |
| 182 | /// events in `buffer.jsonl` for the next interactive flush. |
| 183 | fn persist_local(context: &Context) -> FlushOutcome { |
| 184 | match decision::re_decide(context.config_path.as_deref(), context.surface) { |
| 185 | TelemetryDecision::Enabled(_) => {} |
| 186 | TelemetryDecision::OptedOut | TelemetryDecision::ForcedOff => { |
| 187 | return FlushOutcome::Suppressed; |
| 188 | } |
| 189 | } |
| 190 | if buffer::tombstone_present(&context.root) { |
| 191 | return FlushOutcome::Suppressed; |
| 192 | } |
| 193 | if context.endpoint.is_none() { |
| 194 | return flush(context); |
| 195 | } |
| 196 | if buffer::read_lines(&buffer::buffer_path(&context.root)).is_empty() { |
| 197 | FlushOutcome::Empty |
| 198 | } else { |
| 199 | FlushOutcome::Buffered |
| 200 | } |
| 201 | } |
| 202 | |
| 203 | /// Drain, re-check consent, and deliver. |
| 204 | /// |
| 205 | /// The re-check is the point: telemetry is resolved once at init, but the |
| 206 | /// documented mid-session opt-out is an external file write this process would |
| 207 | /// otherwise never observe. If the answer is now `OptedOut`, `decide` has |
| 208 | /// already wiped and left the tombstone, and the drained events go nowhere. |
| 209 | fn flush(context: &Context) -> FlushOutcome { |
| 210 | match decision::re_decide(context.config_path.as_deref(), context.surface) { |
| 211 | TelemetryDecision::Enabled(_) => {} |
| 212 | TelemetryDecision::OptedOut | TelemetryDecision::ForcedOff => { |
| 213 | return FlushOutcome::Suppressed; |
| 214 | } |
| 215 | } |
| 216 | if buffer::tombstone_present(&context.root) { |
| 217 | return FlushOutcome::Suppressed; |
| 218 | } |
| 219 | |
| 220 | let lines = buffer::drain(&context.root); |
| 221 | if lines.is_empty() { |
| 222 | return FlushOutcome::Empty; |
| 223 | } |
| 224 | let events = parse_events(&lines); |
| 225 | if events.is_empty() { |
| 226 | return FlushOutcome::Empty; |
| 227 | } |
| 228 | |
| 229 | let Ok(install) = envelope::read_or_create_install_id(&context.root) else { |
| 230 | return FlushOutcome::Dropped; |
| 231 | }; |
| 232 | |
| 233 | let mut state = envelope::read_state(&context.root); |
| 234 | state.schema_version = SCHEMA_VERSION; |
| 235 | state.last_flush = Some(envelope::now_rfc3339()); |
| 236 | // Written on attempt, not on success, so a permanently offline machine |
| 237 | // attempts at most once per interval rather than on every launch. |
| 238 | let _ = envelope::write_state(&context.root, &state); |
| 239 | |
| 240 | let batch = Batch { |
| 241 | schema_version: SCHEMA_VERSION, |
| 242 | notice_version: crate::event::NOTICE_VERSION, |
| 243 | sent_at: envelope::now_rfc3339(), |
| 244 | install_id: install.install_id, |
| 245 | app_version: context.app_version.clone(), |
| 246 | git_sha: context.git_sha.clone(), |
| 247 | surface: context.surface, |
| 248 | os: envelope::current_os(), |
| 249 | arch: envelope::current_arch(), |
| 250 | libc: envelope::current_libc(), |
| 251 | tty: context.tty, |
| 252 | events, |
| 253 | }; |
| 254 | |
| 255 | match client::send(&context.root, context.endpoint.as_deref(), &batch) { |
| 256 | SendOutcome::DryRun => FlushOutcome::DryRun, |
| 257 | SendOutcome::Accepted => FlushOutcome::Sent, |
| 258 | SendOutcome::Dropped => FlushOutcome::Dropped, |
| 259 | } |
| 260 | } |
| 261 | |
| 262 | /// Parse drained lines into events, capped at [`BATCH_MAX_EVENTS`] and |
| 263 | /// [`BATCH_MAX_BYTES`], skipping anything that does not parse **or does not |
| 264 | /// satisfy its declared string bounds**. |
| 265 | /// |
| 266 | /// The bound re-check is the point. Everything upstream of here builds events |
| 267 | /// from closed enums, `u32`s, and two reducers — but this function is a |
| 268 | /// deserializer, and its input is a file on disk that any process running as |
| 269 | /// the user can append to. `Event::is_bounded` is what stops |
| 270 | /// `{"event":"panic","site":"<anything at all>"}` from becoming a first-party |
| 271 | /// POST under the user's install id. |
| 272 | pub(crate) fn parse_events(lines: &[String]) -> Vec<Event> { |
| 273 | let mut events = Vec::new(); |
| 274 | let mut bytes = 0usize; |
| 275 | for line in lines { |
| 276 | if events.len() >= BATCH_MAX_EVENTS || bytes + line.len() > BATCH_MAX_BYTES { |
| 277 | break; |
| 278 | } |
| 279 | if let Ok(event) = serde_json::from_str::<Event>(line) { |
| 280 | if !event.is_bounded() { |
| 281 | tracing::debug!("telemetry dropped an out-of-bounds buffered event"); |
| 282 | continue; |
| 283 | } |
| 284 | bytes += line.len(); |
| 285 | events.push(event); |
| 286 | } |
| 287 | } |
| 288 | events |
| 289 | } |
| 290 | |
| 291 | #[cfg(test)] |
| 292 | mod tests { |
| 293 | use super::*; |
| 294 | |
| 295 | #[test] |
| 296 | fn local_persistence_joins_the_writer_without_a_deadline() { |
| 297 | // The caller blocks on a mock writer that answers on its own |
| 298 | // schedule: no sleep, no timing assertion, no race with the clock. |
| 299 | let (tx, rx) = channel(); |
| 300 | let handle = Handle { tx }; |
| 301 | handle.record(Event::SessionStart { |
| 302 | source: crate::SessionSource::Unknown, |
| 303 | }); |
| 304 | let waiter = std::thread::spawn(move || handle.persist_local()); |
| 305 | assert!(matches!(rx.try_recv(), Ok(Message::Event(_)))); |
| 306 | let Message::PersistLocal(ack) = rx.recv().expect("local persistence request") else { |
| 307 | panic!("short CLI persistence must not request a network shutdown flush"); |
| 308 | }; |
| 309 | ack.send(FlushOutcome::Buffered) |
| 310 | .expect("the caller is still joined"); |
| 311 | assert_eq!(waiter.join().expect("waiter"), FlushOutcome::Buffered); |
| 312 | assert!( |
| 313 | rx.try_recv().is_err(), |
| 314 | "one persist request enqueues exactly one message" |
| 315 | ); |
| 316 | } |
| 317 | |
| 318 | #[test] |
| 319 | fn local_persistence_fails_open_when_the_writer_is_gone() { |
| 320 | // The writer thread exits after a persist or shutdown request; a |
| 321 | // second caller must fail open, not hang on a dead receiver. Send |
| 322 | // fails deterministically here, so no timing assertion is needed. |
| 323 | let (tx, rx) = channel::<Message>(); |
| 324 | drop(rx); |
| 325 | let handle = Handle { tx }; |
| 326 | assert_eq!(handle.persist_local(), FlushOutcome::TimedOut); |
| 327 | } |
| 328 | } |
| 329 |