jonaskruckenberg.de
Next Generation WASM Microkernel Operating System
1// Copyright 2025 Jonas Kruckenberg
2//
3// Licensed under the Apache License, Version 2.0, <LICENSE-APACHE or
4// http://apache.org/licenses/LICENSE-2.0> or the MIT license <LICENSE-MIT or
5// http://opensource.org/licenses/MIT>, at your option. This file may not be
6// copied, modified, or distributed except according to those terms.
7
8mod color;
9mod filter;
10mod log;
11mod registry;
12mod writer;
13
14use crate::state::try_global;
15use crate::tracing::writer::{MakeWriter, Semihosting};
16pub use ::tracing::*;
17use color::{Color, SetColor};
18use core::cell::{Cell, OnceCell};
19use core::fmt;
20use core::fmt::Write;
21use cpu_local::cpu_local;
22pub use filter::Filter;
23use registry::Registry;
24use spin::OnceLock;
25use tracing::field;
26use tracing_core::span::{Attributes, Current, Id, Record};
27use tracing_core::{Collect, Dispatch, Event, Interest, Level, LevelFilter, Metadata};
28
29static SUBSCRIBER: OnceLock<Subscriber> = OnceLock::new();
30
31cpu_local! {
32 /// Per-cpu indentation representing the span depth we're currently in
33 static OUTPUT_INDENT: Cell<usize> = Cell::new(0);
34 static CPUID: OnceCell<usize> = OnceCell::new();
35}
36
37pub fn per_cpu_init_early(cpuid: usize) {
38 CPUID.get_or_init(|| cpuid);
39}
40
41/// Perform early initialization of the tracing subsystem. This will enable printing of `log` and `span`
42/// events, but no spans yet.
43///
44/// This should be called as early in the boot process as possible.
45pub fn init_early() {
46 let subscriber = SUBSCRIBER.get_or_init(|| Subscriber {
47 // level_filter,
48 output: Output::new(Semihosting::new()),
49 lateinit: OnceLock::new(),
50 });
51 ::log::set_logger(subscriber).unwrap();
52
53 let subscriber = SUBSCRIBER.get().unwrap();
54 let dispatch = Dispatch::from_static(subscriber);
55 dispatch::set_global_default(dispatch).unwrap();
56}
57
58/// Fully initialize the subsystem, after this point tracing [`Span`]s will be processed as well.
59pub fn init(filter: Filter) {
60 let subscriber = SUBSCRIBER
61 .get()
62 .expect("tracing::init must be called after tracing::init_early");
63
64 ::log::set_max_level(match filter.max_level() {
65 LevelFilter::OFF => ::log::LevelFilter::Off,
66 LevelFilter::TRACE => ::log::LevelFilter::Trace,
67 LevelFilter::DEBUG => ::log::LevelFilter::Debug,
68 LevelFilter::INFO => ::log::LevelFilter::Info,
69 LevelFilter::WARN => ::log::LevelFilter::Warn,
70 LevelFilter::ERROR => ::log::LevelFilter::Error,
71 });
72
73 subscriber
74 .lateinit
75 .get_or_init(|| (Registry::default(), filter));
76}
77
78struct Subscriber {
79 // level_filter: LevelFilter,
80 output: Output<Semihosting>,
81 lateinit: OnceLock<(Registry, Filter)>,
82}
83
84impl Collect for Subscriber {
85 fn register_callsite(&self, meta: &'static Metadata<'static>) -> Interest {
86 if self.enabled(meta) {
87 Interest::always()
88 } else {
89 Interest::never()
90 }
91 }
92
93 fn enabled(&self, meta: &Metadata<'_>) -> bool {
94 if let Some((_, filter)) = self.lateinit.get() {
95 filter.enabled(meta)
96 } else {
97 true
98 }
99 }
100
101 fn max_level_hint(&self) -> Option<LevelFilter> {
102 if let Some((_, filter)) = self.lateinit.get() {
103 Some(filter.max_level())
104 } else {
105 None
106 }
107 }
108
109 fn new_span(&self, attrs: &Attributes<'_>) -> Id {
110 let Some((registry, _)) = self.lateinit.get() else {
111 tracing::warn!("tracing spans be only be tracked *after* tracing::init is called");
112 return Id::from_u64(0xDEAD);
113 };
114
115 let id = registry.new_span(attrs);
116 let meta = attrs.metadata();
117
118 let Some(mut writer) = self.output.writer(meta) else {
119 return id;
120 };
121
122 let _ = write_level(&mut writer, *meta.level());
123 let _ = write_cpu(&mut writer);
124 let _ = write_timestamp(&mut writer);
125
126 // let _ = writer.indent(IndentKind::NewSpan);
127 let _ = write!(
128 writer.with_fg_color(Color::BrightBlack),
129 "{}: ",
130 meta.target()
131 );
132 let _ = writer.with_bold().write_str(meta.name());
133 let _ = writer.with_fg_color(Color::BrightBlack).write_str(": ");
134
135 // ensure the span's fields are nicely indented if they wrap by
136 // "entering" and then "exiting"`````findent`
137 // the span.
138 self.output.enter();
139 attrs.record(&mut Visitor::new(180, &mut writer));
140 self.output.exit();
141
142 let _ = writer.write_char('\n');
143
144 id
145 }
146
147 fn record(&self, _span: &Id, _values: &Record<'_>) {
148 // TODO
149 }
150
151 fn record_follows_from(&self, _span: &Id, _follows: &Id) {
152 // TODO
153 }
154
155 fn event(&self, event: &Event<'_>) {
156 let meta = event.metadata();
157
158 let Some(mut writer) = self.output.writer(meta) else {
159 return;
160 };
161
162 let _ = write_level(&mut writer, *meta.level());
163 let _ = write_cpu(&mut writer);
164 let _ = write_timestamp(&mut writer);
165 // let _ = writer.indent(IndentKind::Event);
166 let _ = write!(
167 writer.with_fg_color(Color::BrightBlack),
168 "{}: ",
169 meta.target()
170 );
171 event.record(&mut Visitor::new(180, &mut writer));
172 let _ = writer.write_char('\n');
173 }
174
175 fn enter(&self, id: &Id) {
176 self.output.enter();
177 if let Some((registry, _)) = self.lateinit.get() {
178 registry.enter(id);
179 } else {
180 tracing::warn!("tracing spans be only be tracked *after* tracing::init is called");
181 }
182 }
183
184 fn exit(&self, id: &Id) {
185 self.output.exit();
186 if let Some((registry, _)) = self.lateinit.get() {
187 registry.exit(id);
188 } else {
189 tracing::warn!("tracing spans be only be tracked *after* tracing::init is called");
190 }
191 }
192
193 fn clone_span(&self, id: &Id) -> Id {
194 if let Some((registry, _)) = self.lateinit.get() {
195 registry.clone_span(id)
196 } else {
197 tracing::warn!("tracing spans be only be tracked *after* tracing::init is called");
198 Id::from_u64(0xDEAD)
199 }
200 }
201
202 fn try_close(&self, id: Id) -> bool {
203 if let Some((registry, _)) = self.lateinit.get() {
204 registry.try_close(id)
205 } else {
206 tracing::warn!("tracing spans be only be tracked *after* tracing::init is called");
207 false
208 }
209 }
210
211 fn current_span(&self) -> Current {
212 if let Some((registry, _)) = self.lateinit.get() {
213 registry.current_span()
214 } else {
215 tracing::warn!("tracing spans be only be tracked *after* tracing::init is called");
216 Current::none()
217 }
218 }
219}
220
221struct Output<W> {
222 make_writer: W,
223 max_line_len: usize,
224}
225
226impl<W> Output<W> {
227 fn new<'a>(make_writer: W) -> Self
228 where
229 W: MakeWriter<'a>,
230 {
231 Self {
232 max_line_len: make_writer.line_len() - 16,
233 make_writer,
234 }
235 }
236
237 #[inline]
238 fn enabled<'a>(&'a self, metadata: &Metadata<'_>) -> bool
239 where
240 W: MakeWriter<'a>,
241 {
242 self.make_writer.enabled(metadata)
243 }
244
245 #[inline]
246 fn enter(&self) {
247 OUTPUT_INDENT.set(OUTPUT_INDENT.get() + 1);
248 }
249
250 #[inline]
251 fn exit(&self) {
252 let prev = OUTPUT_INDENT.replace(OUTPUT_INDENT.get() - 1);
253 debug_assert!(prev > 0);
254 }
255
256 fn writer<'a>(&'a self, meta: &Metadata<'_>) -> Option<W::Writer>
257 where
258 W: MakeWriter<'a>,
259 {
260 self.make_writer.make_writer_for(meta)
261
262 // Some(Writer {
263 // writer,
264 // current_line: 0,
265 // max_line_len: self.max_line_len,
266 // indent: OUTPUT_INDENT.get(),
267 // })
268 }
269}
270
271#[inline]
272fn write_level<W>(w: &mut W, level: Level) -> fmt::Result
273where
274 W: Write + SetColor,
275{
276 w.write_char('[')?;
277 match level {
278 Level::TRACE => w.with_fg_color(Color::Cyan).write_str("TRACE"),
279 Level::DEBUG => w.with_fg_color(Color::Blue).write_str("DEBUG"),
280 Level::INFO => w.with_fg_color(Color::Green).write_str("INFO "),
281 Level::WARN => w.with_fg_color(Color::Yellow).write_str("WARN "),
282 Level::ERROR => {
283 w.set_bold(true);
284 let res = w.with_fg_color(Color::Red).write_str("ERROR");
285 w.set_bold(false);
286 res
287 }
288 }?;
289 w.write_char(']')
290}
291
292#[inline]
293fn write_cpu<W>(w: &mut W) -> fmt::Result
294where
295 W: Write,
296{
297 if let Some(cpuid) = CPUID.get() {
298 w.write_fmt(format_args!("[CPU {cpuid}]"))
299 } else {
300 w.write_fmt(format_args!("[CPU ??]"))
301 }
302}
303
304#[inline]
305fn write_timestamp<W>(w: &mut W) -> fmt::Result
306where
307 W: Write + SetColor,
308{
309 w.write_char('[')?;
310
311 if let Some(global) = try_global() {
312 let elapsed = global.time_origin.elapsed(&global.timer);
313 write!(
314 w.with_fg_color(Color::BrightBlack),
315 "{:>6}.{:06}",
316 elapsed.as_secs(),
317 elapsed.subsec_micros()
318 )?;
319 } else {
320 write!(w.with_fg_color(Color::BrightBlack), " ?.??????")?;
321 }
322
323 w.write_char(']')?;
324 Ok(())
325}
326
327struct Visitor<'writer, W> {
328 writer: &'writer mut W,
329 seen: bool,
330 newline: bool,
331 comma: bool,
332 max_line_len: usize,
333}
334
335impl<'writer, W> Visitor<'writer, W>
336where
337 W: Write,
338 &'writer mut W: SetColor,
339{
340 fn new(max_line_len: usize, writer: &'writer mut W) -> Self {
341 Self {
342 writer,
343 seen: false,
344 comma: false,
345 newline: false,
346 max_line_len,
347 }
348 }
349
350 fn record_inner(&mut self, field: &field::Field, val: &dyn fmt::Debug) {
351 // XXX(eliza): sad and gross hack
352 struct HasWrittenNewline<'a, W> {
353 writer: &'a mut W,
354 has_written_newline: bool,
355 has_written_punct: bool,
356 }
357
358 impl<W: Write> Write for HasWrittenNewline<'_, W> {
359 #[inline]
360 fn write_str(&mut self, s: &str) -> fmt::Result {
361 self.has_written_punct = s.ends_with(|ch: char| ch.is_ascii_punctuation());
362 if s.contains('\n') {
363 self.has_written_newline = true;
364 }
365 self.writer.write_str(s)
366 }
367 }
368
369 impl<W: Write> SetColor for HasWrittenNewline<'_, W>
370 where
371 W: SetColor,
372 {
373 fn fg_color(&self) -> Color {
374 self.writer.fg_color()
375 }
376
377 fn set_fg_color(&mut self, color: Color) {
378 self.writer.set_fg_color(color);
379 }
380
381 fn set_bold(&mut self, bold: bool) {
382 self.writer.set_bold(bold);
383 }
384 }
385
386 let mut writer = HasWrittenNewline {
387 writer: &mut self.writer,
388 has_written_newline: false,
389 has_written_punct: false,
390 };
391 let nl = if self.newline { '\n' } else { ' ' };
392
393 if field.name() == "message" {
394 if self.seen {
395 let _ = write!(writer.with_bold(), "{nl}{val:?}");
396 } else {
397 let _ = write!(writer.with_bold(), "{val:?}");
398 self.comma = !writer.has_written_punct;
399 }
400 self.seen = true;
401 return;
402 }
403
404 if self.comma {
405 let _ = writer.with_fg_color(Color::BrightBlack).write_char(',');
406 }
407
408 if self.seen {
409 let _ = writer.write_char(nl);
410 }
411
412 if !self.comma {
413 self.seen = true;
414 self.comma = true;
415 }
416
417 // pretty-print the name with dots in the punctuation color
418 let mut name_pieces = field.name().split('.');
419 if let Some(piece) = name_pieces.next() {
420 let _ = writer.write_str(piece);
421 for piece in name_pieces {
422 let _ = writer.with_fg_color(Color::BrightBlack).write_char('.');
423 let _ = writer.write_str(piece);
424 }
425 }
426
427 let _ = writer.with_fg_color(Color::BrightBlack).write_char('=');
428 let _ = write!(writer, "{val:?}");
429 self.newline |= writer.has_written_newline;
430 }
431}
432
433impl<'writer, W> field::Visit for Visitor<'writer, W>
434where
435 W: Write,
436 &'writer mut W: SetColor,
437{
438 #[inline]
439 fn record_u64(&mut self, field: &field::Field, val: u64) {
440 self.record_inner(field, &val);
441 }
442
443 #[inline]
444 fn record_i64(&mut self, field: &field::Field, val: i64) {
445 self.record_inner(field, &val);
446 }
447
448 #[inline]
449 fn record_bool(&mut self, field: &field::Field, val: bool) {
450 self.record_inner(field, &val);
451 }
452
453 #[inline]
454 fn record_str(&mut self, field: &field::Field, val: &str) {
455 if val.len() >= self.max_line_len {
456 self.newline = true;
457 }
458 self.record_inner(field, &val);
459 }
460
461 fn record_debug(&mut self, field: &field::Field, val: &dyn fmt::Debug) {
462 self.record_inner(field, val);
463 }
464}