Logging in the Rust matcher

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]
 

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
 

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

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

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(),

matcher-rs/src/issuance.rs

@@ -16,33 +16,83 @@ const ALLOWED_PROTOCOLS: [&str; 4] = [
 ];
 
 pub fn issuance_main(credman: &mut impl CredmanApi) -> Result<(), Box<dyn std::error::Error>> {
+    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::<u32>()].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(&regularized) {
+                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(())
 }
 

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

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;