From ec6d0b4bd48b3e6a7ad8d2c279a6626e1d45fa96 Mon Sep 17 00:00:00 2001 From: chrysn Date: Tue, 29 Oct 2024 12:46:50 +0100 Subject: [PATCH] refactor(coap): Use demt-or-log instead of explicitly passed string writer --- Cargo.lock | 25 ++++++++ src/lib/coapcore/Cargo.toml | 7 +++ src/lib/coapcore/src/lib.rs | 17 ++++++ src/lib/coapcore/src/seccontext.rs | 93 ++++++++++++++++++------------ src/riot-rs-coap/Cargo.toml | 3 + src/riot-rs-coap/src/lib.rs | 10 +--- src/riot-rs/Cargo.toml | 1 + 7 files changed, 109 insertions(+), 47 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 08a03b8c2..20e298533 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -593,12 +593,15 @@ dependencies = [ "coap-message-implementations", "coap-message-utils", "coap-numbers", + "defmt", + "defmt-or-log", "heapless 0.8.0", "hexlit", "lakers", "lakers-crypto-rustcrypto", "liboscore", "liboscore-msgbackend", + "log 0.4.22", "minicbor 0.23.0", ] @@ -867,6 +870,28 @@ dependencies = [ "syn 2.0.85", ] +[[package]] +name = "defmt-or-log" +version = "0.2.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8370630b4dee85ab47d9087813771c5c7fe88d24fdd48649bbdfe6089da4c53a" +dependencies = [ + "defmt", + "defmt-or-log-macros", + "log 0.4.22", +] + +[[package]] +name = "defmt-or-log-macros" +version = "0.1.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d675dd299edbb7c8e01d4e9f520a0d8f22a8fe4af812c211c3fad5e9dcf41763" +dependencies = [ + "proc-macro2", + "quote", + "syn 2.0.85", +] + [[package]] name = "defmt-parser" version = "0.3.4" diff --git a/src/lib/coapcore/Cargo.toml b/src/lib/coapcore/Cargo.toml index 1d05a6795..afbfb3b48 100644 --- a/src/lib/coapcore/Cargo.toml +++ b/src/lib/coapcore/Cargo.toml @@ -32,3 +32,10 @@ liboscore-msgbackend = { git = "https://gitlab.com/oscore/liboscore/", features ], rev = "447e34fc5af427de7513f96a756babfe2f0b2c5c" } minicbor = "0.23.0" heapless = "0.8.0" +defmt-or-log = { version = "0.2.1", default-features = false } +defmt = { workspace = true, optional = true } +log = { version = "0.4", optional = true } + +[features] +defmt = ["defmt-or-log/defmt", "dep:defmt"] +log = ["defmt-or-log/log", "dep:log"] diff --git a/src/lib/coapcore/src/lib.rs b/src/lib/coapcore/src/lib.rs index 049a19300..30f9ef01e 100644 --- a/src/lib/coapcore/src/lib.rs +++ b/src/lib/coapcore/src/lib.rs @@ -9,6 +9,23 @@ //! the CoAP server itself, but merely a middleware. (Providing the full CoAP will be a requirement //! for at least as long as the OSCORE component is tightly coupled to a particular implementation //! of [`coap-message`]). +//! +//! ## Logging +//! +//! Extensive logging is available in this crate through [`defmt_or_log`], depending on features +//! enabled. +//! +//! Errors from CoAP are currently logged through its [`Debug2Format`](defmt_or_log::Debug2Format) +//! facility, representing a compromise between development and runtime complexity. Should +//! benchmarks show this to be a significant factor in code size in applications that need error +//! handling, more fine grained control can be implemented (eg. offering an option to make +//! Debug2Format merely print the type name or even make it empty). +//! +//! See the book for [how defmt is configured in +//! RIOT-rs](https://future-proof-iot.github.io/RIOT-rs/dev/docs/book/tooling/defmt.html). +//! +//! **Warning**: At the Debug level, this module may show cryptographic key material. This will be +//! revised once all components . #![no_std] // Might warrant a standalone crate at some point diff --git a/src/lib/coapcore/src/seccontext.rs b/src/lib/coapcore/src/seccontext.rs index 9310625fc..336c212fb 100644 --- a/src/lib/coapcore/src/seccontext.rs +++ b/src/lib/coapcore/src/seccontext.rs @@ -4,6 +4,7 @@ use coap_message::{ }; use coap_message_utils::{Error as CoAPError, OptionsExt as _}; use core::fmt::Write; +use defmt_or_log::{debug, error, info, warn, Debug2Format}; // If this exceeds 47, COwn will need to be extended. const MAX_CONTEXTS: usize = 4; @@ -21,6 +22,7 @@ pub type SecContextPool = /// This type represents any of the 48 efficient identifiers that use CBOR one-byte integer /// encodings (see RFC9528 Section 3.3.2), or equivalently the 1-byte long OSCORE identifiers // FIXME Could even limit to positive values if MAX_CONTEXTS < 24 +#[cfg_attr(feature = "defmt", derive(defmt::Format))] #[derive(Copy, Clone, PartialEq, Debug)] struct COwn(u8); @@ -82,6 +84,7 @@ impl Into for COwn { /// FIXME: At the moment, this always represents an authorization that allows everything, and only /// has runtime information about whether or not stdout is allowed. On the long run, this will /// likely be a CBOR item with pre-verified structure. +#[cfg_attr(feature = "defmt", derive(defmt::Format))] #[derive(Debug)] struct AifStaticRest { may_use_stdout: bool, @@ -111,6 +114,7 @@ impl AifStaticRest { } } +#[cfg_attr(feature = "defmt", derive(defmt::Format))] #[derive(Debug)] struct SecContextState { // FIXME: Should also include timeout. How do? Store expiry, do raytime in not-even-RTC mode, @@ -163,6 +167,26 @@ enum SecContextStage { Oscore(liboscore::PrimitiveContext), } +#[cfg(feature = "defmt")] +impl defmt::Format for SecContextStage { + fn format(&self, f: defmt::Formatter) { + match self { + SecContextStage::Empty => defmt::write!(f, "Empty"), + SecContextStage::EdhocResponderProcessedM1 { c_r, .. } => { + defmt::write!(f, "EdhocResponderProcessedM1 {{ c_r: {:?}, ... }}", c_r) + } + SecContextStage::EdhocResponderSentM2 { c_r, .. } => { + defmt::write!(f, "EdhocResponderSentM2 {{ c_r: {:?}, ... }}", c_r) + } + SecContextStage::Oscore(primitive_context) => defmt::write!( + f, + "Oscore(with recipient_id {:?})", + primitive_context.recipient_id() + ), + } + } +} + impl core::fmt::Display for SecContextState { fn fmt(&self, f: &mut core::fmt::Formatter<'_>) -> Result<(), core::fmt::Error> { use SecContextStage::*; @@ -234,7 +258,7 @@ impl SecContextState { /// While the EDHOC part could be implemented as a handler that is to be added into the tree, the /// OSCORE part needs to wrap the inner handler anyway, and EDHOC and OSCORE are intertwined rather /// strongly in processing the EDHOC option. -pub struct OscoreEdhocHandler<'a, H: coap_handler::Handler, L: Write, Crypto: lakers::Crypto> { +pub struct OscoreEdhocHandler<'a, H: coap_handler::Handler, Crypto: lakers::Crypto> { // It'd be tempted to have sharing among multiple handlers for multiple CoAP stacks, but // locks for such sharing could still be acquired in a factory (at which point it may make // sense to make this a &mut). @@ -254,27 +278,21 @@ pub struct OscoreEdhocHandler<'a, H: coap_handler::Handler, L: Write, Crypto: la // called, or an AuthorizationChecked::Allowed is around. inner: H, - log: L, - crypto_factory: fn() -> Crypto, } -impl<'a, H: coap_handler::Handler, L: Write, Crypto: lakers::Crypto> - OscoreEdhocHandler<'a, H, L, Crypto> -{ +impl<'a, H: coap_handler::Handler, Crypto: lakers::Crypto> OscoreEdhocHandler<'a, H, Crypto> { // FIXME: Apart from an own identity, this will also need a function to convert ID_CRED_I into // a (CRED_I, AifStaticRest) pair. pub fn new( own_identity: (&'a lakers::CredentialRPK, &'static [u8]), inner: H, - log: L, crypto_factory: fn() -> Crypto, ) -> Self { Self { pool: Default::default(), own_identity, inner, - log, crypto_factory, } } @@ -368,8 +386,8 @@ impl RenderableOnMinimal for OrI } } -impl<'a, H: coap_handler::Handler, L: Write, Crypto: lakers::Crypto> coap_handler::Handler - for OscoreEdhocHandler<'a, H, L, Crypto> +impl<'a, H: coap_handler::Handler, Crypto: lakers::Crypto> coap_handler::Handler + for OscoreEdhocHandler<'a, H, Crypto> { type RequestData = OrInner< EdhocResponse>, @@ -469,6 +487,7 @@ impl<'a, H: coap_handler::Handler, L: Write, Crypto: lakers::Crypto> coap_handle let starts_with_true = first_byte == &0xf5; if starts_with_true { + info!("Processing incoming EDHOC message 1"); let message_1 = &lakers::EdhocMessageBuffer::new_from_slice(&request.payload()[1..]) .map_err(too_small)?; @@ -502,15 +521,14 @@ impl<'a, H: coap_handler::Handler, L: Write, Crypto: lakers::Crypto> coap_handle ), ); - writeln!(self.log, "Entries in pool:").unwrap(); + debug!("Entries in pool:"); for (i, e) in self.pool.entries.iter().enumerate() { - writeln!(self.log, "{i}. {e}").unwrap(); + debug!("{}. {}", i, e); } - write!(self.log, "Sequence: ").unwrap(); + debug!("Sequence:"); for index in self.pool.sorted.iter() { - write!(self.log, "{index},").unwrap(); + debug!("* {}", index); } - writeln!(self.log, "").unwrap(); let evicted = self.pool.force_insert(SecContextState { protocol_stage: SecContextStage::EdhocResponderProcessedM1 { c_r, @@ -520,9 +538,9 @@ impl<'a, H: coap_handler::Handler, L: Write, Crypto: lakers::Crypto> coap_handle authorization: self.unauthenticated_edhoc_user_authorization(), }); if let Some(evicted) = evicted { - writeln!(self.log, "To insert new EDHOC, evicted {}", evicted).unwrap(); + warn!("To insert new EDHOC, evicted {}", evicted); } else { - writeln!(self.log, "To insert new EDHOC, evicted none").unwrap(); + debug!("To insert new EDHOC, evicted none"); } Ok(Own(EdhocResponse::OkSend2(c_r))) @@ -589,11 +607,7 @@ impl<'a, H: coap_handler::Handler, L: Write, Crypto: lakers::Crypto> coap_handle if id_cred_i.reference_only() { match id_cred_i.kid { 43 => { - writeln!( - self.log, - "Peer indicates use of the one preconfigured key" - ) - .unwrap(); + info!("Peer indicates use of the one preconfigured key"); use hexlit::hex; const CRED_I: &[u8] = &hex!("A2027734322D35302D33312D46462D45462D33372D33322D333908A101A5010202412B2001215820AC75E9ECE3E50BFC8ED60399889522405C47BF16DF96660A41298CB4307F7EB62258206E5DE611388A4B8A8211334AC7D37ECB52A387D257E6DB3C2A93DF21FF3AFFC8"); @@ -614,12 +628,10 @@ impl<'a, H: coap_handler::Handler, L: Write, Crypto: lakers::Crypto> coap_handle } } } else { - writeln!( - self.log, + info!( "Got credential by value: {:?}..", &id_cred_i.value.get_slice(0, 5) - ) - .unwrap(); + ); cred_i = lakers::CredentialRPK::new(id_cred_i.value) // FIXME What kind of error do we send here? @@ -642,8 +654,8 @@ impl<'a, H: coap_handler::Handler, L: Write, Crypto: lakers::Crypto> coap_handle let oscore_salt = responder.edhoc_exporter(1u8, &[], 8); // label is 1 let oscore_secret = &oscore_secret[..16]; let oscore_salt = &oscore_salt[..8]; - writeln!(self.log, "OSCORE secret: {:?}...", &oscore_secret[..5]).unwrap(); - writeln!(self.log, "OSCORE salt: {:?}", &oscore_salt).unwrap(); + debug!("OSCORE secret: {:?}...", &oscore_secret[..5]); + debug!("OSCORE salt: {:?}", &oscore_salt); let sender_id = c_i.as_slice(); let recipient_id = kid.0; @@ -679,6 +691,11 @@ impl<'a, H: coap_handler::Handler, L: Write, Crypto: lakers::Crypto> coap_handle // processing. } + info!( + "Processed {} bytes at start of message into new EDHOC context", + cutoff + ); + cutoff } else { 0 @@ -753,7 +770,7 @@ impl<'a, H: coap_handler::Handler, L: Write, Crypto: lakers::Crypto> coap_handle let Ok((correlation, extracted)) = decrypted else { // FIXME is that the right code? - writeln!(self.log, "Decryption failure").unwrap(); + error!("Decryption failure"); return Err(Own(CoAPError::unauthorized())); }; @@ -884,13 +901,13 @@ impl<'a, H: coap_handler::Handler, L: Write, Crypto: lakers::Crypto> coap_handle // One attempt to render rendering errors // FIXME rewind message Err(e) => { - write!(self.log, "Rendering successful extraction failed with {e:?}, ").unwrap(); + error!("Rendering successful extraction failed with {:?}", Debug2Format(&e)); match e.render(response) { Ok(()) => { - writeln!(self.log, "error rendered").unwrap(); + error!("Error rendered."); }, Err(e2) => { - writeln!(self.log, "error could not be rendered: {e2:?}").unwrap(); + error!("Error could not be rendered: {:?}.", Debug2Format(&e2)); // FIXME rewind message response.set_code(coap_numbers::code::INTERNAL_SERVER_ERROR); } @@ -898,21 +915,21 @@ impl<'a, H: coap_handler::Handler, L: Write, Crypto: lakers::Crypto> coap_handle }, }, AuthorizationChecked::Allowed(Err(inner_request_error)) => { - write!(self.log, "Extraction failed with {inner_request_error:?}, ").unwrap(); + error!("Extraction failed with {:?}.", Debug2Format(&inner_request_error)); match inner_request_error.render(response) { Ok(()) => { - writeln!(self.log, "rendered successfully").unwrap(); + error!("Original error rendered successfully."); }, Err(e) => { - write!(self.log, "could not be rendered due to {e:?}, ").unwrap(); + error!("Original error could not be rendered due to {:?}:", Debug2Format(&e)); // Two attempts to render extraction errors // FIXME rewind message match e.render(response) { Ok(()) => { - writeln!(self.log, "which was rendered fine").unwrap(); + error!("Error was rendered fine."); }, Err(e2) => { - writeln!(self.log, "rendering which caused {e2:?}").unwrap(); + error!("Rendering error caused {:?}.", Debug2Format(&e2)); // FIXME rewind message response.set_code( coap_numbers::code::INTERNAL_SERVER_ERROR, @@ -931,7 +948,7 @@ impl<'a, H: coap_handler::Handler, L: Write, Crypto: lakers::Crypto> coap_handle ) .is_err() { - writeln!(self.log, "Oups, responding with weird state").unwrap(); + error!("Oups, responding with weird state"); // todo!("Thanks to the protect API we've lost access to our response"); } }); diff --git a/src/riot-rs-coap/Cargo.toml b/src/riot-rs-coap/Cargo.toml index c751bafd0..d4c57b6f0 100644 --- a/src/riot-rs-coap/Cargo.toml +++ b/src/riot-rs-coap/Cargo.toml @@ -37,6 +37,9 @@ workspace = true ## if no features are configured at all. doc = ["embassy-net/proto-ipv6", "embassy-net/medium-ip"] +## Enables defmt logging of coapcore +defmt = ["coapcore/log"] + # Only around while we carry the embedded-nal-async impl proto-ipv4 = ["embassy-net/proto-ipv4"] proto-ipv6 = ["embassy-net/proto-ipv6"] diff --git a/src/riot-rs-coap/src/lib.rs b/src/riot-rs-coap/src/lib.rs index 5c42683fa..784313132 100644 --- a/src/riot-rs-coap/src/lib.rs +++ b/src/riot-rs-coap/src/lib.rs @@ -20,14 +20,6 @@ use static_cell::StaticCell; const CONCURRENT_REQUESTS: usize = 3; -struct DevNull; - -impl core::fmt::Write for DevNull { - fn write_str(&mut self, _: &str) -> core::fmt::Result { - Ok(()) - } -} - // FIXME: log_stdout is not something we want to have here // FIXME: I'd rather have the client_out available anywhere, but at least the way CoAPRuntimeClient // is set up right now, server and client have to run in the same thread. @@ -75,7 +67,7 @@ pub async fn coap_run( // FIXME: Should we allow users to override that? After all, this is just convenience and may // be limiting in special applications. let handler = handler.with_wkc(); - let mut handler = seccontext::OscoreEdhocHandler::new(own_identity, handler, DevNull, || { + let mut handler = seccontext::OscoreEdhocHandler::new(own_identity, handler, || { lakers_crypto_rustcrypto::Crypto::new(riot_rs_random::crypto_rng()) }); diff --git a/src/riot-rs/Cargo.toml b/src/riot-rs/Cargo.toml index 3c11d2bf5..fcbec9ce5 100644 --- a/src/riot-rs/Cargo.toml +++ b/src/riot-rs/Cargo.toml @@ -89,6 +89,7 @@ wifi-esp = ["riot-rs-embassy/wifi-esp"] debug-console = ["riot-rs-rt/debug-console"] ## Enables logging support through `defmt`. defmt = [ + "riot-rs-coap?/defmt", "riot-rs-debug/defmt", "riot-rs-embassy/defmt", "riot-rs-threads?/defmt",