From f7766392b4aaf8310d09648e5e1f88c66d2e6807 Mon Sep 17 00:00:00 2001 From: nazo6 Date: Wed, 28 Aug 2024 00:03:14 +0900 Subject: [PATCH] feat(rrp): add rrp logger --- Cargo.lock | 19 ++++- Cargo.toml | 3 + lib/rktk-keymanager/Cargo.toml | 4 +- lib/rktk-rrp/Cargo.toml | 1 + lib/rktk-rrp/src/client.rs | 7 +- lib/rktk-rrp/src/endpoints.rs | 18 +++++ lib/rktk-rrp/src/server.rs | 3 +- lib/rktk/Cargo.toml | 3 + lib/rktk/src/task/logger.rs | 71 +++++++++++++++++++ lib/rktk/src/task/main_loop/master.rs | 25 ++++++- .../src/task/main_loop/master/rrp_server.rs | 14 ++++ lib/rktk/src/task/mod.rs | 8 +++ rrp-web/rrp-client-web/Cargo.toml | 1 + rrp-web/rrp-client-web/src/client.rs | 62 +++++++++------- rrp-web/rrp-client-web/src/lib.rs | 33 ++++++++- rrp-web/src/page/Home/LogViewer.tsx | 31 ++++++++ rrp-web/src/page/Home/index.tsx | 16 ++++- 17 files changed, 279 insertions(+), 40 deletions(-) create mode 100644 lib/rktk/src/task/logger.rs create mode 100644 rrp-web/src/page/Home/LogViewer.tsx diff --git a/Cargo.lock b/Cargo.lock index fe81e52a..9500c8e9 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -274,9 +274,9 @@ dependencies = [ [[package]] name = "critical-section" -version = "1.1.2" +version = "1.1.3" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "7059fff8937831a9ae6f0fe4d658ffabf58f2ca96aa9dec1c889f936f705f216" +checksum = "f64009896348fc5af4222e9cf7d7d82a95a256c634ebcf61c53e4ea461422242" [[package]] name = "crossbeam-utils" @@ -1020,6 +1020,18 @@ dependencies = [ "wasi", ] +[[package]] +name = "gloo-timers" +version = "0.3.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "bbb143cf96099802033e0d4f4963b19fd2e0b728bcf076cd9cf7f6634f092994" +dependencies = [ + "futures-channel", + "futures-core", + "js-sys", + "wasm-bindgen", +] + [[package]] name = "gloo-utils" version = "0.2.0" @@ -1861,6 +1873,7 @@ dependencies = [ "futures", "heapless 0.7.17", "itertools 0.13.0", + "log", "paste", "postcard", "pretty_assertions", @@ -1975,6 +1988,7 @@ dependencies = [ "postcard", "rktk-keymanager", "serde", + "serde_with", "specta", "tsify-next", "wasm-bindgen", @@ -2007,6 +2021,7 @@ dependencies = [ "async-lock", "console_log", "futures", + "gloo-timers", "log", "rktk-keymanager", "rktk-rrp", diff --git a/Cargo.toml b/Cargo.toml index 45ba2ba5..59dc01ee 100644 --- a/Cargo.toml +++ b/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" diff --git a/lib/rktk-keymanager/Cargo.toml b/lib/rktk-keymanager/Cargo.toml index 00ef466a..9c81c44f 100644 --- a/lib/rktk-keymanager/Cargo.toml +++ b/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", ] } diff --git a/lib/rktk-rrp/Cargo.toml b/lib/rktk-rrp/Cargo.toml index d7c05de7..3661c1e7 100644 --- a/lib/rktk-rrp/Cargo.toml +++ b/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"] } diff --git a/lib/rktk-rrp/src/client.rs b/lib/rktk-rrp/src/client.rs index 5ef4e68e..81f93aad 100644 --- a/lib/rktk-rrp/src/client.rs +++ b/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; }) }}; diff --git a/lib/rktk-rrp/src/endpoints.rs b/lib/rktk-rrp/src/endpoints.rs index dcd2de9e..43808985 100644 --- a/lib/rktk-rrp/src/endpoints.rs +++ b/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; +} diff --git a/lib/rktk-rrp/src/server.rs b/lib/rktk-rrp/src/server.rs index 725e6d3f..ed5389d3 100644 --- a/lib/rktk-rrp/src/server.rs +++ b/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 { diff --git a/lib/rktk/Cargo.toml b/lib/rktk/Cargo.toml index fa28b364..cdb16986 100644 --- a/lib/rktk/Cargo.toml +++ b/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"] } diff --git a/lib/rktk/src/task/logger.rs b/lib/rktk/src/task/logger.rs new file mode 100644 index 00000000..0deb4713 --- /dev/null +++ b/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 = 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) {} +} diff --git a/lib/rktk/src/task/main_loop/master.rs b/lib/rktk/src/task/main_loop/master.rs index 4138c1ae..fef2ddc1 100644 --- a/lib/rktk/src/task/main_loop/master.rs +++ b/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; } diff --git a/lib/rktk/src/task/main_loop/master/rrp_server.rs b/lib/rktk/src/task/main_loop/master/rrp_server.rs index 789b1ebf..d7c9e769 100644 --- a/lib/rktk/src/task/main_loop/master/rrp_server.rs +++ b/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 + '_ { + futures::stream::iter(core::iter::from_fn(|| { + if let Ok(chunk) = crate::task::logger::LOG_CHANNEL.try_receive() { + Some(chunk) + } else { + None + } + })) + } } diff --git a/lib/rktk/src/task/mod.rs b/lib/rktk/src/task/mod.rs index cdc24021..6ac1a09f 100644 --- a/lib/rktk/src/task/mod.rs +++ b/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; diff --git a/rrp-web/rrp-client-web/Cargo.toml b/rrp-web/rrp-client-web/Cargo.toml index 8ee2fd5d..a0cdcef4 100644 --- a/rrp-web/rrp-client-web/Cargo.toml +++ b/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"] } diff --git a/rrp-web/rrp-client-web/src/client.rs b/rrp-web/rrp-client-web/src/client.rs index d773a819..3507c31d 100644 --- a/rrp-web/rrp-client-web/src/client.rs +++ b/rrp-web/rrp-client-web/src/client.rs @@ -1,3 +1,5 @@ +use futures::future::select; +use gloo_timers::future::TimeoutFuture; use rktk_rrp::endpoint_client; use wasm_bindgen::JsCast; use wasm_bindgen::JsValue; @@ -45,36 +47,43 @@ impl SerialClient { .dyn_into::() .expect("Invalid readable stream"); - let res = async { - loop { - let typed_array = web_sys::js_sys::Uint8Array::new(&JsValue::from(1)); - let promise = reader.read_with_array_buffer_view(&typed_array); - let obj = JsFuture::from(promise) - .await - .map_err(|e| anyhow::anyhow!("Failed to read data: {:?}", e))?; + let res = match select( + std::pin::pin!(async { + loop { + let typed_array = web_sys::js_sys::Uint8Array::new(&JsValue::from(1)); + let promise = reader.read_with_array_buffer_view(&typed_array); + let obj = JsFuture::from(promise) + .await + .map_err(|e| anyhow::anyhow!("Failed to read data: {:?}", e))?; - let done = js_sys::Reflect::get(&obj, &JsValue::from("done")) - .expect("Failed to get done property of data") - .as_bool() - .unwrap_or(false); - if done { - Err(anyhow::anyhow!("EOF"))?; - } else { - let array = js_sys::Reflect::get(&obj, &JsValue::from("value")) - .expect("Failed to get value property of data") - .dyn_into::() - .expect("Expected Uint8Array"); + let done = js_sys::Reflect::get(&obj, &JsValue::from("done")) + .expect("Failed to get done property of data") + .as_bool() + .unwrap_or(false); + if done { + Err(anyhow::anyhow!("EOF"))?; + } else { + let array = js_sys::Reflect::get(&obj, &JsValue::from("value")) + .expect("Failed to get value property of data") + .dyn_into::() + .expect("Expected Uint8Array"); - let val = array.get_index(0); - buf.push(val); - if val == 0 { - break; + let val = array.get_index(0); + buf.push(val); + if val == 0 { + break; + } } } - } - Result::<(), anyhow::Error>::Ok(()) - } - .await; + Result::<(), anyhow::Error>::Ok(()) + }), + TimeoutFuture::new(500), + ) + .await + { + futures::future::Either::Left((res, _)) => res, + futures::future::Either::Right(_) => Err(anyhow::anyhow!("Timeout")), + }; reader.release_lock(); @@ -90,5 +99,6 @@ impl SerialClient { set_keymaps stream normal get_keymap_config normal normal set_keymap_config normal normal + get_log normal stream ); } diff --git a/rrp-web/rrp-client-web/src/lib.rs b/rrp-web/rrp-client-web/src/lib.rs index 56697b92..80d2bf6c 100644 --- a/rrp-web/rrp-client-web/src/lib.rs +++ b/rrp-web/rrp-client-web/src/lib.rs @@ -1,5 +1,5 @@ use async_lock::Mutex; -use futures::stream::StreamExt as _; +use futures::{stream::StreamExt as _, StreamExt}; use log::info; use rktk_rrp::endpoints::*; @@ -108,4 +108,35 @@ impl Client { .await .map_err(|e| format!("{:?}", e)) } + + #[wasm_bindgen] + pub async fn get_log(&self) -> Result, String> { + let mut serial = self.serial_client.lock().await; + let stream = serial.get_log(()).await.map_err(|e| format!("{:?}", e))?; + let mut stream = std::pin::pin!(stream); + + let mut logs = Vec::new(); + let mut log = Vec::new(); + let mut breaking = true; + while let Some(chunk) = stream.next().await { + match chunk { + get_log::LogChunk::Bytes { bytes, len } => { + breaking = false; + log.extend_from_slice(&bytes[..len as usize]); + } + get_log::LogChunk::Break => { + if !breaking { + let Ok(str) = String::from_utf8(log.clone()).map_err(|e| e.to_string()) + else { + continue; + }; + logs.push(str); + log.clear(); + breaking = true; + } + } + } + } + Ok(logs) + } } diff --git a/rrp-web/src/page/Home/LogViewer.tsx b/rrp-web/src/page/Home/LogViewer.tsx new file mode 100644 index 00000000..5ee054eb --- /dev/null +++ b/rrp-web/src/page/Home/LogViewer.tsx @@ -0,0 +1,31 @@ +import { Connection } from "@/lib/connection"; +import { useInfiniteQuery } from "@tanstack/react-query"; +import { useEffect } from "react"; + +export function LogViewerPage(props: { connection: Connection }) { + const { data, error, fetchNextPage } = useInfiniteQuery({ + queryKey: ["getLog"], + queryFn: async () => { + const data = await props.connection.client.get_log(); + const now = new Date().toISOString(); + return data.map((log) => ({ time: now, log })); + }, + initialPageParam: 0, + getNextPageParam: (_l, _a, pp) => pp + 1, + }); + + useEffect(() => { + const interval = setInterval(() => { + fetchNextPage(); + }, 1000); + return () => clearInterval(interval); + }, []); + + const logs = data?.pages.flat().reverse(); + + return ( +
+ {logs?.map((log, i) =>
{log.time} {log.log}
)} +
+ ); +} diff --git a/rrp-web/src/page/Home/index.tsx b/rrp-web/src/page/Home/index.tsx index d404ad10..685c9697 100644 --- a/rrp-web/src/page/Home/index.tsx +++ b/rrp-web/src/page/Home/index.tsx @@ -7,12 +7,19 @@ import { useToastController, } from "@fluentui/react-components"; import { useEffect, useState } from "react"; -import { KeyboardFilled, OptionsFilled } from "@fluentui/react-icons"; +import { + DocumentBulletListFilled, + KeyboardFilled, + OptionsFilled, +} from "@fluentui/react-icons"; import { KeyboardOptionsPage } from "./KeyboardOptions"; import { Connection, useDisconnect } from "@/lib/connection"; +import { LogViewerPage } from "./LogViewer"; export function Home({ connection }: { connection: Connection }) { - const [selectedTab, setSelectedTab] = useState<"keymap" | "option">("keymap"); + const [selectedTab, setSelectedTab] = useState<"keymap" | "option" | "log">( + "keymap", + ); const { dispatchToast } = useToastController(); const disconnect = useDisconnect(); @@ -41,6 +48,8 @@ export function Home({ connection }: { connection: Connection }) { page = ; } else if (selectedTab === "option") { page = ; + } else if (selectedTab === "log") { + page = ; } else { page =
; } @@ -58,6 +67,9 @@ export function Home({ connection }: { connection: Connection }) { }> Keyboard options + }> + Log +
{page}