Merge pull request #93 from caspark/add-tracing-for-logging

Add tracing for logging

Cargo.toml

@@ -21,15 +21,18 @@ rand = "0.8"
 bitfield-rle = "0.2.1"
 parking_lot = "0.12"
 instant = "0.1"
-getrandom = {version = "0.2", optional = true}
+getrandom = { version = "0.2", optional = true }
+tracing = "0.1"
 
 [target.'cfg(target_arch = "wasm32")'.dependencies]
 js-sys = "0.3"
 
 [dev-dependencies]
 serial_test = "0.5"
 structopt = "0.3"
-macroquad = "0.4"
+macroquad = { version = "0.4", features = ["log-rs"] }
+tracing-subscriber = "0.3"
+tracing-log = "0.2"
 
 # Examples
 [[example]]

examples/ex_game/ex_game_p2p.rs

@@ -33,6 +33,16 @@ struct Opt {
 
 #[macroquad::main(window_conf)]
 async fn main() -> Result<(), Box<dyn std::error::Error>> {
+    // configure logging: output ggrs and example game logs to standard out
+    tracing::subscriber::set_global_default(
+        tracing_subscriber::FmtSubscriber::builder()
+            .with_max_level(tracing::Level::DEBUG)
+            .finish(),
+    )
+    .expect("setting up tracing subscriber failed");
+    // forward logs from log crate to the tracing subscriber (allows seeing macroquad logs)
+    tracing_log::LogTracer::init()?;
+
     // read cmd line arguments
     let opt = Opt::from_args();
     let num_players = opt.players.len();
@@ -91,7 +101,7 @@ async fn main() -> Result<(), Box<dyn std::error::Error>> {
 
         // print GGRS events
         for event in sess.events() {
-            println!("Event: {:?}", event);
+            info!("Event: {:?}", event);
         }
 
         // this is to keep ticks between clients synchronized.

examples/ex_game/ex_game_spectator.rs

@@ -33,6 +33,16 @@ struct Opt {
 
 #[macroquad::main(window_conf)]
 async fn main() -> Result<(), Box<dyn std::error::Error>> {
+    // configure logging: output ggrs and example game logs to standard out
+    tracing::subscriber::set_global_default(
+        tracing_subscriber::FmtSubscriber::builder()
+            .with_max_level(tracing::Level::DEBUG)
+            .finish(),
+    )
+    .expect("setting up tracing subscriber failed");
+    // forward logs from log crate to the tracing subscriber (allows seeing macroquad logs)
+    tracing_log::LogTracer::init()?;
+
     // read cmd line arguments
     let opt = Opt::from_args();
 
@@ -58,9 +68,9 @@ async fn main() -> Result<(), Box<dyn std::error::Error>> {
 
         // handle GGRS events
         for event in sess.events() {
-            println!("Event: {:?}", event);
+            info!("Event: {:?}", event);
             if let GgrsEvent::Disconnected { .. } = event {
-                println!("Disconnected from host.");
+                info!("Disconnected from host.");
                 return Ok(());
             }
         }
@@ -80,7 +90,7 @@ async fn main() -> Result<(), Box<dyn std::error::Error>> {
                 match sess.advance_frame() {
                     Ok(requests) => game.handle_requests(requests, false),
                     Err(GgrsError::PredictionThreshold) => {
-                        println!(
+                        info!(
                             "Frame {} skipped: Waiting for input from host.",
                             game.current_frame()
                         );

examples/ex_game/ex_game_synctest.rs

@@ -30,6 +30,16 @@ struct Opt {
 
 #[macroquad::main(window_conf)]
 async fn main() -> Result<(), Box<dyn std::error::Error>> {
+    // configure logging: output ggrs and example game logs to standard out
+    tracing::subscriber::set_global_default(
+        tracing_subscriber::FmtSubscriber::builder()
+            .with_max_level(tracing::Level::DEBUG)
+            .finish(),
+    )
+    .expect("setting up tracing subscriber failed");
+    // forward logs from log crate to the tracing subscriber (allows seeing macroquad logs)
+    tracing_log::LogTracer::init()?;
+
     // read cmd line arguments
     let opt = Opt::from_args();
 

src/network/messages.rs

@@ -27,7 +27,7 @@ pub(crate) struct SyncReply {
     pub random_reply: u32, // here's your random data back
 }
 
-#[derive(Clone, Debug, PartialEq, Eq, Serialize, Deserialize)]
+#[derive(Clone, PartialEq, Eq, Serialize, Deserialize)]
 pub(crate) struct Input {
     pub peer_connect_status: Vec<ConnectionStatus>,
     pub disconnect_requested: bool,
@@ -48,6 +48,29 @@ impl Default for Input {
     }
 }
 
+impl std::fmt::Debug for Input {
+    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+        f.debug_struct("Input")
+            .field("peer_connect_status", &self.peer_connect_status)
+            .field("disconnect_requested", &self.disconnect_requested)
+            .field("start_frame", &self.start_frame)
+            .field("ack_frame", &self.ack_frame)
+            .field("bytes", &BytesDebug(&self.bytes))
+            .finish()
+    }
+}
+struct BytesDebug<'a>(&'a [u8]);
+
+impl<'a> std::fmt::Debug for BytesDebug<'a> {
+    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+        f.write_str("0x")?;
+        for byte in self.0 {
+            write!(f, "{:02x}", byte)?;
+        }
+        Ok(())
+    }
+}
+
 #[derive(Copy, Clone, Debug, PartialEq, Eq, Serialize, Deserialize)]
 pub(crate) struct InputAck {
     pub ack_frame: Frame,

src/network/protocol.rs

@@ -8,6 +8,7 @@ use crate::time_sync::TimeSync;
 use crate::{
     Config, DesyncDetection, Frame, GgrsError, NonBlockingSocket, PlayerHandle, NULL_FRAME,
 };
+use tracing::trace;
 
 use instant::{Duration, Instant};
 use std::collections::vec_deque::Drain;
@@ -432,10 +433,20 @@ impl<T: Config> UdpProtocol<T> {
         socket: &mut Box<dyn NonBlockingSocket<T::Address>>,
     ) {
         if self.state == ProtocolState::Shutdown {
+            trace!(
+                "Protocol is shutting down; dropping {} messages",
+                self.send_queue.len()
+            );
             self.send_queue.drain(..);
             return;
         }
 
+        if self.send_queue.is_empty() {
+            // avoid log spam if there's nothing to send
+            return;
+        }
+
+        trace!("Sending {} messages over socket", self.send_queue.len());
         for msg in self.send_queue.drain(..) {
             socket.send_to(&msg, &self.peer_addr);
         }
@@ -485,6 +496,18 @@ impl<T: Config> UdpProtocol<T> {
                 &self.last_acked_input.bytes,
                 self.pending_output.iter().map(|gi| &gi.bytes),
             );
+            trace!(
+                "Encoded {} bytes from {} pending output(s) into {} bytes",
+                {
+                    let mut sum = 0;
+                    for gi in self.pending_output.iter() {
+                        sum += gi.bytes.len();
+                    }
+                    sum
+                },
+                self.pending_output.len(),
+                body.bytes.len()
+            );
 
             body.ack_frame = self.last_recv_frame();
             body.disconnect_requested = self.state == ProtocolState::Disconnected;
@@ -530,6 +553,8 @@ impl<T: Config> UdpProtocol<T> {
     }
 
     fn queue_message(&mut self, body: MessageBody) {
+        trace!("Queuing message to {:?}: {:?}", self.peer_addr, body);
+
         // set the header
         let header = MessageHeader { magic: self.magic };
         let msg = Message { header, body };
@@ -547,13 +572,17 @@ impl<T: Config> UdpProtocol<T> {
      */
 
     pub(crate) fn handle_message(&mut self, msg: &Message) {
+        trace!("Handling message from {:?}: {:?}", self.peer_addr, msg);
+
         // don't handle messages if shutdown
         if self.state == ProtocolState::Shutdown {
+            trace!("Protocol is shutting down; ignoring message");
             return;
         }
 
         // filter packets that don't match the magic if we have set it already
         if self.remote_magic != 0 && msg.header.magic != self.remote_magic {
+            trace!("Received message with wrong magic; ignoring");
             return;
         }
 
@@ -562,6 +591,7 @@ impl<T: Config> UdpProtocol<T> {
 
         // if the connection has been marked as interrupted, send an event to signal we are receiving again
         if self.disconnect_notify_sent && self.state == ProtocolState::Running {
+            trace!("Received message on interrupted protocol; sending NetworkResumed event");
             self.disconnect_notify_sent = false;
             self.event_queue.push_back(Event::NetworkResumed);
         }

src/network/udp_socket.rs

@@ -3,6 +3,8 @@ use std::{
     net::{IpAddr, Ipv4Addr, SocketAddr, UdpSocket},
 };
 
+use tracing::warn;
+
 use crate::{network::messages::Message, NonBlockingSocket};
 
 const RECV_BUFFER_SIZE: usize = 4096;
@@ -47,12 +49,9 @@ impl NonBlockingSocket<SocketAddr> for UdpNonBlockingSocket {
         //
         // On the other hand, the occaisional large packet is kind of harmless - whether it gets
         // fragmented or not, the odds are that it will get through unless the connection is truly
-        // horrible.
-        //
-        // So ideally we'd inform the user by logging a warning, but we don't have any logging set
-        // up - so as a compromise, we ignore this in release mode but panic in debug mode.
-        if buf.len() > IDEAL_MAX_UDP_PACKET_SIZE && cfg!(debug_assertions) {
-            panic!(
+        // horrible. So, we'll just log a warning.
+        if buf.len() > IDEAL_MAX_UDP_PACKET_SIZE {
+            warn!(
                 "Sending UDP packet of size {} bytes, which is \
                 larger than ideal ({IDEAL_MAX_UDP_PACKET_SIZE})",
                 buf.len()

src/sessions/p2p_session.rs

@@ -9,6 +9,7 @@ use crate::{
     network::protocol::Event, Config, Frame, GgrsEvent, GgrsRequest, NonBlockingSocket,
     PlayerHandle, PlayerType, SessionState, NULL_FRAME,
 };
+use tracing::{debug, trace, warn};
 
 use std::collections::vec_deque::Drain;
 use std::collections::HashMap;
@@ -192,10 +193,14 @@ impl<T: Config> P2PSession<T> {
             SessionState::Synchronizing
         };
 
-        let sparse_saving = if max_prediction == 0 {
+        let sparse_saving = if max_prediction == 0 && sparse_saving {
             // in lockstep mode, saving will never happen, but we use the last saved frame to mark
             // control marking frames confirmed, so we need to turn off sparse saving to ensure that
             // frames are marked as confirmed - otherwise we will never advance the game state.
+            warn!(
+                "Sparse saving setting is ignored because lockstep mode is on \
+                (max_prediction set to 0), so no saving will take place"
+            );
             false
         } else {
             sparse_saving
@@ -268,14 +273,17 @@ impl<T: Config> P2PSession<T> {
 
         // session is not running and synchronized
         if self.state != SessionState::Running {
+            trace!("Session not synchronized; returning error");
             return Err(GgrsError::NotSynchronized);
         }
 
         // check if input for all local players is queued
         for handle in self.player_reg.local_player_handles() {
             if !self.local_inputs.contains_key(&handle) {
                 return Err(GgrsError::InvalidRequest {
-                    info: "Missing local input while calling advance_frame().".to_owned(),
+                    info: format!(
+                        "Missing local input for handle {handle} while calling advance_frame()."
+                    ),
                 });
             }
         }
@@ -308,6 +316,7 @@ impl<T: Config> P2PSession<T> {
 
         // if we are in the first frame, we have to save the state
         if self.sync_layer.current_frame() == 0 && !lockstep {
+            trace!("Saving state of first frame");
             requests.push(self.sync_layer.save_current_state());
         }
 
@@ -416,7 +425,7 @@ impl<T: Config> P2PSession<T> {
             self.local_inputs.clear();
             requests.push(GgrsRequest::AdvanceFrame { inputs });
         } else {
-            println!(
+            debug!(
                 "Prediction Threshold reached. Skipping on frame {}",
                 self.sync_layer.current_frame()
             );
@@ -707,6 +716,10 @@ impl<T: Config> P2PSession<T> {
         let count = current_frame - frame_to_load;
 
         // request to load that frame
+        debug!(
+            "Pushing request to load frame {} (current frame {})",
+            frame_to_load, current_frame
+        );
         requests.push(self.sync_layer.load_frame(frame_to_load));
 
         // we are now at the desired frame