diff --git a/matcher-rs/Cargo.lock b/matcher-rs/Cargo.lock index dbbf038..aa9c870 100644 --- a/matcher-rs/Cargo.lock +++ b/matcher-rs/Cargo.lock @@ -2,10 +2,17 @@ # It is not intended for manual editing. version = 4 +[[package]] +name = "log" +version = "0.4.29" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "5e5032e24019045c762d3c0f28f5b6b8bbf38563a65908389bf7978758920897" + [[package]] name = "matcher-rs" version = "0.1.0" dependencies = [ + "log", "nanoserde", ] diff --git a/matcher-rs/Cargo.toml b/matcher-rs/Cargo.toml index 5b38f50..da90052 100644 --- a/matcher-rs/Cargo.toml +++ b/matcher-rs/Cargo.toml @@ -9,6 +9,12 @@ crate-type = ["cdylib", "rlib"] [dependencies] nanoserde = "0.1" +log = "0.4" + +[features] +default = ["static_log_off"] +static_log_off = ["log/max_level_off"] +logging = [] [dev-dependencies] diff --git a/matcher-rs/build.sh b/matcher-rs/build.sh index d862a82..010cfcd 100644 --- a/matcher-rs/build.sh +++ b/matcher-rs/build.sh @@ -12,6 +12,6 @@ cargo +nightly build \ # 2. Further shrink using wasm-opt (if available) for wasm in target/wasm32-unknown-unknown/release/*.wasm; do - wasm-opt -Oz --strip-debug --enable-bulk-memory --enable-sign-ext "$wasm" -o "$wasm" + wasm-opt -Oz --strip-debug --enable-bulk-memory --enable-sign-ext --enable-nontrapping-float-to-int "$wasm" -o "$wasm" done diff --git a/matcher-rs/src/bin/issuance.rs b/matcher-rs/src/bin/issuance.rs index 01dda1c..6f57a4d 100644 --- a/matcher-rs/src/bin/issuance.rs +++ b/matcher-rs/src/bin/issuance.rs @@ -1,6 +1,7 @@ use matcher_rs::{credman::CredmanApiImpl, issuance::issuance_main}; fn main() { + matcher_rs::logger::init(); issuance_main(&mut CredmanApiImpl {}).unwrap(); } diff --git a/matcher-rs/src/bindings.rs b/matcher-rs/src/bindings.rs index c000d59..4b670ea 100644 --- a/matcher-rs/src/bindings.rs +++ b/matcher-rs/src/bindings.rs @@ -139,4 +139,6 @@ unsafe extern "C" { set_id: *const c_char, set_index: i32, ); + pub fn fd_write(fd: i32, iovs_ptr: *const c_void, iovs_len: i32, nwritten_ptr: *mut i32) + -> i32; } diff --git a/matcher-rs/src/credman.rs b/matcher-rs/src/credman.rs index aff5239..28440a1 100644 --- a/matcher-rs/src/credman.rs +++ b/matcher-rs/src/credman.rs @@ -26,6 +26,7 @@ impl CredmanApi for CredmanApiImpl { unsafe { GetRequestSize(&mut size); } + log::debug!("Host requested request buffer of size: {}", size); let mut r = vec![0; size as usize]; unsafe { GetRequestBuffer(r.as_mut_ptr() as *mut c_void); @@ -37,6 +38,7 @@ impl CredmanApi for CredmanApiImpl { unsafe { GetCredentialsSize(&mut size); } + log::debug!("Host requested registered data buffer of size: {}", size); let mut r = vec![0; size.try_into().unwrap()]; unsafe { ReadCredentialsBuffer(r.as_mut_ptr() as *mut c_void, 0, size as usize); @@ -52,9 +54,16 @@ impl CredmanApi for CredmanApiImpl { disclaimer: Option<&CStr>, warning: Option<&CStr>, ) { + log::info!("Adding string ID entry: {:?}", entry_id); let icon_bytes = icon.map_or(std::ptr::null(), |x| x.as_ptr()) as *const std::os::raw::c_char; let icon_length = icon.map_or(0, |x| x.len()); + log::trace!( + "Entry details - title: {:?}, subtitle: {:?}, icon_len: {}", + title, + subtitle, + icon_length + ); unsafe { AddStringIdEntry( entry_id.as_ptr(), diff --git a/matcher-rs/src/issuance.rs b/matcher-rs/src/issuance.rs index 3e5fd82..1e41513 100644 --- a/matcher-rs/src/issuance.rs +++ b/matcher-rs/src/issuance.rs @@ -16,33 +16,83 @@ const ALLOWED_PROTOCOLS: [&str; 4] = [ ]; pub fn issuance_main(credman: &mut impl CredmanApi) -> Result<(), Box> { + log::info!("Starting issuance matching process"); let matcher_data_buffer = credman.get_registered_data(); + log::debug!( + "Retrieved matcher data buffer, size: {}", + matcher_data_buffer.len() + ); + let json_start = u32::from_le_bytes(matcher_data_buffer[..size_of::()].try_into()?); - let matcher_data: IssuanceMatcherData = DeJson::deserialize_json(std::str::from_utf8( - &matcher_data_buffer[json_start.try_into()?..], - )?)?; - let request: DigitalCredentialCreationRequest = - DeJson::deserialize_json(std::str::from_utf8(&credman.get_request_buffer())?)?; - if request.requests.iter().any(|r| { - ALLOWED_PROTOCOLS.iter().any(|s| r.protocol == *s) - && matcher_data - .filter - .matches(&RegularizedOpenId4VciRequestData::from(&r.data)) - }) { - let icon = &matcher_data_buffer[matcher_data.icon.0..matcher_data.icon.1]; - let entry_id = CString::new(matcher_data.entry_id)?; - let title = matcher_data.title.map(|s| CString::new(s)).transpose()?; - let subtitle = matcher_data.subtitle.map(|s| CString::new(s)).transpose()?; - credman.add_string_id_entry( - &entry_id, - if icon.is_empty() { None } else { Some(icon) }, - title.as_deref(), - subtitle.as_deref(), - None, - None, - ); + let matcher_data_str = std::str::from_utf8(&matcher_data_buffer[json_start.try_into()?..])?; + let matcher_data: IssuanceMatcherData = match DeJson::deserialize_json(matcher_data_str) { + Ok(data) => data, + Err(e) => { + log::error!( + "Failed to deserialize matcher data: {:?}. JSON: {}", + e, + matcher_data_str + ); + return Err(e.into()); + } + }; + log::debug!("Parsed matcher data for entry: {}", matcher_data.entry_id); + + let request_buffer = credman.get_request_buffer(); + let request_str = std::str::from_utf8(&request_buffer)?; + let request: DigitalCredentialCreationRequest = match DeJson::deserialize_json(request_str) { + Ok(req) => req, + Err(e) => { + log::error!( + "Failed to deserialize request: {:?}. JSON: {}", + e, + request_str + ); + return Err(e.into()); + } + }; + log::debug!( + "Parsed request with {} sub-requests", + request.requests.len() + ); + + for (i, r) in request.requests.iter().enumerate() { + log::trace!("Checking request {}: protocol={}", i, r.protocol); + if ALLOWED_PROTOCOLS.iter().any(|s| r.protocol == *s) { + let regularized = RegularizedOpenId4VciRequestData::from(&r.data); + if matcher_data.filter.matches(®ularized) { + log::info!("Match found for request {} with protocol {}", i, r.protocol); + let icon = &matcher_data_buffer[matcher_data.icon.0..matcher_data.icon.1]; + let entry_id = CString::new(matcher_data.entry_id.clone())?; + let title = matcher_data + .title + .as_ref() + .map(|s| CString::new(s.clone())) + .transpose()?; + let subtitle = matcher_data + .subtitle + .as_ref() + .map(|s| CString::new(s.clone())) + .transpose()?; + + log::debug!("Adding string ID entry: {}", matcher_data.entry_id); + credman.add_string_id_entry( + &entry_id, + if icon.is_empty() { None } else { Some(icon) }, + title.as_deref(), + subtitle.as_deref(), + None, + None, + ); + // Assuming we only need to add one entry if any request matches + break; + } + } else { + log::warn!("Unsupported protocol: {}", r.protocol); + } } + log::info!("Issuance matching process completed"); Ok(()) } diff --git a/matcher-rs/src/issuance_matcher.rs b/matcher-rs/src/issuance_matcher.rs index b43be5a..0d1c512 100644 --- a/matcher-rs/src/issuance_matcher.rs +++ b/matcher-rs/src/issuance_matcher.rs @@ -30,45 +30,107 @@ impl Default for OpenId4VciFilter { impl OpenId4VciFilter { pub fn matches(&self, request: &RegularizedOpenId4VciRequestData) -> bool { - match &self { - Self::Unit {} => true, - Self::And { filters } => filters.iter().all(|f| f.matches(request)), - Self::Or { filters } => filters.iter().any(|f| f.matches(request)), - Self::Not { filter } => !filter.matches(request), - Self::AllowsIssuers { issuers } => issuers.contains(request.credential_issuer), - Self::AllowsConfigurationIds { configuration_ids } => request - .credential_configuration_ids - .iter() - .any(|id| configuration_ids.contains(id)), - Self::SupportsAuthCodeFlow {} => request.grants.contains_key("authorization_code"), - Self::SupportsPreAuthFlow {} => request - .grants - .contains_key("urn:ietf:params:oauth:grant-type:pre-authorized_code"), - Self::SupportsNonceEndpoint {} => request - .credential_issuer_metadata - .is_some_and(|m| !m.nonce_endpoint.is_empty()), - Self::SupportsDeferredCredentialEndpoint {} => request - .credential_issuer_metadata - .is_some_and(|m| !m.deferred_credential_endpoint.is_empty()), - Self::SupportsNotificationEndpoint {} => request - .credential_issuer_metadata - .is_some_and(|m| !m.notification_endpoint.is_empty()), + let matched = match &self { + Self::Unit {} => { + log::trace!("Filter Unit matched"); + true + } + Self::And { filters } => { + let res = filters.iter().all(|f| f.matches(request)); + log::trace!("Filter And matched: {}", res); + res + } + Self::Or { filters } => { + let res = filters.iter().any(|f| f.matches(request)); + log::trace!("Filter Or matched: {}", res); + res + } + Self::Not { filter } => { + let res = !filter.matches(request); + log::trace!("Filter Not matched: {}", res); + res + } + Self::AllowsIssuers { issuers } => { + let res = issuers.contains(request.credential_issuer); + log::trace!( + "Filter AllowsIssuers (issuer={}) matched: {}", + request.credential_issuer, + res + ); + res + } + Self::AllowsConfigurationIds { configuration_ids } => { + let res = request + .credential_configuration_ids + .iter() + .any(|id| configuration_ids.contains(id)); + log::trace!("Filter AllowsConfigurationIds matched: {}", res); + res + } + Self::SupportsAuthCodeFlow {} => { + let res = request.grants.contains_key("authorization_code"); + log::trace!("Filter SupportsAuthCodeFlow matched: {}", res); + res + } + Self::SupportsPreAuthFlow {} => { + let res = request + .grants + .contains_key("urn:ietf:params:oauth:grant-type:pre-authorized_code"); + log::trace!("Filter SupportsPreAuthFlow matched: {}", res); + res + } + Self::SupportsNonceEndpoint {} => { + let res = request + .credential_issuer_metadata + .is_some_and(|m| !m.nonce_endpoint.is_empty()); + log::trace!("Filter SupportsNonceEndpoint matched: {}", res); + res + } + Self::SupportsDeferredCredentialEndpoint {} => { + let res = request + .credential_issuer_metadata + .is_some_and(|m| !m.deferred_credential_endpoint.is_empty()); + log::trace!("Filter SupportsDeferredCredentialEndpoint matched: {}", res); + res + } + Self::SupportsNotificationEndpoint {} => { + let res = request + .credential_issuer_metadata + .is_some_and(|m| !m.notification_endpoint.is_empty()); + log::trace!("Filter SupportsNotificationEndpoint matched: {}", res); + res + } Self::RequiresBatchIssuance { min_batch_size } => { - request.credential_issuer_metadata.is_some_and(|m| { + let res = request.credential_issuer_metadata.is_some_and(|m| { m.batch_credential_issuance .as_ref() .is_some_and(|b| b.batch_size >= *min_batch_size) - }) + }); + log::trace!( + "Filter RequiresBatchIssuance (min={}) matched: {}", + min_batch_size, + res + ); + res + } + Self::SupportsMdocDoctype { doctypes } => { + let res = request + .credential_configurations + .iter() + .any(|c| doctypes.contains(&c.doctype)); + log::trace!("Filter SupportsMdocDoctype matched: {}", res); + res + } + Self::SupportsSdJwtVct { vcts } => { + let res = request + .credential_configurations + .iter() + .any(|c| vcts.contains(&c.vct)); + log::trace!("Filter SupportsSdJwtVct matched: {}", res); + res } - Self::SupportsMdocDoctype { doctypes } => request - .credential_configurations - .iter() - .any(|c| doctypes.contains(&c.doctype)), - Self::SupportsSdJwtVct { vcts } => request - .credential_configurations - .iter() - .any(|c| vcts.contains(&c.vct)), - } + }; + matched } } diff --git a/matcher-rs/src/lib.rs b/matcher-rs/src/lib.rs index a172c8a..1091a2d 100644 --- a/matcher-rs/src/lib.rs +++ b/matcher-rs/src/lib.rs @@ -2,4 +2,5 @@ pub mod bindings; pub mod credman; pub mod issuance; pub mod issuance_matcher; +pub mod logger; pub mod openid4vci; diff --git a/matcher-rs/src/logger.rs b/matcher-rs/src/logger.rs new file mode 100644 index 0000000..dd36232 --- /dev/null +++ b/matcher-rs/src/logger.rs @@ -0,0 +1,91 @@ +//! WASM Logging implementation using `fd_write`. +//! +//! Logging is stripped by default at compile time to minimize the WASM binary size, +//! as the `log` crate and string formatting (fmt) significantly increase the footprint. +//! +//! To enable logging during development: +//! Use `--no-default-features --features logging` when building. +//! +//! Example: +//! cargo build --release --no-default-features --features logging + +#[cfg(feature = "logging")] +use crate::bindings::fd_write; +#[cfg(feature = "logging")] +use log::{Metadata, Record}; +#[cfg(feature = "logging")] +use std::os::raw::c_void; + +#[cfg(feature = "logging")] +struct WasmLogger; + +#[cfg(feature = "logging")] +#[repr(C)] +struct Ciovec { + buf: *const u8, + buf_len: u32, +} + +#[cfg(feature = "logging")] +impl log::Log for WasmLogger { + fn enabled(&self, _metadata: &Metadata) -> bool { + true + } + + fn log(&self, record: &Record) { + if self.enabled(record.metadata()) { + let msg = format!("{}: {}\n", record.level(), record.args()); + let ciovec = Ciovec { + buf: msg.as_ptr(), + buf_len: msg.len() as u32, + }; + let mut nwritten = 0; + unsafe { + fd_write( + 1, // stdout + &ciovec as *const _ as *const c_void, + 1, + &mut nwritten, + ); + } + } + } + + fn flush(&self) {} +} + +#[cfg(feature = "logging")] +static LOGGER: WasmLogger = WasmLogger; + +#[cfg(feature = "logging")] +pub fn init() { + log::set_logger(&LOGGER) + .map(|()| log::set_max_level(log::LevelFilter::Trace)) + .ok(); + + std::panic::set_hook(Box::new(|panic_info| { + let msg = panic_info.payload_as_str().unwrap_or("unknown"); + let formatted = match panic_info.location() { + Some(loc) => format!("Panic at {}: {}\n", loc, msg), + None => format!("Panic: {}\n", msg), + }; + let ciovec = Ciovec { + buf: formatted.as_ptr(), + buf_len: formatted.len() as u32, + }; + let mut nwritten = 0; + unsafe { + fd_write( + 1, // stdout + &ciovec as *const _ as *const c_void, + 1, + &mut nwritten, + ); + } + })); +} + +#[cfg(not(feature = "logging"))] +pub fn init() { + log::set_max_level(log::LevelFilter::Off); +} diff --git a/matcher-rs/src/openid4vci.rs b/matcher-rs/src/openid4vci.rs index 2afc092..b0763d6 100644 --- a/matcher-rs/src/openid4vci.rs +++ b/matcher-rs/src/openid4vci.rs @@ -41,16 +41,28 @@ pub struct RegularizedOpenId4VciRequestData<'a> { // Implement From on a Reference impl<'a> From<&'a OpenId4VciRequestData> for RegularizedOpenId4VciRequestData<'a> { fn from(value: &'a OpenId4VciRequestData) -> Self { + log::trace!( + "Regularizing request for issuer: {}", + value.credential_issuer + ); let mut configurations = Vec::with_capacity(value.credential_configuration_ids.len()); if let Some(metadata) = &value.credential_issuer_metadata { for id in &value.credential_configuration_ids { if let Some(config) = metadata.credential_configurations_supported.get(id) { configurations.push(config); + } else { + log::trace!("Configuration ID '{}' not found in metadata", id); } } + } else { + log::trace!("No metadata available for regularization"); } + log::trace!( + "Regularization complete: {} configurations matched", + configurations.len() + ); Self { credential_issuer: &value.credential_issuer, credential_configuration_ids: &value.credential_configuration_ids,