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