From 7186d61467eb43b807fdcfcfa8b492874c60da09 Mon Sep 17 00:00:00 2001 From: Mihai Dinculescu Date: Mon, 24 Oct 2022 19:28:27 +0100 Subject: [PATCH] Tweak tracing information --- CHANGELOG.md | 4 + examples/README.md | 12 +- examples/src/data_with_tracing.rs | 11 + simconnect-sdk/src/simconnect/base.rs | 357 +++++++++++--------- simconnect-sdk/src/simconnect/events.rs | 2 +- simconnect-sdk/src/simconnect/facilities.rs | 18 +- simconnect-sdk/src/simconnect/objects.rs | 16 +- 7 files changed, 253 insertions(+), 167 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 3133ad0..94ef053 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,6 +6,10 @@ file. This change log follows the conventions of ## [Unreleased] +## Changed + +- The tracing information has been adjusted to be at the `info` and `debug` levels instead of `info`. + ## [v0.1.2] - 2022-10-22 ### Added diff --git a/examples/README.md b/examples/README.md index 589c25b..f6a2b0e 100644 --- a/examples/README.md +++ b/examples/README.md @@ -13,10 +13,18 @@ cd simconnect-sdk cargo run --bin data ``` -## Receiving data using tracing +## Receiving data with tracing + +To see all tracing information at the `trace` level and above (most verbose), run: ```bash -RUST_LOG=info cargo run --bin data_with_tracing +RUST_LOG=trace cargo run --bin data_with_tracing +``` + +To see all tracing information at the `debug` level and above (less verbose than `info`), run: + +```bash +RUST_LOG=debug cargo run --bin data_with_tracing ``` ## Receiving data without the derive macro diff --git a/examples/src/data_with_tracing.rs b/examples/src/data_with_tracing.rs index f617e66..0a23381 100644 --- a/examples/src/data_with_tracing.rs +++ b/examples/src/data_with_tracing.rs @@ -22,6 +22,17 @@ struct AirplaneData { sim_on_ground: bool, } +/// To see all tracing information at the `trace` level and above (most verbose), run: +/// +/// ```bash +/// RUST_LOG=trace cargo run --bin data_with_tracing +/// ``` +/// +/// To see all tracing information at the `debug` level and above (less verbose than `info`), run: +/// +/// ```bash +/// RUST_LOG=debug cargo run --bin data_with_tracing +/// ``` fn main() -> Result<(), Box> { setup_logging()?; diff --git a/simconnect-sdk/src/simconnect/base.rs b/simconnect-sdk/src/simconnect/base.rs index 1c18c4d..aa5020d 100644 --- a/simconnect-sdk/src/simconnect/base.rs +++ b/simconnect-sdk/src/simconnect/base.rs @@ -1,5 +1,7 @@ use std::{collections::HashMap, ffi::c_void}; +use tracing::{error, span, trace, warn, Level}; + use crate::{ as_c_string, bindings, helpers::fixed_c_str_to_string, ok_if_fail, success, Airport, Event, Notification, Object, SimConnectError, Waypoint, NDB, VOR, @@ -87,7 +89,7 @@ pub struct SimConnect { impl SimConnect { /// Create a new SimConnect SDK client. - #[tracing::instrument(name = "SimConnect::new")] + #[tracing::instrument(name = "SimConnect::new", level = "debug")] pub fn new(name: &str) -> Result { let mut handle = std::ptr::null_mut(); @@ -136,180 +138,212 @@ impl SimConnect { let recv_id = unsafe { (*data_buf).dwID as i32 }; - let result = match recv_id { - bindings::SIMCONNECT_RECV_ID_SIMCONNECT_RECV_ID_OPEN => Some(Notification::Open), - bindings::SIMCONNECT_RECV_ID_SIMCONNECT_RECV_ID_QUIT => Some(Notification::Quit), - bindings::SIMCONNECT_RECV_ID_SIMCONNECT_RECV_ID_EVENT => { - let event: &bindings::SIMCONNECT_RECV_EVENT = - unsafe { &*(data_buf as *const bindings::SIMCONNECT_RECV_EVENT) }; + if recv_id == bindings::SIMCONNECT_RECV_ID_SIMCONNECT_RECV_ID_NULL { + Ok(None) + } else { + let span = span!(Level::TRACE, "SimConnect::get_next_dispatch"); + let _enter = span.enter(); - let event = Event::try_from(event.uEventID) - .map_err(|_| SimConnectError::SimConnectUnrecognizedEvent(event.uEventID))?; - - Some(Notification::Event(event)) - } - bindings::SIMCONNECT_RECV_ID_SIMCONNECT_RECV_ID_SIMOBJECT_DATA => { - let event: &bindings::SIMCONNECT_RECV_SIMOBJECT_DATA = - unsafe { &*(data_buf as *const bindings::SIMCONNECT_RECV_SIMOBJECT_DATA) }; - - let type_name = self.get_type_name_by_request_id(event.dwDefineID); - - match type_name { - Some(type_name) => { - let data = Object { - type_name, - data_addr: std::ptr::addr_of!(event.dwData), - }; - - Some(Notification::Object(data)) - } - _ => None, + let result = match recv_id { + bindings::SIMCONNECT_RECV_ID_SIMCONNECT_RECV_ID_OPEN => { + trace!("Received SIMCONNECT_RECV_OPEN"); + Some(Notification::Open) } - } - bindings::SIMCONNECT_RECV_ID_SIMCONNECT_RECV_ID_AIRPORT_LIST => { - let event: &bindings::SIMCONNECT_RECV_AIRPORT_LIST = - unsafe { &*(data_buf as *const bindings::SIMCONNECT_RECV_AIRPORT_LIST) }; + bindings::SIMCONNECT_RECV_ID_SIMCONNECT_RECV_ID_QUIT => { + trace!("Received SIMCONNECT_RECV_QUIT"); + Some(Notification::Quit) + } + bindings::SIMCONNECT_RECV_ID_SIMCONNECT_RECV_ID_EVENT => { + trace!("Received SIMCONNECT_RECV_EVENT"); + let event: &bindings::SIMCONNECT_RECV_EVENT = + unsafe { &*(data_buf as *const bindings::SIMCONNECT_RECV_EVENT) }; - let data = (0..event._base.dwArraySize as usize) - .map(|i| { - // `rgData` is defined as a 1-element array, but it is actually a variable-length array. - let record = unsafe { event.rgData.get_unchecked(i) }; + let event = Event::try_from(event.uEventID).map_err(|_| { + SimConnectError::SimConnectUnimplementedEvent(event.uEventID) + })?; - Airport { - icao: fixed_c_str_to_string(&record.Icao), - lat: record.Latitude, - lon: record.Longitude, - alt: record.Altitude, + Some(Notification::Event(event)) + } + bindings::SIMCONNECT_RECV_ID_SIMCONNECT_RECV_ID_SIMOBJECT_DATA => { + trace!("Received SIMCONNECT_RECV_SIMOBJECT_DATA"); + + let event: &bindings::SIMCONNECT_RECV_SIMOBJECT_DATA = + unsafe { &*(data_buf as *const bindings::SIMCONNECT_RECV_SIMOBJECT_DATA) }; + + let type_name = self.get_type_name_by_request_id(event.dwDefineID); + + match type_name { + Some(type_name) => { + let data = Object { + type_name, + data_addr: std::ptr::addr_of!(event.dwData), + }; + + Some(Notification::Object(data)) } - }) - .collect::>(); + _ => None, + } + } + bindings::SIMCONNECT_RECV_ID_SIMCONNECT_RECV_ID_AIRPORT_LIST => { + trace!("Received SIMCONNECT_RECV_AIRPORT_LIST"); - Some(Notification::AirportList(data)) - } - bindings::SIMCONNECT_RECV_ID_SIMCONNECT_RECV_ID_WAYPOINT_LIST => { - let event: &bindings::SIMCONNECT_RECV_WAYPOINT_LIST = - unsafe { &*(data_buf as *const bindings::SIMCONNECT_RECV_WAYPOINT_LIST) }; + let event: &bindings::SIMCONNECT_RECV_AIRPORT_LIST = + unsafe { &*(data_buf as *const bindings::SIMCONNECT_RECV_AIRPORT_LIST) }; - let data = (0..event._base.dwArraySize as usize) - .map(|i| { - // `rgData` is defined as a 1-element array, but it is actually a variable-length array. - let record = unsafe { event.rgData.get_unchecked(i) }; + let data = (0..event._base.dwArraySize as usize) + .map(|i| { + // `rgData` is defined as a 1-element array, but it is actually a variable-length array. + let record = unsafe { event.rgData.get_unchecked(i) }; - Waypoint { - icao: fixed_c_str_to_string(&record._base.Icao), - lat: record._base.Latitude, - lon: record._base.Longitude, - alt: record._base.Altitude, - mag_var: record.fMagVar, - } - }) - .collect::>(); + Airport { + icao: fixed_c_str_to_string(&record.Icao), + lat: record.Latitude, + lon: record.Longitude, + alt: record.Altitude, + } + }) + .collect::>(); - Some(Notification::WaypointList(data)) - } - bindings::SIMCONNECT_RECV_ID_SIMCONNECT_RECV_ID_NDB_LIST => { - let event: &bindings::SIMCONNECT_RECV_NDB_LIST = - unsafe { &*(data_buf as *const bindings::SIMCONNECT_RECV_NDB_LIST) }; + Some(Notification::AirportList(data)) + } + bindings::SIMCONNECT_RECV_ID_SIMCONNECT_RECV_ID_WAYPOINT_LIST => { + trace!("Received SIMCONNECT_RECV_WAYPOINT_LIST"); - let data = (0..event._base.dwArraySize as usize) - .map(|i| { - // `rgData` is defined as a 1-element array, but it is actually a variable-length array. - let record = unsafe { event.rgData.get_unchecked(i) }; + let event: &bindings::SIMCONNECT_RECV_WAYPOINT_LIST = + unsafe { &*(data_buf as *const bindings::SIMCONNECT_RECV_WAYPOINT_LIST) }; - NDB { - icao: fixed_c_str_to_string(&record._base._base.Icao), - lat: record._base._base.Latitude, - lon: record._base._base.Longitude, - alt: record._base._base.Altitude, - mag_var: record._base.fMagVar, - frequency: record.fFrequency, - } - }) - .collect::>(); + let data = (0..event._base.dwArraySize as usize) + .map(|i| { + // `rgData` is defined as a 1-element array, but it is actually a variable-length array. + let record = unsafe { event.rgData.get_unchecked(i) }; - Some(Notification::NdbList(data)) - } - bindings::SIMCONNECT_RECV_ID_SIMCONNECT_RECV_ID_VOR_LIST => { - let event: &bindings::SIMCONNECT_RECV_VOR_LIST = - unsafe { &*(data_buf as *const bindings::SIMCONNECT_RECV_VOR_LIST) }; + Waypoint { + icao: fixed_c_str_to_string(&record._base.Icao), + lat: record._base.Latitude, + lon: record._base.Longitude, + alt: record._base.Altitude, + mag_var: record.fMagVar, + } + }) + .collect::>(); - let data = (0..event._base.dwArraySize as usize) - .map(|i| { - // `rgData` is defined as a 1-element array, but it is actually a variable-length array. - let record = unsafe { event.rgData.get_unchecked(i) }; + Some(Notification::WaypointList(data)) + } + bindings::SIMCONNECT_RECV_ID_SIMCONNECT_RECV_ID_NDB_LIST => { + trace!("Received SIMCONNECT_RECV_NDB_LIST"); - let has_nav_signal = record.Flags - & bindings::SIMCONNECT_RECV_ID_VOR_LIST_HAS_NAV_SIGNAL - == bindings::SIMCONNECT_RECV_ID_VOR_LIST_HAS_NAV_SIGNAL; - let has_localizer = record.Flags - & bindings::SIMCONNECT_RECV_ID_VOR_LIST_HAS_LOCALIZER - == bindings::SIMCONNECT_RECV_ID_VOR_LIST_HAS_LOCALIZER; - let has_glide_slope = record.Flags - & bindings::SIMCONNECT_RECV_ID_VOR_LIST_HAS_GLIDE_SLOPE - == bindings::SIMCONNECT_RECV_ID_VOR_LIST_HAS_GLIDE_SLOPE; - let has_dme = record.Flags & bindings::SIMCONNECT_RECV_ID_VOR_LIST_HAS_DME - == bindings::SIMCONNECT_RECV_ID_VOR_LIST_HAS_DME; + let event: &bindings::SIMCONNECT_RECV_NDB_LIST = + unsafe { &*(data_buf as *const bindings::SIMCONNECT_RECV_NDB_LIST) }; - VOR { - icao: fixed_c_str_to_string(&record._base._base._base.Icao), - lat: record._base._base._base.Latitude, - lon: record._base._base._base.Longitude, - alt: record._base._base._base.Altitude, - mag_var: record._base._base.fMagVar, - has_nav_signal, - has_localizer, - has_glide_slope, - has_dme, - localizer: if has_localizer { - Some(record.fLocalizer) - } else { - None - }, - glide_lat: if has_nav_signal { - Some(record.GlideLat) - } else { - None - }, - glide_lon: if has_nav_signal { - Some(record.GlideLon) - } else { - None - }, - glide_alt: if has_nav_signal { - Some(record.GlideAlt) - } else { - None - }, - glide_slope_angle: if has_glide_slope { - Some(record.fGlideSlopeAngle) - } else { - None - }, - frequency: if has_dme { - Some(record._base.fFrequency) - } else { - None - }, - } - }) - .collect::>(); + let data = (0..event._base.dwArraySize as usize) + .map(|i| { + // `rgData` is defined as a 1-element array, but it is actually a variable-length array. + let record = unsafe { event.rgData.get_unchecked(i) }; - Some(Notification::VorList(data)) - } - bindings::SIMCONNECT_RECV_ID_SIMCONNECT_RECV_ID_EXCEPTION => { - let event: &bindings::SIMCONNECT_RECV_EXCEPTION = - unsafe { &*(data_buf as *const bindings::SIMCONNECT_RECV_EXCEPTION) }; - Some(Notification::Exception(event.dwException)) - } - bindings::SIMCONNECT_RECV_ID_SIMCONNECT_RECV_ID_NULL => None, - id => panic!("Got unrecognized notification: {id}"), - }; + NDB { + icao: fixed_c_str_to_string(&record._base._base.Icao), + lat: record._base._base.Latitude, + lon: record._base._base.Longitude, + alt: record._base._base.Altitude, + mag_var: record._base.fMagVar, + frequency: record.fFrequency, + } + }) + .collect::>(); - Ok(result) + Some(Notification::NdbList(data)) + } + bindings::SIMCONNECT_RECV_ID_SIMCONNECT_RECV_ID_VOR_LIST => { + trace!("Received SIMCONNECT_RECV_VOR_LIST"); + + let event: &bindings::SIMCONNECT_RECV_VOR_LIST = + unsafe { &*(data_buf as *const bindings::SIMCONNECT_RECV_VOR_LIST) }; + + let data = (0..event._base.dwArraySize as usize) + .map(|i| { + // `rgData` is defined as a 1-element array, but it is actually a variable-length array. + let record = unsafe { event.rgData.get_unchecked(i) }; + + let has_nav_signal = record.Flags + & bindings::SIMCONNECT_RECV_ID_VOR_LIST_HAS_NAV_SIGNAL + == bindings::SIMCONNECT_RECV_ID_VOR_LIST_HAS_NAV_SIGNAL; + let has_localizer = record.Flags + & bindings::SIMCONNECT_RECV_ID_VOR_LIST_HAS_LOCALIZER + == bindings::SIMCONNECT_RECV_ID_VOR_LIST_HAS_LOCALIZER; + let has_glide_slope = record.Flags + & bindings::SIMCONNECT_RECV_ID_VOR_LIST_HAS_GLIDE_SLOPE + == bindings::SIMCONNECT_RECV_ID_VOR_LIST_HAS_GLIDE_SLOPE; + let has_dme = record.Flags + & bindings::SIMCONNECT_RECV_ID_VOR_LIST_HAS_DME + == bindings::SIMCONNECT_RECV_ID_VOR_LIST_HAS_DME; + + VOR { + icao: fixed_c_str_to_string(&record._base._base._base.Icao), + lat: record._base._base._base.Latitude, + lon: record._base._base._base.Longitude, + alt: record._base._base._base.Altitude, + mag_var: record._base._base.fMagVar, + has_nav_signal, + has_localizer, + has_glide_slope, + has_dme, + localizer: if has_localizer { + Some(record.fLocalizer) + } else { + None + }, + glide_lat: if has_nav_signal { + Some(record.GlideLat) + } else { + None + }, + glide_lon: if has_nav_signal { + Some(record.GlideLon) + } else { + None + }, + glide_alt: if has_nav_signal { + Some(record.GlideAlt) + } else { + None + }, + glide_slope_angle: if has_glide_slope { + Some(record.fGlideSlopeAngle) + } else { + None + }, + frequency: if has_dme { + Some(record._base.fFrequency) + } else { + None + }, + } + }) + .collect::>(); + + Some(Notification::VorList(data)) + } + bindings::SIMCONNECT_RECV_ID_SIMCONNECT_RECV_ID_EXCEPTION => { + let event: &bindings::SIMCONNECT_RECV_EXCEPTION = + unsafe { &*(data_buf as *const bindings::SIMCONNECT_RECV_EXCEPTION) }; + + warn!("Received {:?}", event); + + Some(Notification::Exception(event.dwException)) + } + bindings::SIMCONNECT_RECV_ID_SIMCONNECT_RECV_ID_NULL => None, + id => { + error!("Received unhandled notification ID: {}", id); + panic!("Got unrecognized notification: {id}"); + } + }; + + Ok(result) + } } /// Register a Request ID in the internal state so that the user doesn't have to manually manage Request IDs. - #[tracing::instrument(name = "SimConnect::new_request_id")] + #[tracing::instrument(name = "SimConnect::new_request_id", level = "trace", skip(self))] pub(super) fn new_request_id(&mut self, type_name: String) -> Result { if self.registered_objects.contains_key(&type_name) { return Err(SimConnectError::ObjectAlreadyRegistered(type_name)); @@ -331,13 +365,21 @@ impl SimConnect { } /// Unregister a Request ID in the internal state so that the user doesn't have to manually manage Request IDs. - #[tracing::instrument(name = "SimConnect::unregister_request_id_by_type_name")] + #[tracing::instrument( + name = "SimConnect::unregister_request_id_by_type_name", + level = "trace", + skip(self) + )] pub(super) fn unregister_request_id_by_type_name(&mut self, type_name: &str) -> Option { self.registered_objects.remove(type_name) } /// Get the Type Name of a Request ID. - #[tracing::instrument(name = "SimConnect::get_type_name_by_request_id")] + #[tracing::instrument( + name = "SimConnect::get_type_name_by_request_id", + level = "trace", + skip(self) + )] pub(super) fn get_type_name_by_request_id(&self, request_id: u32) -> Option { self.registered_objects .iter() @@ -347,6 +389,7 @@ impl SimConnect { } impl Drop for SimConnect { + #[tracing::instrument(name = "SimConnect::drop", level = "debug", skip(self))] fn drop(&mut self) { let _ = unsafe { bindings::SimConnect_Close(self.handle.as_ptr()) }; } diff --git a/simconnect-sdk/src/simconnect/events.rs b/simconnect-sdk/src/simconnect/events.rs index b7349cd..e066c9a 100644 --- a/simconnect-sdk/src/simconnect/events.rs +++ b/simconnect-sdk/src/simconnect/events.rs @@ -4,7 +4,7 @@ impl SimConnect { /// Associates a client defined event with a Microsoft Flight Simulator event name. /// /// WIP - #[tracing::instrument(name = "SimConnect::register_event")] + #[tracing::instrument(name = "SimConnect::register_event", level = "debug", skip(self))] pub fn register_event( &self, event: Event, diff --git a/simconnect-sdk/src/simconnect/facilities.rs b/simconnect-sdk/src/simconnect/facilities.rs index 9de8dbe..f76e6f2 100644 --- a/simconnect-sdk/src/simconnect/facilities.rs +++ b/simconnect-sdk/src/simconnect/facilities.rs @@ -10,7 +10,11 @@ impl SimConnect { /// The simulation keeps a facilities cache of all the airports, waypoints, NDB and VOR stations within a certain radius of the user aircraft. /// This radius varies depending on where the aircraft is in the world, but is at least large enough to encompass the whole of the reality bubble for airports and waypoints, and can be over 200 miles for VOR and NDB stations. /// As the user aircraft moves facilities will be added to, and removed from, the cache. However, in the interests pf performance, hysteresis is built into the system. - #[tracing::instrument(name = "SimConnect::request_facilities_list")] + #[tracing::instrument( + name = "SimConnect::request_facilities_list", + level = "debug", + skip(self) + )] pub fn request_facilities_list( &mut self, facility_type: FacilityType, @@ -42,7 +46,11 @@ impl SimConnect { /// The simulation keeps a facilities cache of all the airports, waypoints, NDB and VOR stations within a certain radius of the user aircraft. /// This radius varies depending on where the aircraft is in the world, but is at least large enough to encompass the whole of the reality bubble for airports and waypoints, and can be over 200 miles for VOR and NDB stations. /// As the user aircraft moves facilities will be added to, and removed from, the cache. However, in the interests pf performance, hysteresis is built into the system. - #[tracing::instrument(name = "SimConnect::subscribe_to_facilities")] + #[tracing::instrument( + name = "SimConnect::subscribe_to_facilities", + level = "debug", + skip(self) + )] pub fn subscribe_to_facilities( &mut self, facility_type: FacilityType, @@ -65,7 +73,11 @@ impl SimConnect { /// /// # Remarks /// This is used to terminate notifications generated by the [`crate::SimConnect::request_facilities_list`] or [`crate::SimConnect::subscribe_to_facilities`] functions. - #[tracing::instrument(name = "SimConnect::unsubscribe_to_facilities")] + #[tracing::instrument( + name = "SimConnect::unsubscribe_to_facilities", + level = "debug", + skip(self) + )] pub fn unsubscribe_to_facilities( &mut self, facility_type: FacilityType, diff --git a/simconnect-sdk/src/simconnect/objects.rs b/simconnect-sdk/src/simconnect/objects.rs index fe03395..0f600bf 100644 --- a/simconnect-sdk/src/simconnect/objects.rs +++ b/simconnect-sdk/src/simconnect/objects.rs @@ -5,7 +5,7 @@ use crate::{ impl SimConnect { // Register an object with SimConnect by assigning it an unique interval `request_id` and then calling the [`crate::SimConnectObjectExt::register`] method on the struct. - #[tracing::instrument(name = "SimConnect::register_object")] + #[tracing::instrument(name = "SimConnect::register_object", level = "debug", skip(self))] pub fn register_object(&mut self) -> Result { let type_name: String = std::any::type_name::().into(); @@ -17,7 +17,7 @@ impl SimConnect { } // Unregister an object with SimConnect. - #[tracing::instrument(name = "SimConnect::unregister_object")] + #[tracing::instrument(name = "SimConnect::unregister_object", level = "debug", skip(self))] pub fn unregister_object(&mut self) -> Result { let type_name: String = std::any::type_name::().into(); @@ -41,7 +41,11 @@ impl SimConnect { /// /// # Remarks /// The [`crate::SimConnectObject`] macro will automatically call this method for the struct. - #[tracing::instrument(name = "SimConnect::add_to_data_definition")] + #[tracing::instrument( + name = "SimConnect::add_to_data_definition", + level = "debug", + skip(self) + )] pub fn add_to_data_definition( &self, request_id: u32, @@ -84,7 +88,11 @@ impl SimConnect { /// /// # Remarks /// The [`crate::SimConnectObject`] macro will automatically call this method for the struct. - #[tracing::instrument(name = "SimConnect::request_data_on_sim_object")] + #[tracing::instrument( + name = "SimConnect::request_data_on_sim_object", + level = "debug", + skip(self) + )] pub fn request_data_on_sim_object( &self, request_id: u32,