Use crate `log`. Print with color in console.

Cargo.toml

@@ -25,6 +25,7 @@ linked_list_allocator = "0.5.0"
 redox_syscall = "0.1.37"
 xmas-elf = "0.6"
 arrayvec = { version = "0.4.7", default-features = false }
+log = "0.4"
 simple-filesystem = { path = "../simple-filesystem" }
 
 [build-dependencies]

src/arch/x86_64/driver/acpi/mod.rs

@@ -9,7 +9,7 @@ pub fn init() -> Result<AcpiResult, AcpiError> {
 	if rsdp.rsdt_physical_address > PHYSICAL_MEMORY_LIMIT {
 		return Err(AcpiError::NotMapped);
 	}
-	debug!("RSDT at {:#x}", rsdp.rsdt_physical_address);
+    trace!("RSDT at {:#x}", rsdp.rsdt_physical_address);
 	let rsdt = unsafe{ &*(rsdp.rsdt_physical_address as *const Rsdt) };
 	let mut madt: Option<&'static Madt> = None;
 	for i in 0 .. rsdt.entry_count() {
@@ -18,12 +18,12 @@ pub fn init() -> Result<AcpiResult, AcpiError> {
 			return Err(AcpiError::NotMapped);
 		}
 		let header = unsafe{ &*(entry as *const Header) };
-		// debug!("{:?}", header);
+        trace!("{:?}", header);
 		if &header.signature == b"APIC" {
 			madt = Some(unsafe{ &*(entry as *const Madt) });
 		}
 	}
-	debug!("{:?}", madt);
+    trace!("{:?}", madt);
 	config_smp(madt.expect("acpi: madt not found."))
 }
 
@@ -53,7 +53,7 @@ fn config_smp(madt: &'static Madt) -> Result<AcpiResult, AcpiError> {
 	let mut cpu_acpi_ids: [u8; MAX_CPU_NUM] = [0; MAX_CPU_NUM];
 	let mut ioapic_id: Option<u8> = None;
 	for entry in madt.entry_iter() {
-		debug!("{:?}", entry);
+        trace!("{:?}", entry);
 		match &entry {
 			&MadtEntry::LocalApic(ref lapic) => {
 				cpu_acpi_ids[cpu_num as usize] = lapic.id;
@@ -77,7 +77,7 @@ fn config_smp(madt: &'static Madt) -> Result<AcpiResult, AcpiError> {
 fn find_rsdp() -> Option<&'static Rsdp> {
 	use util::{Checkable, find_in_memory};
 	let ebda = unsafe { *(0x40E as *const u16) as usize } << 4;
-	debug!("EBDA at {:#x}", ebda);
+    trace!("EBDA at {:#x}", ebda);
 
 	macro_rules! return_if_find_in {
 		($begin:expr, $end:expr) => (

src/arch/x86_64/driver/apic/ioapic.rs

@@ -19,7 +19,7 @@ pub fn init(ioapic_id: u8)
 	for i in 0.. ioapic.maxintr() + 1 {
 		ioapic.write_irq(i, RedirectionEntry::DISABLED, 0);
 	}
-	debug!("ioapic: init end");
+    info!("ioapic: init end");
 }
 
 const IOAPIC_ADDRESS  : u32 = 0xFEC00000;   // Default physical address of IO APIC
@@ -81,7 +81,7 @@ impl IoApic {
 	}
 	pub fn enable(&mut self, irq: u8, cpunum: u8)
 	{
-		debug!("ioapic: enable irq {} @ cpu{}", irq, cpunum);
+        info!("ioapic: enable irq {} @ cpu{}", irq, cpunum);
 		// Mark interrupt edge-triggered, active high,
 		// enabled, and routed to the given cpunum,
 		// which happens to be that cpu's APIC ID.

src/arch/x86_64/driver/apic/lapic.rs

@@ -13,11 +13,11 @@ pub fn set_addr(lapic_addr: *const ()) {
 }
 
 pub fn init() {
-	debug!("WARNING: lapic::init use C lib");
+    warn!("lapic::init use C lib");
 	unsafe {
 		lapicinit();
 	}
-	debug!("lapic: init end");
+    info!("lapic: init end");
 }
 
 pub fn ack(_irq: u8) {
@@ -27,7 +27,7 @@ pub fn ack(_irq: u8) {
 }
 
 pub fn start_ap(apicid: u8, addr: u32) {
-	debug!("WARNING: lapic::start_ap use C lib");
+    warn!("lapic::start_ap use C lib");
 	unsafe {
 		lapicstartap(apicid, addr);
 	}

src/arch/x86_64/driver/mod.rs

@@ -19,7 +19,7 @@ pub fn init(mut page_map: impl FnMut(usize)) -> acpi::AcpiResult {
 
     let acpi = acpi::init().expect("Failed to init ACPI");
     assert_eq!(acpi.lapic_addr as usize, 0xfee00000);
-    debug!("{:?}", acpi);
+    trace!("acpi = {:?}", acpi);
 
     if cfg!(feature = "use_apic") {
         pic::disable();

src/arch/x86_64/driver/pic.rs

@@ -10,7 +10,7 @@ pub fn disable() {
     // Mask all interrupts (Copy from xv6 x86_64)
     MASTER.lock().cmd.write(0xFF);
     SLAVE.lock().cmd.write(0xFF);
-    debug!("pic: disabled");
+    info!("pic: disabled");
 }
 
 pub fn init() {
@@ -43,7 +43,7 @@ pub fn init() {
     master.ack();
     slave.ack();
 
-    debug!("pic: init end");    
+    info!("pic: init end");
 }
 
 pub fn enable_irq(irq: u8)

src/arch/x86_64/driver/pit.rs

@@ -5,7 +5,7 @@ static mut PIT: Pit = Pit::new(0x40);
 pub fn init() {
     assert_has_not_been_called!("pit::init must be called only once");
     unsafe{ PIT.init(100); }
-    debug!("pit: init end");
+    info!("pit: init end");
 }
 
 struct Pit {

src/arch/x86_64/driver/vga.rs

@@ -8,7 +8,7 @@ pub const VGA_BUFFER: Unique<VgaBuffer> = unsafe{
 };
 
 #[allow(dead_code)]
-#[derive(Debug, Clone, Copy)]
+#[derive(Debug, Clone, Copy, Eq, PartialEq)]
 #[repr(u8)]
 pub enum Color {
     Black      = 0,

src/arch/x86_64/gdt.rs

@@ -58,10 +58,10 @@ static mut TSS_PTR: Unique<TaskStateSegment> = unsafe{ Unique::new_unchecked(0 a
 ///
 /// 每次进入用户态前，都要调用此函数，才能保证正确返回内核态
 pub fn set_ring0_rsp(rsp: usize) {
-//    debug!("gdt.set_ring0_rsp: {:#x}", rsp);
+    trace!("gdt.set_ring0_rsp: {:#x}", rsp);
     unsafe {
         TSS_PTR.as_mut().privilege_stack_table[0] = VirtualAddress(rsp);
-//        debug!("TSS:\n{:?}", TSS_PTR.as_ref());
+        trace!("TSS:\n{:?}", TSS_PTR.as_ref());
     }
 }
 

src/arch/x86_64/interrupt/handler.rs

@@ -5,12 +5,12 @@ use self::template::*;
 pub type TrapFrame = InterruptStackP;
 
 interrupt_stack!(breakpoint, stack, {
-    println!("\nEXCEPTION: Breakpoint");
+    error!("\nEXCEPTION: Breakpoint");
     stack.dump();
 });
 
 interrupt_error_p!(double_fault, stack, {
-    println!("\nEXCEPTION: Double Fault");
+    error!("\nEXCEPTION: Double Fault");
     stack.dump();
     loop {}
 });
@@ -18,7 +18,7 @@ interrupt_error_p!(double_fault, stack, {
 interrupt_error_p!(page_fault, stack, {
     use x86_64::registers::control_regs::cr2;
     let addr = cr2().0;
-    println!("\nEXCEPTION: Page Fault @ {:#x}, code: {:#x}", addr, stack.code);
+    error!("\nEXCEPTION: Page Fault @ {:#x}, code: {:#x}", addr, stack.code);
 
     use memory::page_fault_handler;
     if page_fault_handler(addr) {
@@ -30,13 +30,13 @@ interrupt_error_p!(page_fault, stack, {
 });
 
 interrupt_error_p!(general_protection_fault, stack, {
-    println!("\nEXCEPTION: General Protection Fault");
+    error!("\nEXCEPTION: General Protection Fault");
     stack.dump();
     loop {}
 });
 
 interrupt_stack_p!(invalid_opcode, stack, {
-    println!("\nEXCEPTION: Invalid Opcode");
+    error!("\nEXCEPTION: Invalid Opcode");
     stack.dump();
     loop {}
 });
@@ -50,23 +50,23 @@ use super::consts::*;
 
 interrupt!(keyboard, {
     use arch::driver::keyboard;
-    println!("\nInterupt: Keyboard");
+    info!("\nInterupt: Keyboard");
     let c = keyboard::get();
-    println!("Key = '{}' {}", c as u8 as char, c);
+    info!("Key = '{}' {}", c as u8 as char, c);
     ack(IRQ_KBD);
 
 });
 
 interrupt!(com1, {
     use arch::driver::serial::COM1;
-    println!("\nInterupt: COM1");
+    info!("\nInterupt: COM1");
     COM1.lock().receive();
     ack(IRQ_COM1);
 });
 
 interrupt!(com2, {
     use arch::driver::serial::COM2;
-    println!("\nInterupt: COM2");
+    info!("\nInterupt: COM2");
     COM2.lock().receive();
     ack(IRQ_COM2);
 });
@@ -82,7 +82,7 @@ interrupt_switch!(timer, stack, rsp, {
     static mut tick: usize = 0;
     unsafe{ tick += 1; }
     if tick % 100 == 0 {
-        println!("\nInterupt: Timer\ntick = {}", tick);
+        info!("\nInterupt: Timer\ntick = {}", tick);
         use process;
         process::schedule(&mut rsp);
     }
@@ -91,7 +91,7 @@ interrupt_switch!(timer, stack, rsp, {
 
 interrupt_stack_p!(to_user, stack, {
     use arch::gdt;
-    println!("\nInterupt: To User");
+    info!("\nInterupt: To User");
     let rsp = unsafe{ (stack as *const InterruptStackP).offset(1) } as usize;
     gdt::set_ring0_rsp(rsp);
     stack.iret.cs = gdt::UCODE_SELECTOR.0 as usize;
@@ -100,22 +100,22 @@ interrupt_stack_p!(to_user, stack, {
 });
 
 interrupt_stack_p!(to_kernel, stack, {
-//    println!("rsp @ {:#x}", stack as *const _ as usize);
+//    info!("rsp @ {:#x}", stack as *const _ as usize);
     use arch::gdt;
-    println!("\nInterupt: To Kernel");
+    info!("\nInterupt: To Kernel");
     stack.iret.cs = gdt::KCODE_SELECTOR.0 as usize;
     stack.iret.ss = gdt::KDATA_SELECTOR.0 as usize;
 });
 
 interrupt_switch!(syscall, stack, rsp, {
-    println!("\nInterupt: Syscall {:#x?}", stack.scratch.rax);
+    info!("\nInterupt: Syscall {:#x?}", stack.scratch.rax);
     use syscall::syscall;
     let ret = syscall(stack, &mut rsp, false);
     stack.scratch.rax = ret as usize;
 });
 
 interrupt_switch!(syscall32, stack, rsp, {
-//    println!("\nInterupt: Syscall {:#x?}", stack.scratch.rax);
+//    info!("\nInterupt: Syscall {:#x?}", stack.scratch.rax);
     use syscall::syscall;
     let ret = syscall(stack, &mut rsp, true);
     stack.scratch.rax = ret as usize;

src/arch/x86_64/paging/cow.rs

@@ -169,8 +169,6 @@ mod test {
     use super::*;
 
     pub fn test_cow() {
-        debug!("Testing: Copy on write");
-
         let mut page_table = unsafe { ActivePageTable::new() };
         let frame = alloc_frame();
 
@@ -208,7 +206,5 @@ mod test {
                    "The last write reference should not allocate new frame.");
         assert_eq!(unsafe { *(0x1000 as *const u8) }, 2);
         assert_eq!(unsafe { *(0x2000 as *const u8) }, 3);
-
-        debug!("Success: Copy on write");
     }
 }

src/fs.rs

@@ -35,7 +35,7 @@ pub fn load_sfs() {
     let sfs = SimpleFileSystem::open(Box::new(slice)).unwrap();
     let root = sfs.root_inode();
     let files = root.borrow().list().unwrap();
-    debug!("Loading programs: {:?}", files);
+    trace!("Loading programs: {:?}", files);
 
 //    for name in files.iter().filter(|&f| f != "." && f != "..") {
     for name in files.iter().filter(|&f| f == "forktest") {

src/io/mod.rs

@@ -3,15 +3,10 @@ use arch::driver::serial::COM1;
 
 mod vga_writer;
 
-macro_rules! _debug {
+pub fn init() {
-    ($($arg:tt)*) => ({
+    static LOGGER: SimpleLogger = SimpleLogger;
-        $crate::io::debug(format_args!($($arg)*));
+    log::set_logger(&LOGGER).unwrap();
-    });
+    log::set_max_level(LevelFilter::Debug);
-}
-
-macro_rules! debug {
-    ($fmt:expr) => (_debug!(concat!($fmt, "\n")));
-    ($fmt:expr, $($arg:tt)*) => (_debug!(concat!($fmt, "\n"), $($arg)*));
 }
 
 macro_rules! print {
@@ -25,6 +20,14 @@ macro_rules! println {
     ($fmt:expr, $($arg:tt)*) => (print!(concat!($fmt, "\n"), $($arg)*));
 }
 
+/// Add escape sequence to print with color in Linux console
+macro_rules! with_color {
+    ($args: ident, $color: ident) => {{
+        let (show, code) = color_to_console_code($color);
+        format_args!("{}[{};{}m{}{}[0m", 27 as char, show.clone(), code + 30, $args, 27 as char)
+    }};
+}
+
 use arch::driver::vga::Color;
 
 fn print_in_color(args: fmt::Arguments, color: Color) {
@@ -38,19 +41,17 @@ fn print_in_color(args: fmt::Arguments, color: Color) {
     // TODO: 解决死锁问题
     // 若进程在持有锁时被中断，中断处理程序请求输出，就会死锁
     unsafe{ COM1.force_unlock(); }
-    COM1.lock().write_fmt(args).unwrap();
+    COM1.lock().write_fmt(with_color!(args, color)).unwrap();
 }
 
 pub fn print(args: fmt::Arguments) {
-    print_in_color(args, Color::LightGray);
+    use core::fmt::Write;
-}
+    unsafe { COM1.force_unlock(); }
-
+    COM1.lock().write_fmt(args).unwrap();
-pub fn debug(args: fmt::Arguments) {
-    print_in_color(args, Color::LightRed);
 }
 
 pub fn write(fd: usize, base: *const u8, len: usize) -> i32 {
-    debug!("write: fd: {}, base: {:?}, len: {:#x}", fd, base, len);
+    info!("write: fd: {}, base: {:?}, len: {:#x}", fd, base, len);
     use core::slice;
     use core::str;
     let slice = unsafe { slice::from_raw_parts(base, len) };
@@ -60,7 +61,7 @@ pub fn write(fd: usize, base: *const u8, len: usize) -> i32 {
 
 pub fn open(path: *const u8, flags: usize) -> i32 {
     let path = unsafe { from_cstr(path) };
-    debug!("open: path: {:?}, flags: {:?}", path, flags);
+    info!("open: path: {:?}, flags: {:?}", path, flags);
     match path {
         "stdin:" => 0,
         "stdout:" => 1,
@@ -69,7 +70,7 @@ pub fn open(path: *const u8, flags: usize) -> i32 {
 }
 
 pub fn close(fd: usize) -> i32 {
-    debug!("close: fd: {:?}", fd);
+    info!("close: fd: {:?}", fd);
     0
 }
 
@@ -77,4 +78,55 @@ pub unsafe fn from_cstr(s: *const u8) -> &'static str {
     use core::{str, slice};
     let len = (0usize..).find(|&i| *s.offset(i as isize) == 0).unwrap();
     str::from_utf8(slice::from_raw_parts(s, len)).unwrap()
+}
+
+use log;
+use log::{Record, Level, Metadata, Log, SetLoggerError, LevelFilter};
+
+struct SimpleLogger;
+
+impl Log for SimpleLogger {
+    fn enabled(&self, metadata: &Metadata) -> bool {
+        true
+//        metadata.level() <= Level::Info
+    }
+    fn log(&self, record: &Record) {
+        if self.enabled(record.metadata()) {
+            print_in_color(format_args!("{}\n", record.args()), Color::from(record.level()));
+        }
+    }
+    fn flush(&self) {}
+}
+
+impl From<Level> for Color {
+    fn from(level: Level) -> Self {
+        match level {
+            Level::Error => Color::Red,
+            Level::Warn => Color::Yellow,
+            Level::Info => Color::Blue,
+            Level::Debug => Color::LightRed,
+            Level::Trace => Color::DarkGray,
+        }
+    }
+}
+
+fn color_to_console_code(color: Color) -> (u8, u8) {
+    match color {
+        Color::Black => (0, 0),
+        Color::Blue => (0, 4),
+        Color::Green => (0, 2),
+        Color::Cyan => (0, 6),
+        Color::Red => (0, 1),
+        Color::Magenta => (0, 5),
+        Color::Brown => (0, 3),
+        Color::LightGray => (1, 7),
+        Color::DarkGray => (0, 7),
+        Color::LightBlue => (1, 4),
+        Color::LightGreen => (1, 2),
+        Color::LightCyan => (1, 6),
+        Color::LightRed => (1, 1),
+        Color::Pink => (1, 5),
+        Color::Yellow => (1, 3),
+        Color::White => (1, 0),
+    }
 }

src/lib.rs

@@ -34,6 +34,8 @@ extern crate bit_field;
 extern crate syscall as redox_syscall;
 extern crate xmas_elf;
 extern crate arrayvec;
+#[macro_use]
+extern crate log;
 extern crate simple_filesystem;
 
 #[macro_use]    // print!
@@ -57,6 +59,7 @@ mod arch;
 #[no_mangle]
 pub extern "C" fn rust_main(multiboot_information_address: usize) -> ! {
     arch::cpu::init();
+    io::init();
 
     // ATTENTION: we have a very small stack and no guard page
     println!("Hello World{}", "!");
@@ -69,8 +72,7 @@ pub extern "C" fn rust_main(multiboot_information_address: usize) -> ! {
     arch::gdt::init();
     arch::idt::init();
 
-    arch::paging::test_cow();
+    test!(cow);
-
     test!(global_allocator);
     test!(guard_page);
     test!(find_mp);
@@ -161,4 +163,9 @@ mod test {
 
         println!("It did not crash!");
     }
+
+    pub fn cow() {
+        use arch;
+        arch::paging::test_cow();
+    }
 }

src/memory/mod.rs

@@ -36,7 +36,7 @@ pub fn page_fault_handler(addr: VirtAddr) -> bool {
 pub fn init(boot_info: BootInformation) -> MemoryController {
     assert_has_not_been_called!("memory::init must be called only once");
 
-    debug!("{:?}", boot_info);
+    info!("{:?}", boot_info);
 
     let memory_map_tag = boot_info.memory_map_tag().expect(
         "Memory map tag required");

src/memory/stack_allocator.rs

@@ -84,6 +84,6 @@ impl Stack {
 
 impl Drop for Stack {
     fn drop(&mut self) {
-        debug!("WARNING: stack leak: {:#x?}", self);
+        warn!("stack leak: {:#x?}", self);
     }
 }

src/process/mod.rs

@@ -54,13 +54,12 @@ pub fn sys_fork(tf: &TrapFrame) -> i32 {
     let mut mc = MC.try().unwrap().lock();
     let new = processor.current().fork(tf, &mut mc);
     let pid = processor.add(new);
-    debug!("fork: {}", pid);
+    info!("fork: {} -> {}", processor.current().pid, pid);
     pid as i32
 }
 
 /// Wait the process exit. Return the exit code.
 pub fn sys_wait(rsp: &mut usize, pid: usize) -> i32 {
-    debug!("wait: {}", pid);
     let mut processor = PROCESSOR.try().unwrap().lock();
     let target = match pid {
         0 => WaitTarget::AnyChild,

src/process/process.rs

@@ -89,7 +89,7 @@ impl Process {
         memory_set.push(MemoryArea::new(user_stack_buttom, user_stack_top,
                                         EntryFlags::WRITABLE | EntryFlags::NO_EXECUTE | EntryFlags::USER_ACCESSIBLE, "user_stack"));
         let page_table = mc.make_page_table(&memory_set);
-//        debug!("{:#x?}", memory_set);
+        trace!("{:#x?}", memory_set);
 
         let entry_addr = match elf.header.pt2 {
             HeaderPt2::Header32(header) => header.entry_point as usize,
@@ -120,7 +120,7 @@ impl Process {
         let kstack = mc.alloc_stack(7).unwrap();
         let tf = TrapFrame::new_user_thread(entry_addr, user_stack_top - 8, is32);
         let rsp = kstack.push_at_top(tf);
-//        debug!("rsp = {:#x}", rsp);
+        trace!("rsp = {:#x}", rsp);
 
         Process {
             pid: 0,

src/process/processor.rs

@@ -81,7 +81,7 @@ impl Processor {
             from.page_table = Some(old_table);
         }
 
-        debug!("Processor: switch from {} to {}\n  rsp: {:#x} -> {:#x}", pid0, pid, rsp0, rsp);
+        info!("Processor: switch from {} to {}\n  rsp: {:#x} -> {:#x}", pid0, pid, rsp0, rsp);
     }
 
     fn get(&self, pid: Pid) -> &Process {
@@ -108,7 +108,7 @@ impl Processor {
 
     pub fn exit(&mut self, pid: Pid, error_code: ErrorCode) {
         assert_ne!(pid, self.current_pid);
-        debug!("Processor: {} exit, code: {}", pid, error_code);
+        info!("Processor: {} exit, code: {}", pid, error_code);
         self.get_mut(pid).status = Status::Exited(error_code);
         if let Some(waiter) = self.find_waiter(pid) {
             {
@@ -116,7 +116,7 @@ impl Processor {
                 p.status = Status::Ready;
                 p.set_return_value(error_code);
             }
-            debug!("Processor: remove {}", pid);
+            info!("Processor: remove {}", pid);
             self.procs.remove(&pid);
         }
     }
@@ -139,11 +139,11 @@ impl Processor {
             WaitTarget::Proc(pid) => (pid, self.get(pid).exit_code()),
         };
         if let Some(exit_code) = exit_code {
-            debug!("Processor: remove {}", pid);
+            info!("Processor: {} wait find and remove {}", self.current_pid, pid);
             self.procs.remove(&pid);
             WaitResult::Ok(exit_code)
         } else {
-            debug!("Processor: {} wait for {}", self.current_pid, pid);
+            info!("Processor: {} wait for {}", self.current_pid, pid);
             let current_pid = self.current_pid;
             self.get_mut(current_pid).status = Status::Sleeping(pid);
             WaitResult::Blocked

src/syscall.rs

@@ -37,7 +37,7 @@ pub unsafe fn syscall(tf: &TrapFrame, rsp: &mut usize, is32: bool) -> i32 {
                 0
             },
         _ => {
-            debug!("unknown syscall {:#x?}", id);
+            warn!("unknown syscall {:#x?}", id);
             -1
         },
     }