feat(rrp): add rrp logger

Cargo.toml

@@ -66,6 +66,7 @@ defmt = "0.3.8"
 defmt-rtt = "0.4.1"
 
 # common libraries
+serde_with = { version = "3.9.0", default-features = false }
 futures = { version = "0.3.30", default-features = false }
 serde = { version = "1.0.207", default-features = false }
 postcard = "1.0.8"
@@ -75,3 +76,5 @@ rand_core = "0.6.4"
 specta = { version = "2.0.0-rc.20" }
 tsify-next = { git = "https://github.com/siefkenj/tsify", features = ["js"] }
 wasm-bindgen = "0.2.93"
+
+log = "0.4.22"

lib/rktk-keymanager/Cargo.toml

@@ -15,9 +15,7 @@ paste = "1.0.15"
 macro_rules_attribute = { workspace = true }
 
 serde = { workspace = true, optional = true, features = ["derive"] }
-serde_with = { version = "3.9.0", optional = true, default-features = false, features = [
-  "macros",
-] }
+serde_with = { workspace = true, features = ["macros"], optional = true }
 postcard = { workspace = true, optional = true, features = [
   "experimental-derive",
 ] }

lib/rktk-rrp/Cargo.toml

@@ -12,6 +12,7 @@ postcard = { workspace = true, features = ["experimental-derive"] }
 heapless = { workspace = true }
 futures = { workspace = true }
 serde = { workspace = true, features = ["derive"] }
+serde_with = { workspace = true, features = ["macros"] }
 macro_rules_attribute = { workspace = true }
 
 specta = { workspace = true, optional = true, features = ["derive"] }

lib/rktk-rrp/src/client.rs

@@ -46,16 +46,17 @@ macro_rules! endpoint_client {
             let mut buf = vec![];
             loop {
                 let Ok(size) = $et.read_until_zero(&mut buf).await else {
-                    continue;
+                    break;
                 };
                 if buf.len() == 1 {
-                    return None;
+                    break;
                 }
                 let Ok(req) = from_bytes_cobs::<$crate::endpoints::$endpoint::StreamResponse>(&mut buf) else {
-                    continue;
+                    break;
                 };
                 return Some((req, ()));
             }
+            return None;
         })
     }};
 

lib/rktk-rrp/src/endpoints.rs

@@ -67,3 +67,21 @@ pub mod set_keymap_config {
     pub type Request = rktk_keymanager::state::config::StateConfig;
     pub type Response = ();
 }
+
+pub mod get_log {
+    use macro_rules_attribute::apply;
+
+    #[serde_with::serde_as]
+    #[apply(super::common_derive)]
+    pub enum LogChunk {
+        Bytes {
+            #[serde(with = "serde_with::As::<[serde_with::Same; 128]>")]
+            bytes: [u8; 128],
+            len: u8,
+        },
+        Break,
+    }
+
+    pub type Request = ();
+    pub type StreamResponse = LogChunk;
+}

lib/rktk-rrp/src/server.rs

@@ -76,7 +76,8 @@ macro_rules! endpoint_server {
 
     (@send stream $et:expr, $ep:ident, $data:expr) => {{
         use $crate::__reexports::futures::stream::StreamExt;
-        while let Some(res) = $data.next().await {
+        let mut data = core::pin::pin!($data);
+        while let Some(res) = data.next().await {
             let res: StreamResponse = res;
             let mut buf = [0u8; StreamResponse::POSTCARD_MAX_SIZE + StreamResponse::POSTCARD_MAX_SIZE / 254 + 2];
             let Ok(res) = postcard::to_slice_cobs(&res, &mut buf) else {

lib/rktk/Cargo.toml

@@ -36,6 +36,9 @@ postcard = { workspace = true, features = [
   "heapless-cas",
 ] }
 
+log = { workspace = true }
+critical-section = { version = "1.1.3" }
+
 [dev-dependencies]
 embassy-time = { workspace = true, features = ["mock-driver", "generic-queue"] }
 critical-section = { version = "1.1.2", features = ["std"] }

lib/rktk/src/task/logger.rs

@@ -0,0 +1,71 @@
+use core::fmt::Write;
+
+use embassy_sync::{blocking_mutex::raw::CriticalSectionRawMutex, channel::Channel};
+use rktk_rrp::endpoints::get_log::LogChunk;
+
+pub struct LogWriter {
+    // If ths channel becomes full, entire log entry will be dropped.
+    aborted: bool,
+}
+
+impl Drop for LogWriter {
+    fn drop(&mut self) {
+        if !self.aborted {
+            let _ = LOG_CHANNEL.try_send(LogChunk::Break);
+        }
+    }
+}
+
+impl Write for LogWriter {
+    fn write_str(&mut self, s: &str) -> core::fmt::Result {
+        if self.aborted {
+            return Ok(());
+        }
+
+        for chunk in s.as_bytes().chunks(128) {
+            let mut buf = [0; 128];
+            buf[..chunk.len()].copy_from_slice(chunk);
+
+            if let Err(_e) = LOG_CHANNEL.try_send(LogChunk::Bytes {
+                bytes: buf,
+                len: chunk.len() as u8,
+            }) {
+                self.aborted = true;
+                return Ok(());
+            }
+        }
+
+        Ok(())
+    }
+}
+
+pub static LOG_CHANNEL: Channel<CriticalSectionRawMutex, LogChunk, 32> = Channel::new();
+
+pub struct RrpLogger;
+
+pub static RRP_LOGGER: RrpLogger = RrpLogger;
+
+impl log::Log for RrpLogger {
+    fn enabled(&self, _metadata: &log::Metadata) -> bool {
+        !LOG_CHANNEL.is_full()
+    }
+
+    fn log(&self, record: &log::Record) {
+        if !self.enabled(record.metadata()) {
+            return;
+        }
+
+        let _ = LOG_CHANNEL.try_send(LogChunk::Break);
+
+        let mut writer = LogWriter { aborted: false };
+        write!(
+            &mut writer,
+            "{}\t{}\t{}",
+            record.level(),
+            record.module_path().unwrap_or_default(),
+            record.args()
+        )
+        .unwrap();
+    }
+    fn flush(&self) {}
+}

lib/rktk/src/task/main_loop/master.rs

@@ -1,5 +1,5 @@
 use embassy_futures::join::join;
-use embassy_time::Timer;
+use embassy_time::{Duration, Timer};
 use rktk_keymanager::state::{
     config::{KeyResolverConfig, MouseConfig, StateConfig},
     KeyChangeEvent, State, StateReport,
@@ -108,7 +108,7 @@ pub async fn start<'a, KS: KeyscanDriver, M: MouseDriver, R: ReporterDriver, S:
 
         match s.read_version().await {
             Ok(1) => {
-                crate::print!("Storage version matched!");
+                // crate::print!("Storage version matched!");
                 config_storage = Some(s);
             }
             Ok(i) => {
@@ -164,6 +164,11 @@ pub async fn start<'a, KS: KeyscanDriver, M: MouseDriver, R: ReporterDriver, S:
     join(
         async {
             let mut prev_time = embassy_time::Instant::now();
+
+            let mut duration_max = Duration::from_millis(0);
+            let mut duration_sum = Duration::from_millis(0);
+            let mut loop_count = 0;
+
             loop {
                 let start = embassy_time::Instant::now();
                 let since_last_update = start - prev_time;
@@ -217,6 +222,22 @@ pub async fn start<'a, KS: KeyscanDriver, M: MouseDriver, R: ReporterDriver, S:
 
                 let took = start.elapsed();
 
+                if took > duration_max {
+                    duration_max = took;
+                }
+                duration_sum += took;
+                loop_count += 1;
+                if loop_count % 100 == 0 {
+                    log::info!(
+                        "Max: {}us, Avg: {}us",
+                        duration_max.as_micros(),
+                        duration_sum.as_micros() / loop_count
+                    );
+                    duration_max = Duration::from_millis(0);
+                    duration_sum = Duration::from_millis(0);
+                    loop_count = 0;
+                }
+
                 if took < SCAN_INTERVAL_KEYBOARD {
                     Timer::after(SCAN_INTERVAL_KEYBOARD - took).await;
                 }

lib/rktk/src/task/main_loop/master/rrp_server.rs

@@ -61,6 +61,7 @@ impl<'a, S: StorageDriver> Server<'a, S> {
         set_keymaps stream normal => set_keymaps
         get_keymap_config normal normal => get_keymap_config
         set_keymap_config normal normal => set_keymap_config
+        get_log normal stream => get_log
     );
 
     async fn get_info(&mut self, _req: get_keyboard_info::Request) -> get_keyboard_info::Response {
@@ -144,4 +145,17 @@ impl<'a, S: StorageDriver> Server<'a, S> {
         }
         *self.state.lock().await = State::new(keymap, req);
     }
+
+    async fn get_log(
+        &mut self,
+        _req: get_log::Request,
+    ) -> impl Stream<Item = get_log::StreamResponse> + '_ {
+        futures::stream::iter(core::iter::from_fn(|| {
+            if let Ok(chunk) = crate::task::logger::LOG_CHANNEL.try_receive() {
+                Some(chunk)
+            } else {
+                None
+            }
+        }))
+    }
 }

lib/rktk/src/task/mod.rs

@@ -19,6 +19,7 @@ use crate::{
 
 mod backlight;
 pub mod display;
+mod logger;
 mod main_loop;
 
 /// All drivers required to run the keyboard.
@@ -87,6 +88,13 @@ pub async fn start<
     >,
     key_config: KeyConfig,
 ) {
+    critical_section::with(|_| unsafe {
+        let _ = log::set_logger_racy(&logger::RRP_LOGGER);
+        log::set_max_level_racy(log::LevelFilter::Info);
+    });
+
+    log::info!("RKTK Start");
+
     if let Some(dtr) = &mut drivers.double_tap_reset {
         dtr.execute(Duration::from_millis(CONFIG.double_tap_threshold))
             .await;

rrp-web/rrp-client-web/Cargo.toml

@@ -32,3 +32,4 @@ futures = { workspace = true }
 serde-wasm-bindgen = "0.6.5"
 tsify-next = { workspace = true }
 async-lock = "3.4.0"
+gloo-timers = { version = "0.3.0", features = ["futures"] }