logging.rs (14918B)
1 use std::{ 2 fmt, fs, io, 3 path::{Path, PathBuf}, 4 sync::OnceLock, 5 }; 6 7 use chrono::{SecondsFormat, Utc}; 8 use serde::Serialize; 9 use serde_json::{Map, Value}; 10 use thiserror::Error; 11 use tracing::field::{Field, Visit}; 12 use tracing::{Event, Level, Subscriber, info}; 13 use tracing_appender::{ 14 non_blocking::WorkerGuard, 15 rolling::{RollingFileAppender, Rotation}, 16 }; 17 use tracing_subscriber::{ 18 EnvFilter, fmt as tracing_fmt, 19 fmt::{FmtContext, FormatEvent, FormatFields, format::Writer}, 20 prelude::*, 21 registry::LookupSpan, 22 }; 23 24 use crate::{ 25 APP_PLATFORM_RUNTIME, AppBuildIdentity, AppCoreRuntimeMetadata, AppHostRuntimeMetadata, 26 }; 27 use crate::{AppRuntimeSnapshot, runtime_mode_label}; 28 29 pub const APP_LOG_SCHEMA_VERSION: &str = "radroots.app.log.v1"; 30 pub const APP_LOG_PRODUCT: &str = "app"; 31 32 static LOG_GUARD: OnceLock<WorkerGuard> = OnceLock::new(); 33 static TRACING_INSTALLED: OnceLock<()> = OnceLock::new(); 34 static PANIC_HOOK_INSTALLED: OnceLock<()> = OnceLock::new(); 35 36 #[derive(Clone, Debug, Eq, PartialEq)] 37 pub struct AppLoggingOptions { 38 pub log_dir: PathBuf, 39 pub snapshot: AppRuntimeSnapshot, 40 pub stdout: bool, 41 pub default_level: String, 42 } 43 44 #[derive(Debug, Error)] 45 pub enum AppLoggingError { 46 #[error(transparent)] 47 Io(#[from] io::Error), 48 #[error(transparent)] 49 Json(#[from] serde_json::Error), 50 #[error(transparent)] 51 AppenderInit(#[from] tracing_appender::rolling::InitError), 52 #[error(transparent)] 53 TracingInit(#[from] tracing_subscriber::util::TryInitError), 54 } 55 56 #[derive(Clone, Debug)] 57 struct StructuredLogFormatter { 58 snapshot: AppRuntimeSnapshot, 59 } 60 61 #[derive(Debug, Default)] 62 struct StructuredFieldVisitor { 63 event_name: Option<String>, 64 message: Option<String>, 65 metadata: Map<String, Value>, 66 } 67 68 #[derive(Serialize)] 69 struct AppLogRecord<'a> { 70 timestamp: String, 71 schema_version: &'static str, 72 product: &'static str, 73 category: String, 74 event: String, 75 level: &'static str, 76 message: String, 77 runtime_mode: &'static str, 78 run_id: &'a str, 79 platform_runtime: &'static str, 80 core: &'a AppCoreRuntimeMetadata, 81 build: &'a AppBuildIdentity, 82 host: &'a AppHostRuntimeMetadata, 83 metadata: Map<String, Value>, 84 } 85 86 impl AppLoggingOptions { 87 pub fn localhost_dev(snapshot: AppRuntimeSnapshot, local_log_root: &Path) -> Self { 88 Self { 89 log_dir: app_runtime_log_dir(local_log_root), 90 snapshot, 91 stdout: true, 92 default_level: "info".to_owned(), 93 } 94 } 95 } 96 97 impl StructuredFieldVisitor { 98 fn record_value(&mut self, field: &Field, value: Value) { 99 match field.name() { 100 "message" => { 101 self.message = match value { 102 Value::String(message) => Some(message), 103 other => Some(other.to_string()), 104 }; 105 } 106 "event" => { 107 self.event_name = match value { 108 Value::String(event_name) => Some(event_name), 109 other => Some(other.to_string()), 110 }; 111 } 112 _ => { 113 self.metadata.insert(field.name().to_owned(), value); 114 } 115 } 116 } 117 } 118 119 impl Visit for StructuredFieldVisitor { 120 fn record_bool(&mut self, field: &Field, value: bool) { 121 self.record_value(field, Value::Bool(value)); 122 } 123 124 fn record_i64(&mut self, field: &Field, value: i64) { 125 self.record_value(field, Value::from(value)); 126 } 127 128 fn record_u64(&mut self, field: &Field, value: u64) { 129 self.record_value(field, Value::from(value)); 130 } 131 132 fn record_f64(&mut self, field: &Field, value: f64) { 133 self.record_value(field, Value::from(value)); 134 } 135 136 fn record_str(&mut self, field: &Field, value: &str) { 137 self.record_value(field, Value::String(value.to_owned())); 138 } 139 140 fn record_error(&mut self, field: &Field, value: &(dyn std::error::Error + 'static)) { 141 self.record_value(field, Value::String(value.to_string())); 142 } 143 144 fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { 145 self.record_value(field, Value::String(format!("{value:?}"))); 146 } 147 } 148 149 impl<S, N> FormatEvent<S, N> for StructuredLogFormatter 150 where 151 S: Subscriber + for<'lookup> LookupSpan<'lookup>, 152 N: for<'writer> FormatFields<'writer> + 'static, 153 { 154 fn format_event( 155 &self, 156 _ctx: &FmtContext<'_, S, N>, 157 mut writer: Writer<'_>, 158 event: &Event<'_>, 159 ) -> fmt::Result { 160 let mut visitor = StructuredFieldVisitor::default(); 161 event.record(&mut visitor); 162 163 let record = AppLogRecord { 164 timestamp: structured_timestamp(), 165 schema_version: APP_LOG_SCHEMA_VERSION, 166 product: APP_LOG_PRODUCT, 167 category: target_category(event.metadata().target()), 168 event: visitor 169 .event_name 170 .unwrap_or_else(|| format!("{}.log", target_category(event.metadata().target()))), 171 level: level_label(event.metadata().level()), 172 message: visitor.message.unwrap_or_default(), 173 runtime_mode: runtime_mode_label(&self.snapshot.runtime_mode), 174 run_id: &self.snapshot.run_id, 175 platform_runtime: APP_PLATFORM_RUNTIME, 176 core: &self.snapshot.core, 177 build: &self.snapshot.build, 178 host: &self.snapshot.host, 179 metadata: visitor.metadata, 180 }; 181 let payload = serde_json::to_string(&record).map_err(|_| fmt::Error)?; 182 183 writeln!(writer, "{payload}") 184 } 185 } 186 187 pub fn app_runtime_log_dir(local_log_root: &Path) -> PathBuf { 188 local_log_root 189 .join("apps") 190 .join("local") 191 .join(APP_LOG_PRODUCT) 192 .join(APP_PLATFORM_RUNTIME) 193 } 194 195 pub fn bootstrap_logging( 196 snapshot: &AppRuntimeSnapshot, 197 local_log_root: &Path, 198 ) -> Result<PathBuf, AppLoggingError> { 199 let options = AppLoggingOptions::localhost_dev(snapshot.clone(), local_log_root); 200 let log_dir = options.log_dir.clone(); 201 init_logging(options)?; 202 Ok(log_dir) 203 } 204 205 pub fn init_logging(options: AppLoggingOptions) -> Result<(), AppLoggingError> { 206 if TRACING_INSTALLED.get().is_some() { 207 return Ok(()); 208 } 209 210 fs::create_dir_all(&options.log_dir)?; 211 prepare_latest_alias(&options.log_dir)?; 212 213 let file_appender = build_file_appender(&options.log_dir)?; 214 let (file_writer, guard) = tracing_appender::non_blocking(file_appender); 215 let _ = LOG_GUARD.set(guard); 216 217 let formatter = StructuredLogFormatter { 218 snapshot: options.snapshot.clone(), 219 }; 220 let file_layer = tracing_fmt::layer() 221 .with_writer(file_writer) 222 .with_ansi(false) 223 .event_format(formatter.clone()); 224 let stdout_layer = options.stdout.then(|| { 225 tracing_fmt::layer() 226 .with_writer(std::io::stdout) 227 .with_ansi(false) 228 .event_format(formatter) 229 }); 230 231 tracing_subscriber::registry() 232 .with(resolve_env_filter(options.default_level.as_str())) 233 .with(file_layer) 234 .with(stdout_layer) 235 .try_init()?; 236 let _ = TRACING_INSTALLED.set(()); 237 238 info!( 239 target: "runtime", 240 event = "logging.initialized", 241 file = %current_day_log_path(&options.log_dir).display(), 242 stdout = options.stdout, 243 "logging initialized" 244 ); 245 246 Ok(()) 247 } 248 249 pub fn install_panic_hook() { 250 if PANIC_HOOK_INSTALLED.set(()).is_err() { 251 return; 252 } 253 254 let default_hook = std::panic::take_hook(); 255 std::panic::set_hook(Box::new(move |panic_info| { 256 tracing::error!( 257 target: "panic", 258 event = "runtime.panic", 259 panic = %render_panic_payload(panic_info), 260 location = %render_panic_location(panic_info), 261 "panic captured" 262 ); 263 default_hook(panic_info); 264 })); 265 } 266 267 fn build_file_appender(log_dir: &Path) -> Result<RollingFileAppender, AppLoggingError> { 268 Ok(RollingFileAppender::builder() 269 .rotation(Rotation::DAILY) 270 .filename_suffix("jsonl") 271 .build(log_dir)?) 272 } 273 274 fn current_day_log_path(log_dir: &Path) -> PathBuf { 275 log_dir.join(format!("{}.jsonl", current_utc_day())) 276 } 277 278 fn current_utc_day() -> String { 279 Utc::now().format("%Y-%m-%d").to_string() 280 } 281 282 fn level_label(level: &Level) -> &'static str { 283 match *level { 284 Level::ERROR => "error", 285 Level::WARN => "warning", 286 Level::INFO => "info", 287 Level::DEBUG => "debug", 288 Level::TRACE => "debug", 289 } 290 } 291 292 fn prepare_latest_alias(log_dir: &Path) -> Result<(), AppLoggingError> { 293 let latest_path = log_dir.join("latest.jsonl"); 294 match fs::symlink_metadata(&latest_path) { 295 Ok(metadata) => { 296 if metadata.file_type().is_symlink() || metadata.is_file() { 297 fs::remove_file(&latest_path)?; 298 } 299 } 300 Err(error) if error.kind() == io::ErrorKind::NotFound => {} 301 Err(error) => return Err(error.into()), 302 } 303 304 #[cfg(unix)] 305 std::os::unix::fs::symlink( 306 current_day_log_path(log_dir) 307 .file_name() 308 .map(|value| value.to_owned()) 309 .unwrap_or_default(), 310 &latest_path, 311 )?; 312 313 #[cfg(not(unix))] 314 fs::write(&latest_path, [])?; 315 316 Ok(()) 317 } 318 319 fn render_panic_location(panic_info: &std::panic::PanicHookInfo<'_>) -> String { 320 panic_info 321 .location() 322 .map(|location| { 323 format!( 324 "{}:{}:{}", 325 location.file(), 326 location.line(), 327 location.column() 328 ) 329 }) 330 .unwrap_or_else(|| "<unknown>".to_owned()) 331 } 332 333 fn render_panic_payload(panic_info: &std::panic::PanicHookInfo<'_>) -> String { 334 if let Some(payload) = panic_info.payload().downcast_ref::<&str>() { 335 (*payload).to_owned() 336 } else if let Some(payload) = panic_info.payload().downcast_ref::<String>() { 337 payload.clone() 338 } else { 339 "non-string panic payload".to_owned() 340 } 341 } 342 343 fn resolve_env_filter(default_level: &str) -> EnvFilter { 344 EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new(default_level)) 345 } 346 347 fn structured_timestamp() -> String { 348 Utc::now().to_rfc3339_opts(SecondsFormat::Millis, true) 349 } 350 351 fn target_category(target: &str) -> String { 352 if target.is_empty() { 353 return "runtime".to_owned(); 354 } 355 356 target 357 .rsplit("::") 358 .next() 359 .unwrap_or(target) 360 .trim() 361 .trim_matches(':') 362 .to_owned() 363 } 364 365 #[cfg(test)] 366 mod tests { 367 use std::{ 368 fs, 369 io::Write, 370 path::{Path, PathBuf}, 371 time::{SystemTime, UNIX_EPOCH}, 372 }; 373 374 use chrono::{SecondsFormat, Utc}; 375 use serde_json::json; 376 377 use crate::{ 378 APP_PROJECTION_SOURCE, AppBuildIdentity, AppRuntimeCapture, AppRuntimeMode, 379 AppRuntimeSnapshot, 380 }; 381 382 use super::{ 383 APP_LOG_PRODUCT, APP_LOG_SCHEMA_VERSION, app_runtime_log_dir, build_file_appender, 384 current_day_log_path, prepare_latest_alias, 385 }; 386 387 fn temp_dir(name: &str) -> PathBuf { 388 let nanos = SystemTime::now() 389 .duration_since(UNIX_EPOCH) 390 .expect("system time") 391 .as_nanos(); 392 let path = std::env::temp_dir().join(format!("radroots-app-log-{name}-{nanos}")); 393 let _ = fs::remove_dir_all(&path); 394 path 395 } 396 397 fn test_snapshot() -> AppRuntimeSnapshot { 398 AppRuntimeSnapshot::from_capture( 399 AppBuildIdentity { 400 package_name: "radroots_app".to_owned(), 401 package_version: "0.1.0".to_owned(), 402 build_profile: "debug".to_owned(), 403 target_triple: "aarch64-apple-darwin".to_owned(), 404 projection_source: APP_PROJECTION_SOURCE.to_owned(), 405 git_commit: None, 406 }, 407 AppRuntimeMode::LocalhostDev, 408 AppRuntimeCapture { 409 host_locale: "en_US.UTF-8".to_owned(), 410 operating_system: "macos".to_owned(), 411 run_id: "run-localhost-dev-123-pid456".to_owned(), 412 }, 413 ) 414 } 415 416 #[test] 417 fn app_runtime_log_dir_uses_canonical_local_layout() { 418 let dir = app_runtime_log_dir(Path::new("/tmp/repo/logs")); 419 420 assert_eq!( 421 dir, 422 PathBuf::from("/tmp/repo/logs") 423 .join("apps") 424 .join("local") 425 .join(APP_LOG_PRODUCT) 426 .join("app-macos-native") 427 ); 428 } 429 430 #[cfg(unix)] 431 #[test] 432 fn prepare_latest_alias_tracks_current_day_log_file() { 433 let dir = temp_dir("latest-alias"); 434 fs::create_dir_all(&dir).expect("create dir"); 435 436 prepare_latest_alias(&dir).expect("prepare latest alias"); 437 438 let target = fs::read_link(dir.join("latest.jsonl")).expect("read latest symlink"); 439 assert_eq!( 440 target, 441 PathBuf::from(format!("{}.jsonl", Utc::now().format("%Y-%m-%d"))) 442 ); 443 let _ = fs::remove_dir_all(&dir); 444 } 445 446 #[test] 447 fn rolling_file_appender_writes_to_active_day_log_file() { 448 let dir = temp_dir("rolling-file"); 449 fs::create_dir_all(&dir).expect("create dir"); 450 451 let mut appender = build_file_appender(&dir).expect("build file appender"); 452 writeln!(appender, "{{\"event\":\"runtime.launch\"}}").expect("write structured record"); 453 appender.flush().expect("flush structured record"); 454 455 let log_path = current_day_log_path(&dir); 456 let payload = fs::read_to_string(&log_path).expect("read current day log"); 457 458 assert!(log_path.ends_with(format!("{}.jsonl", Utc::now().format("%Y-%m-%d")))); 459 assert!(payload.contains("\"event\":\"runtime.launch\"")); 460 461 let _ = fs::remove_dir_all(&dir); 462 } 463 464 #[test] 465 fn structured_record_shape_remains_stable() { 466 let snapshot = test_snapshot(); 467 let payload = serde_json::to_value(json!({ 468 "timestamp": Utc::now().to_rfc3339_opts(SecondsFormat::Millis, true), 469 "schema_version": APP_LOG_SCHEMA_VERSION, 470 "product": APP_LOG_PRODUCT, 471 "category": "bootstrap", 472 "event": "runtime.launch", 473 "level": "info", 474 "message": "app launch", 475 "runtime_mode": "localhost-dev", 476 "run_id": snapshot.run_id, 477 "platform_runtime": "app-macos-native", 478 "core": snapshot.core, 479 "build": snapshot.build, 480 "host": snapshot.host, 481 "metadata": { 482 "home_screen": "Radroots" 483 } 484 })) 485 .expect("serialize"); 486 487 assert_eq!(payload["schema_version"], "radroots.app.log.v1"); 488 assert_eq!(payload["event"], "runtime.launch"); 489 assert_eq!(payload["platform_runtime"], "app-macos-native"); 490 assert_eq!(payload["metadata"]["home_screen"], "Radroots"); 491 } 492 }