fix: 🐛 Fix and rework logging

alvr-org · Aug 22, 2024 · 834ee11 · 834ee11
1 parent c4c9849
commit 834ee11
Show file tree

Hide file tree

Showing 20 changed files with 247 additions and 168 deletions.
diff --git a/alvr/common/src/logging.rs b/alvr/common/src/logging.rs
@@ -15,81 +15,83 @@ pub const CLIENT_GFX_DBG_LABEL: &str = "CLIENT GFX";
 pub const ENCODER_DBG_LABEL: &str = "ENCODER";
 pub const DECODER_DBG_LABEL: &str = "DECODER";
 
-#[macro_export]
-macro_rules! _dbg_label {
-    ($label:expr, $($args:tt)*) => {{
-        #[cfg(debug_assertions)]
-        $crate::log::debug!("[{}] {}", $label, format_args!($($args)*));
-    }};
-}
-
 #[macro_export]
 macro_rules! dbg_server_impl {
     ($($args:tt)*) => {
-        $crate::_dbg_label!($crate::SERVER_IMPL_DBG_LABEL, $($args)*);
+        #[cfg(debug_assertions)]
+        $crate::log::debug!(target: $crate::SERVER_IMPL_DBG_LABEL, $($args)*);
     };
 }
 
 #[macro_export]
 macro_rules! dbg_client_impl {
     ($($args:tt)*) => {
-        $crate::_dbg_label!($crate::CLIENT_IMPL_DBG_LABEL, $($args)*);
+        #[cfg(debug_assertions)]
+        $crate::log::debug!(target: $crate::CLIENT_IMPL_DBG_LABEL, $($args)*);
     };
 }
 
 #[macro_export]
 macro_rules! dbg_server_core {
     ($($args:tt)*) => {
-        $crate::_dbg_label!($crate::SERVER_CORE_DBG_LABEL, $($args)*);
+        #[cfg(debug_assertions)]
+        $crate::log::debug!(target: $crate::SERVER_CORE_DBG_LABEL, $($args)*);
     };
 }
 
 #[macro_export]
 macro_rules! dbg_client_core {
     ($($args:tt)*) => {
-        $crate::_dbg_label!($crate::CLIENT_CORE_DBG_LABEL, $($args)*);
+        #[cfg(debug_assertions)]
+        $crate::log::debug!(target: $crate::CLIENT_CORE_DBG_LABEL, $($args)*);
     };
 }
 
 #[macro_export]
 macro_rules! dbg_connection {
     ($($args:tt)*) => {
-        $crate::_dbg_label!($crate::CONNECTION_DBG_LABEL, $($args)*);
+        #[cfg(debug_assertions)]
+        $crate::log::debug!(target: $crate::CONNECTION_DBG_LABEL, $($args)*);
     };
 }
 
 #[macro_export]
 macro_rules! dbg_sockets {
     ($($args:tt)*) => {
-        $crate::_dbg_label!($crate::SOCKETS_DBG_LABEL, $($args)*);
+        #[cfg(debug_assertions)]
+        $crate::log::debug!(target: $crate::SOCKETS_DBG_LABEL, $($args)*);
     };
 }
 
 #[macro_export]
 macro_rules! dbg_server_gfx {
     ($($args:tt)*) => {
-        $crate::_dbg_label!($crate::SERVER_GFX_DBG_LABEL, $($args)*);
+        #[cfg(debug_assertions)]
+        $crate::log::debug!(target: $crate::SERVER_GFX_DBG_LABEL, $($args)*);
     };
 }
 
 #[macro_export]
 macro_rules! dbg_client_gfx {
     ($($args:tt)*) => {
-        $crate::_dbg_label!($crate::CLIENT_GFX_DBG_LABEL, $($args)*);
+        #[cfg(debug_assertions)]
+        $crate::log::debug!(target: $crate::CLIENT_GFX_DBG_LABEL, $($args)*);
     };
 }
 
 #[macro_export]
 macro_rules! dbg_encoder {
     ($($args:tt)*) => {
-        $crate::_dbg_label!($crate::ENCODER_DBG_LABEL, $($args)*);
+        #[cfg(debug_assertions)]
+        $crate::log::debug!(target: $crate::ENCODER_DBG_LABEL, $($args)*);
     };
 }
 
 #[macro_export]
 macro_rules! dbg_decoder {
     ($($args:tt)*) => {
-        $crate::_dbg_label!($crate::DECODER_DBG_LABEL, $($args)*);
+        #[cfg(debug_assertions)]
+        $crate::log::debug!(target: $crate::DECODER_DBG_LABEL, $($args)*);
     };
 }
 
@@ -117,32 +119,35 @@ pub struct DebugGroupsConfig {
     pub decoder: bool,
 }
 
-pub fn filter_debug_groups(message: &str, config: &DebugGroupsConfig) -> bool {
-    if message.starts_with(&format!("[{SERVER_IMPL_DBG_LABEL}]")) {
-        config.server_impl
-    } else if message.starts_with(&format!("[{CLIENT_IMPL_DBG_LABEL}]")) {
-        config.client_impl
-    } else if message.starts_with(&format!("[{SERVER_CORE_DBG_LABEL}]")) {
-        config.server_core
-    } else if message.starts_with(&format!("[{CLIENT_CORE_DBG_LABEL}]")) {
-        config.client_core
-    } else if message.starts_with(&format!("[{CONNECTION_DBG_LABEL}]")) {
-        config.connection
-    } else if message.starts_with(&format!("[{SOCKETS_DBG_LABEL}]")) {
-        config.sockets
-    } else if message.starts_with(&format!("[{SERVER_GFX_DBG_LABEL}]")) {
-        config.server_gfx
-    } else if message.starts_with(&format!("[{CLIENT_GFX_DBG_LABEL}]")) {
-        config.client_gfx
-    } else if message.starts_with(&format!("[{ENCODER_DBG_LABEL}]")) {
-        config.encoder
-    } else if message.starts_with(&format!("[{DECODER_DBG_LABEL}]")) {
-        config.decoder
-    } else {
-        true
+pub fn filter_debug_groups(target: &str, config: &DebugGroupsConfig) -> bool {
+    match target {
+        SERVER_IMPL_DBG_LABEL => config.server_impl,
+        CLIENT_IMPL_DBG_LABEL => config.client_impl,
+        SERVER_CORE_DBG_LABEL => config.server_core,
+        CLIENT_CORE_DBG_LABEL => config.client_core,
+        CONNECTION_DBG_LABEL => config.connection,
+        SOCKETS_DBG_LABEL => config.sockets,
+        SERVER_GFX_DBG_LABEL => config.server_gfx,
+        CLIENT_GFX_DBG_LABEL => config.client_gfx,
+        ENCODER_DBG_LABEL => config.encoder,
+        DECODER_DBG_LABEL => config.decoder,
+        _ => true,
     }
 }
 
+pub fn is_enabled_debug_group(target: &str, config: &DebugGroupsConfig) -> bool {
+    (config.server_impl && target == SERVER_IMPL_DBG_LABEL)
+        || (config.client_impl && target == CLIENT_IMPL_DBG_LABEL)
+        || (config.server_core && target == SERVER_CORE_DBG_LABEL)
+        || (config.client_core && target == CLIENT_CORE_DBG_LABEL)
+        || (config.connection && target == CONNECTION_DBG_LABEL)
+        || (config.sockets && target == SOCKETS_DBG_LABEL)
+        || (config.server_gfx && target == SERVER_GFX_DBG_LABEL)
+        || (config.client_gfx && target == CLIENT_GFX_DBG_LABEL)
+        || (config.encoder && target == ENCODER_DBG_LABEL)
+        || (config.decoder && target == DECODER_DBG_LABEL)
+}
+
 #[derive(
     SettingsSchema, Serialize, Deserialize, Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord,
 )]

diff --git a/alvr/dashboard/src/dashboard/components/logs.rs b/alvr/dashboard/src/dashboard/components/logs.rs
@@ -38,59 +38,37 @@ impl LogsTab {
     }
 
     pub fn push_event(&mut self, event: Event) {
-        match event.event_type {
-            EventType::Log(log_event) => {
-                let color;
-                let ty;
-                match log_event.severity {
-                    LogSeverity::Error => {
-                        color = log_colors::ERROR_LIGHT;
-                        ty = "ERROR";
-                    }
-                    LogSeverity::Warning => {
-                        color = log_colors::WARNING_LIGHT;
-                        ty = "WARN";
-                    }
-                    LogSeverity::Info => {
-                        color = log_colors::INFO_LIGHT;
-                        ty = "INFO";
-                    }
-                    LogSeverity::Debug => {
-                        color = log_colors::DEBUG_LIGHT;
-                        ty = "DEBUG";
-                    }
-                };
+        let color = if let EventType::Log(entry) = &event.event_type {
+            Some(match entry.severity {
+                LogSeverity::Error => log_colors::ERROR_LIGHT,
+                LogSeverity::Warning => log_colors::WARNING_LIGHT,
+                LogSeverity::Info => log_colors::INFO_LIGHT,
+                LogSeverity::Debug => log_colors::DEBUG_LIGHT,
+            })
+        } else if let Switch::Enabled(config) = &self.raw_events_config {
+            (!config.hide_spammy_events
+                || !matches!(
+                    event.event_type,
+                    EventType::StatisticsSummary(_)
+                        | EventType::GraphStatistics(_)
+                        | EventType::Tracking(_)
+                ))
+            .then_some(log_colors::EVENT_LIGHT)
+        } else {
+            None
+        };
 
-                self.entries.push_back(Entry {
-                    color,
-                    timestamp: event.timestamp,
-                    ty: ty.into(),
-                    message: log_event.content,
-                });
-            }
-            event_type => {
-                if let Switch::Enabled(config) = &self.raw_events_config {
-                    if !config.hide_spammy_events
-                        || !matches!(
-                            event_type,
-                            EventType::StatisticsSummary(_)
-                                | EventType::GraphStatistics(_)
-                                | EventType::Tracking(_)
-                        )
-                    {
-                        self.entries.push_back(Entry {
-                            color: log_colors::EVENT_LIGHT,
-                            timestamp: event.timestamp,
-                            ty: "EVENT".into(),
-                            message: format!("{event_type:?}"),
-                        });
-                    }
-                }
-            }
-        }
+        if let Some(color) = color {
+            self.entries.push_back(Entry {
+                color,
+                timestamp: event.timestamp.clone(),
+                ty: event.event_type_string(),
+                message: event.message(),
+            });
 
-        if self.entries.len() > self.log_limit {
-            self.entries.pop_front();
+            if self.entries.len() > self.log_limit {
+                self.entries.pop_front();
+            }
         }
     }
 

diff --git a/alvr/dashboard/src/data_sources.rs b/alvr/dashboard/src/data_sources.rs
@@ -231,7 +231,6 @@ impl DataSources {
                         match ws.read() {
                             Ok(tungstenite::Message::Text(json_string)) => {
                                 if let Ok(event) = serde_json::from_str(&json_string) {
-                                    debug!("Server event received: {:?}", event);
                                     events_sender
                                         .send(PolledEvent {
                                             inner: event,

diff --git a/alvr/dashboard/src/logging_backend.rs b/alvr/dashboard/src/logging_backend.rs
@@ -21,7 +21,7 @@ pub fn init_logging(event_sender: mpsc::Sender<PolledEvent>) {
             LevelFilter::Info
         })
         .format(move |f, record| {
-            let timestamp = chrono::Local::now().format("%H:%M:%S.%f").to_string();
+            let timestamp = chrono::Local::now().format("%H:%M:%S.%3f").to_string();
 
             event_sender
                 .lock()

diff --git a/alvr/events/src/lib.rs b/alvr/events/src/lib.rs
@@ -1,4 +1,4 @@
-use alvr_common::{info, DeviceMotion, LogEntry, Pose};
+use alvr_common::{info, DeviceMotion, LogEntry, LogSeverity, Pose};
 use alvr_packets::{AudioDevicesList, ButtonValue};
 use alvr_session::SessionConfig;
 use serde::{Deserialize, Serialize};
@@ -79,6 +79,7 @@ pub struct HapticsEvent {
 #[serde(tag = "id", content = "data")]
 pub enum EventType {
     Log(LogEntry),
+    DebugGroup { group: String, message: String },
     Session(Box<SessionConfig>),
     StatisticsSummary(StatisticsSummary),
     GraphStatistics(GraphStatistics),
@@ -96,6 +97,45 @@ pub struct Event {
     pub event_type: EventType,
 }
 
+impl Event {
+    pub fn event_type_string(&self) -> String {
+        match &self.event_type {
+            EventType::Log(entry) => match entry.severity {
+                LogSeverity::Error => "ERROR".into(),
+                LogSeverity::Warning => "WARNING".into(),
+                LogSeverity::Info => "INFO".into(),
+                LogSeverity::Debug => "DEBUG".into(),
+            },
+            EventType::DebugGroup { group, .. } => group.clone(),
+            EventType::Session(_) => "SESSION".to_string(),
+            EventType::StatisticsSummary(_) => "STATS".to_string(),
+            EventType::GraphStatistics(_) => "GRAPH".to_string(),
+            EventType::Tracking(_) => "TRACKING".to_string(),
+            EventType::Buttons(_) => "BUTTONS".to_string(),
+            EventType::Haptics(_) => "HAPTICS".to_string(),
+            EventType::AudioDevices(_) => "AUDIO DEV".to_string(),
+            EventType::DriversList(_) => "DRV LIST".to_string(),
+            EventType::ServerRequestsSelfRestart => "RESTART".to_string(),
+        }
+    }
+
+    pub fn message(&self) -> String {
+        match &self.event_type {
+            EventType::Log(log_entry) => log_entry.content.clone(),
+            EventType::DebugGroup { message, .. } => message.clone(),
+            EventType::Session(_) => "Updated".into(),
+            EventType::StatisticsSummary(_) => "".into(),
+            EventType::GraphStatistics(_) => "".into(),
+            EventType::Tracking(tracking) => serde_json::to_string(tracking).unwrap(),
+            EventType::Buttons(buttons) => serde_json::to_string(buttons).unwrap(),
+            EventType::Haptics(haptics) => serde_json::to_string(haptics).unwrap(),
+            EventType::AudioDevices(devices) => serde_json::to_string(devices).unwrap(),
+            EventType::DriversList(drivers) => serde_json::to_string(drivers).unwrap(),
+            EventType::ServerRequestsSelfRestart => "Request for server restart".into(),
+        }
+    }
+}
+
 pub fn send_event(event_type: EventType) {
     info!("{}", serde_json::to_string(&event_type).unwrap());
 }
diff --git a/alvr/server_core/src/c_api.rs b/alvr/server_core/src/c_api.rs
@@ -200,7 +200,7 @@ pub unsafe extern "C" fn alvr_path_to_id(path_string: *const c_char) -> u64 {
 }
 
 #[no_mangle]
-pub unsafe extern "C" fn alvr_log_error(string_ptr: *const c_char) {
+pub unsafe extern "C" fn alvr_error(string_ptr: *const c_char) {
     alvr_common::show_e(CStr::from_ptr(string_ptr).to_string_lossy());
 }
 
@@ -209,28 +209,23 @@ pub unsafe fn log(level: log::Level, string_ptr: *const c_char) {
 }
 
 #[no_mangle]
-pub unsafe extern "C" fn alvr_log_warn(string_ptr: *const c_char) {
+pub unsafe extern "C" fn alvr_warn(string_ptr: *const c_char) {
     log(log::Level::Warn, string_ptr);
 }
 
 #[no_mangle]
-pub unsafe extern "C" fn alvr_log_info(string_ptr: *const c_char) {
+pub unsafe extern "C" fn alvr_info(string_ptr: *const c_char) {
     log(log::Level::Info, string_ptr);
 }
 
-#[no_mangle]
-pub unsafe extern "C" fn alvr_log_debug(string_ptr: *const c_char) {
-    log(log::Level::Debug, string_ptr);
-}
-
 #[no_mangle]
 pub unsafe extern "C" fn alvr_dbg_server_impl(string_ptr: *const c_char) {
-    alvr_common::dbg_server_impl!("{}", CStr::from_ptr(string_ptr).to_str().unwrap());
+    alvr_common::dbg_server_impl!("{}", CStr::from_ptr(string_ptr).to_string_lossy());
 }
 
 #[no_mangle]
 pub unsafe extern "C" fn alvr_dbg_encoder(string_ptr: *const c_char) {
-    alvr_common::dbg_encoder!("{}", CStr::from_ptr(string_ptr).to_str().unwrap());
+    alvr_common::dbg_encoder!("{}", CStr::from_ptr(string_ptr).to_string_lossy());
 }
 
 // Should not be used in production

diff --git a/alvr/server_core/src/connection.rs b/alvr/server_core/src/connection.rs
@@ -683,6 +683,8 @@ fn connection_pipeline(
         },
     ));
 
+    debug!(target: "server_core", "Connection established with {client_hostname}");
+
     *ctx.bitrate_manager.lock() = BitrateManager::new(settings.video.bitrate.history_size, fps);
 
     dbg_connection!("connection_pipeline: StreamSocket connect_to_client");
-Original file line number
+Diff line change
@@ Expand Up / @@ -683,6 +683,8 @@ fn connection_pipeline( @@
             },
         ));
+        debug!(target: "server_core", "Connection established with {client_hostname}");
         *ctx.bitrate_manager.lock() = BitrateManager::new(settings.video.bitrate.history_size, fps);
         dbg_connection!("connection_pipeline: StreamSocket connect_to_client");
@@ Expand Down @@