From cb4307e3967d4bc49a8977dd9fda4d5b7d2b5c10 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bartosz=20R=C3=B3=C5=BCa=C5=84ski?= Date: Wed, 17 May 2023 21:59:56 +0300 Subject: [PATCH] Proper logging instead of prints. (#47) --- Cargo.lock | 24 +++++++++ Cargo.toml | 1 + ffi/Cargo.toml | 1 + ffi/build.rs | 2 +- ffi/src/initialization.rs | 3 +- ffi/src/lib.rs | 1 + ffi/src/log.rs | 106 ++++++++++++++++++++++++++++++++++++++ ffi/src/post_impl.rs | 4 +- initializer/Cargo.toml | 1 + initializer/src/main.rs | 1 + profiler/Cargo.toml | 1 + profiler/src/main.rs | 1 + scrypt-ocl/Cargo.toml | 1 + scrypt-ocl/src/lib.rs | 23 ++++----- src/initialize.rs | 5 +- src/reader.rs | 2 +- 16 files changed, 156 insertions(+), 21 deletions(-) create mode 100644 ffi/src/log.rs diff --git a/Cargo.lock b/Cargo.lock index f37a699b..8decc556 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -730,6 +730,19 @@ dependencies = [ "num-traits 0.1.43", ] +[[package]] +name = "env_logger" +version = "0.10.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "85cdab6a89accf66733ad5a1693a4dcced6aeff64602b634530dd73c1f3ee9f0" +dependencies = [ + "humantime", + "is-terminal", + "log", + "regex", + "termcolor", +] + [[package]] name = "errno" version = "0.3.1" @@ -976,6 +989,12 @@ version = "0.4.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "7f24254aa9a54b5c858eaee2f5bccdb46aaf0e486a595ed5fd8f86ba55232a70" +[[package]] +name = "humantime" +version = "2.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "9a3a5bfb195931eeb336b2a7b4d761daec841b97f947d34394601737a7bba5e4" + [[package]] name = "iana-time-zone" version = "0.1.56" @@ -1047,6 +1066,7 @@ version = "0.1.8" dependencies = [ "base64 0.21.0", "clap 4.2.4", + "env_logger", "eyre", "post-rs", "rand", @@ -1454,6 +1474,7 @@ version = "0.1.11" dependencies = [ "cbindgen", "eyre", + "log", "post-rs", "scrypt-ocl", ] @@ -1470,6 +1491,7 @@ dependencies = [ "criterion", "eyre", "itertools", + "log", "pprof", "proptest", "rand", @@ -1534,6 +1556,7 @@ name = "profiler" version = "0.1.0" dependencies = [ "clap 4.2.4", + "env_logger", "eyre", "post-rs", "rayon", @@ -1841,6 +1864,7 @@ dependencies = [ name = "scrypt-ocl" version = "0.1.11" dependencies = [ + "log", "ocl", "post-rs", "rstest", diff --git a/Cargo.toml b/Cargo.toml index ba48ccd3..75635be7 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -27,6 +27,7 @@ blake3 = "1.3.3" bitvec = "1.0.1" rayon = "1.6.1" rand = "0.8.5" +log = "0.4.17" [dev-dependencies] criterion = "0.4" diff --git a/ffi/Cargo.toml b/ffi/Cargo.toml index 48497ec9..1d7d9018 100644 --- a/ffi/Cargo.toml +++ b/ffi/Cargo.toml @@ -10,6 +10,7 @@ crate_type = ["staticlib", "cdylib"] [dependencies] eyre = "0.6.8" +log = { version = "0.4.17", features = ["std"] } post-rs = { path = "../" } scrypt-ocl = { path = "../scrypt-ocl" } diff --git a/ffi/build.rs b/ffi/build.rs index a5529995..e7daf17f 100644 --- a/ffi/build.rs +++ b/ffi/build.rs @@ -9,7 +9,7 @@ fn main() { .with_language(cbindgen::Language::C) .with_crate(crate_dir) .with_parse_deps(true) - .with_parse_include(&["post-rs", "scrypt-jane"]) + .with_parse_include(&["post-rs", "scrypt-jane", "log"]) .generate() .expect("Unable to generate bindings") .write_to_file("prover.h"); diff --git a/ffi/src/initialization.rs b/ffi/src/initialization.rs index 8a30228d..612ed002 100644 --- a/ffi/src/initialization.rs +++ b/ffi/src/initialization.rs @@ -165,7 +165,7 @@ pub extern "C" fn new_initializer( match _new_initializer(provider_id, n, commitment, vrf_difficulty) { Ok(initializer) => initializer, Err(e) => { - eprintln!("Error creating initializer: {e:?}"); + log::error!("Error creating initializer: {e:?}"); std::ptr::null_mut() } } @@ -346,6 +346,5 @@ mod tests { InitializeResult::InitializeOk, super::get_providers(providers.as_mut_ptr(), count) ); - println!("{providers:?}"); } } diff --git a/ffi/src/lib.rs b/ffi/src/lib.rs index e641b031..d7626b31 100644 --- a/ffi/src/lib.rs +++ b/ffi/src/lib.rs @@ -1,4 +1,5 @@ mod initialization; +mod log; mod post_impl; #[repr(C)] diff --git a/ffi/src/log.rs b/ffi/src/log.rs new file mode 100644 index 00000000..c8534914 --- /dev/null +++ b/ffi/src/log.rs @@ -0,0 +1,106 @@ +use std::ffi::c_char; + +use log::{Level, Log, Metadata, Record}; + +/// FFI-safe borrowed Rust &str +#[repr(C)] +pub struct StringView { + pub ptr: *const c_char, + pub len: usize, +} + +impl StringView { + #[cfg(test)] + pub unsafe fn to_str<'a>(&self) -> &'a str { + let bytes = std::slice::from_raw_parts(self.ptr as _, self.len); + std::str::from_utf8_unchecked(bytes) + } +} + +impl<'a> From<&'a str> for StringView { + fn from(s: &'a str) -> Self { + Self { + ptr: s.as_ptr() as _, + len: s.len(), + } + } +} + +#[repr(C)] +pub struct ExternCRecord { + pub level: Level, + pub message: StringView, + pub module_path: StringView, + pub file: StringView, + pub line: i64, +} + +struct ExternCLog { + callback: extern "C" fn(&ExternCRecord), + level: Level, +} + +impl ExternCLog { + fn new(level: Level, callback: extern "C" fn(&ExternCRecord)) -> Self { + Self { level, callback } + } +} + +impl Log for ExternCLog { + fn enabled(&self, metadata: &Metadata) -> bool { + metadata.level() <= self.level + } + + fn log(&self, record: &Record) { + let msg = record.args().to_string(); + let c_record = ExternCRecord { + level: record.level(), + message: StringView::from(msg.as_str()), + module_path: StringView::from(record.module_path().unwrap_or("")), + file: StringView::from(record.file().unwrap_or("")), + line: record.line().map(|u| u as i64).unwrap_or(-1_i64), + }; + + (self.callback)(&c_record); + } + + fn flush(&self) {} +} + +/// Set a logging callback function +/// The function is idempotent, calling it more then once will have no effect. +/// Returns 0 if the callback was set successfully, 1 otherwise. +#[no_mangle] +pub extern "C" fn set_logging_callback( + level: Level, + callback: extern "C" fn(&ExternCRecord), +) -> i32 { + match log::set_boxed_logger(Box::new(ExternCLog::new(level, callback))) + .map(|()| log::set_max_level(level.to_level_filter())) + { + Ok(_) => 0, + Err(e) => { + eprintln!("Failed to set logger ({e})"); + 1 + } + } +} + +#[cfg(test)] +mod tests { + use crate::log::ExternCRecord; + + #[test] + fn logging_callback() { + extern "C" fn log_cb(record: &ExternCRecord) { + assert_eq!("Hello, logger", unsafe { record.message.to_str() }); + assert_eq!(log::Level::Info, record.level); + } + + super::set_logging_callback(log::Level::Info, log_cb); + log::info!("Hello, logger"); + log::trace!("Trace log level is disabled"); + + assert_eq!(1, super::set_logging_callback(log::Level::Warn, log_cb)); + } +} diff --git a/ffi/src/post_impl.rs b/ffi/src/post_impl.rs index 22cd77bc..d5ba570e 100644 --- a/ffi/src/post_impl.rs +++ b/ffi/src/post_impl.rs @@ -50,7 +50,7 @@ pub extern "C" fn generate_proof( Ok(proof) => proof, Err(e) => { //TODO(poszu) communicate errors better - eprintln!("{e:?}"); + log::error!("{e:?}"); std::ptr::null_mut() } } @@ -124,7 +124,7 @@ pub unsafe extern "C" fn verify_proof( let result = match verify(&proof, metadata, params) { Ok(_) => VerifyResult::Ok, Err(err) => { - eprintln!("Proof is invalid: {err}"); + log::error!("Proof is invalid: {err}"); VerifyResult::Invalid } }; diff --git a/initializer/Cargo.toml b/initializer/Cargo.toml index 78c74264..a3d31084 100644 --- a/initializer/Cargo.toml +++ b/initializer/Cargo.toml @@ -13,3 +13,4 @@ scrypt-ocl = { path = "../scrypt-ocl" } rayon = "1.7.0" eyre = "0.6.8" rand = "0.8.5" +env_logger = "0.10.0" diff --git a/initializer/src/main.rs b/initializer/src/main.rs index 46453920..075848c5 100644 --- a/initializer/src/main.rs +++ b/initializer/src/main.rs @@ -220,6 +220,7 @@ fn list_providers() -> eyre::Result<()> { } fn main() -> eyre::Result<()> { + env_logger::init(); let args = Cli::parse(); match args diff --git a/profiler/Cargo.toml b/profiler/Cargo.toml index fd41c66d..6b41fb6d 100644 --- a/profiler/Cargo.toml +++ b/profiler/Cargo.toml @@ -5,6 +5,7 @@ edition = "2021" [dependencies] clap = { version = "4.1.11", features = ["derive"] } +env_logger = "0.10.0" eyre = "0.6.8" post-rs = { path = "../" } rayon = "1.7.0" diff --git a/profiler/src/main.rs b/profiler/src/main.rs index 92910d0c..6e41c7e2 100644 --- a/profiler/src/main.rs +++ b/profiler/src/main.rs @@ -71,6 +71,7 @@ fn file_data(path: &Path, size: u64) -> Result { } fn main() -> Result<(), Box> { + env_logger::init(); let args = Args::parse(); let challenge = b"hello world, challenge me!!!!!!!"; diff --git a/scrypt-ocl/Cargo.toml b/scrypt-ocl/Cargo.toml index fc9da757..4e4d7a5e 100644 --- a/scrypt-ocl/Cargo.toml +++ b/scrypt-ocl/Cargo.toml @@ -7,6 +7,7 @@ edition = "2021" ocl = "0.19.4" thiserror = "1.0.40" post-rs = { path = "../" } +log = "0.4.17" [dev-dependencies] post-rs = { path = "../" } diff --git a/scrypt-ocl/src/lib.rs b/scrypt-ocl/src/lib.rs index 4eef12f2..87580b21 100644 --- a/scrypt-ocl/src/lib.rs +++ b/scrypt-ocl/src/lib.rs @@ -131,7 +131,7 @@ impl Scrypter { DeviceInfoResult::MaxComputeUnits ); let max_wg_size = device.max_wg_size()?; - println!( + log::debug!( "device memory: {} MB, max_mem_alloc_size: {} MB, max_compute_units: {max_compute_units}, max_wg_size: {max_wg_size}", device_memory / 1024 / 1024, max_mem_alloc_size / 1024 / 1024, @@ -165,7 +165,7 @@ impl Scrypter { ); let kernel_wg_size = kernel.wg_info(device, KernelWorkGroupInfo::WorkGroupSize)?; - println!("preferred_wg_size_multiple: {preferred_wg_size_mult}, kernel_wg_size: {kernel_wg_size}"); + log::debug!("preferred_wg_size_multiple: {preferred_wg_size_mult}, kernel_wg_size: {kernel_wg_size}"); let max_global_work_size_based_on_total_mem = ((device_memory - INPUT_SIZE as u64) / kernel_memory as u64) as usize; @@ -178,11 +178,11 @@ impl Scrypter { let local_work_size = preferred_wg_size_mult; // Round down to nearest multiple of local_work_size let global_work_size = (max_global_work_size / local_work_size) * local_work_size; - eprintln!( + log::debug!( "Using: global_work_size: {global_work_size}, local_work_size: {local_work_size}" ); - println!("Allocating buffer for input: {INPUT_SIZE} bytes"); + log::trace!("Allocating buffer for input: {INPUT_SIZE} bytes"); let input = Buffer::::builder() .len(INPUT_SIZE / 4) .flags(MemFlags::new().read_only()) @@ -190,7 +190,7 @@ impl Scrypter { .build()?; let output_size = global_work_size * ENTIRE_LABEL_SIZE; - println!("Allocating buffer for output: {output_size} bytes"); + log::trace!("Allocating buffer for output: {output_size} bytes"); let output = Buffer::::builder() .len(output_size) .flags(MemFlags::new().write_only()) @@ -198,7 +198,7 @@ impl Scrypter { .build()?; let lookup_size = global_work_size * kernel_lookup_mem_size; - println!("Allocating buffer for lookup: {lookup_size} bytes"); + log::trace!("Allocating buffer for lookup: {lookup_size} bytes"); let lookup_memory = Buffer::::builder() .len(lookup_size / 4) .flags(MemFlags::new().host_no_access()) @@ -250,8 +250,9 @@ impl Scrypter { } else { self.global_work_size }; - // TODO(poszu) trace log when logging is implemented - // println!("initializing {index} -> {index_end} ({labels_to_init} labels, GWS: {gws})"); + log::trace!( + "initializing {index} -> {index_end} ({labels_to_init} labels, GWS: {gws})" + ); self.kernel .set_default_global_work_size(SpatialDims::One(gws)); @@ -272,8 +273,7 @@ impl Scrypter { label: nonce.label, }); vrf_difficulty = Some(nonce.label); - //TODO: remove print - eprintln!("Found new smallest nonce: {best_nonce:?}"); + log::trace!("Found new smallest nonce: {best_nonce:?}"); } } @@ -311,8 +311,7 @@ impl OpenClInitializer { }; let platform = provider.platform; let device = provider.device; - // TODO remove print - println!("Using provider: {provider}"); + log::trace!("Using provider: {provider}"); let scrypter = Scrypter::new(platform, device, n)?; diff --git a/src/initialize.rs b/src/initialize.rs index 4b397e7e..78ded67f 100644 --- a/src/initialize.rs +++ b/src/initialize.rs @@ -105,7 +105,7 @@ impl Initialize for CpuInitializer { labels: Range, mut vrf_difficulty: Option<[u8; 32]>, ) -> Result, Box> { - println!("Initializing labels {:?}...", labels); + log::trace!("Initializing labels {:?}...", labels); let data = labels .clone() .into_par_iter() @@ -128,8 +128,7 @@ impl Initialize for CpuInitializer { label, }); vrf_difficulty = Some(label); - //TODO: remove print - eprintln!("Found new smallest nonce: {best_nonce:?}"); + log::trace!("Found new smallest nonce: {best_nonce:?}"); } } writer.write_all(&label[..16])?; diff --git a/src/reader.rs b/src/reader.rs index 99f68c23..cc8be7a7 100644 --- a/src/reader.rs +++ b/src/reader.rs @@ -99,7 +99,7 @@ pub(crate) fn read_data( // If there are more files, check if the size of the file is correct if files.peek().is_some() && pos_file_size != file_size { - eprintln!( + log::warn!( "invalid POS file, expected size: {file_size} vs actual size: {pos_file_size}" ); }