Tree-based message logging and toggleable trace printing (#728)

* Log message tree

* Log when message execution deferred

* Tree structure in traces

* Fix ordering when queue partially consumed

* Change some log settings and wording

* Revert default max log level to debug

* Change messages to On/Names/Contents as log::info, change trace to toggle, rename GlobalMessage to DebugMessage

* DebugPrintDocument cleanup

Co-authored-by: Keavon Chambers <keavon@keavon.com>

editor/src/communication/dispatcher.rs

@@ -1,7 +1,8 @@
 use super::broadcast_message_handler::BroadcastMessageHandler;
 use crate::consts::{DEFAULT_FONT_FAMILY, DEFAULT_FONT_STYLE};
+use crate::debug::debug_message::LoggingMessages;
+use crate::debug::DebugMessageHandler;
 use crate::document::PortfolioMessageHandler;
-use crate::global::GlobalMessageHandler;
 use crate::input::{InputMapperMessageHandler, InputPreprocessorMessageHandler};
 use crate::layout::layout_message_handler::LayoutMessageHandler;
 use crate::message_prelude::*;
@@ -23,8 +24,8 @@ pub struct Dispatcher {
 #[derive(Debug, Default)]
 struct DispatcherMessageHandlers {
 	broadcast_message_handler: BroadcastMessageHandler,
+	debug_message_handler: DebugMessageHandler,
 	dialog_message_handler: DialogMessageHandler,
-	global_message_handler: GlobalMessageHandler,
 	input_mapper_message_handler: InputMapperMessageHandler,
 	input_preprocessor_message_handler: InputPreprocessorMessageHandler,
 	layout_message_handler: LayoutMessageHandler,
@@ -54,31 +55,44 @@ impl Dispatcher {
 		Self::default()
 	}
 
+	// If the deepest queues (higher index in queues list) are now empty (after being popped from) then remove them
+	fn cleanup_queues(&mut self, leave_last: bool) {
+		while self.message_queues.last().filter(|queue| queue.is_empty()).is_some() {
+			if leave_last && self.message_queues.len() == 1 {
+				break;
+			}
+			self.message_queues.pop();
+		}
+	}
+
 	#[remain::check]
 	pub fn handle_message<T: Into<Message>>(&mut self, message: T) {
 		use Message::*;
 
-		self.message_queues.push(VecDeque::from_iter([message.into()]));
+		if let Some(first) = self.message_queues.first_mut() {
+			first.push_back(message.into());
+		} else {
+			self.message_queues.push(VecDeque::from_iter([message.into()]));
+		}
 
 		while let Some(message) = self.message_queues.last_mut().and_then(VecDeque::pop_front) {
-			// If the deepest queue is now empty (after being popped from) then remove it
-			if self.message_queues.last().filter(|queue| queue.is_empty()).is_some() {
-				self.message_queues.pop();
-			}
-
 			// Skip processing of this message if it will be processed later (at the end of the shallowest level queue)
 			if SIDE_EFFECT_FREE_MESSAGES.contains(&message.to_discriminant()) {
 				let already_in_queue = self.message_queues.first().filter(|queue| queue.contains(&message)).is_some();
 				if already_in_queue {
+					self.log_deferred_message(&message, &self.message_queues, self.message_handlers.debug_message_handler.logging_messages_mode);
+					self.cleanup_queues(false);
 					continue;
 				} else if self.message_queues.len() > 1 {
+					self.log_deferred_message(&message, &self.message_queues, self.message_handlers.debug_message_handler.logging_messages_mode);
+					self.cleanup_queues(true);
 					self.message_queues[0].push_back(message);
 					continue;
 				}
 			}
 
 			// Print the message at a verbosity level of `log`
-			self.log_message(&message);
+			self.log_message(&message, &self.message_queues, self.message_handlers.debug_message_handler.logging_messages_mode);
 
 			// Create a new queue for the child messages
 			let mut queue = VecDeque::new();
@@ -101,6 +115,9 @@ impl Dispatcher {
 				}
 
 				Broadcast(message) => self.message_handlers.broadcast_message_handler.process_action(message, (), &mut queue),
+				Debug(message) => {
+					self.message_handlers.debug_message_handler.process_action(message, (), &mut queue);
+				}
 				Dialog(message) => {
 					self.message_handlers
 						.dialog_message_handler
@@ -110,6 +127,7 @@ impl Dispatcher {
 					// Handle these messages immediately by returning early
 					if let FrontendMessage::UpdateImageData { .. } | FrontendMessage::TriggerFontLoad { .. } | FrontendMessage::TriggerRefreshBoundsOfViewports = message {
 						self.responses.push(message);
+						self.cleanup_queues(false);
 
 						// Return early to avoid running the code after the match block
 						return;
@@ -118,9 +136,6 @@ impl Dispatcher {
 						self.responses.push(message);
 					}
 				}
-				Global(message) => {
-					self.message_handlers.global_message_handler.process_action(message, (), &mut queue);
-				}
 				InputMapper(message) => {
 					let actions = self.collect_actions();
 					self.message_handlers
@@ -162,6 +177,8 @@ impl Dispatcher {
 			if !queue.is_empty() {
 				self.message_queues.push(queue);
 			}
+
+			self.cleanup_queues(false);
 		}
 	}
 
@@ -171,7 +188,7 @@ impl Dispatcher {
 		list.extend(self.message_handlers.dialog_message_handler.actions());
 		list.extend(self.message_handlers.input_preprocessor_message_handler.actions());
 		list.extend(self.message_handlers.input_mapper_message_handler.actions());
-		list.extend(self.message_handlers.global_message_handler.actions());
+		list.extend(self.message_handlers.debug_message_handler.actions());
 		if self.message_handlers.portfolio_message_handler.active_document().is_some() {
 			list.extend(self.message_handlers.tool_message_handler.actions());
 		}
@@ -179,12 +196,45 @@ impl Dispatcher {
 		list
 	}
 
-	fn log_message(&self, message: &Message) {
+	/// Create the tree structure for logging the messages as a tree
-		use Message::*;
+	fn create_indents(queues: &[VecDeque<Message>]) -> String {
+		String::from_iter(queues.iter().enumerate().skip(1).map(|(index, queue)| {
+			if index == queues.len() - 1 {
+				if queue.is_empty() {
+					"└── "
+				} else {
+					"├── "
+				}
+			} else if queue.is_empty() {
+				"   "
+			} else {
+				"│    "
+			}
+		}))
+	}
 
-		if log::max_level() == log::LevelFilter::Trace && !(matches!(message, InputPreprocessor(_)) || MessageDiscriminant::from(message).local_name().ends_with("PointerMove")) {
+	/// Logs a message that is about to be executed,
-			log::trace!("Message: {:?}", message);
+	/// either as a tree with a discriminant or the entire payload (depending on settings)
-			// log::trace!("Hints: {:?}", self.input_mapper_message_handler.hints(self.collect_actions()));
+	fn log_message(&self, message: &Message, queues: &[VecDeque<Message>], log_tree_contents: LoggingMessages) {
+		if !MessageDiscriminant::from(message).local_name().ends_with("PointerMove") {
+			match log_tree_contents {
+				LoggingMessages::Off => {}
+				LoggingMessages::Names => {
+					log::info!("{}{:?}", Self::create_indents(queues), message.to_discriminant());
+				}
+				LoggingMessages::Contents => {
+					if !(matches!(message, Message::InputPreprocessor(_))) {
+						log::info!("Message: {}{:?}", Self::create_indents(queues), message);
+					}
+				}
+			}
+		}
+	}
+
+	/// Logs into the tree that the message is in the side effect free messages and its execution will be deferred
+	fn log_deferred_message(&self, message: &Message, queues: &[VecDeque<Message>], log_tree_contents: LoggingMessages) {
+		if let LoggingMessages::Names = log_tree_contents {
+			log::info!("{}Deferred \"{:?}\" because it's a SIDE_EFFECT_FREE_MESSAGE", Self::create_indents(queues), message.to_discriminant());
 		}
 	}
 }

editor/src/communication/message.rs

@@ -27,12 +27,12 @@ pub enum Message {
 	#[child]
 	Broadcast(BroadcastMessage),
 	#[child]
+	Debug(DebugMessage),
+	#[child]
 	Dialog(DialogMessage),
 	#[child]
 	Frontend(FrontendMessage),
 	#[child]
-	Global(GlobalMessage),
-	#[child]
 	InputMapper(InputMapperMessage),
 	#[child]
 	InputPreprocessor(InputPreprocessorMessage),

editor/src/debug/debug_message.rs

@@ -0,0 +1,20 @@
+use crate::message_prelude::*;
+
+use serde::{Deserialize, Serialize};
+
+#[impl_message(Message, Debug)]
+#[derive(PartialEq, Eq, Clone, Debug, Hash, Serialize, Deserialize)]
+pub enum DebugMessage {
+	ToggleTraceLogs,
+	MessageOff,
+	MessageNames,
+	MessageContents,
+}
+
+#[derive(Debug, Default, Clone, Copy)]
+pub enum LoggingMessages {
+	#[default]
+	Off,
+	Names,
+	Contents,
+}

editor/src/debug/debug_message_handler.rs

@@ -0,0 +1,52 @@
+use crate::debug::debug_message::LoggingMessages;
+use crate::message_prelude::*;
+
+use std::collections::VecDeque;
+
+#[derive(Debug, Default)]
+pub struct DebugMessageHandler {
+	pub logging_messages_mode: LoggingMessages,
+}
+
+impl MessageHandler<DebugMessage, ()> for DebugMessageHandler {
+	#[remain::check]
+	fn process_action(&mut self, message: DebugMessage, _data: (), responses: &mut VecDeque<Message>) {
+		match message {
+			DebugMessage::ToggleTraceLogs => {
+				if let log::LevelFilter::Debug = log::max_level() {
+					log::set_max_level(log::LevelFilter::Trace);
+				} else {
+					log::set_max_level(log::LevelFilter::Debug);
+				}
+
+				// Refresh the checkmark beside the menu entry for this
+				responses.push_back(MenuBarMessage::SendLayout.into());
+			}
+			DebugMessage::MessageOff => {
+				self.logging_messages_mode = LoggingMessages::Off;
+
+				// Refresh the checkmark beside the menu entry for this
+				responses.push_back(MenuBarMessage::SendLayout.into());
+			}
+			DebugMessage::MessageNames => {
+				self.logging_messages_mode = LoggingMessages::Names;
+
+				// Refresh the checkmark beside the menu entry for this
+				responses.push_back(MenuBarMessage::SendLayout.into());
+			}
+			DebugMessage::MessageContents => {
+				self.logging_messages_mode = LoggingMessages::Contents;
+
+				// Refresh the checkmark beside the menu entry for this
+				responses.push_back(MenuBarMessage::SendLayout.into());
+			}
+		}
+	}
+
+	advertise_actions!(DebugMessageDiscriminant;
+		ToggleTraceLogs,
+		MessageOff,
+		MessageNames,
+		MessageContents,
+	);
+}

editor/src/debug/mod.rs

@@ -0,0 +1,8 @@
+pub mod debug_message;
+
+mod debug_message_handler;
+
+#[doc(inline)]
+pub use debug_message::{DebugMessage, DebugMessageDiscriminant};
+#[doc(inline)]
+pub use debug_message_handler::DebugMessageHandler;

editor/src/document/document_message_handler.rs

@@ -1003,7 +1003,12 @@ impl MessageHandler<DocumentMessage, (&InputPreprocessorMessageHandler, &FontCac
 				);
 			}
 			DebugPrintDocument => {
-				log::debug!("{:#?}\n{:#?}", self.graphene_document, self.layer_metadata);
+				let initial_level = log::max_level();
+				log::set_max_level(log::LevelFilter::Trace);
+
+				log::trace!("{:#?}\n{:#?}", self.graphene_document, self.layer_metadata);
+
+				log::set_max_level(initial_level);
 			}
 			DeleteLayer { layer_path } => {
 				responses.push_front(DocumentOperation::DeleteLayer { path: layer_path.clone() }.into());

editor/src/document/menu_bar_message_handler.rs

@@ -281,30 +281,44 @@ impl PropertyHolder for MenuBarMessageHandler {
 					],
 					vec![
 						MenuEntry {
-							label: "Debug: Set Log Level".into(),
+							label: "Debug: Print Messages".into(),
 							action: MenuEntry::no_action(),
 							children: Some(vec![vec![
 								MenuEntry {
-									label: "Log Level Info".into(),
+									label: "Off".into(),
-									action: MenuEntry::create_action(|_| GlobalMessage::LogInfo.into()),
+									// icon: Some("Checkmark".into()), // TODO: Find a way to set this icon on the active mode
-									shortcut: Some(vec![Key::Key1]),
+									shortcut: Some(vec![Key::KeyAlt, Key::Key0]),
+									action: MenuEntry::create_action(|_| DebugMessage::MessageOff.into()),
 									..MenuEntry::default()
 								},
 								MenuEntry {
-									label: "Log Level Debug".into(),
+									label: "Only Names".into(),
-									action: MenuEntry::create_action(|_| GlobalMessage::LogDebug.into()),
+									shortcut: Some(vec![Key::KeyAlt, Key::Key1]),
-									shortcut: Some(vec![Key::Key2]),
+									action: MenuEntry::create_action(|_| DebugMessage::MessageNames.into()),
 									..MenuEntry::default()
 								},
 								MenuEntry {
-									label: "Log Level Trace".into(),
+									label: "Full Contents".into(),
-									action: MenuEntry::create_action(|_| GlobalMessage::LogTrace.into()),
+									shortcut: Some(vec![Key::KeyAlt, Key::Key2]),
-									shortcut: Some(vec![Key::Key3]),
+									action: MenuEntry::create_action(|_| DebugMessage::MessageContents.into()),
 									..MenuEntry::default()
 								},
 							]]),
 							..MenuEntry::default()
 						},
+						MenuEntry {
+							label: "Debug: Print Trace Logs".into(),
+							icon: Some(if let log::LevelFilter::Trace = log::max_level() { "CheckboxChecked" } else { "CheckboxUnchecked" }.into()),
+							shortcut: Some(vec![Key::KeyAlt, Key::KeyT]),
+							action: MenuEntry::create_action(|_| DebugMessage::ToggleTraceLogs.into()),
+							..MenuEntry::default()
+						},
+						MenuEntry {
+							label: "Debug: Print Document".into(),
+							shortcut: Some(vec![Key::KeyAlt, Key::KeyP]),
+							action: MenuEntry::create_action(|_| DebugMessage::ToggleTraceLogs.into()),
+							..MenuEntry::default()
+						},
 						MenuEntry {
 							label: "Debug: Panic (DANGER)".into(),
 							action: MenuEntry::create_action(|_| panic!()),

editor/src/global/global_message.rs

@@ -1,12 +0,0 @@
-use crate::message_prelude::*;
-
-use serde::{Deserialize, Serialize};
-
-#[remain::sorted]
-#[impl_message(Message, Global)]
-#[derive(PartialEq, Eq, Clone, Debug, Hash, Serialize, Deserialize)]
-pub enum GlobalMessage {
-	LogDebug,
-	LogInfo,
-	LogTrace,
-}

editor/src/global/global_message_handler.rs

@@ -1,35 +0,0 @@
-use crate::message_prelude::*;
-
-use std::collections::VecDeque;
-
-#[derive(Debug, Default)]
-pub struct GlobalMessageHandler {}
-
-impl MessageHandler<GlobalMessage, ()> for GlobalMessageHandler {
-	#[remain::check]
-	fn process_action(&mut self, message: GlobalMessage, _data: (), _responses: &mut VecDeque<Message>) {
-		use GlobalMessage::*;
-
-		#[remain::sorted]
-		match message {
-			LogDebug => {
-				log::set_max_level(log::LevelFilter::Debug);
-				log::info!("Set log verbosity to debug");
-			}
-			LogInfo => {
-				log::set_max_level(log::LevelFilter::Info);
-				log::info!("Set log verbosity to info");
-			}
-			LogTrace => {
-				log::set_max_level(log::LevelFilter::Trace);
-				log::info!("Set log verbosity to trace");
-			}
-		}
-	}
-
-	advertise_actions!(GlobalMessageDiscriminant;
-		LogInfo,
-		LogDebug,
-		LogTrace,
-	);
-}

editor/src/global/mod.rs

@@ -1,7 +0,0 @@
-mod global_message;
-mod global_message_handler;
-
-#[doc(inline)]
-pub use global_message::{GlobalMessage, GlobalMessageDiscriminant};
-#[doc(inline)]
-pub use global_message_handler::GlobalMessageHandler;

editor/src/input/input_mapper.rs

@@ -157,7 +157,7 @@ impl Default for Mapping {
 			entry! {action=DialogMessage::RequestExportDialog, key_down=KeyE, modifiers=[KeyControl]},
 			entry! {action=DocumentMessage::SaveDocument, key_down=KeyS, modifiers=[KeyControl]},
 			entry! {action=DocumentMessage::SaveDocument, key_down=KeyS, modifiers=[KeyControl, KeyShift]},
-			entry! {action=DocumentMessage::DebugPrintDocument, key_down=Key9},
+			entry! {action=DocumentMessage::DebugPrintDocument, key_down=KeyP, modifiers=[KeyAlt]},
 			entry! {action=DocumentMessage::ZoomCanvasToFitAll, key_down=Key0, modifiers=[KeyControl]},
 			entry! {action=DocumentMessage::DuplicateSelectedLayers, key_down=KeyD, modifiers=[KeyControl]},
 			entry! {action=DocumentMessage::GroupSelectedLayers, key_down=KeyG, modifiers=[KeyControl]},
@@ -224,10 +224,11 @@ impl Default for Mapping {
 			entry! {action=DocumentMessage::ReorderSelectedLayers { relative_index_offset: 1 }, key_down=KeyRightBracket, modifiers=[KeyControl]},
 			entry! {action=DocumentMessage::ReorderSelectedLayers { relative_index_offset: -1 }, key_down=KeyLeftBracket, modifiers=[KeyControl]},
 			entry! {action=DocumentMessage::ReorderSelectedLayers { relative_index_offset: isize::MIN }, key_down=KeyLeftCurlyBracket, modifiers=[KeyControl]}, // TODO: Use KeyLeftBracket with Ctrl+Shift modifiers once input system is fixed
-			// Global Actions
+			// Debug Actions
-			entry! {action=GlobalMessage::LogInfo, key_down=Key1},
+			entry! {action=DebugMessage::ToggleTraceLogs, key_down=KeyT, modifiers=[KeyAlt]},
-			entry! {action=GlobalMessage::LogDebug, key_down=Key2},
+			entry! {action=DebugMessage::MessageOff, key_down=Key0, modifiers=[KeyAlt]},
-			entry! {action=GlobalMessage::LogTrace, key_down=Key3},
+			entry! {action=DebugMessage::MessageNames, key_down=Key1, modifiers=[KeyAlt]},
+			entry! {action=DebugMessage::MessageContents, key_down=Key2, modifiers=[KeyAlt]},
 		];
 		let (mut key_up, mut key_down, mut pointer_move, mut mouse_scroll, mut double_click) = mappings;
 

editor/src/input/input_mapper_message_handler.rs

@@ -16,7 +16,7 @@ impl InputMapperMessageHandler {
 		let mut actions = actions
 			.into_iter()
 			.flatten()
-			.filter(|a| !matches!(*a, MessageDiscriminant::Tool(ToolMessageDiscriminant::ActivateTool) | MessageDiscriminant::Global(_)));
+			.filter(|a| !matches!(*a, MessageDiscriminant::Tool(ToolMessageDiscriminant::ActivateTool) | MessageDiscriminant::Debug(_)));
 		self.mapping
 			.key_down
 			.iter()

editor/src/lib.rs

@@ -4,10 +4,10 @@ pub mod communication;
 #[macro_use]
 pub mod misc;
 pub mod consts;
+pub mod debug;
 pub mod dialog;
 pub mod document;
 pub mod frontend;
-pub mod global;
 pub mod input;
 pub mod layout;
 pub mod viewport_tools;
@@ -62,6 +62,7 @@ pub mod message_prelude {
 	pub use crate::document::clipboards::Clipboard;
 	pub use crate::LayerId;
 
+	pub use crate::debug::{DebugMessage, DebugMessageDiscriminant};
 	pub use crate::dialog::messages::*;
 	pub use crate::document::{ArtboardMessage, ArtboardMessageDiscriminant};
 	pub use crate::document::{DocumentMessage, DocumentMessageDiscriminant};
@@ -72,7 +73,6 @@ pub mod message_prelude {
 	pub use crate::document::{PropertiesPanelMessage, PropertiesPanelMessageDiscriminant};
 	pub use crate::document::{TransformLayerMessage, TransformLayerMessageDiscriminant};
 	pub use crate::frontend::{FrontendMessage, FrontendMessageDiscriminant};
-	pub use crate::global::{GlobalMessage, GlobalMessageDiscriminant};
 	pub use crate::input::{InputMapperMessage, InputMapperMessageDiscriminant, InputPreprocessorMessage, InputPreprocessorMessageDiscriminant};
 	pub use crate::layout::{LayoutMessage, LayoutMessageDiscriminant};
 	pub use crate::misc::derivable_custom_traits::{ToDiscriminant, TransitiveChild};

graphene/src/boolean_ops.rs

@@ -176,7 +176,6 @@ impl PathGraph {
 		}
 		new.add_edges_from_path(alpha, Origin::Alpha);
 		new.add_edges_from_path(beta, Origin::Beta);
-		// log::debug!("size: {}, {:?}", new.size(), new);
 		Ok(new)
 	}
 

graphene/src/intersection.rs

@@ -322,7 +322,6 @@ fn path_intersections(a: &SubCurve, b: &SubCurve, intersections: &mut Vec<Inters
 				cross.t_a = a.start_t + cross.t_a * recursion;
 				cross.quality = guess_quality(a.curve, b.curve, &cross);
 
-				// log::debug!("checking: {:?}", cross.quality);
 				if cross.quality <= F64LOOSE {
 					// Invalid intersections should still be rejected
 					// Rejects "valid" intersections on the non-inclusive end of a `PathSeg`
@@ -336,7 +335,7 @@ fn path_intersections(a: &SubCurve, b: &SubCurve, intersections: &mut Vec<Inters
 				// Return the best estimate of intersection regardless of quality
 				// Also provides a base case and prevents infinite recursion
 				if a.available_precision() <= F64PRECISE || b.available_precision() <= F64PRECISE {
-					log::debug!("precision reached");
+					log::trace!("Precision reached");
 					intersections.push(cross);
 					return;
 				}
@@ -344,7 +343,7 @@ fn path_intersections(a: &SubCurve, b: &SubCurve, intersections: &mut Vec<Inters
 			// Alternate base case
 			// Note: may occur for the less forgiving side of a `PathSeg` endpoint intersect
 			if a.available_precision() <= F64PRECISE || b.available_precision() <= F64PRECISE {
-				log::debug!("precision reached without finding intersect");
+				log::trace!("Precision reached without finding intersect");
 				return;
 			}
 		}
@@ -658,9 +657,6 @@ pub fn point_t_value(a: &PathSeg, p: &Point) -> Option<f64> {
 }
 
 pub fn intersections(a: &BezPath, b: &BezPath) -> Vec<Intersect> {
-	// log::info!("{:?}", a.to_svg());
-	// log::info!("{:?}", b.to_svg());
-
 	let mut intersections: Vec<Intersect> = Vec::new();
 	// There is some duplicate computation of b_extrema here, but I doubt it's significant
 	a.segments().enumerate().for_each(|(a_index, a_seg)| {
@@ -676,8 +672,6 @@ pub fn intersections(a: &BezPath, b: &BezPath) -> Vec<Intersect> {
 		})
 	});
 
-	// log::info!("{:?}", intersections);
-
 	intersections
 }