Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat: ✨ Add debug groups #2332

Merged
merged 6 commits into from
Aug 20, 2024
Merged

feat: ✨ Add debug groups #2332

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
248e936
feat: :sparkles: Add debug groups
zmerp Aug 16, 2024
05e2cab
Expose logging to c apis
zmerp Aug 16, 2024
e60fd74
Hide debug groups settings in release mode
zmerp Aug 16, 2024
065aa64
Use dbg macros instead of functions
zmerp Aug 16, 2024
9bdefc0
Rename "handshake" to "connection"
zmerp Aug 16, 2024
f6aa5ba
Populate client_core, sever_core and connection debug groups
zmerp Aug 16, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
10 changes: 10 additions & 0 deletions alvr/client_core/src/c_api.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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();
Expand Down
20 changes: 19 additions & 1 deletion alvr/client_core/src/connection.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down Expand Up @@ -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 {
Expand All @@ -117,6 +119,8 @@ pub fn connection_lifecycle_loop(

thread::sleep(CONNECTION_RETRY_INTERVAL);
}

dbg_connection!("connection_lifecycle_loop: End");
}

fn connection_pipeline(
Expand All @@ -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()?;
Expand Down Expand Up @@ -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(),
Expand All @@ -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()?;
Expand Down Expand Up @@ -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,
Expand All @@ -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,
Expand Down Expand Up @@ -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();
Expand All @@ -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();
Expand All @@ -589,5 +605,7 @@ fn connection_pipeline(
control_receive_thread.join().ok();
stream_receive_thread.join().ok();

dbg_connection!("connection_pipeline: End");

Ok(())
}
46 changes: 42 additions & 4 deletions alvr/client_core/src/lib.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down Expand Up @@ -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()));
Expand Down Expand Up @@ -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;
Expand All @@ -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 {
Expand All @@ -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 {
Expand All @@ -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(
Expand All @@ -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();
}
Expand All @@ -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();

Expand Down Expand Up @@ -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 {
Expand All @@ -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 {
Expand All @@ -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()?;

Expand Down Expand Up @@ -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);

Expand All @@ -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() {
Expand Down
31 changes: 23 additions & 8 deletions alvr/client_core/src/logging_backend.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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::{
Expand All @@ -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();
Expand All @@ -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() {
Expand All @@ -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
Expand Down Expand Up @@ -80,6 +87,8 @@ pub fn init_logging() {
.send(ClientControlPacket::Log { level, message })
.ok();
}

true
}

#[cfg(target_os = "android")]
Expand All @@ -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),
);
Expand All @@ -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();
Expand Down
Loading
Loading