| 1 | //! Integration tests for journal log writer |
| 2 | //! |
| 3 | //! Tests cover: |
| 4 | //! - Basic entry writing |
| 5 | //! - File rotation (size-based, count-based) |
| 6 | //! - Retention policies |
| 7 | |
| 8 | use journal_common::{Microseconds, load_machine_id, monotonic_now}; |
| 9 | use journal_log_writer::{ |
| 10 | Config, EntryTimestamps, Log, LogLifecycleEvent, LogLifecycleObserver, RetentionPolicy, |
| 11 | RotationPolicy, |
| 12 | }; |
| 13 | use journal_registry::Origin; |
| 14 | use std::fs; |
| 15 | use std::path::{Path, PathBuf}; |
| 16 | use std::process::Command; |
| 17 | use std::sync::{Arc, Mutex, OnceLock}; |
| 18 | use tempfile::TempDir; |
| 19 | |
| 20 | /// Helper to create a default test config |
| 21 | fn test_config() -> Config { |
| 22 | let origin = Origin { |
| 23 | machine_id: None, |
| 24 | namespace: None, |
| 25 | source: journal_registry::Source::System, |
| 26 | }; |
| 27 | |
| 28 | Config::new( |
| 29 | origin, |
| 30 | RotationPolicy::default(), |
| 31 | RetentionPolicy::default(), |
| 32 | ) |
| 33 | } |
| 34 | |
| 35 | /// Helper to count journal files in a directory |
| 36 | fn count_journal_files(dir: &TempDir) -> usize { |
| 37 | let machine_id = load_machine_id().unwrap(); |
| 38 | let journal_dir = dir.path().join(machine_id.as_simple().to_string()); |
| 39 | |
| 40 | fs::read_dir(&journal_dir) |
| 41 | .unwrap() |
| 42 | .filter_map(|e| e.ok()) |
| 43 | .filter(|e| { |
| 44 | e.path() |
| 45 | .extension() |
| 46 | .and_then(|s| s.to_str()) |
| 47 | .map(|s| s == "journal") |
| 48 | .unwrap_or(false) |
| 49 | }) |
| 50 | .count() |
| 51 | } |
| 52 | |
| 53 | fn journal_file_path(dir: &TempDir) -> PathBuf { |
| 54 | let machine_id = load_machine_id().unwrap(); |
| 55 | let journal_dir = dir.path().join(machine_id.as_simple().to_string()); |
| 56 | |
| 57 | let journal_files: Vec<_> = fs::read_dir(&journal_dir) |
| 58 | .unwrap() |
| 59 | .filter_map(|e| e.ok()) |
| 60 | .filter(|e| { |
| 61 | e.path() |
| 62 | .extension() |
| 63 | .and_then(|s| s.to_str()) |
| 64 | .map(|s| s == "journal") |
| 65 | .unwrap_or(false) |
| 66 | }) |
| 67 | .collect(); |
| 68 | |
| 69 | assert_eq!( |
| 70 | journal_files.len(), |
| 71 | 1, |
| 72 | "expected exactly one journal file in {:?}", |
| 73 | journal_dir |
| 74 | ); |
| 75 | journal_files[0].path() |
| 76 | } |
| 77 | |
| 78 | fn journal_file_paths(dir: &TempDir) -> Vec<PathBuf> { |
| 79 | let machine_id = load_machine_id().unwrap(); |
| 80 | let journal_dir = dir.path().join(machine_id.as_simple().to_string()); |
| 81 | |
| 82 | let mut journal_files: Vec<_> = fs::read_dir(&journal_dir) |
| 83 | .unwrap() |
| 84 | .filter_map(|e| e.ok()) |
| 85 | .filter(|e| { |
| 86 | e.path() |
| 87 | .extension() |
| 88 | .and_then(|s| s.to_str()) |
| 89 | .map(|s| s == "journal") |
| 90 | .unwrap_or(false) |
| 91 | }) |
| 92 | .map(|e| e.path()) |
| 93 | .collect(); |
| 94 | journal_files.sort(); |
| 95 | journal_files |
| 96 | } |
| 97 | |
| 98 | fn read_journal_json(path: &Path) -> Vec<serde_json::Value> { |
| 99 | if !journalctl_available() { |
| 100 | eprintln!("journalctl not available; skipping journalctl-backed assertions"); |
| 101 | return Vec::new(); |
| 102 | } |
| 103 | |
| 104 | let output = Command::new("journalctl") |
| 105 | .arg("--output=json") |
| 106 | .arg("--file") |
| 107 | .arg(path) |
| 108 | .output() |
| 109 | .expect("failed to run journalctl"); |
| 110 | assert!(output.status.success(), "journalctl should succeed"); |
| 111 | |
| 112 | String::from_utf8_lossy(&output.stdout) |
| 113 | .lines() |
| 114 | .filter(|line| !line.trim().is_empty()) |
| 115 | .map(|line| serde_json::from_str::<serde_json::Value>(line).unwrap()) |
| 116 | .collect() |
| 117 | } |
| 118 | |
| 119 | fn journalctl_available() -> bool { |
| 120 | static AVAILABLE: OnceLock<bool> = OnceLock::new(); |
| 121 | *AVAILABLE.get_or_init(|| { |
| 122 | Command::new("journalctl") |
| 123 | .arg("--version") |
| 124 | .output() |
| 125 | .map(|output| output.status.success()) |
| 126 | .unwrap_or(false) |
| 127 | }) |
| 128 | } |
| 129 | |
| 130 | #[derive(Default)] |
| 131 | struct RecordingObserver { |
| 132 | events: Mutex<Vec<LogLifecycleEvent>>, |
| 133 | } |
| 134 | |
| 135 | impl LogLifecycleObserver for RecordingObserver { |
| 136 | fn on_event(&self, event: &LogLifecycleEvent) { |
| 137 | self.events |
| 138 | .lock() |
| 139 | .expect("lock observer events") |
| 140 | .push(event.clone()); |
| 141 | } |
| 142 | } |
| 143 | |
| 144 | fn parse_u64_field(row: &serde_json::Value, key: &str) -> Option<u64> { |
| 145 | row.get(key)?.as_str()?.parse::<u64>().ok() |
| 146 | } |
| 147 | |
| 148 | #[test] |
| 149 | fn test_write_single_entry() { |
| 150 | let dir = TempDir::new().unwrap(); |
| 151 | let config = test_config(); |
| 152 | |
| 153 | let mut log = Log::new(dir.path(), config).unwrap(); |
| 154 | |
| 155 | let entry = [b"MESSAGE=Hello, World!" as &[u8], b"PRIORITY=6"]; |
| 156 | |
| 157 | log.write_entry(&entry, None).unwrap(); |
| 158 | log.sync().unwrap(); |
| 159 | |
| 160 | // Verify file was created |
| 161 | assert_eq!(count_journal_files(&dir), 1); |
| 162 | } |
| 163 | |
| 164 | #[test] |
| 165 | fn test_write_multiple_entries() { |
| 166 | let dir = TempDir::new().unwrap(); |
| 167 | let config = test_config(); |
| 168 | |
| 169 | let mut log = Log::new(dir.path(), config).unwrap(); |
| 170 | |
| 171 | // Write 10 entries |
| 172 | for i in 0..10 { |
| 173 | let message = format!("MESSAGE=Entry {}", i); |
| 174 | let entry = [message.as_bytes(), b"PRIORITY=6"]; |
| 175 | log.write_entry(&entry, None).unwrap(); |
| 176 | } |
| 177 | |
| 178 | log.sync().unwrap(); |
| 179 | |
| 180 | // Should still be 1 file |
| 181 | assert_eq!(count_journal_files(&dir), 1); |
| 182 | } |
| 183 | |
| 184 | #[test] |
| 185 | fn test_rotation_by_entry_count() { |
| 186 | let dir = TempDir::new().unwrap(); |
| 187 | |
| 188 | // Rotate after 5 entries |
| 189 | let rotation = RotationPolicy::default().with_number_of_entries(5); |
| 190 | let config = test_config().with_rotation_policy(rotation); |
| 191 | |
| 192 | let mut log = Log::new(dir.path(), config).unwrap(); |
| 193 | |
| 194 | // Write 12 entries (should create 3 files: 5 + 5 + 2) |
| 195 | for i in 0..12 { |
| 196 | let message = format!("MESSAGE=Entry {}", i); |
| 197 | let entry = [message.as_bytes(), b"PRIORITY=6"]; |
| 198 | log.write_entry(&entry, None).unwrap(); |
| 199 | } |
| 200 | |
| 201 | log.sync().unwrap(); |
| 202 | |
| 203 | assert_eq!(count_journal_files(&dir), 3); |
| 204 | } |
| 205 | |
| 206 | #[test] |
| 207 | fn test_rotation_by_file_size() { |
| 208 | let dir = TempDir::new().unwrap(); |
| 209 | |
| 210 | // Rotate at ~50KB (small for testing) |
| 211 | let rotation = RotationPolicy::default().with_size_of_journal_file(50 * 1024); |
| 212 | let config = test_config().with_rotation_policy(rotation); |
| 213 | |
| 214 | let mut log = Log::new(dir.path(), config).unwrap(); |
| 215 | |
| 216 | // Write entries with large messages to trigger size-based rotation |
| 217 | for i in 0..100 { |
| 218 | let message = format!( |
| 219 | "MESSAGE=Entry {} with lots of padding: {}", |
| 220 | i, |
| 221 | "x".repeat(1000) |
| 222 | ); |
| 223 | let entry = [message.as_bytes(), b"PRIORITY=6"]; |
| 224 | log.write_entry(&entry, None).unwrap(); |
| 225 | } |
| 226 | |
| 227 | log.sync().unwrap(); |
| 228 | |
| 229 | // Should have rotated at least once |
| 230 | assert!(count_journal_files(&dir) > 1); |
| 231 | } |
| 232 | |
| 233 | #[test] |
| 234 | fn test_retention_by_file_count() { |
| 235 | let dir = TempDir::new().unwrap(); |
| 236 | |
| 237 | // Rotate after 3 entries, keep max 2 files |
| 238 | let rotation = RotationPolicy::default().with_number_of_entries(3); |
| 239 | let retention = RetentionPolicy::default().with_number_of_journal_files(2); |
| 240 | let config = test_config() |
| 241 | .with_rotation_policy(rotation) |
| 242 | .with_retention_policy(retention); |
| 243 | |
| 244 | let mut log = Log::new(dir.path(), config).unwrap(); |
| 245 | |
| 246 | // Write 10 entries (should create 4 files, but keep only 2) |
| 247 | for i in 0..10 { |
| 248 | let message = format!("MESSAGE=Entry {}", i); |
| 249 | let entry = [message.as_bytes(), b"PRIORITY=6"]; |
| 250 | log.write_entry(&entry, None).unwrap(); |
| 251 | } |
| 252 | |
| 253 | log.sync().unwrap(); |
| 254 | |
| 255 | // Retention is enforced during rotation, so there might be 1 extra file |
| 256 | // (the active file + retention limit). Check that we're at or near the limit. |
| 257 | let file_count = count_journal_files(&dir); |
| 258 | assert!( |
| 259 | file_count <= 3, |
| 260 | "Should have at most 3 files (active + retention limit), got {}", |
| 261 | file_count |
| 262 | ); |
| 263 | } |
| 264 | |
| 265 | #[test] |
| 266 | fn test_retention_by_total_size() { |
| 267 | let dir = TempDir::new().unwrap(); |
| 268 | |
| 269 | // Rotate after 5 entries, keep max 2 files based on actual data size |
| 270 | // Note: Journal files pre-allocate space (sparse files), but retention |
| 271 | // is based on actual data written (append_offset), not logical file size |
| 272 | let rotation = RotationPolicy::default().with_number_of_entries(5); |
| 273 | |
| 274 | // Each small entry is ~50-100 bytes, plus journal overhead (~4KB per file) |
| 275 | // Set limit to ~12KB to allow 2-3 files before triggering retention |
| 276 | let retention = RetentionPolicy::default().with_size_of_journal_files(12 * 1024); |
| 277 | |
| 278 | let config = test_config() |
| 279 | .with_rotation_policy(rotation) |
| 280 | .with_retention_policy(retention); |
| 281 | |
| 282 | let mut log = Log::new(dir.path(), config).unwrap(); |
| 283 | |
| 284 | // Write 20 entries (creates 4 files of 5 entries each) |
| 285 | for i in 0..20 { |
| 286 | let message = format!("MESSAGE=Entry {}", i); |
| 287 | let entry = [message.as_bytes(), b"PRIORITY=6"]; |
| 288 | log.write_entry(&entry, None).unwrap(); |
| 289 | } |
| 290 | |
| 291 | log.sync().unwrap(); |
| 292 | |
| 293 | let file_count = count_journal_files(&dir); |
| 294 | |
| 295 | // Should have rotated (4 files), but retention should limit to 3 |
| 296 | // (oldest file deleted when total data size exceeds 12KB limit) |
| 297 | assert!( |
| 298 | file_count <= 3, |
| 299 | "Size-based retention should limit files, got {}", |
| 300 | file_count |
| 301 | ); |
| 302 | } |
| 303 | |
| 304 | #[test] |
| 305 | fn test_empty_entry() { |
| 306 | let dir = TempDir::new().unwrap(); |
| 307 | let config = test_config(); |
| 308 | |
| 309 | let mut log = Log::new(dir.path(), config).unwrap(); |
| 310 | |
| 311 | // Write empty entry (should be no-op) |
| 312 | let entry: [&[u8]; 0] = []; |
| 313 | log.write_entry(&entry, None).unwrap(); |
| 314 | |
| 315 | // Should not create any files (no rotation triggered) |
| 316 | assert_eq!(count_journal_files(&dir), 0); |
| 317 | } |
| 318 | |
| 319 | #[test] |
| 320 | fn test_boot_id_injection() { |
| 321 | use journal_common::load_boot_id; |
| 322 | |
| 323 | if !journalctl_available() { |
| 324 | eprintln!("journalctl not available; skipping test_boot_id_injection"); |
| 325 | return; |
| 326 | } |
| 327 | |
| 328 | let dir = TempDir::new().unwrap(); |
| 329 | let config = test_config(); |
| 330 | |
| 331 | let mut log = Log::new(dir.path(), config).unwrap(); |
| 332 | |
| 333 | // Write a single entry |
| 334 | let entry = [b"MESSAGE=Test entry" as &[u8], b"PRIORITY=6"]; |
| 335 | log.write_entry(&entry, None).unwrap(); |
| 336 | log.sync().unwrap(); |
| 337 | |
| 338 | // Find the created journal file |
| 339 | let machine_id = load_machine_id().unwrap(); |
| 340 | let journal_dir = dir.path().join(machine_id.as_simple().to_string()); |
| 341 | let journal_files: Vec<_> = fs::read_dir(&journal_dir) |
| 342 | .unwrap() |
| 343 | .filter_map(|e| e.ok()) |
| 344 | .filter(|e| { |
| 345 | e.path() |
| 346 | .extension() |
| 347 | .and_then(|s| s.to_str()) |
| 348 | .map(|s| s == "journal") |
| 349 | .unwrap_or(false) |
| 350 | }) |
| 351 | .collect(); |
| 352 | |
| 353 | assert_eq!( |
| 354 | journal_files.len(), |
| 355 | 1, |
| 356 | "Should have created exactly one journal file" |
| 357 | ); |
| 358 | |
| 359 | let journal_path = journal_files[0].path(); |
| 360 | let boot_id = load_boot_id().unwrap(); |
| 361 | let expected_boot_id = boot_id.as_simple().to_string(); |
| 362 | |
| 363 | // Use journalctl to verify _BOOT_ID field is present |
| 364 | let output = Command::new("journalctl") |
| 365 | .arg("--output=json") |
| 366 | .arg("--file") |
| 367 | .arg(&journal_path) |
| 368 | .output() |
| 369 | .expect("Failed to run journalctl"); |
| 370 | |
| 371 | assert!(output.status.success(), "journalctl should succeed"); |
| 372 | |
| 373 | let output_str = String::from_utf8_lossy(&output.stdout); |
| 374 | |
| 375 | // Check that the output contains the expected _BOOT_ID field |
| 376 | let boot_id_field = format!("\"_BOOT_ID\":\"{}\"", expected_boot_id); |
| 377 | assert!( |
| 378 | output_str.contains(&boot_id_field), |
| 379 | "_BOOT_ID field with value {} should be present in journal entry output", |
| 380 | expected_boot_id |
| 381 | ); |
| 382 | } |
| 383 | |
| 384 | #[test] |
| 385 | fn test_write_uses_machine_id_subdirectory() { |
| 386 | let dir = TempDir::new().unwrap(); |
| 387 | let target_dir = dir.path().join("flows_raw"); |
| 388 | fs::create_dir_all(&target_dir).unwrap(); |
| 389 | let mut log = Log::new(&target_dir, test_config()).unwrap(); |
| 390 | |
| 391 | let entry = [b"MESSAGE=machine id suffix" as &[u8], b"PRIORITY=6"]; |
| 392 | log.write_entry(&entry, None).unwrap(); |
| 393 | log.sync().unwrap(); |
| 394 | |
| 395 | let root_files: Vec<_> = fs::read_dir(&target_dir) |
| 396 | .unwrap() |
| 397 | .filter_map(|e| e.ok()) |
| 398 | .filter(|e| { |
| 399 | e.path() |
| 400 | .extension() |
| 401 | .and_then(|s| s.to_str()) |
| 402 | .map(|s| s == "journal") |
| 403 | .unwrap_or(false) |
| 404 | }) |
| 405 | .collect(); |
| 406 | assert_eq!( |
| 407 | root_files.len(), |
| 408 | 0, |
| 409 | "expected no .journal files directly in configured directory" |
| 410 | ); |
| 411 | |
| 412 | let machine_id = load_machine_id().unwrap(); |
| 413 | let machine_id_dir = target_dir.join(machine_id.as_simple().to_string()); |
| 414 | assert!( |
| 415 | machine_id_dir.is_dir(), |
| 416 | "machine-id subdirectory should be created under configured directory" |
| 417 | ); |
| 418 | |
| 419 | let machine_id_files: Vec<_> = fs::read_dir(&machine_id_dir) |
| 420 | .unwrap() |
| 421 | .filter_map(|e| e.ok()) |
| 422 | .filter(|e| { |
| 423 | e.path() |
| 424 | .extension() |
| 425 | .and_then(|s| s.to_str()) |
| 426 | .map(|s| s == "journal") |
| 427 | .unwrap_or(false) |
| 428 | }) |
| 429 | .collect(); |
| 430 | assert_eq!( |
| 431 | machine_id_files.len(), |
| 432 | 1, |
| 433 | "expected one .journal file under the machine-id directory" |
| 434 | ); |
| 435 | } |
| 436 | |
| 437 | #[test] |
| 438 | fn test_entry_realtime_override_is_clamped_monotonic() { |
| 439 | if !journalctl_available() { |
| 440 | eprintln!( |
| 441 | "journalctl not available; skipping test_entry_realtime_override_is_clamped_monotonic" |
| 442 | ); |
| 443 | return; |
| 444 | } |
| 445 | |
| 446 | let dir = TempDir::new().unwrap(); |
| 447 | let config = test_config(); |
| 448 | let mut log = Log::new(dir.path(), config).unwrap(); |
| 449 | |
| 450 | let first_entry = [b"MESSAGE=first" as &[u8], b"PRIORITY=6"]; |
| 451 | log.write_entry(&first_entry, None).unwrap(); |
| 452 | |
| 453 | let second_entry = [b"MESSAGE=second" as &[u8], b"PRIORITY=6"]; |
| 454 | let ts = EntryTimestamps::default().with_entry_realtime_usec(1); |
| 455 | log.write_entry_with_timestamps(&second_entry, ts).unwrap(); |
| 456 | log.sync().unwrap(); |
| 457 | |
| 458 | let rows = read_journal_json(&journal_file_path(&dir)); |
| 459 | |
| 460 | let mut first_rt = None; |
| 461 | let mut second_rt = None; |
| 462 | for row in rows { |
| 463 | match row.get("MESSAGE").and_then(|v| v.as_str()) { |
| 464 | Some("first") => first_rt = parse_u64_field(&row, "__REALTIME_TIMESTAMP"), |
| 465 | Some("second") => second_rt = parse_u64_field(&row, "__REALTIME_TIMESTAMP"), |
| 466 | _ => {} |
| 467 | } |
| 468 | } |
| 469 | |
| 470 | let first_rt = first_rt.expect("missing first entry realtime timestamp"); |
| 471 | let second_rt = second_rt.expect("missing second entry realtime timestamp"); |
| 472 | assert!( |
| 473 | second_rt > first_rt, |
| 474 | "second realtime timestamp must be strictly greater ({} !> {})", |
| 475 | second_rt, |
| 476 | first_rt |
| 477 | ); |
| 478 | } |
| 479 | |
| 480 | #[test] |
| 481 | fn test_entry_monotonic_override_is_clamped_monotonic() { |
| 482 | if !journalctl_available() { |
| 483 | eprintln!( |
| 484 | "journalctl not available; skipping test_entry_monotonic_override_is_clamped_monotonic" |
| 485 | ); |
| 486 | return; |
| 487 | } |
| 488 | |
| 489 | let dir = TempDir::new().unwrap(); |
| 490 | let config = test_config(); |
| 491 | let mut log = Log::new(dir.path(), config).unwrap(); |
| 492 | |
| 493 | let first_entry = [b"MESSAGE=mono-first" as &[u8], b"PRIORITY=6"]; |
| 494 | log.write_entry(&first_entry, None).unwrap(); |
| 495 | |
| 496 | let second_entry = [b"MESSAGE=mono-second" as &[u8], b"PRIORITY=6"]; |
| 497 | let ts = EntryTimestamps::default().with_entry_monotonic_usec(1); |
| 498 | log.write_entry_with_timestamps(&second_entry, ts).unwrap(); |
| 499 | log.sync().unwrap(); |
| 500 | |
| 501 | let rows = read_journal_json(&journal_file_path(&dir)); |
| 502 | |
| 503 | let mut first_mono = None; |
| 504 | let mut second_mono = None; |
| 505 | for row in rows { |
| 506 | match row.get("MESSAGE").and_then(|v| v.as_str()) { |
| 507 | Some("mono-first") => first_mono = parse_u64_field(&row, "__MONOTONIC_TIMESTAMP"), |
| 508 | Some("mono-second") => second_mono = parse_u64_field(&row, "__MONOTONIC_TIMESTAMP"), |
| 509 | _ => {} |
| 510 | } |
| 511 | } |
| 512 | |
| 513 | let first_mono = first_mono.expect("missing first entry monotonic timestamp"); |
| 514 | let second_mono = second_mono.expect("missing second entry monotonic timestamp"); |
| 515 | assert!( |
| 516 | second_mono > first_mono, |
| 517 | "second monotonic timestamp must be strictly greater ({} !> {})", |
| 518 | second_mono, |
| 519 | first_mono |
| 520 | ); |
| 521 | } |
| 522 | |
| 523 | #[test] |
| 524 | fn test_source_timestamp_is_preserved_with_entry_override() { |
| 525 | if !journalctl_available() { |
| 526 | eprintln!( |
| 527 | "journalctl not available; skipping test_source_timestamp_is_preserved_with_entry_override" |
| 528 | ); |
| 529 | return; |
| 530 | } |
| 531 | |
| 532 | let dir = TempDir::new().unwrap(); |
| 533 | let config = test_config(); |
| 534 | let mut log = Log::new(dir.path(), config).unwrap(); |
| 535 | |
| 536 | let source_ts = 123_456_u64; |
| 537 | let entry = [b"MESSAGE=source-ts" as &[u8], b"PRIORITY=6"]; |
| 538 | let ts = EntryTimestamps::default() |
| 539 | .with_entry_realtime_usec(1) |
| 540 | .with_source_realtime_usec(source_ts); |
| 541 | log.write_entry_with_timestamps(&entry, ts).unwrap(); |
| 542 | log.sync().unwrap(); |
| 543 | |
| 544 | let rows = read_journal_json(&journal_file_path(&dir)); |
| 545 | let row = rows |
| 546 | .iter() |
| 547 | .find(|row| row.get("MESSAGE").and_then(|v| v.as_str()) == Some("source-ts")) |
| 548 | .expect("missing source-ts entry"); |
| 549 | |
| 550 | let stored_source_ts = parse_u64_field(row, "_SOURCE_REALTIME_TIMESTAMP") |
| 551 | .expect("missing _SOURCE_REALTIME_TIMESTAMP"); |
| 552 | assert_eq!(stored_source_ts, source_ts); |
| 553 | } |
| 554 | |
| 555 | #[test] |
| 556 | fn test_monotonic_override_remains_strict_after_restart() { |
| 557 | if !journalctl_available() { |
| 558 | eprintln!( |
| 559 | "journalctl not available; skipping test_monotonic_override_remains_strict_after_restart" |
| 560 | ); |
| 561 | return; |
| 562 | } |
| 563 | |
| 564 | let dir = TempDir::new().unwrap(); |
| 565 | let config = test_config(); |
| 566 | |
| 567 | let first_monotonic = 1_000_000_u64; |
| 568 | { |
| 569 | let mut log = Log::new(dir.path(), config).unwrap(); |
| 570 | let first = [b"MESSAGE=restart-first" as &[u8], b"PRIORITY=6"]; |
| 571 | let ts = EntryTimestamps::default() |
| 572 | .with_entry_realtime_usec(first_monotonic) |
| 573 | .with_entry_monotonic_usec(first_monotonic); |
| 574 | log.write_entry_with_timestamps(&first, ts).unwrap(); |
| 575 | log.sync().unwrap(); |
| 576 | } |
| 577 | |
| 578 | { |
| 579 | let mut log = Log::new(dir.path(), test_config()).unwrap(); |
| 580 | let second = [b"MESSAGE=restart-second" as &[u8], b"PRIORITY=6"]; |
| 581 | // Equal monotonic override must still be bumped above the persisted tail value. |
| 582 | let ts = EntryTimestamps::default() |
| 583 | .with_entry_realtime_usec(1) |
| 584 | .with_entry_monotonic_usec(first_monotonic); |
| 585 | log.write_entry_with_timestamps(&second, ts).unwrap(); |
| 586 | log.sync().unwrap(); |
| 587 | } |
| 588 | |
| 589 | let mut first_seen = None; |
| 590 | let mut second_seen = None; |
| 591 | |
| 592 | for file in journal_file_paths(&dir) { |
| 593 | for row in read_journal_json(&file) { |
| 594 | match row.get("MESSAGE").and_then(|v| v.as_str()) { |
| 595 | Some("restart-first") => { |
| 596 | first_seen = parse_u64_field(&row, "__MONOTONIC_TIMESTAMP"); |
| 597 | } |
| 598 | Some("restart-second") => { |
| 599 | second_seen = parse_u64_field(&row, "__MONOTONIC_TIMESTAMP"); |
| 600 | } |
| 601 | _ => {} |
| 602 | } |
| 603 | } |
| 604 | } |
| 605 | |
| 606 | let first_seen = first_seen.expect("missing first entry monotonic timestamp"); |
| 607 | let second_seen = second_seen.expect("missing second entry monotonic timestamp"); |
| 608 | assert!( |
| 609 | second_seen > first_seen, |
| 610 | "second monotonic timestamp must be strictly greater after restart ({} !> {})", |
| 611 | second_seen, |
| 612 | first_seen |
| 613 | ); |
| 614 | } |
| 615 | |
| 616 | #[test] |
| 617 | fn test_data_entry_preserves_timestamp_overrides_when_remapping_is_emitted() { |
| 618 | if !journalctl_available() { |
| 619 | eprintln!( |
| 620 | "journalctl not available; skipping test_remapping_entry_respects_timestamp_overrides" |
| 621 | ); |
| 622 | return; |
| 623 | } |
| 624 | |
| 625 | let dir = TempDir::new().unwrap(); |
| 626 | let config = test_config(); |
| 627 | let mut log = Log::new(dir.path(), config).unwrap(); |
| 628 | |
| 629 | let entry = [ |
| 630 | b"MESSAGE=remap-ts" as &[u8], |
| 631 | b"PRIORITY=6", |
| 632 | b"foo.bar=value", |
| 633 | ]; |
| 634 | let realtime_override = Microseconds::now().get().saturating_add(1_000_000); |
| 635 | let monotonic_override = monotonic_now() |
| 636 | .expect("read monotonic clock") |
| 637 | .get() |
| 638 | .saturating_add(1_000_000); |
| 639 | let ts = EntryTimestamps::default() |
| 640 | .with_entry_realtime_usec(realtime_override) |
| 641 | .with_entry_monotonic_usec(monotonic_override); |
| 642 | log.write_entry_with_timestamps(&entry, ts).unwrap(); |
| 643 | log.sync().unwrap(); |
| 644 | |
| 645 | let rows = read_journal_json(&journal_file_path(&dir)); |
| 646 | let remap_row = rows |
| 647 | .iter() |
| 648 | .find(|row| row.get("ND_REMAPPING").and_then(|v| v.as_str()) == Some("1")) |
| 649 | .expect("missing remapping row"); |
| 650 | let data_row = rows |
| 651 | .iter() |
| 652 | .find(|row| row.get("MESSAGE").and_then(|v| v.as_str()) == Some("remap-ts")) |
| 653 | .expect("missing data row"); |
| 654 | |
| 655 | let remap_rt = |
| 656 | parse_u64_field(remap_row, "__REALTIME_TIMESTAMP").expect("missing remap realtime"); |
| 657 | let data_rt = parse_u64_field(data_row, "__REALTIME_TIMESTAMP").expect("missing data realtime"); |
| 658 | let remap_mono = |
| 659 | parse_u64_field(remap_row, "__MONOTONIC_TIMESTAMP").expect("missing remap monotonic"); |
| 660 | let data_mono = |
| 661 | parse_u64_field(data_row, "__MONOTONIC_TIMESTAMP").expect("missing data monotonic"); |
| 662 | |
| 663 | assert_eq!(remap_rt, realtime_override); |
| 664 | assert_eq!(data_rt, realtime_override.saturating_add(1)); |
| 665 | assert_eq!(remap_mono, monotonic_override); |
| 666 | assert_eq!(data_mono, monotonic_override.saturating_add(1)); |
| 667 | } |
| 668 | |
| 669 | #[test] |
| 670 | fn test_lifecycle_observer_reports_rotation_and_retention_deletion() { |
| 671 | let dir = tempfile::tempdir().expect("create temp dir"); |
| 672 | let config = Config::new( |
| 673 | Origin { |
| 674 | machine_id: None, |
| 675 | namespace: None, |
| 676 | source: journal_registry::Source::System, |
| 677 | }, |
| 678 | RotationPolicy::default().with_number_of_entries(1), |
| 679 | RetentionPolicy::default().with_number_of_journal_files(1), |
| 680 | ); |
| 681 | let observer = Arc::new(RecordingObserver::default()); |
| 682 | let mut log = Log::new(dir.path(), config) |
| 683 | .expect("create log") |
| 684 | .with_lifecycle_observer(observer.clone()); |
| 685 | |
| 686 | log.write_entry(&[b"MESSAGE=one"], None) |
| 687 | .expect("write first entry"); |
| 688 | log.write_entry(&[b"MESSAGE=two"], None) |
| 689 | .expect("write second entry"); |
| 690 | log.write_entry(&[b"MESSAGE=three"], None) |
| 691 | .expect("write third entry"); |
| 692 | |
| 693 | let events = observer |
| 694 | .events |
| 695 | .lock() |
| 696 | .expect("lock observer events") |
| 697 | .clone(); |
| 698 | let rotation_count = events |
| 699 | .iter() |
| 700 | .filter(|event| matches!(event, LogLifecycleEvent::Rotated { .. })) |
| 701 | .count(); |
| 702 | let deleted_files = events |
| 703 | .iter() |
| 704 | .find_map(|event| match event { |
| 705 | LogLifecycleEvent::RetainedDeleted { files } => Some(files.clone()), |
| 706 | _ => None, |
| 707 | }) |
| 708 | .unwrap_or_default(); |
| 709 | |
| 710 | assert_eq!( |
| 711 | rotation_count, 2, |
| 712 | "expected two rotations after three writes" |
| 713 | ); |
| 714 | assert_eq!(deleted_files.len(), 1, "expected one retained deletion"); |
| 715 | assert!( |
| 716 | !Path::new(deleted_files[0].path()).exists(), |
| 717 | "retained file should be gone from disk: {}", |
| 718 | deleted_files[0].path() |
| 719 | ); |
| 720 | } |
| 721 | |
| 722 | #[test] |
| 723 | fn test_lifecycle_observer_reports_missing_retention_deletions() { |
| 724 | let dir = tempfile::tempdir().expect("create temp dir"); |
| 725 | let config = Config::new( |
| 726 | Origin { |
| 727 | machine_id: None, |
| 728 | namespace: None, |
| 729 | source: journal_registry::Source::System, |
| 730 | }, |
| 731 | RotationPolicy::default().with_number_of_entries(1), |
| 732 | RetentionPolicy::default().with_number_of_journal_files(1), |
| 733 | ); |
| 734 | let observer = Arc::new(RecordingObserver::default()); |
| 735 | let mut log = Log::new(dir.path(), config) |
| 736 | .expect("create log") |
| 737 | .with_lifecycle_observer(observer.clone()); |
| 738 | |
| 739 | log.write_entry(&[b"MESSAGE=one"], None) |
| 740 | .expect("write first entry"); |
| 741 | log.write_entry(&[b"MESSAGE=two"], None) |
| 742 | .expect("write second entry"); |
| 743 | |
| 744 | let archived_path = journal_file_paths(&dir) |
| 745 | .into_iter() |
| 746 | .find(|path| path.to_string_lossy().contains('@')) |
| 747 | .expect("archived path after first rotation"); |
| 748 | fs::remove_file(&archived_path).expect("remove archived file before retention"); |
| 749 | |
| 750 | log.write_entry(&[b"MESSAGE=three"], None) |
| 751 | .expect("write third entry"); |
| 752 | |
| 753 | let events = observer.events.lock().expect("lock observer events"); |
| 754 | let retained = events |
| 755 | .iter() |
| 756 | .filter_map(|event| match event { |
| 757 | LogLifecycleEvent::RetainedDeleted { files } => Some(files), |
| 758 | _ => None, |
| 759 | }) |
| 760 | .flatten() |
| 761 | .collect::<Vec<_>>(); |
| 762 | |
| 763 | assert!( |
| 764 | retained |
| 765 | .iter() |
| 766 | .any(|file| Path::new(file.path()) == archived_path), |
| 767 | "files removed from chain/accounting must still be reported for retention follow-up" |
| 768 | ); |
| 769 | } |