feat: ✨ Add debug groups (#2332)

* feat: ✨ Add debug groups

* Expose logging to c apis

* Hide debug groups settings in release mode

* Use dbg macros instead of functions

* Rename "handshake" to "connection"

* Populate client_core, sever_core and connection debug groups

alvr/client_core/src/c_api.rs

@@ -191,6 +191,16 @@ pub unsafe extern "C" fn alvr_log(level: AlvrLogLevel, message: *const c_char) {
     }
 }
 
+#[no_mangle]
+pub unsafe extern "C" fn alvr_dbg_client_impl(message: *const c_char) {
+    alvr_common::dbg_client_impl!("{}", CStr::from_ptr(message).to_str().unwrap())
+}
+
+#[no_mangle]
+pub unsafe extern "C" fn alvr_dbg_decoder(message: *const c_char) {
+    alvr_common::dbg_decoder!("{}", CStr::from_ptr(message).to_str().unwrap())
+}
+
 #[no_mangle]
 pub unsafe extern "C" fn alvr_log_time(tag: *const c_char) {
     let tag = CStr::from_ptr(tag).to_str().unwrap();

alvr/client_core/src/connection.rs

@@ -11,7 +11,7 @@ use crate::{
 };
 use alvr_audio::AudioDevice;
 use alvr_common::{
-    debug, error, info,
+    dbg_connection, debug, error, info,
     parking_lot::{Condvar, Mutex, RwLock},
     wait_rwlock, warn, AnyhowToCon, ConResult, ConnectionError, ConnectionState, LifecycleState,
     ALVR_VERSION,
@@ -94,6 +94,8 @@ pub fn connection_lifecycle_loop(
     lifecycle_state: Arc<RwLock<LifecycleState>>,
     event_queue: Arc<Mutex<VecDeque<ClientCoreEvent>>>,
 ) {
+    dbg_connection!("connection_lifecycle_loop: Begin");
+
     set_hud_message(&event_queue, INITIAL_MESSAGE);
 
     while *lifecycle_state.read() != LifecycleState::ShuttingDown {
@@ -117,6 +119,8 @@ pub fn connection_lifecycle_loop(
 
         thread::sleep(CONNECTION_RETRY_INTERVAL);
     }
+
+    dbg_connection!("connection_lifecycle_loop: End");
 }
 
 fn connection_pipeline(
@@ -125,6 +129,8 @@ fn connection_pipeline(
     lifecycle_state: Arc<RwLock<LifecycleState>>,
     event_queue: Arc<Mutex<VecDeque<ClientCoreEvent>>>,
 ) -> ConResult {
+    dbg_connection!("connection_pipeline: Begin");
+
     let (mut proto_control_socket, server_ip) = {
         let config = Config::load();
         let announcer_socket = AnnouncerSocket::new(&config.hostname).to_con()?;
@@ -158,6 +164,7 @@ fn connection_pipeline(
         .input_sample_rate()
         .to_con()?;
 
+    dbg_connection!("connection_pipeline: Send stream capabilities");
     proto_control_socket
         .send(&ClientConnectionResult::ConnectionAccepted {
             client_protocol_id: alvr_common::protocol_id_u64(),
@@ -179,6 +186,7 @@ fn connection_pipeline(
         .to_con()?;
     let config_packet =
         proto_control_socket.recv::<StreamConfigPacket>(HANDSHAKE_ACTION_TIMEOUT)?;
+    dbg_connection!("connection_pipeline: stream config received");
 
     let (settings, negotiated_config) =
         alvr_packets::decode_stream_config(&config_packet).to_con()?;
@@ -224,6 +232,7 @@ fn connection_pipeline(
         }
     }
 
+    dbg_connection!("connection_pipeline: create StreamSocket");
     let stream_socket_builder = StreamSocketBuilder::listen_for_server(
         Duration::from_secs(1),
         settings.connection.stream_port,
@@ -234,12 +243,14 @@ fn connection_pipeline(
     )
     .to_con()?;
 
+    dbg_connection!("connection_pipeline: Send StreamReady");
     if let Err(e) = control_sender.send(&ClientControlPacket::StreamReady) {
         info!("Server disconnected. Cause: {e:?}");
         set_hud_message(&event_queue, SERVER_DISCONNECTED_MESSAGE);
         return Ok(());
     }
 
+    dbg_connection!("connection_pipeline: accept connection");
     let mut stream_socket = stream_socket_builder.accept_from_server(
         server_ip,
         settings.connection.stream_port,
@@ -551,12 +562,15 @@ fn connection_pipeline(
         *LOG_CHANNEL_SENDER.lock() = Some(LogMirrorData {
             sender: log_channel_sender,
             filter_level,
+            debug_groups_config: settings.extra.logging.debug_groups,
         });
     }
     event_queue.lock().push_back(streaming_start_event);
 
     *connection_state_lock = ConnectionState::Streaming;
 
+    dbg_connection!("connection_pipeline: Unlock streams");
+
     // Make sure IPD and FoV are resent after reconnection
     // todo: send this data as part of the connection handshake
     ctx.view_params_queue.write().clear();
@@ -581,6 +595,8 @@ fn connection_pipeline(
     // Remove lock to allow threads to properly exit:
     drop(connection_state_lock);
 
+    dbg_connection!("connection_pipeline: Destroying streams");
+
     video_receive_thread.join().ok();
     game_audio_thread.join().ok();
     microphone_thread.join().ok();
@@ -589,5 +605,7 @@ fn connection_pipeline(
     control_receive_thread.join().ok();
     stream_receive_thread.join().ok();
 
+    dbg_connection!("connection_pipeline: End");
+
     Ok(())
 }

alvr/client_core/src/lib.rs

@@ -20,7 +20,7 @@ mod audio;
 pub mod graphics;
 
 use alvr_common::{
-    error,
+    dbg_client_core, error,
     glam::{UVec2, Vec2, Vec3},
     parking_lot::{Mutex, RwLock},
     warn, ConnectionState, DeviceMotion, LifecycleState, Pose, HEAD_ID,
@@ -105,16 +105,20 @@ pub struct ClientCoreContext {
 
 impl ClientCoreContext {
     pub fn new(capabilities: ClientCapabilities) -> Self {
+        dbg_client_core!("Create");
+
         // Make sure to reset config in case of version compat mismatch.
         if Config::load().protocol_id != alvr_common::protocol_id() {
             // NB: Config::default() sets the current protocol ID
             Config::default().store();
         }
 
         #[cfg(target_os = "android")]
-        platform::try_get_permission(platform::MICROPHONE_PERMISSION);
-        #[cfg(target_os = "android")]
-        platform::set_wifi_lock(true);
+        {
+            dbg_client_core!("Getting permissions");
+            platform::try_get_permission(platform::MICROPHONE_PERMISSION);
+            platform::set_wifi_lock(true);
+        }
 
         let lifecycle_state = Arc::new(RwLock::new(LifecycleState::Idle));
         let event_queue = Arc::new(Mutex::new(VecDeque::new()));
@@ -142,10 +146,14 @@ impl ClientCoreContext {
     }
 
     pub fn resume(&self) {
+        dbg_client_core!("resume");
+
         *self.lifecycle_state.write() = LifecycleState::Resumed;
     }
 
     pub fn pause(&self) {
+        dbg_client_core!("pause");
+
         let mut connection_state_lock = self.connection_context.state.write();
 
         *self.lifecycle_state.write() = LifecycleState::Idle;
@@ -160,10 +168,14 @@ impl ClientCoreContext {
     }
 
     pub fn poll_event(&self) -> Option<ClientCoreEvent> {
+        dbg_client_core!("poll_event");
+
         self.event_queue.lock().pop_front()
     }
 
     pub fn send_battery(&self, device_id: u64, gauge_value: f32, is_plugged: bool) {
+        dbg_client_core!("send_battery");
+
         if let Some(sender) = &mut *self.connection_context.control_sender.lock() {
             sender
                 .send(&ClientControlPacket::Battery(BatteryInfo {
@@ -176,12 +188,16 @@ impl ClientCoreContext {
     }
 
     pub fn send_playspace(&self, area: Option<Vec2>) {
+        dbg_client_core!("send_playspace");
+
         if let Some(sender) = &mut *self.connection_context.control_sender.lock() {
             sender.send(&ClientControlPacket::PlayspaceSync(area)).ok();
         }
     }
 
     pub fn send_active_interaction_profile(&self, device_id: u64, profile_id: u64) {
+        dbg_client_core!("send_active_interaction_profile");
+
         if let Some(sender) = &mut *self.connection_context.control_sender.lock() {
             sender
                 .send(&ClientControlPacket::ActiveInteractionProfile {
@@ -193,6 +209,8 @@ impl ClientCoreContext {
     }
 
     pub fn send_custom_interaction_profile(&self, device_id: u64, input_ids: HashSet<u64>) {
+        dbg_client_core!("send_custom_interaction_profile");
+
         if let Some(sender) = &mut *self.connection_context.control_sender.lock() {
             sender
                 .send(&alvr_packets::encode_reserved_client_control_packet(
@@ -206,6 +224,8 @@ impl ClientCoreContext {
     }
 
     pub fn send_buttons(&self, entries: Vec<ButtonEntry>) {
+        dbg_client_core!("send_buttons");
+
         if let Some(sender) = &mut *self.connection_context.control_sender.lock() {
             sender.send(&ClientControlPacket::Buttons(entries)).ok();
         }
@@ -219,6 +239,8 @@ impl ClientCoreContext {
         hand_skeletons: [Option<[Pose; 26]>; 2],
         face_data: FaceData,
     ) {
+        dbg_client_core!("send_tracking");
+
         let last_ipd = {
             let mut view_params_queue_lock = self.connection_context.view_params_queue.write();
 
@@ -281,6 +303,8 @@ impl ClientCoreContext {
     }
 
     pub fn get_head_prediction_offset(&self) -> Duration {
+        dbg_client_core!("get_head_prediction_offset");
+
         if let Some(stats) = &*self.connection_context.statistics_manager.lock() {
             stats.average_total_pipeline_latency()
         } else {
@@ -289,6 +313,8 @@ impl ClientCoreContext {
     }
 
     pub fn get_tracker_prediction_offset(&self) -> Duration {
+        dbg_client_core!("get_tracker_prediction_offset");
+
         if let Some(stats) = &*self.connection_context.statistics_manager.lock() {
             stats.tracker_prediction_offset()
         } else {
@@ -297,6 +323,8 @@ impl ClientCoreContext {
     }
 
     pub fn get_frame(&self) -> Option<DecodedFrame> {
+        dbg_client_core!("get_frame");
+
         let mut decoder_source_lock = self.connection_context.decoder_source.lock();
         let decoder_source = decoder_source_lock.as_mut()?;
 
@@ -333,26 +361,34 @@ impl ClientCoreContext {
 
     /// Call only with external decoder
     pub fn request_idr(&self) {
+        dbg_client_core!("request_idr");
+
         if let Some(sender) = &mut *self.connection_context.control_sender.lock() {
             sender.send(&ClientControlPacket::RequestIdr).ok();
         }
     }
 
     /// Call only with external decoder
     pub fn report_frame_decoded(&self, target_timestamp: Duration) {
+        dbg_client_core!("report_frame_decoded");
+
         if let Some(stats) = &mut *self.connection_context.statistics_manager.lock() {
             stats.report_frame_decoded(target_timestamp);
         }
     }
 
     /// Call only with external decoder
     pub fn report_compositor_start(&self, target_timestamp: Duration) {
+        dbg_client_core!("report_compositor_start");
+
         if let Some(stats) = &mut *self.connection_context.statistics_manager.lock() {
             stats.report_compositor_start(target_timestamp);
         }
     }
 
     pub fn report_submit(&self, target_timestamp: Duration, vsync_queue: Duration) {
+        dbg_client_core!("report_submit");
+
         if let Some(stats) = &mut *self.connection_context.statistics_manager.lock() {
             stats.report_submit(target_timestamp, vsync_queue);
 
@@ -369,6 +405,8 @@ impl ClientCoreContext {
 
 impl Drop for ClientCoreContext {
     fn drop(&mut self) {
+        dbg_client_core!("Drop");
+
         *self.lifecycle_state.write() = LifecycleState::ShuttingDown;
 
         if let Some(thread) = self.connection_thread.lock().take() {

alvr/client_core/src/logging_backend.rs

@@ -2,7 +2,7 @@ use alvr_common::{
     log::{Level, Record},
     once_cell::sync::Lazy,
     parking_lot::Mutex,
-    LogSeverity, OptLazy,
+    DebugGroupsConfig, LogSeverity, OptLazy,
 };
 use alvr_packets::ClientControlPacket;
 use std::{
@@ -15,6 +15,7 @@ const LOG_REPEAT_TIMEOUT: Duration = Duration::from_secs(1);
 pub struct LogMirrorData {
     pub sender: mpsc::Sender<ClientControlPacket>,
     pub filter_level: LogSeverity,
+    pub debug_groups_config: DebugGroupsConfig,
 }
 
 pub static LOG_CHANNEL_SENDER: OptLazy<LogMirrorData> = alvr_common::lazy_mut_none();
@@ -34,9 +35,11 @@ static LAST_LOG_EVENT: Lazy<Mutex<RepeatedLogEvent>> = Lazy::new(|| {
 });
 
 pub fn init_logging() {
-    fn send_log(record: &Record) {
+    fn send_log(record: &Record) -> bool {
         let Some(data) = &*LOG_CHANNEL_SENDER.lock() else {
-            return;
+            // if channel has not been setup, always print everything to stdout
+            // todo: the client debug groups settings should be moved client side when feasible
+            return true;
         };
 
         let level = match record.level() {
@@ -46,11 +49,15 @@ pub fn init_logging() {
             Level::Debug | Level::Trace => LogSeverity::Debug,
         };
         if level < data.filter_level {
-            return;
+            return false;
         }
 
         let message = format!("{}", record.args());
 
+        if !alvr_common::filter_debug_groups(&message, &data.debug_groups_config) {
+            return false;
+        }
+
         let mut last_log_event_lock = LAST_LOG_EVENT.lock();
 
         if last_log_event_lock.message == message
@@ -80,6 +87,8 @@ pub fn init_logging() {
                 .send(ClientControlPacket::Log { level, message })
                 .ok();
         }
+
+        true
     }
 
     #[cfg(target_os = "android")]
@@ -88,8 +97,11 @@ pub fn init_logging() {
             android_logger::Config::default()
                 .with_tag("[ALVR NATIVE-RUST]")
                 .format(|f, record| {
-                    send_log(&record);
-                    std::fmt::write(f, *record.args())
+                    if send_log(record) {
+                        writeln!(f, "{}", record.args())
+                    } else {
+                        Ok(())
+                    }
                 })
                 .with_max_level(alvr_common::log::LevelFilter::Info),
         );
@@ -99,8 +111,11 @@ pub fn init_logging() {
         use std::io::Write;
         env_logger::builder()
             .format(|f, record| {
-                send_log(record);
-                writeln!(f, "{}", record.args())
+                if send_log(record) {
+                    writeln!(f, "{}", record.args())
+                } else {
+                    Ok(())
+                }
             })
             .try_init()
             .ok();