Standardise log levels (#223)

.github/workflows/dylint.yml

@@ -0,0 +1,38 @@
+name: Logging policy lints
+
+on: [push, pull_request]
+
+jobs:
+  dylint:
+    name: dylint logging policy
+    runs-on: ubuntu-latest
+    steps:
+      - uses: actions/checkout@v2
+      - name: Checkout submodules
+        run: git submodule update --init --recursive
+      - name: Update apt cache
+        run: sudo apt-get update
+      - name: Install system dependencies
+        run: sudo apt-get install libudev-dev libdbus-1-dev libsodium-dev libnfc-dev libpcsclite-dev
+      - name: Install Rust (stable, builds cargo-dylint)
+        uses: actions-rs/toolchain@16499b5e05bf2e26879000db0c1d13f7e13fa3af #@v1
+        with:
+          profile: minimal
+          toolchain: stable
+          override: true
+      - name: Install the lint toolchain
+        run: |
+          TOOLCHAIN=$(grep '^channel' lints/logging_lints/rust-toolchain | sed -E 's/.*"(.*)".*/\1/')
+          rustup toolchain install "$TOOLCHAIN" --profile minimal -c rustc-dev -c llvm-tools-preview
+      - name: Install cargo-dylint
+        run: cargo install cargo-dylint dylint-link
+      - name: Run logging policy lints
+        # The three deterministic lints fail the build. The sensitive-field
+        # heuristic stays a warning, as documented in docs/logging.md.
+        run: |
+          set -o pipefail
+          cargo dylint --all --workspace -- --all-features 2>&1 | tee dylint.log
+          if grep -qE 'dylint::(tracing_message_interpolation|print_macro_in_library|log_crate_macro)' dylint.log; then
+            echo "::error::Logging policy violations found, see docs/logging.md"
+            exit 1
+          fi

Cargo.toml

@@ -2,6 +2,11 @@
 resolver = "2"
 members = ["libwebauthn", "libwebauthn-tests"]
 
+# Custom dylint lints enforcing the logging policy (docs/logging.md).
+# Run with `cargo dylint --all --workspace -- --all-features`.
+[workspace.metadata.dylint]
+libraries = [{ path = "lints/logging_lints" }]
+
 # The trussed ecosystem is currently a bit messy, so we have to do some patching of the versions
 [patch.crates-io]
 trussed = { git = "https://github.com/trussed-dev/trussed.git", rev = "024e0eca5fb7dbd2457831f7c7bffe4341e08775" }

docs/logging.md

@@ -0,0 +1,127 @@
+# Logging policy
+
+libwebauthn uses the [`tracing`](https://docs.rs/tracing) crate for all
+diagnostics. This document defines how to choose a level, what must never be
+logged, and how to write the call. The mechanical rules are enforced by a custom
+dylint lint (see [Enforcement](#enforcement)).
+
+## Principles
+
+1. libwebauthn is a library, not an application. Errors reach the caller through
+   `Result`. Logging is for diagnosis and must not drive control flow.
+2. A run at the default level must be quiet and safe to share. An INFO-level log
+   should be safe to paste into a bug report, with no secrets and no per-packet
+   noise.
+3. Messages are static. Dynamic data goes into structured fields so logs stay
+   greppable and machine-parseable.
+
+## Levels
+
+Choose the level by the nature of the event, not by how much you care about it.
+
+### `error!`
+
+Only for faults inside libwebauthn itself: a broken invariant, an unreachable
+state, a bug. If correct library code cannot produce the condition, it belongs
+at `error!`.
+
+Not for: a device returning a CTAP error status, an IO or transport failure, a
+timeout, user cancellation, or an authenticator rejecting a request. Those are
+returned to the caller and logged at `warn!` or lower.
+
+### `warn!`
+
+Unexpected behaviour from the device or peer, and recoverable anomalies the
+operator may want to know about. For example a malformed or out-of-spec response
+that we can still handle, a fallback to a less preferred protocol, an unexpected
+field we ignore, or a non-fatal failure we continue past.
+
+### `info!`
+
+Sparse, high-level lifecycle events meaningful to an operator. For example
+establishing a connection, selecting a transport or FIDO revision, or the start
+and end of a ceremony. INFO carries no sensitive data and never appears inside a
+loop or per packet. Device enumeration is polled by callers, so it logs the
+count at `debug!` and the device list at `trace!`.
+
+### `debug!`
+
+Developer-facing protocol flow: command and response codes, status, lengths,
+small non-sensitive fields, and state transitions. Byte arrays appear here only
+as their length. Sensitive values appear here only as a length or a presence
+flag, never in full.
+
+### `trace!`
+
+Raw wire data: full byte arrays, raw CBOR and APDU buffers, full request and
+response structures, per-packet dumps. This is the only level at which a raw
+secret may appear.
+
+## Sensitive data
+
+These are sensitive and must never be logged above `debug!`:
+
+- PINs, PIN hashes, and PIN tokens
+- shared secrets and key-agreement material
+- `pinUvAuthToken` and `pinUvAuthParam`
+- HMAC salts and outputs, and PRF values
+- large-blob plaintext
+- private keys
+- credential IDs
+- user handles and user names
+
+At `debug!` log only a length or a presence flag. A full value may appear only
+at `trace!`.
+
+## How to write a log call
+
+The message is always a static string literal. Never interpolate (`"{x}"`) and
+never pass `format!`. Put dynamic data in fields.
+
+- Use `%value` for `Display` and `?value` for `Debug`.
+- Name fields in snake_case: `field = value`.
+- One field: bare. Two or more: a brace block.
+
+```rust
+// one field: bare
+warn!(?err, "Authenticator returned a malformed response");
+
+// two or more fields: brace block
+debug!({ rp_id = %rp_id, cred_count = creds.len() }, "Starting preflight");
+
+// byte arrays: length at debug, full bytes at trace
+debug!(len = apdu.len(), "Received APDU");
+trace!(?apdu, "Received APDU");
+```
+
+Prefer a span over repeating the same field on every event. A ceremony or a
+transport can open a span carrying shared context such as the transport and the
+rp_id.
+
+Do not use `println!`, `eprintln!`, or the `log` crate's macros in the library.
+Everything goes through `tracing`.
+
+## Enforcement
+
+A custom dylint lint in [`lints/`](../lints) checks the mechanical rules:
+
+- the message must be a static string literal, with no interpolation or
+  `format!`
+- no `println!`, `eprintln!`, `print!`, or `eprint!`
+- no `log::` macros
+- a best-effort denylist flags sensitive field names (pin, secret, token, and so
+  on) used at `info!` and above
+
+Level choice, and whether a particular value is sensitive, cannot be decided by a
+tool. Those rules are upheld in review against this document.
+
+Run it locally:
+
+```sh
+cargo install cargo-dylint dylint-link   # once
+cargo dylint --all --workspace -- --all-features
+```
+
+CI runs the same command on every push. The three deterministic lints fail the
+build. The sensitive-field heuristic stays a warning, since whether a value is
+sensitive cannot be decided by a tool.

libwebauthn-tests/src/virt/device.rs

@@ -170,7 +170,7 @@ impl HidDevice for Device<'_> {
 
             if let Some(response) = self.0.borrow_mut().pop() {
                 return if buffer.len() >= response.len() {
-                    info!("received response: {} bytes", response.len());
+                    info!(len = response.len(), "Received response");
                     buffer[..response.len()].copy_from_slice(&response);
                     Ok(&buffer[..response.len()])
                 } else {

libwebauthn-tests/src/virt/pipe.rs

@@ -401,15 +401,14 @@ impl<'a, const N: usize> Pipe<'a, N> {
                     Ok(message) => {
                         if message.len() > self.buffer.len() {
                             error!(
-                                "Message is longer than buffer ({} > {})",
-                                message.len(),
-                                self.buffer.len(),
+                                { message_len = message.len(), buffer_len = self.buffer.len() },
+                                "Message is longer than buffer"
                             );
                             self.start_sending_error(request, CtapError::InvalidLength);
                         } else {
                             info!(
-                                "Got {} bytes response from authenticator, starting send",
-                                message.len()
+                                len = message.len(),
+                                "Got response from authenticator, starting send"
                             );
                             let response = Response::from_request_and_size(request, message.len());
                             self.buffer[..message.len()].copy_from_slice(message);

libwebauthn/src/fido.rs

@@ -142,7 +142,10 @@ where
         res.push(self.flags.bits());
         res.write_u32::<BigEndian>(self.signature_count)
             .map_err(|e| {
-                error!("Failed to create AuthenticatorData output vec at signature_count: {e:?}");
+                error!(
+                    ?e,
+                    "Failed to create AuthenticatorData output vec at signature_count"
+                );
                 PlatformError::InvalidDeviceResponse
             })?;
 
@@ -157,7 +160,8 @@ where
             res.write_u16::<BigEndian>(att_data.credential_id.len() as u16)
             .map_err(|e| {
                 error!(
-                    "Failed to create AuthenticatorData output vec at attested_credential.credential_id: {e:?}"
+                    ?e,
+                    "Failed to create AuthenticatorData output vec at attested_credential.credential_id"
                 );
                 PlatformError::InvalidDeviceResponse
             })?;

libwebauthn/src/lib.rs

@@ -125,9 +125,9 @@ macro_rules! unwrap_field {
         if let Some(f) = $field {
             f
         } else {
-            tracing::error!(
-                "Device response did not contain expected field: {}",
-                stringify!($field)
+            tracing::warn!(
+                field = stringify!($field),
+                "Device response did not contain expected field"
             );
             return Err($crate::webauthn::error::PlatformError::InvalidDeviceResponse.into());
         }

libwebauthn/src/management/bio_enrollment.rs

@@ -87,7 +87,7 @@ where
         match resp.modality {
             Some(modality) => Ok(modality),
             None => {
-                warn!("Channel did not return modality.");
+                warn!("Channel did not return modality");
                 Err(WebAuthnError::Ctap(CtapError::Other))
             }
         }
@@ -101,7 +101,7 @@ where
         // No UV needed
         let resp = self.ctap2_bio_enrollment(&req, timeout).await?;
         let Some(fingerprint_kind) = resp.fingerprint_kind else {
-            warn!("Channel did not return fingerprint_kind in sensor info.");
+            warn!("Channel did not return fingerprint_kind in sensor info");
             return Err(WebAuthnError::Ctap(CtapError::Other));
         };
         Ok(Ctap2BioEnrollmentFingerprintSensorInfo {

libwebauthn/src/ops/u2f.rs

@@ -3,7 +3,7 @@ use std::time::Duration;
 use cosey as cose;
 use serde_bytes::ByteBuf;
 use sha2::{Digest, Sha256};
-use tracing::{error, trace};
+use tracing::{error, trace, warn};
 use x509_parser::nom::AsBytes;
 
 use super::webauthn::MakeCredentialRequest;
@@ -57,17 +57,20 @@ impl UpgradableResponse<MakeCredentialResponse, MakeCredentialRequest> for Regis
         // from ANS X9.62 / Sec-1 v2 uncompressed curve point representation [SEC1V2]
         // to COSE_Key representation ([RFC8152] Section 7).
         let Ok(encoded_point) = p256::EncodedPoint::from_bytes(&self.public_key) else {
-            error!(?self.public_key, "Failed to parse public key as SEC-1 v2 encoded point");
+            warn!(
+                public_key_len = self.public_key.len(),
+                "Failed to parse public key as SEC-1 v2 encoded point"
+            );
             return Err(WebAuthnError::Ctap(CtapError::Other));
         };
         let x_bytes = encoded_point.x().ok_or_else(|| {
-            error!("Public key is the identity point");
+            warn!("Public key is the identity point");
             WebAuthnError::Platform(PlatformError::CryptoError(
                 "public key is the identity point".into(),
             ))
         })?;
         let y_bytes = encoded_point.y().ok_or_else(|| {
-            error!("Public key is identity or compressed");
+            warn!("Public key is identity or compressed");
             WebAuthnError::Platform(PlatformError::CryptoError(
                 "public key is identity or compressed".into(),
             ))
@@ -250,7 +253,7 @@ impl UpgradableResponse<GetAssertionResponse, SignRequest> for SignResponse {
             .as_slice()
             .into();
 
-        trace!(?upgraded_response);
+        trace!(?upgraded_response, "Upgraded U2F sign response");
         Ok(upgraded_response)
     }
 }

libwebauthn/src/ops/webauthn/get_assertion.rs

@@ -3,7 +3,7 @@ use std::{collections::HashMap, time::Duration};
 use async_trait::async_trait;
 use serde::{Deserialize, Serialize};
 use sha2::{Digest, Sha256};
-use tracing::{debug, error, trace};
+use tracing::{debug, trace, warn};
 
 use crate::{
     fido::AuthenticatorData,
@@ -421,7 +421,7 @@ impl Ctap2HMACGetSecretOutput {
         let output = match uv_proto.decrypt(shared_secret, &self.encrypted_output) {
             Ok(o) => o,
             Err(e) => {
-                error!("Failed to decrypt HMAC Secret output with the shared secret: {e:?}. Skipping HMAC extension");
+                warn!(?e, "Failed to decrypt HMAC Secret output with the shared secret, skipping HMAC extension");
                 return None;
             }
         };
@@ -435,7 +435,10 @@ impl Ctap2HMACGetSecretOutput {
             output2.copy_from_slice(o2);
             res.output2 = Some(output2);
         } else {
-            error!("Failed to split HMAC Secret outputs. Unexpected output length: {}. Skipping HMAC extension", output.len());
+            warn!(
+                output_len = output.len(),
+                "Failed to split HMAC Secret outputs, skipping HMAC extension"
+            );
             return None;
         }
 

libwebauthn/src/ops/webauthn/idl/mod.rs

@@ -131,7 +131,7 @@ pub(crate) async fn rp_id_authorised(
         RelatedOrigins::Enabled { source, max_labels } => {
             match source.allowed_origins(rp_id).await {
                 Err(err) => {
-                    debug!(rp_id = %rp_id.0, %err, "Related-origins resolution failed");
+                    debug!({ rp_id = %rp_id.0, %err }, "Related-origins resolution failed");
                     false
                 }
                 Ok(origins) => match validate_related_origins(
@@ -142,7 +142,7 @@ pub(crate) async fn rp_id_authorised(
                 ) {
                     Ok(()) => true,
                     Err(err) => {
-                        debug!(rp_id = %rp_id.0, %err, "Related-origins match failed");
+                        debug!({ rp_id = %rp_id.0, %err }, "Related-origins match failed");
                         false
                     }
                 },

libwebauthn/src/ops/webauthn/large_blob.rs

@@ -110,9 +110,7 @@ async fn fetch_serialized_array<C: Ctap2 + ?Sized>(
         let chunk_len = chunk.len();
         out.extend_from_slice(&chunk);
         trace!(
-            offset,
-            chunk_len,
-            total = out.len(),
+            { offset, chunk_len, total = out.len() },
             "authenticatorLargeBlobs(get) chunk"
         );
         if chunk_len < max_fragment as usize {
@@ -121,8 +119,8 @@ async fn fetch_serialized_array<C: Ctap2 + ?Sized>(
         }
         if out.len() > LARGE_BLOB_MAX_ARRAY_BYTES {
             warn!(
-                total = out.len(),
-                "largeBlobArray exceeded {LARGE_BLOB_MAX_ARRAY_BYTES}, aborting"
+                { total = out.len(), cap = LARGE_BLOB_MAX_ARRAY_BYTES },
+                "largeBlobArray exceeded platform cap, aborting"
             );
             return Err(LargeBlobError::Corrupted(
                 "serialized array exceeds platform cap".into(),
@@ -154,8 +152,7 @@ impl LargeBlobMapEntry {
         }
         if self.orig_size > LARGE_BLOB_MAX_ORIG_SIZE {
             warn!(
-                orig_size = self.orig_size,
-                cap = LARGE_BLOB_MAX_ORIG_SIZE,
+                { orig_size = self.orig_size, cap = LARGE_BLOB_MAX_ORIG_SIZE },
                 "largeBlob entry origSize exceeds platform cap; skipping"
             );
             return Ok(None);
@@ -627,9 +624,7 @@ async fn upload_serialized_array<C: Ctap2 + ?Sized>(
             Ctap2LargeBlobsRequest::new_set_continuation(chunk.to_vec(), offset, chunk_auth)
         };
         trace!(
-            offset,
-            chunk_len = chunk.len(),
-            total,
+            { offset, chunk_len = chunk.len(), total },
             "authenticatorLargeBlobs(set) chunk"
         );
         channel