kernel/io/console/
tracing.rs

1//! Implement `tracing` subscriber that outputs logs to the console.
2
3use core::fmt::{self, Write};
4
5use alloc::vec::Vec;
6use kernel_user_link::file::{BlockingMode, OpenOptions};
7use tracing::{info, span, Level};
8
9use crate::{
10    cmdline,
11    io::console,
12    sync::{once::OnceLock, spin::mutex::Mutex},
13};
14
15static LOG_FILE: OnceLock<Mutex<LogFile>> = OnceLock::new();
16
17const fn level_str(level: &Level, color: bool) -> &'static str {
18    if color {
19        match *level {
20            Level::TRACE => "\x1b[37mTRACE\x1b[0m",
21            Level::DEBUG => "\x1b[34mDEBUG\x1b[0m",
22            Level::INFO => "\x1b[32mINFO\x1b[0m",
23            Level::WARN => "\x1b[33mWARN\x1b[0m",
24            Level::ERROR => "\x1b[31mERROR\x1b[0m",
25        }
26    } else {
27        match *level {
28            Level::TRACE => "TRACE",
29            Level::DEBUG => "DEBUG",
30            Level::INFO => "INFO",
31            Level::WARN => "WARN",
32            Level::ERROR => "ERROR",
33        }
34    }
35}
36
37fn log_file() -> &'static Mutex<LogFile> {
38    LOG_FILE.get_or_init(|| Mutex::new(LogFile::default()))
39}
40
41pub fn flush_log_file() {
42    if let Some(log_file) = LOG_FILE.try_get() {
43        log_file.lock().flush()
44    }
45}
46
47pub fn shutdown_log_file() {
48    info!("Shutting down log file...");
49    if let Some(log_file) = LOG_FILE.try_get() {
50        log_file.lock().shutdown()
51    }
52}
53
54/// This require heap allocation sadly, as it uses `Arc` internally, even though it could be done
55/// without it
56pub fn init() {
57    tracing::dispatch::set_global_default(tracing::Dispatch::from_static(&CONSOLE_SUBSCRIBER))
58        .unwrap();
59}
60
61/// Move the log buffer into the heap, and we can store more data there
62pub fn move_to_dynamic_buffer() {
63    log_file().lock().move_to_dynamic_buffer()
64}
65
66static mut INITIAL_BUFFER: [u8; 0x1000] = [0; 0x1000];
67
68enum Buffer {
69    Static {
70        buffer: &'static mut [u8],
71        len: usize,
72    },
73    Dynamic(Vec<u8>),
74}
75
76impl Buffer {
77    fn static_buf() -> Self {
78        Buffer::Static {
79            // SAFETY: We are the only place where this buffer is used, and the `LogFile` is behind a mutex
80            buffer: unsafe { core::ptr::addr_of_mut!(INITIAL_BUFFER).as_mut().unwrap() },
81            len: 0,
82        }
83    }
84
85    fn move_to_dynamic(&mut self) {
86        match self {
87            Buffer::Static { buffer, len } => {
88                *self = Buffer::Dynamic(buffer[..*len].to_vec());
89            }
90            Buffer::Dynamic(_) => {}
91        }
92    }
93
94    fn is_empty(&self) -> bool {
95        match self {
96            Buffer::Static { len, .. } => *len == 0,
97            Buffer::Dynamic(v) => v.is_empty(),
98        }
99    }
100
101    fn as_bytes(&self) -> &[u8] {
102        match self {
103            Buffer::Static { buffer, len } => &buffer[..*len],
104            Buffer::Dynamic(v) => v,
105        }
106    }
107
108    fn clear(&mut self) {
109        match self {
110            Buffer::Static { len, .. } => *len = 0,
111            Buffer::Dynamic(v) => v.clear(),
112        }
113    }
114
115    fn push_str(&mut self, s: &str) {
116        match self {
117            Buffer::Static { buffer, len } => {
118                if len == &buffer.len() {
119                    return;
120                }
121
122                let mut i = *len;
123                let new_buf = s.bytes();
124                let needed_end = i + new_buf.len();
125                let end = if needed_end > buffer.len() {
126                    buffer.len()
127                } else {
128                    needed_end
129                };
130
131                if end == buffer.len() {
132                    println!("\n\nWARN: Buffer is full, cannot write more data");
133                }
134
135                for b in new_buf {
136                    buffer[i] = b;
137                    i += 1;
138                    if i == end {
139                        break;
140                    }
141                }
142                *len = i;
143            }
144            Buffer::Dynamic(v) => {
145                v.extend_from_slice(s.as_bytes());
146            }
147        }
148    }
149}
150
151struct LogFile {
152    file: Option<crate::fs::File>,
153    shutdown: bool,
154    buffer: Buffer,
155}
156
157impl LogFile {
158    pub fn move_to_dynamic_buffer(&mut self) {
159        self.buffer.move_to_dynamic();
160    }
161
162    pub fn flush(&mut self) {
163        if self.buffer.is_empty() || self.shutdown {
164            return;
165        }
166
167        if self.file.is_none() {
168            let file = crate::fs::File::open_blocking(
169                cmdline::cmdline().log_file,
170                BlockingMode::None,
171                OpenOptions::CREATE | OpenOptions::TRUNCATE | OpenOptions::WRITE,
172            );
173            // cannot create the file yet
174            match file {
175                // not yet initialized the filesystem mapping, wait until we do
176                Err(crate::fs::FileSystemError::FileNotFound) => return,
177                Err(e) => {
178                    println!("Failed to open log file: {:?}", e);
179                    return;
180                }
181                Ok(f) => {
182                    self.file = Some(f);
183                }
184            }
185        }
186
187        {
188            let file = self.file.as_mut().unwrap();
189
190            file.write(self.buffer.as_bytes()).unwrap();
191            file.flush().unwrap();
192        }
193
194        self.buffer.clear();
195    }
196
197    pub fn shutdown(&mut self) {
198        self.flush();
199        self.file = None;
200        self.shutdown = true;
201    }
202}
203
204impl Default for LogFile {
205    fn default() -> Self {
206        LogFile {
207            file: None,
208            shutdown: false,
209            buffer: Buffer::static_buf(),
210        }
211    }
212}
213
214impl Write for LogFile {
215    fn write_str(&mut self, s: &str) -> core::fmt::Result {
216        self.buffer.push_str(s);
217        Ok(())
218    }
219}
220
221struct MultiWriter<'a> {
222    console: &'a mut dyn Write,
223    file: &'a mut LogFile,
224}
225
226impl<'a> Write for MultiWriter<'a> {
227    fn write_str(&mut self, s: &str) -> core::fmt::Result {
228        self.console.write_str(s)?;
229        self.file.write_str(s)?;
230        Ok(())
231    }
232}
233
234static CONSOLE_SUBSCRIBER: ConsoleSubscriber = ConsoleSubscriber;
235
236pub struct ConsoleSubscriber;
237
238impl tracing::Collect for ConsoleSubscriber {
239    fn enabled(&self, metadata: &tracing::Metadata<'_>) -> bool {
240        let max: Level = cmdline::cmdline().max_log_level.into();
241        if metadata.level() > &max {
242            return false;
243        }
244        true
245    }
246
247    fn new_span(&self, _span: &span::Attributes<'_>) -> span::Id {
248        panic!("Spans are not supported")
249    }
250
251    fn record(&self, _span: &span::Id, _values: &span::Record<'_>) {
252        panic!("Spans are not supported")
253    }
254
255    fn record_follows_from(&self, _span: &span::Id, _follows: &span::Id) {
256        panic!("Spans are not supported")
257    }
258
259    fn event(&self, event: &tracing::Event<'_>) {
260        // TODO: filter by level
261        console::run_with_console(|console| {
262            let log_file = &mut log_file().lock();
263
264            // first write the level separately in order to control the colors
265            console.write_char('[')?;
266            log_file.write_char('[')?;
267            console.write_str(level_str(event.metadata().level(), true))?;
268            log_file.write_str(level_str(event.metadata().level(), false))?;
269
270            let mut writer = MultiWriter {
271                console,
272                file: log_file,
273            };
274            writer.write_str("  ")?;
275            writer.write_str(event.metadata().module_path().unwrap_or("unknown"))?;
276            writer.write_str("] ")?;
277
278            let mut visitor = Visitor::new(&mut writer);
279            event.record(&mut visitor);
280            visitor.finish()?;
281
282            writer.write_char('\n')?;
283
284            Ok::<_, fmt::Error>(())
285        })
286        .unwrap();
287    }
288
289    fn enter(&self, _span: &span::Id) {
290        panic!("Spans are not supported")
291    }
292
293    fn exit(&self, _span: &span::Id) {
294        panic!("Spans are not supported")
295    }
296
297    fn current_span(&self) -> tracing_core::span::Current {
298        tracing_core::span::Current::none()
299    }
300}
301
302struct Visitor<'a> {
303    console: &'a mut dyn Write,
304    result: Option<fmt::Error>,
305    is_first: bool,
306}
307
308impl<'a> Visitor<'a> {
309    fn new(console: &'a mut dyn Write) -> Self {
310        Self {
311            console,
312            result: None,
313            is_first: true,
314        }
315    }
316
317    fn finish(self) -> Result<(), fmt::Error> {
318        self.result.map_or(Ok(()), Err)
319    }
320}
321
322impl tracing::field::Visit for Visitor<'_> {
323    fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn alloc::fmt::Debug) {
324        if self.result.is_some() {
325            return;
326        }
327
328        if !self.is_first {
329            self.result = self.console.write_str(", ").err();
330        }
331
332        self.is_first = false;
333
334        if field.name() != "message" {
335            self.result = self
336                .console
337                .write_str(field.name())
338                .and_then(|_| self.console.write_str(" = "))
339                .err();
340        }
341
342        self.result = self.console.write_fmt(format_args!("{value:?}")).err();
343    }
344}
kernel/io/console/tracing.rs

kernel/io/console/
tracing.rs
