Switch to trace-based logging - take three

CHANGELOG.md

@@ -22,6 +22,7 @@ You can find its changes [documented below](#070---2021-01-01).
 
 - Warn on unhandled Commands ([#1533] by [@Maan2003])
 - `WindowDesc::new` takes the root widget directly instead of a closure ([#1559] by [@lassipulkkinen])
+- Switch to trace-based logging ([#1562] by [@PoignardAzur])
 
 ### Deprecated
 
@@ -413,6 +414,7 @@ Last release without a changelog :(
 [@derekdreery]: https://github.com/derekdreery
 [@MaximilianKoestler]: https://github.com/MaximilianKoestler
 [@lassipulkkinen]: https://github.com/lassipulkkinen
+[@Poignardazur]: https://github.com/PoignardAzur
 
 [#599]: https://github.com/linebender/druid/pull/599
 [#611]: https://github.com/linebender/druid/pull/611
@@ -611,6 +613,7 @@ Last release without a changelog :(
 [#1534]: https://github.com/linebender/druid/pull/1534
 [#1254]: https://github.com/linebender/druid/pull/1254
 [#1559]: https://github.com/linebender/druid/pull/1559
+[#1562]: https://github.com/linebender/druid/pull/1562
 
 [Unreleased]: https://github.com/linebender/druid/compare/v0.6.0...master
 [0.6.0]: https://github.com/linebender/druid/compare/v0.5.0...v0.6.0

README.md

@@ -42,7 +42,7 @@ fn main() -> Result<(), PlatformError> {
     let main_window = WindowDesc::new(ui_builder());
     let data = 0_u32;
     AppLauncher::with_window(main_window)
-        .use_simple_logger()
+        .use_env_tracing()
         .launch(data)
 }
 

druid-shell/Cargo.toml

@@ -41,7 +41,7 @@ hdr = ["piet-common/hdr"]
 piet-common = "=0.3.2"
 kurbo = "0.7.1"
 
-log = "0.4.11"
+tracing = "0.1.22"
 lazy_static = "1.4.0"
 time = "0.2.16"
 cfg-if = "1.0.0"
@@ -97,5 +97,6 @@ features = ["Window", "MouseEvent", "CssStyleDeclaration", "WheelEvent", "KeyEve
 
 [dev-dependencies]
 piet-common = { version = "=0.3.2", features = ["png"] }
-simple_logger = { version = "1.9.0", default-features = false }
 static_assertions = "1.1.0"
+test-env-log = { version = "0.2.5", features = ["trace"], default-features = false }
+tracing-subscriber = "0.2.15"

druid-shell/examples/invalidate.rs

@@ -102,7 +102,7 @@ impl WinHandler for InvalidateTest {
 }
 
 fn main() {
-    simple_logger::SimpleLogger::new().init().unwrap();
+    tracing_subscriber::fmt().init();
     let app = Application::new().unwrap();
     let mut builder = WindowBuilder::new(app.clone());
     let inv_test = InvalidateTest {

druid-shell/examples/perftest.rs

@@ -136,7 +136,7 @@ impl WinHandler for PerfTest {
 }
 
 fn main() {
-    simple_logger::SimpleLogger::new().init().unwrap();
+    tracing_subscriber::fmt().init();
     let app = Application::new().unwrap();
     let mut builder = WindowBuilder::new(app.clone());
     let perf_test = PerfTest {

druid-shell/examples/quit.rs

@@ -53,7 +53,7 @@ impl WinHandler for QuitState {
         if self.quit_count >= 5 {
             self.handle.close();
         } else {
-            log::info!("Don't wanna quit");
+            tracing::info!("Don't wanna quit");
         }
     }
 
@@ -67,7 +67,7 @@ impl WinHandler for QuitState {
 }
 
 fn main() {
-    simple_logger::SimpleLogger::new().init().unwrap();
+    tracing_subscriber::fmt().init();
     let app = Application::new().unwrap();
     let mut file_menu = Menu::new();
     file_menu.add_item(

druid-shell/examples/shello.rs

@@ -122,7 +122,7 @@ impl WinHandler for HelloState {
 }
 
 fn main() {
-    simple_logger::SimpleLogger::new().init().unwrap();
+    tracing_subscriber::fmt().init();
     let mut file_menu = Menu::new();
     file_menu.add_item(
         0x100,

druid-shell/src/hotkey.rs

@@ -16,7 +16,7 @@
 
 use std::borrow::Borrow;
 
-use log::warn;
+use tracing::warn;
 
 use crate::{IntoKey, KbKey, KeyEvent, Modifiers};
 

druid-shell/src/platform/gtk/application.rs

@@ -45,7 +45,7 @@ impl Application {
         };
 
         gtk_app.connect_activate(|_app| {
-            log::info!("gtk: Activated application");
+            tracing::info!("gtk: Activated application");
         });
 
         if let Err(err) = gtk_app.register(None as Option<&Cancellable>) {

druid-shell/src/platform/gtk/clipboard.rs

@@ -40,7 +40,7 @@ impl Clipboard {
         // to move it into the closure. :/
         let formats = formats.to_owned();
         let success = clipboard.set_with_data(&entries, move |_, sel, idx| {
-            log::info!("got paste callback {}", idx);
+            tracing::info!("got paste callback {}", idx);
             let idx = idx as usize;
             if idx < formats.len() {
                 let item = &formats[idx];
@@ -54,7 +54,7 @@ impl Clipboard {
             }
         });
         if !success {
-            log::warn!("failed to set clipboard data.");
+            tracing::warn!("failed to set clipboard data.");
         }
     }
 

druid-shell/src/platform/gtk/dialog.rs

@@ -84,7 +84,7 @@ pub(crate) fn get_file_dialog_path(
 
         if let Some(dt) = &options.default_type {
             if !found_default_filter {
-                log::warn!("The default type {:?} is not present in allowed types.", dt);
+                tracing::warn!("The default type {:?} is not present in allowed types.", dt);
             }
         }
     }
@@ -102,7 +102,7 @@ pub(crate) fn get_file_dialog_path(
         },
         ResponseType::Cancel => Err(anyhow!("Dialog was deleted")),
         _ => {
-            log::warn!("Unhandled dialog result: {:?}", result);
+            tracing::warn!("Unhandled dialog result: {:?}", result);
             Err(anyhow!("Unhandled dialog result"))
         }
     };

druid-shell/src/platform/gtk/menu.rs

@@ -149,7 +149,7 @@ fn register_accelerator(item: &GtkMenuItem, accel_group: &AccelGroup, menu_key:
             if let Some(gdk_key) = keycodes::key_to_raw_key(k) {
                 *gdk_key
             } else {
-                log::warn!("Cannot map key {:?}", k);
+                tracing::warn!("Cannot map key {:?}", k);
                 return;
             }
         }

druid-shell/src/platform/gtk/window.rs

@@ -31,6 +31,7 @@ use gdk::{EventKey, EventMask, ModifierType, ScrollDirection, WindowExt, WindowT
 use gio::ApplicationExt;
 use gtk::prelude::*;
 use gtk::{AccelGroup, ApplicationWindow, DrawingArea, SettingsExt};
+use tracing::{error, warn};
 
 use crate::kurbo::{Insets, Point, Rect, Size, Vec2};
 use crate::piet::{Piet, PietText, RenderContext};
@@ -354,7 +355,7 @@ impl WindowBuilder {
                     let size_dp = area.size_dp();
                     state.area.set(area);
                     if let Err(e) = state.resize_surface(extents.width, extents.height) {
-                        log::error!("Failed to resize surface: {}", e);
+                        error!("Failed to resize surface: {}", e);
                     }
                     state.with_handler(|h| h.size(size_dp));
                     state.invalidate_rect(size_dp.to_rect());
@@ -365,7 +366,7 @@ impl WindowBuilder {
                 let invalid = match state.invalid.try_borrow_mut() {
                     Ok(mut invalid) => std::mem::replace(&mut *invalid, Region::EMPTY),
                     Err(_) => {
-                        log::error!("invalid region borrowed while drawing");
+                        error!("invalid region borrowed while drawing");
                         Region::EMPTY
                     }
                 };
@@ -389,7 +390,7 @@ impl WindowBuilder {
                         let mut piet_context = Piet::new(&surface_context);
                         handler.paint(&mut piet_context, &invalid);
                         if let Err(e) = piet_context.finish() {
-                            log::error!("piet error on render: {:?}", e);
+                            error!("piet error on render: {:?}", e);
                         }
 
                         // Copy the entire surface to the drawing area (not just the invalid
@@ -401,7 +402,7 @@ impl WindowBuilder {
                         context.fill();
                     });
                 } else {
-                    log::warn!("Drawing was skipped because there was no surface");
+                    warn!("Drawing was skipped because there was no surface");
                 }
             }
 
@@ -666,7 +667,7 @@ impl WindowState {
     #[track_caller]
     fn with_handler<T, F: FnOnce(&mut dyn WinHandler) -> T>(&self, f: F) -> Option<T> {
         if self.invalid.try_borrow_mut().is_err() || self.surface.try_borrow_mut().is_err() {
-            log::error!("other RefCells were borrowed when calling into the handler");
+            error!("other RefCells were borrowed when calling into the handler");
             return None;
         }
 
@@ -684,7 +685,7 @@ impl WindowState {
         match self.handler.try_borrow_mut() {
             Ok(mut h) => Some(f(&mut **h)),
             Err(_) => {
-                log::error!("failed to borrow WinHandler at {}", Location::caller());
+                error!("failed to borrow WinHandler at {}", Location::caller());
                 None
             }
         }
@@ -737,7 +738,7 @@ impl WindowState {
             region.add_rect(rect);
             self.window.queue_draw();
         } else {
-            log::warn!("Not invalidating rect because region already borrowed");
+            warn!("Not invalidating rect because region already borrowed");
         }
     }
 
@@ -819,7 +820,7 @@ impl WindowHandle {
     }
 
     pub fn content_insets(&self) -> Insets {
-        log::warn!("WindowHandle::content_insets unimplemented for GTK platforms.");
+        warn!("WindowHandle::content_insets unimplemented for GTK platforms.");
         Insets::ZERO
     }
 
@@ -847,7 +848,7 @@ impl WindowHandle {
             let (x, y) = state.window.get_size();
             Size::new(x as f64, y as f64)
         } else {
-            log::warn!("Could not get size for GTK window");
+            warn!("Could not get size for GTK window");
             Size::new(0., 0.)
         }
     }
@@ -885,7 +886,7 @@ impl WindowHandle {
     }
 
     pub fn handle_titlebar(&self, _val: bool) {
-        log::warn!("WindowHandle::handle_titlebar is currently unimplemented for gtk.");
+        warn!("WindowHandle::handle_titlebar is currently unimplemented for gtk.");
     }
 
     /// Close the window.
@@ -939,7 +940,7 @@ impl WindowHandle {
         let interval = match u32::try_from(interval) {
             Ok(iv) => iv,
             Err(_) => {
-                log::warn!("timer duration exceeds gtk max of 2^32 millis");
+                warn!("timer duration exceeds gtk max of 2^32 millis");
                 u32::max_value()
             }
         };
@@ -1125,7 +1126,7 @@ fn run_idle(state: &Arc<WindowState>) -> glib::source::Continue {
     });
 
     if result.is_none() {
-        log::warn!("Delaying idle callbacks because the handler is borrowed.");
+        warn!("Delaying idle callbacks because the handler is borrowed.");
         // Keep trying to reschedule this idle callback, because we haven't had a chance
         // to empty the idle queue. Returning glib::source::Continue(true) achieves this but
         // causes 100% CPU usage, apparently because glib likes to call us back very quickly.
@@ -1198,7 +1199,7 @@ fn get_mouse_click_count(event_type: gdk::EventType) -> u8 {
         gdk::EventType::TripleButtonPress => 3,
         gdk::EventType::ButtonRelease => 0,
         _ => {
-            log::warn!("Unexpected mouse click event type: {:?}", event_type);
+            warn!("Unexpected mouse click event type: {:?}", event_type);
             0
         }
     }

druid-shell/src/platform/mac/application.rs

@@ -97,7 +97,7 @@ impl Application {
                 }
             }
         } else {
-            log::warn!("Application state already borrowed");
+            tracing::warn!("Application state already borrowed");
         }
     }
 

druid-shell/src/platform/mac/clipboard.rs

@@ -39,7 +39,7 @@ impl Clipboard {
                 let result: BOOL =
                     msg_send![pasteboard, setString: nsstring forType: NSPasteboardTypeString];
                 if result != YES {
-                    log::warn!("failed to set clipboard");
+                    tracing::warn!("failed to set clipboard");
                 }
             }
         }
@@ -61,7 +61,7 @@ impl Clipboard {
                 let data_type = idents[i];
                 let result: BOOL = msg_send![pasteboard, setData: data forType: data_type];
                 if result != YES {
-                    log::warn!(
+                    tracing::warn!(
                         "failed to set clipboard contents for type '{}'",
                         format.identifier
                     );
@@ -100,7 +100,7 @@ impl Clipboard {
                 let idx: NSUInteger = msg_send![array, indexOfObject: available];
                 let idx = idx as usize;
                 if idx > formats.len() {
-                    log::error!("clipboard object not found");
+                    tracing::error!("clipboard object not found");
                     None
                 } else {
                     Some(formats[idx])

druid-shell/src/platform/mac/dialog.rs

@@ -121,7 +121,7 @@ pub(crate) unsafe fn build_panel(ty: FileDialogType, mut options: FileDialogOpti
                 }
             }
             if !present {
-                log::warn!("The default type {:?} is not present in allowed types.", dt);
+                tracing::warn!("The default type {:?} is not present in allowed types.", dt);
             }
         }
 

druid-shell/src/platform/mac/menu.rs

@@ -179,6 +179,8 @@ impl HotKey {
 #[cfg(test)]
 mod tests {
     use super::*;
+    use test_env_log::test;
+
     #[test]
     fn strip_access() {
         assert_eq!(strip_access_key("&Exit").as_str(), "Exit");

druid-shell/src/platform/mac/screen.rs

@@ -74,6 +74,7 @@ mod test {
     use crate::platform::mac::screen::transform_coords;
     use crate::Monitor;
     use kurbo::Rect;
+    use test_env_log::test;
 
     fn pair(rect: Rect) -> (Rect, Rect) {
         (rect, rect)

druid-shell/src/platform/mac/window.rs

@@ -34,11 +34,11 @@ use cocoa::foundation::{
 use core_graphics::context::CGContextRef;
 use foreign_types::ForeignTypeRef;
 use lazy_static::lazy_static;
-use log::{error, info};
 use objc::declare::ClassDecl;
 use objc::rc::WeakPtr;
 use objc::runtime::{Class, Object, Sel};
 use objc::{class, msg_send, sel, sel_impl};
+use tracing::{debug, error, info};
 
 use crate::kurbo::{Insets, Point, Rect, Size, Vec2};
 use crate::piet::{Piet, PietText, RenderContext};
@@ -799,7 +799,7 @@ fn set_position_deferred(this: &mut Object, _view_state: &mut ViewState, positio
         let screen_height = crate::Screen::get_display_rect().height();
         new_frame.origin.y = screen_height - position.y - frame.size.height; // Flip back
         let () = msg_send![window, setFrame: new_frame display: YES];
-        log::debug!("set_position_deferred {:?}", position);
+        debug!("set_position_deferred {:?}", position);
     }
 }
 
@@ -972,7 +972,7 @@ impl WindowHandle {
     }
 
     pub fn make_cursor(&self, _cursor_desc: &CursorDesc) -> Option<Cursor> {
-        log::warn!("Custom cursors are not yet supported in the macOS backend");
+        tracing::warn!("Custom cursors are not yet supported in the macOS backend");
         None
     }
 
@@ -1156,7 +1156,7 @@ impl WindowHandle {
     }
 
     pub fn handle_titlebar(&self, _val: bool) {
-        log::warn!("WindowHandle::handle_titlebar is currently unimplemented for Mac.");
+        tracing::warn!("WindowHandle::handle_titlebar is currently unimplemented for Mac.");
     }
 
     pub fn resizable(&self, resizable: bool) {