cadmus_core/logging/
kern.rs

1//! Kernel log capture.
2//!
3//! This module provides functionality to capture kernel logs and forward them
4//! to the tracing system.
5//!
6//! By default, if no platform-specific implementation is available, the module
7//! logs a debug message indicating that kernel log capture is not implemented
8//! for the current platform.
9//!
10//! ## Example Log Retreival
11//!
12//! ```sh
13//! [root@monza cadmus-tst]# cat logs/cadmus-019cf7e3-ef3a-7752-846f-83b92ac90634.json | jq '. | select(.target == "cadmus_core::logging::kern")| .fields.body' -r | tail
14//! Mar 16 18:31:49 kernel: [ 3854.620803] -(0)[0:swapper/0][wlan] In HIF ISR.
15//! Mar 16 18:31:50 kernel: [ 3855.188306] -(0)[2715:main_thread][wlan][2715]wlanDumpBssStatistics:(SW4 INFO) LLS BSS[0] BE: T[053937] R[000000] T_D[000000] T_F[000000]
16//! Mar 16 18:31:50 kernel: [ 3855.188331] -(0)[2715:main_thread][wlan][2715]wlanDumpBssStatistics:(SW4 INFO) LLS BSS[0] BK: T[001878] R[000000] T_D[000000] T_F[000000]
17//! Mar 16 18:31:50 kernel: [ 3855.188342] -(0)[2715:main_thread][wlan][2715]wlanDumpBssStatistics:(SW4 INFO) LLS BSS[0] VI: T[000000] R[000000] T_D[000000] T_F[000000]
18//! Mar 16 18:31:50 kernel: [ 3855.188353] -(0)[2715:main_thread][wlan][2715]wlanDumpBssStatistics:(SW4 INFO) LLS BSS[0] VO: T[000004] R[000000] T_D[000000] T_F[000000]
19//! Mar 16 18:31:50 kernel: [ 3855.188485] .(0)[2716:hif_thread]padding for alignment
20//! Mar 16 18:31:50 kernel: [ 3855.641193] .(0)[2715:main_thread][wlan][2715]nicEventLayer0ExtMagic:(NIC INFO) Amsdu update event ucWlanIdx[1] ucLen[0] ucMaxMpduCount[0]
21//! Mar 16 18:31:50 kernel: [ 3855.842447] .(0)[2715:main_thread][wlan][2715]nicEventLayer0ExtMagic:(NIC INFO) Amsdu update event ucWlanIdx[1] ucLen[0] ucMaxMpduCount[0]
22//! Mar 16 18:31:51 kernel: [ 3856.636823] -(0)[0:swapper/0]mtk_axi_interrupt: 252 callbacks suppressed
23//! Mar 16 18:31:51 kernel: [ 3856.636842] -(0)[0:swapper/0][wlan] In HIF ISR.
24//! ```
25
26/// Parsed kernel log entry with extracted fields.
27#[derive(Debug, PartialEq)]
28#[cfg(all(feature = "kobo", feature = "test"))]
29struct ParsedKernelLog {
30    /// The log timestamp (e.g., "Mar 16 17:30:46")
31    pub timestamp: String,
32    /// System uptime in seconds (e.g., "1293.879480")
33    pub uptime: String,
34    /// Process ID (e.g., "0")
35    pub pid: String,
36    /// Thread ID (e.g., "1697")
37    pub thread_id: String,
38    /// Thread name (e.g., "hif_thread", "main_thread", "kworker/0:3")
39    pub thread: String,
40    /// Kernel subsystem (e.g., "wlan") - may be empty
41    pub subsystem: String,
42    /// The actual log message
43    pub message: String,
44}
45
46/// Parses a Kobo kernel log line into structured fields.
47///
48/// Supports multiple log formats:
49/// - Kernel format: `<timestamp> kernel: [<uptime>] -(<pid>)[<thread_id>][<thread>][<subsystem>] <message>`
50/// - Service format: `<timestamp> <service>[<pid>]: <message>`
51///
52/// Returns `Some(ParsedKernelLog)` if the line matches the expected format,
53/// or `None` if the line doesn't match.
54#[cfg(all(feature = "kobo", feature = "test"))]
55fn parse_kern_log(line: &str) -> Option<ParsedKernelLog> {
56    use regex::Regex;
57
58    lazy_static::lazy_static! {
59        // Kernel log format: Mar 16 17:30:46 kernel: [ 1293.879480] -(0)[1697:hif_thread][wlan] In HIF ISR.
60        static ref KERNEL_RE: Regex = Regex::new(
61            r"^(\w{3}\s+\d{1,2}\s+\d{2}:\d{2}:\d{2})\s+\w+:\s+\[\s*(\d+\.\d+)\]\s+[.-]\((\d+)\)\[(\d+):([^\]]+)\](?:\[(\w+)\])?(?:\[\d+\])?\s*(.+)$"
62        ).unwrap();
63
64        // Generic service log format: Mar 16 17:39:06 wpa_supplicant[2000]: wlan0: CTRL-EVENT...
65        static ref SERVICE_RE: Regex = Regex::new(
66            r"^(\w{3}\s+\d{1,2}\s+\d{2}:\d{2}:\d{2})\s+(\w+)\[(\d+)\]:\s+(.+)$"
67        ).unwrap();
68    }
69
70    if let Some(caps) = KERNEL_RE.captures(line) {
71        return Some(ParsedKernelLog {
72            timestamp: caps.get(1)?.as_str().to_string(),
73            uptime: caps.get(2)?.as_str().to_string(),
74            pid: caps.get(3)?.as_str().to_string(),
75            thread_id: caps.get(4)?.as_str().to_string(),
76            thread: caps.get(5)?.as_str().to_string(),
77            subsystem: caps
78                .get(6)
79                .map(|m| m.as_str().to_string())
80                .unwrap_or_default(),
81            message: caps.get(7)?.as_str().to_string(),
82        });
83    }
84
85    if let Some(caps) = SERVICE_RE.captures(line) {
86        return Some(ParsedKernelLog {
87            timestamp: caps.get(1)?.as_str().to_string(),
88            uptime: "".to_string(),
89            pid: caps.get(3)?.as_str().to_string(),
90            thread_id: "".to_string(),
91            thread: caps.get(2)?.as_str().to_string(),
92            subsystem: "".to_string(),
93            message: caps.get(4)?.as_str().to_string(),
94        });
95    }
96
97    None
98}
99
100/// Spawns a background thread that captures kernel logs.
101///
102/// # Platform-specific behavior
103///
104/// ## Kobo
105/// When the `kobo` feature is enabled, this starts `klogd` to enable kernel
106/// logging, then runs `logread -F` to read kernel log messages line by line.
107///
108/// The kernel log format used on Kobo devices:
109/// `<timestamp> kernel: [<uptime>] -(<pid>)[<thread_id>][<thread>][<subsystem>] <message>`
110///
111/// Examples:
112/// - `Mar 16 17:30:46 kernel: [ 1293.879480] -(0)[1697:hif_thread][wlan] In HIF ISR.`
113/// - `Mar 16 17:30:46 kernel: [ 1293.131642] .(0)[1696:main_thread][wlan][1696]wlanPktTxDone:...`
114///
115/// Parsed fields:
116/// - `timestamp`: The log timestamp (e.g., "Mar 16 17:30:46")
117/// - `uptime`: System uptime in seconds (e.g., "1293.879480")
118/// - `pid`: Process ID (e.g., "0")
119/// - `thread_id`: Thread ID (e.g., "1697")
120/// - `thread`: Thread name (e.g., "hif_thread", "main_thread", "kworker/0:3")
121/// - `subsystem`: Kernel subsystem (e.g., "wlan") - may be empty
122/// - `message`: The actual log message
123#[cfg(all(feature = "kobo", feature = "test"))]
124pub fn spawn_kern_log_thread() {
125    use std::io::{BufRead, BufReader};
126    use std::process::{Command, Stdio};
127    use std::thread;
128
129    fn is_process_running(name: &str) -> bool {
130        Command::new("pgrep")
131            .arg("-x")
132            .arg(name)
133            .stdout(Stdio::null())
134            .stderr(Stdio::null())
135            .spawn()
136            .and_then(|mut child| child.wait().map(|status| status.success()))
137            .unwrap_or(false)
138    }
139
140    let klogd_running = is_process_running("klogd");
141    if klogd_running {
142        tracing::info!("klogd already running, reusing existing process");
143    }
144
145    thread::spawn(move || {
146        tracing::info!("Starting kernel log capture thread");
147
148        let klogd = if klogd_running {
149            None
150        } else {
151            match Command::new("klogd").spawn() {
152                Ok(child) => Some(child),
153                Err(e) => {
154                    tracing::warn!(error = %e, "Failed to start klogd");
155                    None
156                }
157            }
158        };
159
160        let mut child = match Command::new("logread")
161            .arg("-F")
162            .stdout(Stdio::piped())
163            .stderr(Stdio::null())
164            .spawn()
165        {
166            Ok(child) => child,
167            Err(e) => {
168                tracing::warn!(error = %e, "Failed to start logread command");
169                return;
170            }
171        };
172
173        let stdout = match child.stdout.take() {
174            Some(stdout) => stdout,
175            None => {
176                tracing::warn!("Failed to capture logread stdout");
177                return;
178            }
179        };
180
181        let reader = BufReader::new(stdout);
182
183        for line in reader.lines() {
184            match line {
185                Ok(line) => {
186                    if let Some(parsed) = parse_kern_log(&line) {
187                        tracing::debug!(
188                            body = %line,
189                            timestamp = %parsed.timestamp,
190                            uptime = %parsed.uptime,
191                            pid = %parsed.pid,
192                            thread_id = %parsed.thread_id,
193                            thread = %parsed.thread,
194                            subsystem = %parsed.subsystem,
195                            message = %parsed.message,
196                        );
197                    } else {
198                        tracing::debug!("{}", line);
199                    }
200                }
201                Err(e) => {
202                    tracing::warn!(error = %e, "Error reading from logread");
203                    break;
204                }
205            }
206        }
207
208        tracing::info!("Kernel log capture thread ending");
209
210        let _ = child.wait();
211        if let Some(mut klogd) = klogd {
212            let _ = klogd.kill();
213            let _ = klogd.wait();
214        }
215    });
216}
217
218#[cfg(all(not(feature = "kobo"), feature = "test"))]
219pub fn spawn_kern_log_thread() {
220    tracing::debug!("Kernel log capture is a no-op on non-Kobo platforms");
221}
222
223#[cfg(test)]
224#[cfg(all(feature = "kobo", feature = "test"))]
225mod tests {
226    use super::*;
227
228    #[test]
229    fn test_parse_kern_log_basic() {
230        let line = "Mar 16 17:30:46 kernel: [ 1293.879480] -(0)[1697:hif_thread][wlan] In HIF ISR.";
231        let parsed = parse_kern_log(line).unwrap();
232
233        assert_eq!(parsed.timestamp, "Mar 16 17:30:46");
234        assert_eq!(parsed.uptime, "1293.879480");
235        assert_eq!(parsed.pid, "0");
236        assert_eq!(parsed.thread_id, "1697");
237        assert_eq!(parsed.thread, "hif_thread");
238        assert_eq!(parsed.subsystem, "wlan");
239        assert_eq!(parsed.message, "In HIF ISR.");
240    }
241
242    #[test]
243    fn test_parse_kern_log_with_dot_prefix() {
244        let line = "Mar 16 17:30:46 kernel: [ 1293.131642] .(0)[1696:main_thread][wlan][1696]wlanPktTxDone:(TX INFO) TX DONE, Type[ARP] Tag[0xea769a80] WIDX:PID[1:15] Status[0], SeqNo: 15<1576 -> 1862> ";
245        let parsed = parse_kern_log(line).unwrap();
246
247        assert_eq!(parsed.timestamp, "Mar 16 17:30:46");
248        assert_eq!(parsed.uptime, "1293.131642");
249        assert_eq!(parsed.pid, "0");
250        assert_eq!(parsed.thread_id, "1696");
251        assert_eq!(parsed.thread, "main_thread");
252        assert_eq!(parsed.subsystem, "wlan");
253        assert!(parsed.message.contains("wlanPktTxDone"));
254    }
255
256    #[test]
257    fn test_parse_kern_log_without_subsystem() {
258        let line = "Mar 16 17:30:46 kernel: [ 1293.879468] -(0)[1697:hif_thread]mtk_axi_interrupt: 191 callbacks suppressed";
259        let parsed = parse_kern_log(line).unwrap();
260
261        assert_eq!(parsed.timestamp, "Mar 16 17:30:46");
262        assert_eq!(parsed.uptime, "1293.879468");
263        assert_eq!(parsed.pid, "0");
264        assert_eq!(parsed.thread_id, "1697");
265        assert_eq!(parsed.thread, "hif_thread");
266        assert_eq!(parsed.subsystem, "");
267        assert!(parsed.message.contains("mtk_axi_interrupt"));
268    }
269
270    #[test]
271    fn test_parse_kern_log_kworker() {
272        let line = "Mar 16 17:30:42 kernel: [ 1289.462571] .(0)[1409:kworker/0:3]bd71827-power bd_work_callback()";
273        let parsed = parse_kern_log(line).unwrap();
274
275        assert_eq!(parsed.timestamp, "Mar 16 17:30:42");
276        assert_eq!(parsed.uptime, "1289.462571");
277        assert_eq!(parsed.pid, "0");
278        assert_eq!(parsed.thread_id, "1409");
279        assert_eq!(parsed.thread, "kworker/0:3");
280        assert_eq!(parsed.subsystem, "");
281        assert!(parsed.message.contains("bd71827-power"));
282    }
283
284    #[test]
285    fn test_parse_kern_log_unparseable() {
286        let line = "Some random log line without expected format";
287        let parsed = parse_kern_log(line);
288        assert!(parsed.is_none());
289    }
290
291    #[test]
292    fn test_parse_kern_log_empty_line() {
293        let line = "";
294        let parsed = parse_kern_log(line);
295        assert!(parsed.is_none());
296    }
297
298    #[test]
299    fn test_parse_kern_log_wpa_supplicant() {
300        let line = "Mar 16 17:39:06 wpa_supplicant[2000]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=NL";
301        let parsed = parse_kern_log(line).unwrap();
302
303        assert_eq!(parsed.timestamp, "Mar 16 17:39:06");
304        assert_eq!(parsed.uptime, "");
305        assert_eq!(parsed.pid, "2000");
306        assert_eq!(parsed.thread_id, "");
307        assert_eq!(parsed.thread, "wpa_supplicant");
308        assert_eq!(parsed.subsystem, "");
309        assert!(parsed.message.contains("CTRL-EVENT-REGDOM-CHANGE"));
310    }
311
312    #[test]
313    fn test_parse_generic_service_log() {
314        let line = "Mar 16 17:39:06 GenericService[1500]: <info> connectivity check";
315        let parsed = parse_kern_log(line).unwrap();
316
317        assert_eq!(parsed.timestamp, "Mar 16 17:39:06");
318        assert_eq!(parsed.uptime, "");
319        assert_eq!(parsed.pid, "1500");
320        assert_eq!(parsed.thread_id, "");
321        assert_eq!(parsed.thread, "GenericService");
322        assert_eq!(parsed.subsystem, "");
323        assert!(parsed.message.contains("connectivity check"));
324    }
325}
cadmus_core/logging/kern.rs

cadmus_core/logging/
kern.rs
