#![cfg_attr(not(target_family = "unix"), no_std)]
#![crate_name = "klogger"]
#![crate_type = "lib"]
#[cfg(not(target_os = "none"))]
extern crate core;
extern crate heapless;
use core::fmt;
use core::ops;
#[macro_use]
pub mod macros;
extern crate log;
extern crate termcodes;
#[cfg(target_arch = "x86_64")]
extern crate x86;
#[cfg(any(
feature = "use_ioports",
all(target_arch = "x86_64", target_os = "none")
))]
#[path = "arch/x86.rs"]
mod arch;
#[cfg(all(not(feature = "use_ioports"), target_family = "unix"))]
#[path = "arch/unix.rs"]
mod arch;
use heapless::consts::*;
use heapless::{String, Vec};
use log::{Level, LevelFilter, Metadata, Record, SetLoggerError};
use termcodes::color;
const MHZ_TO_HZ: u64 = 1000 * 1000;
const KHZ_TO_HZ: u64 = 1000;
const _NS_PER_SEC: u64 = 1_000_000_000u64;
pub static SERIAL_LINE_MUTEX: spin::Mutex<bool> = spin::Mutex::new(false);
#[derive(Debug)]
pub struct Directive {
name: Option<String<U16>>,
level: LevelFilter,
}
#[derive(Debug)]
struct KLogger {
has_tsc: bool,
has_invariant_tsc: bool,
tsc_start: u64,
tsc_frequency: Option<u64>,
filter: Vec<Directive, U8>,
}
enum ElapsedTime {
Undetermined,
Nanoseconds(u64),
Cycles(u64),
}
impl fmt::Display for ElapsedTime {
fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
match self {
ElapsedTime::Nanoseconds(ns) => write!(f, "{:>10}", ns),
ElapsedTime::Cycles(cycles) => write!(f, "{:>10} cyc", cycles),
ElapsedTime::Undetermined => write!(f, ""),
}
}
}
impl KLogger {
fn elapsed(&self) -> ElapsedTime {
if self.has_tsc {
let cur = unsafe { x86::time::rdtsc() };
if self.has_invariant_tsc && self.tsc_frequency.is_some() {
let elapsed_cycles = cur - self.tsc_start;
let _tsc_frequency_hz = self.tsc_frequency.unwrap_or(1);
let ns = elapsed_cycles;
ElapsedTime::Nanoseconds(ns)
} else {
ElapsedTime::Cycles(cur)
}
} else {
ElapsedTime::Undetermined
}
}
pub fn filter(&self) -> LevelFilter {
return self
.filter
.iter()
.map(|d| d.level)
.max()
.unwrap_or(LevelFilter::Off);
}
}
impl log::Log for KLogger {
fn enabled(&self, metadata: &Metadata) -> bool {
let level = metadata.level();
let target = metadata.target();
enabled(&self.filter, level, target)
}
fn log(&self, record: &Record) {
if self.enabled(record.metadata()) {
let color = match record.level() {
Level::Error => color::AnsiValue(202),
Level::Warn => color::AnsiValue(167),
Level::Info => color::AnsiValue(136),
Level::Debug => color::AnsiValue(64),
Level::Trace => color::AnsiValue(32),
};
sprintln!(
"{}{}{} [{}{:5}{}] - {}: {}{}{}",
color::Fg(color::LightYellow),
self.elapsed(),
color::Fg(color::Reset),
color::Fg(color),
record.level(),
color::Fg(color::Reset),
record.target(),
color::Fg(color::LightWhite),
record.args(),
color::Fg(color::Reset),
);
}
}
fn flush(&self) {}
}
static mut LOGGER: KLogger = KLogger {
has_tsc: false,
has_invariant_tsc: false,
tsc_start: 0,
tsc_frequency: None,
filter: Vec(heapless::i::Vec::new()),
};
pub struct Writer<'a> {
#[allow(dead_code)]
line_lock: spin::MutexGuard<'a, bool>,
}
impl<'a> Writer<'a> {
pub fn get_module(module: &str) -> Writer<'a> {
use core::fmt::Write;
let line_lock = SERIAL_LINE_MUTEX.lock();
let mut ret = Writer { line_lock };
write!(&mut ret, "[{}] ", module).expect("Writer");
ret
}
pub fn get() -> Writer<'a> {
let line_lock = SERIAL_LINE_MUTEX.lock();
Writer { line_lock }
}
}
impl<'a> ops::Drop for Writer<'a> {
fn drop(&mut self) {
use core::fmt::Write;
#[allow(clippy::write_with_newline)]
write!(self, "\r\n").expect("Newline");
}
}
impl<'a> fmt::Write for Writer<'a> {
fn write_str(&mut self, s: &str) -> fmt::Result {
unsafe {
arch::puts(s);
}
Ok(())
}
}
pub struct WriterNoDrop;
impl WriterNoDrop {
pub fn get() -> WriterNoDrop {
WriterNoDrop
}
}
impl fmt::Write for WriterNoDrop {
fn write_str(&mut self, s: &str) -> fmt::Result {
unsafe {
arch::puts(s);
}
Ok(())
}
}
pub fn init(args: &str) -> Result<(), SetLoggerError> {
let cpuid = x86::cpuid::CpuId::new();
unsafe {
LOGGER.has_tsc = cpuid
.get_feature_info()
.map_or(false, |finfo| finfo.has_tsc());
LOGGER.has_invariant_tsc = cpuid
.get_extended_function_info()
.map_or(false, |efinfo| efinfo.has_invariant_tsc());
if LOGGER.has_tsc {
LOGGER.tsc_start = x86::time::rdtsc();
}
let tsc_frequency_hz: Option<u64> = cpuid.get_tsc_info().and_then(|tinfo| {
if tinfo.nominal_frequency() != 0 {
Some(tinfo.tsc_frequency())
} else if tinfo.numerator() != 0 && tinfo.denominator() != 0 {
cpuid.get_processor_frequency_info().map(|pinfo| {
let cpu_base_freq_hz = pinfo.processor_base_frequency() as u64 * MHZ_TO_HZ;
let crystal_hz =
cpu_base_freq_hz * tinfo.denominator() as u64 / tinfo.numerator() as u64;
crystal_hz * tinfo.numerator() as u64 / tinfo.denominator() as u64
})
} else {
None
}
});
let vmm_tsc_frequency_hz: Option<u64> = cpuid
.get_hypervisor_info()
.and_then(|hv| hv.tsc_frequency().map(|tsc_khz| tsc_khz as u64 * KHZ_TO_HZ));
if tsc_frequency_hz.is_some() {
LOGGER.tsc_frequency = tsc_frequency_hz;
} else if vmm_tsc_frequency_hz.is_some() {
LOGGER.tsc_frequency = vmm_tsc_frequency_hz;
}
parse_args(&mut LOGGER.filter, args);
log::set_logger(&LOGGER).map(|()| log::set_max_level(LOGGER.filter()))
}
}
pub fn putchar(c: char) {
unsafe {
arch::putc(c);
}
}
fn parse_args(filter: &mut Vec<Directive, U8>, spec: &str) {
let mut parts = spec.split('/');
let mods = parts.next();
if parts.next().is_some() {
sprintln!(
"warning: invalid logging spec '{}', \
ignoring it (too many '/'s)",
spec
);
return;
}
mods.map(|m| {
for s in m.split(',') {
if s.len() == 0 {
continue;
}
let mut parts = s.split('=');
let (log_level, name) =
match (parts.next(), parts.next().map(|s| s.trim()), parts.next()) {
(Some(part0), None, None) => {
match part0.parse() {
Ok(num) => (num, None),
Err(_) => (LevelFilter::max(), Some(part0)),
}
}
(Some(part0), Some(""), None) => (LevelFilter::max(), Some(part0)),
(Some(part0), Some(part1), None) => match part1.parse() {
Ok(num) => (num, Some(part0)),
_ => {
sprintln!(
"warning: invalid logging spec '{}', \
ignoring it",
part1
);
continue;
}
},
_ => {
sprintln!(
"warning: invalid logging spec '{}', \
ignoring it",
s
);
continue;
}
};
match filter.push(Directive {
name: match name {
None => None,
Some(name) => Some(String::from(name)),
},
level: log_level,
}) {
Ok(_) => {}
Err(e) => {
sprintln!("Unable to add new filter {:?}", e);
}
}
}
});
}
fn enabled(directives: &[Directive], level: Level, target: &str) -> bool {
for directive in directives.iter().rev() {
match directive.name {
Some(ref name) if !target.starts_with(&**name) => {}
Some(..) | None => return level <= directive.level,
}
}
false
}
#[cfg(test)]
mod test {
use heapless::consts::*;
use heapless::String;
use heapless::Vec as VEC;
use log::{Level, LevelFilter};
use super::{enabled, parse_args, Directive};
#[test]
fn filter_info() {
let mut filter: Vec<Directive> = Vec::new();
filter.push(Directive {
name: None,
level: LevelFilter::Info,
});
assert!(enabled(&filter, Level::Info, "crate1"));
assert!(!enabled(&filter, Level::Debug, "crate1"));
}
#[test]
fn filter_beginning_longest_match() {
let mut filter: Vec<Directive> = Vec::new();
filter.push(Directive {
name: Some(String::from("crate2")),
level: LevelFilter::Info,
});
filter.push(Directive {
name: Some(String::from("crate2::mod")),
level: LevelFilter::Debug,
});
filter.push(Directive {
name: Some(String::from("crate1::mod1")),
level: LevelFilter::Warn,
});
assert!(enabled(&filter, Level::Debug, "crate2::mod1"));
assert!(!enabled(&filter, Level::Debug, "crate2"));
}
#[test]
fn parse_default() {
let mut filter: VEC<Directive, U8> = VEC::new();
parse_args(&mut filter, "info,crate1::mod1=warn");
assert!(enabled(&filter, Level::Warn, "crate1::mod1"));
assert!(enabled(&filter, Level::Info, "crate2::mod2"));
}
#[test]
fn match_full_path() {
let logger = vec![
Directive {
name: Some(String::from("crate2")),
level: LevelFilter::Info,
},
Directive {
name: Some(String::from("crate1::mod1")),
level: LevelFilter::Warn,
},
];
assert!(enabled(&logger, Level::Warn, "crate1::mod1"));
assert!(!enabled(&logger, Level::Info, "crate1::mod1"));
assert!(enabled(&logger, Level::Info, "crate2"));
assert!(!enabled(&logger, Level::Debug, "crate2"));
}
#[test]
fn no_match() {
let logger = vec![
Directive {
name: Some(String::from("crate2")),
level: LevelFilter::Info,
},
Directive {
name: Some(String::from("crate1::mod1")),
level: LevelFilter::Warn,
},
];
assert!(!enabled(&logger, Level::Warn, "crate3"));
}
#[test]
fn match_beginning() {
let logger = vec![
Directive {
name: Some(String::from("crate2")),
level: LevelFilter::Info,
},
Directive {
name: Some(String::from("crate1::mod1")),
level: LevelFilter::Warn,
},
];
assert!(enabled(&logger, Level::Info, "crate2::mod1"));
}
#[test]
fn match_beginning_longest_match() {
let logger = vec![
Directive {
name: Some(String::from("crate2")),
level: LevelFilter::Info,
},
Directive {
name: Some(String::from("crate2::mod")),
level: LevelFilter::Debug,
},
Directive {
name: Some(String::from("crate1::mod1")),
level: LevelFilter::Warn,
},
];
assert!(enabled(&logger, Level::Debug, "crate2::mod1"));
assert!(!enabled(&logger, Level::Debug, "crate2"));
}
#[test]
fn match_default() {
let logger = vec![
Directive {
name: None,
level: LevelFilter::Info,
},
Directive {
name: Some(String::from("crate1::mod1")),
level: LevelFilter::Warn,
},
];
assert!(enabled(&logger, Level::Warn, "crate1::mod1"));
assert!(enabled(&logger, Level::Info, "crate2::mod2"));
}
#[test]
fn zero_level() {
let logger = vec![
Directive {
name: None,
level: LevelFilter::Info,
},
Directive {
name: Some(String::from("crate1::mod1")),
level: LevelFilter::Off,
},
];
assert!(!enabled(&logger, Level::Error, "crate1::mod1"));
assert!(enabled(&logger, Level::Info, "crate2::mod2"));
}
#[test]
fn parse_args_valid() {
let mut dirs: VEC<Directive, U8> = VEC::new();
parse_args(&mut dirs, "crate1::mod1=error,crate1::mod2,crate2=debug");
assert_eq!(dirs.len(), 3);
assert_eq!(dirs[0].name, Some(String::from("crate1::mod1")));
assert_eq!(dirs[0].level, LevelFilter::Error);
assert_eq!(dirs[1].name, Some(String::from("crate1::mod2")));
assert_eq!(dirs[1].level, LevelFilter::max());
assert_eq!(dirs[2].name, Some(String::from("crate2")));
assert_eq!(dirs[2].level, LevelFilter::Debug);
}
#[test]
fn parse_spec_invalid_crate() {
let mut dirs: VEC<Directive, U8> = VEC::new();
parse_args(&mut dirs, "crate1::mod1=warn=info,crate2=debug");
assert_eq!(dirs.len(), 1);
assert_eq!(dirs[0].name, Some(String::from("crate2")));
assert_eq!(dirs[0].level, LevelFilter::Debug);
}
#[test]
fn parse_spec_invalid_level() {
let mut dirs: VEC<Directive, U8> = VEC::new();
parse_args(&mut dirs, "crate1::mod1=noNumber,crate2=debug");
assert_eq!(dirs.len(), 1);
assert_eq!(dirs[0].name, Some(String::from("crate2")));
assert_eq!(dirs[0].level, LevelFilter::Debug);
}
#[test]
fn parse_spec_string_level() {
let mut dirs: VEC<Directive, U8> = VEC::new();
parse_args(&mut dirs, "crate1::mod1=wrong,crate2=warn");
assert_eq!(dirs.len(), 1);
assert_eq!(dirs[0].name, Some(String::from("crate2")));
assert_eq!(dirs[0].level, LevelFilter::Warn);
}
#[test]
fn parse_spec_empty_level() {
let mut dirs: VEC<Directive, U8> = VEC::new();
parse_args(&mut dirs, "crate1::mod1=wrong,crate2=");
assert_eq!(dirs.len(), 1);
assert_eq!(dirs[0].name, Some(String::from("crate2")));
assert_eq!(dirs[0].level, LevelFilter::max());
}
#[test]
fn parse_spec_global() {
let mut dirs: VEC<Directive, U8> = VEC::new();
parse_args(&mut dirs, "warn,crate2=debug");
assert_eq!(dirs.len(), 2);
assert_eq!(dirs[0].name, None);
assert_eq!(dirs[0].level, LevelFilter::Warn);
assert_eq!(dirs[1].name, Some(String::from("crate2")));
assert_eq!(dirs[1].level, LevelFilter::Debug);
}
}