Merge pull request 'Logging' (#53) from log into main

Reviewed-on: #53

Cargo.toml

@@ -20,6 +20,7 @@ allsorts = "0.10"
 anyhow = "1"
 bytemuck = "1"
 canary-script = { path = "crates/script" }
+log = "0.4"
 lyon = "1"
 ouroboros = "^0.15"
 parking_lot = "0.12"

apps/magpie/Cargo.toml

@@ -13,8 +13,10 @@ required-features = ["service"]
 anyhow = { version = "1", optional = true }
 byteorder = "1.4"
 canary = { path = "../..", optional = true }
+env_logger = { version = "0.10", optional = true }
 futures-util = { version = "0.3", optional = true, features = ["io"] }
 glium = { version = "0.32", optional = true}
+log = "0.4"
 mio = { version = "0.8", features = ["net", "os-poll"], optional = true }
 mio-signals = { version = "0.2", optional = true }
 parking_lot = { version = "0.12", optional = true}
@@ -24,4 +26,4 @@ slab = { version = "0.4", optional = true}
 
 [features]
 async = ["dep:futures-util"]
-service = ["dep:anyhow", "dep:canary", "dep:glium", "dep:mio", "dep:mio-signals", "dep:parking_lot", "dep:slab"]
+service = ["dep:anyhow", "dep:canary", "dep:env_logger", "dep:glium", "dep:mio", "dep:mio-signals", "dep:parking_lot", "dep:slab"]

apps/magpie/src/main.rs

@@ -8,6 +8,12 @@ use ipc::Ipc;
 use window::{WindowMessage, WindowStore};
 
 fn main() -> std::io::Result<()> {
+    env_logger::Builder::new()
+        .filter(None, log::LevelFilter::Info) // By default logs all info messages.
+        .parse_default_env()
+        .init();
+
+    log::info!("Initializing Magpie...");
     let event_loop = EventLoopBuilder::<WindowMessage>::with_user_event().build();
     let window_sender = event_loop.create_proxy();
     let (ipc, ipc_sender) = Ipc::new(window_sender)?;

apps/magpie/src/protocol.rs

@@ -63,7 +63,6 @@ pub type ClientMessenger<T> = Messenger<T, MagpieClientMsg, MagpieServerMsg>;
 impl<T: Write> ClientMessenger<T> {
     pub fn send_panel_json<O: Serialize>(&mut self, id: PanelId, msg: &O) {
         let msg = serde_json::to_string(msg).unwrap();
-        eprintln!("Sending message: {:?}", msg);
 
         let _ = self.send(&MagpieServerMsg::SendMessage(SendMessage {
             id,
@@ -220,7 +219,6 @@ mod async_messages {
     impl<T: AsyncWriteExt + Unpin> ClientMessenger<T> {
         pub async fn send_panel_json_async<O: Serialize>(&mut self, id: PanelId, msg: &O) {
             let msg = serde_json::to_string(msg).unwrap();
-            eprintln!("Sending message: {:?}", msg);
 
             let _ = self
                 .send_async(&MagpieServerMsg::SendMessage(SendMessage {

apps/magpie/src/service/ipc.rs

@@ -47,7 +47,7 @@ impl Drop for Listener {
     fn drop(&mut self) {
         match std::fs::remove_file(&self.path) {
             Ok(_) => {}
-            Err(e) => eprintln!("Could not delete UnixListener {:?}", e),
+            Err(e) => log::error!("Could not delete UnixListener {:?}", e),
         }
     }
 }
@@ -75,20 +75,20 @@ impl Listener {
         use std::io::{Error, ErrorKind};
         match UnixStream::connect(&sock_path) {
             Ok(_) => {
-                eprintln!("Socket is already in use. Another instance of Magpie may be running.");
+                log::warn!("Socket is already in use. Another instance of Magpie may be running.");
                 let kind = ErrorKind::AddrInUse;
                 let error = Error::new(kind, "Socket is already in use.");
                 return Err(error);
             }
             Err(ref err) if err.kind() == ErrorKind::ConnectionRefused => {
-                eprintln!("Found leftover socket; removing.");
+                log::warn!("Found leftover socket; removing.");
                 std::fs::remove_file(&sock_path)?;
             }
             Err(ref err) if err.kind() == ErrorKind::NotFound => {}
             Err(err) => return Err(err),
         }
 
-        eprintln!("Making socket at: {:?}", sock_path);
+        log::info!("Making socket at: {:?}", sock_path);
         let uds = UnixListener::bind(&sock_path)?;
         let path = sock_path.to_path_buf();
         Ok(Self { uds, path })
@@ -120,11 +120,11 @@ pub struct Client {
 impl Client {
     pub fn on_readable(&mut self) -> std::io::Result<bool> {
         if let Err(err) = self.messenger.flush_recv() {
-            eprintln!("flush_recv() error: {:?}", err);
+            log::error!("flush_recv() error: {:?}", err);
         }
 
         while let Some(msg) = self.messenger.try_recv() {
-            println!("Client #{}: {:?}", self.token.0, msg);
+            log::debug!("Client #{}: {:?}", self.token.0, msg);
             match msg {
                 MagpieServerMsg::CreatePanel(CreatePanel {
                     id,
@@ -162,7 +162,7 @@ impl Client {
     }
 
     pub fn disconnect(mut self) {
-        println!("Client #{} disconnected", self.token.0);
+        log::info!("Client #{} disconnected", self.token.0);
 
         let mut transport = self.messenger.into_transport();
         let mut data = self.data.write();
@@ -262,9 +262,10 @@ impl Ipc {
                     match self.listener.accept() {
                         Ok((mut connection, address)) => {
                             let token = Token(self.clients.vacant_key());
-                            println!(
+                            log::info!(
                                 "Accepting connection (Client #{}) from {:?}",
-                                token.0, address
+                                token.0,
+                                address
                             );
 
                             let interest = Interest::READABLE;
@@ -288,7 +289,7 @@ impl Ipc {
                 }
             } else if event.token() == self.signals_token {
                 while let Some(received) = self.signals.receive()? {
-                    eprintln!("Received {:?} signal; exiting...", received);
+                    log::info!("Received {:?} signal; exiting...", received);
                     let _ = self.window_sender.send_event(WindowMessage::Quit);
                     self.quit = true;
                 }
@@ -302,7 +303,7 @@ impl Ipc {
                     self.clients.remove(event.token().0).disconnect();
                 }
             } else {
-                eprintln!("Unrecognized event token: {:?}", event);
+                log::error!("Unrecognized event token: {:?}", event);
             }
         }
 
@@ -316,7 +317,7 @@ impl Ipc {
             match self.poll(&mut events, Some(wait)) {
                 Ok(_) => {}
                 Err(e) => {
-                    eprintln!("IPC poll error: {:?}", e);
+                    log::error!("IPC poll error: {:?}", e);
                 }
             }
         }

apps/magpie/src/service/window.rs

@@ -195,14 +195,18 @@ impl WindowStore {
                 protocol,
                 script,
             } => {
-                println!("Opening window {} with script {:?}", id, script);
+                log::debug!("Opening window {} with script {:?}...", id, script);
+                let start = std::time::Instant::now();
                 let module = std::fs::read(script)?;
                 let mut script = self.runtime.load_module(&module)?;
+                log::debug!("Instantiated window {} script in {:?}", id, start.elapsed());
                 let panel = script.create_panel(&protocol, vec![])?;
+                log::debug!("Created window {} panel in {:?}", id, start.elapsed());
                 let window = Window::new(self.ipc_sender.to_owned(), id, panel, &event_loop)?;
                 let window_id = window.get_id();
                 self.windows.insert(window_id, window);
                 self.ipc_to_window.insert(id, window_id);
+                log::debug!("Opened window {} in {:?}", id, start.elapsed());
             }
             WindowMessage::CloseWindow { id } => {
                 if let Some(window_id) = self.ipc_to_window.remove(&id) {
@@ -242,7 +246,7 @@ impl WindowStore {
                 Ok(false) => {}
                 Ok(true) => *control_flow = ControlFlow::Exit,
                 Err(err) => {
-                    eprintln!("Error while handling message {:?}:\n{}", event, err);
+                    log::error!("Error while handling message {:?}:\n{}", event, err);
                 }
             },
             _ => {}

src/backend/mod.rs

@@ -19,11 +19,13 @@ pub mod wasmtime;
 /// Currently, only ever creates [wasmtime::WasmtimeBackend].
 pub fn make_default_backend() -> anyhow::Result<Box<dyn Backend>> {
     let backend = wasmtime::WasmtimeBackend::new()?;
+    log::info!("Created default ({}) backend", backend.name());
     Ok(Box::new(backend))
 }
 
 /// A WebAssembly runtime backend.
 pub trait Backend {
+    fn name(&self) -> &'static str;
     fn load_module(&self, abi: Arc<ScriptAbi>, module: &[u8]) -> anyhow::Result<Arc<dyn Instance>>;
 }
 

src/backend/wasmtime.rs

@@ -2,20 +2,21 @@
 // SPDX-License-Identifier: LGPL-3.0-or-later
 
 use std::collections::{hash_map::DefaultHasher, HashMap};
-use std::hash::Hasher;
+use std::hash::{Hasher, BuildHasherDefault};
 use std::ops::DerefMut;
+use std::time::Instant;
 
 use super::{Arc, Backend, Instance, PanelId, ScriptAbi};
 use crate::DrawCommand;
 
 use canary_script::{Color, CursorEventKind, Rect, Vec2};
 use parking_lot::Mutex;
-use prehash::{DefaultPrehasher, Prehashed, Prehasher};
+use prehash::Passthru;
 
 type Caller<'a> = wasmtime::Caller<'a, Arc<ScriptAbi>>;
 type Store = wasmtime::Store<Arc<ScriptAbi>>;
 type Linker = wasmtime::Linker<Arc<ScriptAbi>>;
-type ModuleCache = Mutex<HashMap<Prehashed<u64>, wasmtime::Module, DefaultPrehasher>>;
+type ModuleCache = Mutex<HashMap<u64, wasmtime::Module, BuildHasherDefault<Passthru>>>;
 
 pub struct WasmtimeBackend {
     engine: wasmtime::Engine,
@@ -24,6 +25,8 @@ pub struct WasmtimeBackend {
 
 impl WasmtimeBackend {
     pub fn new() -> anyhow::Result<Self> {
+        log::info!("Creating wasmtime backend");
+
         let mut config = wasmtime::Config::new();
         config.wasm_simd(true);
         config.wasm_bulk_memory(true);
@@ -40,21 +43,31 @@ impl WasmtimeBackend {
 }
 
 impl Backend for WasmtimeBackend {
+    fn name(&self) -> &'static str {
+        "wasmtime"
+    }
+
     fn load_module(&self, abi: Arc<ScriptAbi>, module: &[u8]) -> anyhow::Result<Arc<dyn Instance>> {
+        let start = Instant::now();
+
         let mut hasher = DefaultHasher::new();
         hasher.write(module);
-        let hashed = hasher.finish();
+        let hash = hasher.finish();
+        let fmt_hash = format!("{:x}", hash);
 
-        let prehasher = DefaultPrehasher::new();
+        log::debug!("Loading module (hash: {})", fmt_hash);
-        let prehashed = prehasher.prehash(hashed);
         let mut cache = self.module_cache.lock();
 
-        let module = if let Some(module) = cache.get(&prehashed) {
+        let module = if let Some(module) = cache.get(&hash) {
+            log::debug!("Module load cache hit (hash: {})", fmt_hash);
             module
         } else {
+            log::debug!("Module load cache miss; building (hash: {})", fmt_hash);
+            let start = Instant::now();
             let module = wasmtime::Module::new(&self.engine, module)?;
-            cache.insert(prehashed, module);
+            cache.insert(hash, module);
-            cache.get(&prehashed).unwrap()
+            log::debug!("Built module in {:?} (hash: {})", start.elapsed(), fmt_hash);
+            cache.get(&hash).unwrap()
         };
 
         let mut store = wasmtime::Store::new(&self.engine, abi);
@@ -80,6 +93,12 @@ impl Backend for WasmtimeBackend {
 
         let instance = Arc::new(instance);
 
+        log::debug!(
+            "Loaded module in {:?} (hash: {})",
+            start.elapsed(),
+            fmt_hash
+        );
+
         Ok(instance)
     }
 }

src/lib.rs

@@ -21,6 +21,8 @@ pub struct Runtime {
 
 impl Runtime {
     pub fn new(backend: Box<dyn Backend>) -> anyhow::Result<Self> {
+        log::info!("Initializing runtime with {} backend", backend.name());
+
         Ok(Self {
             backend,
             font_store: Arc::new(FontStore::new()),

src/text/mod.rs

@@ -220,6 +220,7 @@ impl Default for FontStore {
 
 impl FontStore {
     pub fn new() -> Self {
+        log::info!("Initializing FontStore");
         let source = font_kit::source::SystemSource::new();
         let source = Box::new(source);
 
@@ -241,14 +242,14 @@ impl FontStore {
         use font_kit::handle::Handle;
         use font_kit::properties::Properties;
 
-        println!("loading font family {}", title);
+        log::info!("Finding font by family: {}", title);
 
         let font_handle = self
             .source
             .select_best_match(&[FamilyName::Title(title.to_string())], &Properties::new())
             .unwrap();
 
-        println!("loading font file: {:?}", font_handle);
+        log::info!("Loading font file: {:?}", font_handle);
 
         let font_data = if let Handle::Path {
             path,