Replace println with log

Author: antoniolocascio

risc_v_simulator/Cargo.toml

@@ -24,6 +24,7 @@ poseidon2 = { workspace = true, optional = true }
 rand = { workspace = true, features = ["std", "thread_rng", "std_rng"]}
 ruint = { version = "1.15", optional = true, default-features = false }
 serde = { workspace = true }
+log = { workspace = true }
 
 [dev-dependencies]
 lib-rv32-asm = {git = "https://github.com/shamatar/lib-rv32.git" }

risc_v_simulator/bin/runner.rs

@@ -1,11 +1,12 @@
 use risc_v_simulator::{runner::run_simple_simulator, sim::SimulatorConfig};
+use log::info;
 
 pub fn main() {
     // let args: Vec<String> = std::env::args().collect();
     // dbg!(&args);
     // assert_eq!(args.len(), 2);
     // let path = &args[1];
-    println!("ZK RISC-V simulator is starting");
+    info!("ZK RISC-V simulator is starting");
 
     let path = "../zksync-os/zksync_os/app.bin";
     let path_sym = "../zksync-os/zksync_os/app.elf";

risc_v_simulator/src/abstractions/non_determinism.rs

@@ -1,3 +1,5 @@
+use log::info;
+
 // there is no interpretation of methods here, it's just read/write and that's all
 pub trait NonDeterminismCSRSource<M: MemorySource + ?Sized> {
     const SHOULD_MOCK_READS_BEFORE_WRITES: bool = true;
@@ -105,7 +107,7 @@ impl QuasiUARTSourceState {
                 }
                 if remaining_words.unwrap() == 0 {
                     let buffer = std::mem::replace(buffer, Vec::new());
-                    println!("UART: `{}`", String::from_utf8_lossy(&buffer));
+                    info!("UART: `{}`", String::from_utf8_lossy(&buffer));
                     *self = QuasiUARTSourceState::Ready;
                 }
             }

risc_v_simulator/src/cycle/state.rs

@@ -1,5 +1,6 @@
 use std::collections::HashMap;
 use std::hint::unreachable_unchecked;
+use log::info;
 
 use super::{status_registers::*, MachineConfig};
 use crate::abstractions::csr_processor::CustomCSRProcessor;
@@ -142,7 +143,7 @@ pub fn output_opcode_stats() {
         keys.sort();
         for key in keys.into_iter() {
             let value = OPCODES_COUNTER.with_borrow(|el| el[key]);
-            println!("Opcode {}: used {} times", key, value);
+            info!("Opcode {}: used {} times", key, value);
         }
     }
 }
@@ -584,7 +585,7 @@ impl<Config: MachineConfig> RiscV32State<Config> {
 
         let current_privilege_mode = self.extra_flags.get_current_mode();
         let mut pc = self.observable.pc;
-        // println!("PC = 0x{:08x}", pc);
+        // info!("PC = 0x{:08x}", pc);
         let mut ret_val: u32 = 0;
         let mut trap = TrapReason::NoTrap;
         let mut instr: u32 = 0;
@@ -746,7 +747,7 @@ impl<Config: MachineConfig> RiscV32State<Config> {
 
                     let virtual_address = rs1.wrapping_add(imm);
 
-                    // println!("Load into x{:02} from 0x{:08x} at PC = 0x{:08x}", rd, virtual_address, pc);
+                    // info!("Load into x{:02} from 0x{:08x} at PC = 0x{:08x}", rd, virtual_address, pc);
 
                     // we formally access it once, but most likely full memory access
                     // will be abstracted away into external interface hiding memory translation too
@@ -848,7 +849,7 @@ impl<Config: MachineConfig> RiscV32State<Config> {
                     // it's S-type, that has no RD, so set it to x0
                     rd = 0;
 
-                    // println!("Store of x{:02} = 0x{:08x} into 0x{:08x} at PC = 0x{:08x}", STypeOpcode::rs2(instr), rs2, virtual_address, pc);
+                    // info!("Store of x{:02} = 0x{:08x} into 0x{:08x} at PC = 0x{:08x}", STypeOpcode::rs2(instr), rs2, virtual_address, pc);
 
                     // store operand rs2
 
@@ -1194,7 +1195,7 @@ impl<Config: MachineConfig> RiscV32State<Config> {
                                 }
                                 csr => {
                                     assert!(Config::ALLOWED_DELEGATION_CSRS.contains(&csr), "Machine {:?} is not configured to support CSR number {} at pc 0x{:08x}", Config::default(), csr, pc);
-                                    // println!("Custom CSR = 0x{:04x} READ at cycle {}", csr_number, proc_cycle);
+                                    // info!("Custom CSR = 0x{:04x} READ at cycle {}", csr_number, proc_cycle);
                                     csr_processor.process_read(self, memory_source, non_determinism_source, tracer, mmu, csr_number, rs1, rs1_as_imm, &mut ret_val, &mut trap);
                                     if trap.is_a_trap() {
                                         break 'cycle_block;
@@ -1250,7 +1251,7 @@ impl<Config: MachineConfig> RiscV32State<Config> {
                                     assert!(Config::ALLOWED_DELEGATION_CSRS.contains(&csr), "Machine {:?} is not configured to support CSR number {}", Config::default(), csr);
                                     Self::add_delegation(csr);
                                     // let t = CSR_COUNTER.fetch_add(1, std::sync::atomic::Ordering::AcqRel);
-                                    // println!("Custom CSR = 0x{:04x} WRITE at cycle {}, total: {}", csr_number, proc_cycle, t + 1);
+                                    // info!("Custom CSR = 0x{:04x} WRITE at cycle {}, total: {}", csr_number, proc_cycle, t + 1);
                                     csr_processor.process_write(self, memory_source, non_determinism_source, tracer, mmu, csr_number, rs1, rs1_as_imm, &mut trap);
                                     if trap.is_a_trap() {
                                         break 'cycle_block;
@@ -1304,7 +1305,7 @@ impl<Config: MachineConfig> RiscV32State<Config> {
                                 }
                                 csr => {
                                     assert!(Config::ALLOWED_DELEGATION_CSRS.contains(&csr), "Machine {:?} is not configured to support CSR number {}", Config::default(), csr);
-                                    // println!("Custom CSR = 0x{:04x} READ at cycle {}", csr_number, proc_cycle);
+                                    // info!("Custom CSR = 0x{:04x} READ at cycle {}", csr_number, proc_cycle);
                                     csr_processor.process_read(self, memory_source, non_determinism_source, tracer, mmu, csr_number, rs1, rs1_as_imm, &mut ret_val, &mut trap);
                                     if trap.is_a_trap() {
                                         break 'cycle_block;
@@ -1391,7 +1392,7 @@ impl<Config: MachineConfig> RiscV32State<Config> {
                         // rd = 0;
                         // // mainly we support WFI, MRET, ECALL and EBREAK
                         // if csr_number == 0x105 {
-                        //     println!("WFI: proc_cycle: {:?}, pc = {}, opcode = 0x{:08x}", proc_cycle, pc, instr);
+                        //     info!("WFI: proc_cycle: {:?}, pc = {}, opcode = 0x{:08x}", proc_cycle, pc, instr);
                         //     self.extra_flags.set_wait_for_interrupt_bit();
                         //     self.pc = pc.wrapping_add(4u32);
                         //     return;
@@ -1490,7 +1491,7 @@ impl<Config: MachineConfig> RiscV32State<Config> {
 
             // If there was a trap, do NOT allow register writeback.
             debug_assert_eq!(trap, TrapReason::NoTrap);
-            // println!("Set x{:02} = 0x{:08x}", rd, ret_val);
+            // info!("Set x{:02} = 0x{:08x}", rd, ret_val);
             self.set_register(rd, ret_val, tracer);
 
             // traps below will update PC themself, so it only happens if we have NO trap
@@ -1499,7 +1500,7 @@ impl<Config: MachineConfig> RiscV32State<Config> {
 
         // Handle traps and interrupts.
         if trap.is_a_trap() {
-            println!("trap: {:?}, pc: {:08x}, instr: {:08x}", trap, pc, instr);
+            info!("trap: {:?}, pc: {:08x}, instr: {:08x}", trap, pc, instr);
 
             if Config::HANDLE_EXCEPTIONS == false {
                 panic!("Simulator encountered an exception");
@@ -1515,7 +1516,7 @@ impl<Config: MachineConfig> RiscV32State<Config> {
                     // TODO: here we have a freedom of what to put into tval. We place opcode value now, because PC will be placed into EPC below
                     self.machine_mode_trap_data.handling.tval = instr;
                 }
-                // println!("Trapping at pc = 0x{:08x} into PC = 0x{:08x}. MECP is set to 0x{:08x}", pc, self.machine_mode_trap_data.setup.tvec, pc);
+                // info!("Trapping at pc = 0x{:08x} into PC = 0x{:08x}. MECP is set to 0x{:08x}", pc, self.machine_mode_trap_data.setup.tvec, pc);
                 // self.pretty_dump();
                 // self.stack_dump(memory, mmu);
 
@@ -1546,11 +1547,11 @@ impl<Config: MachineConfig> RiscV32State<Config> {
         tracer.at_cycle_end(&*self);
 
         //let trap = trap.as_register_value();
-        //println!("end of cycle: PC = 0x{:08x}, trap = 0x{:08x}, interrupt = {:?}", self.pc, trap, trap & INTERRUPT_MASK != 0);
+        //info!("end of cycle: PC = 0x{:08x}, trap = 0x{:08x}, interrupt = {:?}", self.pc, trap, trap & INTERRUPT_MASK != 0);
     }
 
     pub fn pretty_dump(&self) {
-        println!(
+        info!(
             "PC = 0x{:08x}, RA = 0x{:08x}, SP = 0x{:08x}, GP = 0x{:08x}",
             self.observable.pc,
             self.observable.registers[1],
@@ -1567,7 +1568,7 @@ impl<Config: MachineConfig> RiscV32State<Config> {
             for (idx, reg) in chunk.iter() {
                 print!("x{:02} = 0x{:08x}, ", idx, reg);
             }
-            println!("");
+            info!("");
         }
     }
 }

risc_v_simulator/src/mmio/quasi_uart.rs

@@ -1,4 +1,5 @@
 use std::{collections::VecDeque, ffi::CString};
+use log::info;
 
 use super::*;
 
@@ -37,7 +38,7 @@ impl MMIOSource for QuasiUART {
                 let mut buffer = std::mem::replace(&mut self.buffer, vec![]);
                 buffer.truncate(idx + 1);
                 let c_string = CString::from_vec_with_nul(buffer).unwrap();
-                println!("UART: `{}`", c_string.to_string_lossy());
+                info!("UART: `{}`", c_string.to_string_lossy());
                 break;
             }
         }

risc_v_simulator/src/runner/mod.rs

@@ -1,4 +1,5 @@
 use std::path::Path;
+use log::{info, debug};
 
 use crate::abstractions::memory::MemorySource;
 use crate::abstractions::memory::VectorMemoryImpl;
@@ -132,7 +133,7 @@ pub fn run_simulator_with_traces_for_config<C: MachineConfig>(
     let exec = sim.run(
         |_, _| {},
         |sim, cycle| {
-            println!(
+            info!(
                 "mtvec: {:?}",
                 sim.machine.state.machine_mode_trap_data.setup.tvec
             );
@@ -144,13 +145,13 @@ pub fn run_simulator_with_traces_for_config<C: MachineConfig>(
 }
 
 fn read_bin<P: AsRef<Path>>(path: P) -> Vec<u8> {
-    dbg!(path.as_ref());
+    debug!("path.as_ref() = \"{}\"", path.as_ref().display());
     let mut file = std::fs::File::open(path).expect("must open provided file");
     let mut buffer = vec![];
     std::io::Read::read_to_end(&mut file, &mut buffer).expect("must read the file");
 
     assert_eq!(buffer.len() % 4, 0);
-    dbg!(buffer.len() / 4);
+    debug!("buffer.len() / 4 = {}", buffer.len() / 4);
 
     buffer
 }

risc_v_simulator/src/sim/diag.rs

@@ -9,6 +9,7 @@ use std::{
     mem::size_of,
     path::{Path, PathBuf},
 };
+use log::info;
 
 use addr2line::LookupContinuation;
 use addr2line::{
@@ -279,7 +280,7 @@ impl Profiler {
     }
 
     pub(crate) fn print_stats(&self) {
-        println!("{:#?}", self.stats);
+        info!("{:#?}", self.stats);
     }
 }
 
@@ -381,17 +382,17 @@ impl SymbolInfo {
             .expect("Frame info should've been created on frame loading.")
             .to(|x| {
                 if x.is_tracked {
-                    println!("is_traceable:");
-                    println!("address: 0x{:08x}", address);
-                    println!("address: {}", address);
-                    println!("{:#?}", x);
+                    info!("is_traceable:");
+                    info!("address: 0x{:08x}", address);
+                    info!("address: {}", address);
+                    info!("{:#?}", x);
                     tracked = true;
                 }
                 address >= x.prologue_end && address < x.epilogue_begin
             });
 
         if tracked {
-            println!("r {}", r);
+            info!("r {}", r);
         }
 
         r
@@ -420,12 +421,12 @@ impl SymbolInfo {
             gimli::DW_TAG_formal_parameter => "DW_TAG_formal_parameter".to_owned(),
             otherwise => format!("{:x?}", otherwise),
         };
-        println!("tag {:?}", tag_n);
+        info!("tag {:?}", tag_n);
 
         let mut attrs = die.attrs();
 
         while let Ok(Some(attr)) = attrs.next() {
-            println!("   {:x?} -> {:x?}", attr.name(), attr.value());
+            info!("   {:x?} -> {:x?}", attr.name(), attr.value());
 
             match attr.name() {
                 gimli::DW_AT_linkage_name | gimli::DW_AT_name => {
@@ -434,19 +435,19 @@ impl SymbolInfo {
                     match n {
                         gimli::AttributeValue::DebugStrRef(n) => {
                             let s = dw.string(n).unwrap();
-                            println!("      value: {}", s.to_string_lossy());
+                            info!("      value: {}", s.to_string_lossy());
                         }
                         _ => {}
                     }
                 }
 
                 gimli::DW_AT_frame_base => match attr.value() {
                     gimli::AttributeValue::Exprloc(ex) => {
-                        println!("expr decode");
+                        info!("expr decode");
                         let mut ops = ex.operations(unit.encoding());
 
                         while let Ok(Some(op)) = ops.next() {
-                            println!("op: {:?}", op);
+                            info!("op: {:?}", op);
                         }
                     }
                     _ => {}
@@ -460,7 +461,7 @@ impl SymbolInfo {
                         let mut attrs = die2.attrs();
 
                         while let Ok(Some(attr)) = attrs.next() {
-                            println!("      {:x?} -> {:x?}", attr.name(), attr.value());
+                            info!("      {:x?} -> {:x?}", attr.name(), attr.value());
 
                             match attr.name() {
                                 gimli::DW_AT_linkage_name | gimli::DW_AT_name => {
@@ -469,7 +470,7 @@ impl SymbolInfo {
                                     match n {
                                         gimli::AttributeValue::DebugStrRef(n) => {
                                             let s = dw.string(n).unwrap();
-                                            println!("         value: {}", s.to_string_lossy());
+                                            info!("         value: {}", s.to_string_lossy());
                                         }
                                         _ => {}
                                     }
@@ -493,7 +494,7 @@ impl SymbolInfo {
 
         for s in sequences {
             if address >= s.start && address < s.end {
-                println!("found seq: {:x} -> {:x}", s.start, s.end);
+                info!("found seq: {:x} -> {:x}", s.start, s.end);
 
                 let mut sm = line_program.resume_from(&s);
 
@@ -502,7 +503,7 @@ impl SymbolInfo {
                         Some(r) => r.get(),
                         None => 0,
                     };
-                    println!(
+                    info!(
                         "row addr {:08x}, line {}, stmt {}, prol_end {}, epi_start {},",
                         r.address(),
                         line_num,
@@ -653,7 +654,7 @@ impl SymbolInfo {
                             };
 
                             if tracked {
-                                println!("{:#?}", r);
+                                info!("{:#?}", r);
                             }
 
                             return r;

risc_v_simulator/src/sim/mod.rs

@@ -1,5 +1,6 @@
 use std::marker::PhantomData;
 use std::path::{Path, PathBuf};
+use log::{debug, info};
 
 use diag::ProfilerStats;
 
@@ -99,7 +100,7 @@ where
             if self.machine.state().pc == previous_pc {
                 end_of_execution_reached = true;
                 cycles = cycle;
-                println!("Took {} cycles to finish", cycle);
+                info!("Took {} cycles to finish", cycle);
                 break;
             }
             previous_pc = self.machine.state().pc;
@@ -116,7 +117,7 @@ where
         let exec_time = now.elapsed();
 
         if let Some(profiler) = self.profiler.as_mut() {
-            println!("Profiler begins execution");
+            info!("Profiler begins execution");
             profiler.print_stats();
             profiler.write_stacktrace();
         }
@@ -189,13 +190,13 @@ pub enum BinarySource<'a> {
 impl<'a> BinarySource<'a> {
     pub fn to_iter(&self) -> Box<dyn Iterator<Item = u8> + 'a> {
         fn read_bin<P: AsRef<Path>>(path: P) -> Vec<u8> {
-            dbg!(path.as_ref());
+            debug!("path.as_ref() = \"{}\"", path.as_ref().display());
             let mut file = std::fs::File::open(path).expect("must open provided file");
             let mut buffer = vec![];
             std::io::Read::read_to_end(&mut file, &mut buffer).expect("must read the file");
 
             assert_eq!(buffer.len() % 4, 0);
-            dbg!(buffer.len() / 4);
+           debug!("buffer.len() / 4 = {}", buffer.len() / 4);
 
             buffer
         }