Merge branch 'main' into 67-remove-k3-pow

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"

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" }
 

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");

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:?}");
     }
 }

ffi/src/lib.rs

@@ -1,4 +1,5 @@
 mod initialization;
+mod log;
 mod post_impl;
 
 #[repr(C)]

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));
+    }
+}

ffi/src/post_impl.rs

@@ -49,7 +49,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()
         }
     }
@@ -121,7 +121,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
         }
     };

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"

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

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"

profiler/src/main.rs

@@ -68,6 +68,7 @@ fn file_data(path: &Path, size: u64) -> Result<std::fs::File, std::io::Error> {
 }
 
 fn main() -> Result<(), Box<dyn Error>> {
+    env_logger::init();
     let args = Args::parse();
 
     let challenge = b"hello world, challenge me!!!!!!!";

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 = "../" }

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,27 +178,27 @@ 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::<u32>::builder()
             .len(INPUT_SIZE / 4)
             .flags(MemFlags::new().read_only())
             .queue(pro_que.queue().clone())
             .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::<u8>::builder()
             .len(output_size)
             .flags(MemFlags::new().write_only())
             .queue(pro_que.queue().clone())
             .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::<u32>::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)?;
 

src/initialize.rs

@@ -105,7 +105,7 @@ impl Initialize for CpuInitializer {
         labels: Range<u64>,
         mut vrf_difficulty: Option<[u8; 32]>,
     ) -> Result<Option<VrfNonce>, Box<dyn Error>> {
-        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])?;

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}"
             );
         }