diff --git a/backroll/src/backend/p2p.rs b/backroll/src/backend/p2p.rs index aab3a92..6c4e74c 100644 --- a/backroll/src/backend/p2p.rs +++ b/backroll/src/backend/p2p.rs @@ -12,7 +12,7 @@ use async_channel::TryRecvError; use parking_lot::RwLock; use std::sync::Arc; use std::time::Duration; -use tracing::{debug, info}; +use tracing::debug; const RECOMMENDATION_INTERVAL: Frame = 240; const DEFAULT_FRAME_DELAY: Frame = 3; @@ -255,7 +255,7 @@ impl P2PSessionRef { // of the game. All other players need to be disconnected. // that if the endpoint is not initalized, this must be the local player. let current_frame = self.sync.frame_count(); - info!( + debug!( "Disconnecting local player {} at frame {} by user request.", queue, last_frame ); @@ -265,7 +265,7 @@ impl P2PSessionRef { } } } else { - info!( + debug!( "Disconnecting queue {} at frame {} by user request.", queue, last_frame ); @@ -279,7 +279,7 @@ impl P2PSessionRef { self.players[queue].disconnect(); - info!("Changing queue {} local connect status for last frame from {} to {} on disconnect request (current: {}).", + debug!("Changing queue {} local connect status for last frame from {} to {} on disconnect request (current: {}).", queue, self.local_connect_status[queue].read().last_frame, syncto, frame_count); { @@ -289,12 +289,12 @@ impl P2PSessionRef { } if syncto < frame_count { - info!( + debug!( "Adjusting simulation to account for the fact that {} disconnected @ {}.", queue, syncto ); self.sync.adjust_simulation(commands, syncto); - info!("Finished adjusting simulation."); + debug!("Finished adjusting simulation."); } commands.push(Command::Event(Event::Disconnected(PlayerHandle(queue)))); @@ -421,10 +421,10 @@ impl P2PSessionRef { self.poll_n_players(commands) }; - info!("last confirmed frame in p2p backend is {}.", min_frame); + debug!("last confirmed frame in p2p backend is {}.", min_frame); if min_frame >= 0 { debug_assert!(min_frame != Frame::MAX); - info!("setting confirmed frame in sync to {}.", min_frame); + debug!("setting confirmed frame in sync to {}.", min_frame); self.sync.set_last_confirmed_frame(min_frame); } @@ -458,15 +458,15 @@ impl P2PSessionRef { if !local_status.disconnected { min_frame = std::cmp::min(local_status.last_frame, min_frame); } - info!( + debug!( "local endp: connected = {}, last_received = {}, total_min_confirmed = {}.", !local_status.disconnected, local_status.last_frame, min_frame ); if !queue_connected && !local_status.disconnected { - info!("disconnecting player {} by remote request.", i); + debug!("disconnecting player {} by remote request.", i); self.disconnect_player_queue(commands, i, min_frame); } - info!("min_frame = {}.", min_frame); + debug!("min_frame = {}.", min_frame); } min_frame } @@ -477,7 +477,7 @@ impl P2PSessionRef { for queue in 0..self.players.len() { let mut queue_connected = true; let mut queue_min_confirmed = Frame::MAX; - info!("considering queue {}.", queue); + debug!("considering queue {}.", queue); for (i, player) in self.players.iter().enumerate() { // we're going to do a lot of logic here in consideration of endpoint i. // keep accumulating the minimum confirmed point for all n*n packets and @@ -487,10 +487,10 @@ impl P2PSessionRef { let status = peer.get_peer_connect_status(queue); queue_connected = queue_connected && !status.disconnected; queue_min_confirmed = std::cmp::min(status.last_frame, queue_min_confirmed); - info!("endpoint {}: connected = {}, last_received = {}, queue_min_confirmed = {}.", + debug!("endpoint {}: connected = {}, last_received = {}, queue_min_confirmed = {}.", i, queue_connected, status.last_frame, queue_min_confirmed); } else { - info!("endpoint {}: ignoring... not running.", i); + debug!("endpoint {}: ignoring... not running.", i); } } @@ -499,7 +499,7 @@ impl P2PSessionRef { if !local_status.disconnected { queue_min_confirmed = std::cmp::min(local_status.last_frame, queue_min_confirmed); } - info!( + debug!( "local endp: connected = {}, last_received = {}, queue_min_confirmed = {}.", !local_status.disconnected, local_status.last_frame, queue_min_confirmed ); @@ -511,11 +511,11 @@ impl P2PSessionRef { // so, we need to re-adjust. This can happen when we detect our own disconnect at frame n // and later receive a disconnect notification for frame n-1. if !local_status.disconnected || local_status.last_frame > queue_min_confirmed { - info!("disconnecting queue {} by remote request.", queue); + debug!("disconnecting queue {} by remote request.", queue); self.disconnect_player_queue(commands, queue, queue_min_confirmed); } } - info!("min_frame = {}.", min_frame); + debug!("min_frame = {}.", min_frame); } min_frame } @@ -715,7 +715,7 @@ impl P2PSession { pub fn advance_frame(&self) -> Commands { let mut session_ref = self.0.write(); let mut commands = Commands::::default(); - info!("End of frame ({})...", session_ref.sync.frame_count()); + debug!("End of frame ({})...", session_ref.sync.frame_count()); if !session_ref.synchronizing { session_ref.sync.increment_frame(&mut commands); } @@ -760,7 +760,7 @@ impl P2PSession { // of the game. All other players need to be disconnected. // that if the endpoint is not initalized, this must be the local player. let current_frame = session_ref.sync.frame_count(); - info!( + debug!( "Disconnecting local player {} at frame {} by user request.", queue, last_frame ); @@ -770,7 +770,7 @@ impl P2PSession { } } } else { - info!( + debug!( "Disconnecting queue {} at frame {} by user request.", queue, last_frame ); diff --git a/backroll/src/command.rs b/backroll/src/command.rs index bc51ca8..b00d3ea 100644 --- a/backroll/src/command.rs +++ b/backroll/src/command.rs @@ -7,7 +7,7 @@ use std::{ collections::hash_map::DefaultHasher, hash::{Hash, Hasher}, }; -use tracing::{error, info}; +use tracing::{debug, error}; /// A singular command for a Backroll session client to execute. /// @@ -85,7 +85,7 @@ impl SaveState { } fn save_state(self, state: T::State, checksum: Option) { - info!( + debug!( "=== Saved frame state {} (checksum: {:08x}).", self.frame, checksum.unwrap_or(0) diff --git a/backroll/src/input.rs b/backroll/src/input.rs index 6c5fe33..5ddd0ac 100644 --- a/backroll/src/input.rs +++ b/backroll/src/input.rs @@ -1,6 +1,6 @@ use crate::{BackrollError, Config, Frame, PlayerHandle, MAX_PLAYERS, MAX_ROLLBACK_FRAMES}; use std::convert::TryFrom; -use tracing::info; +use tracing::debug; #[inline] fn previous_frame(offset: usize) -> usize { @@ -150,7 +150,7 @@ impl InputQueue { } pub fn last_confirmed_frame(&self) -> Frame { - info!("returning last confirmed frame {}.", self.last_added_frame); + debug!("returning last confirmed frame {}.", self.last_added_frame); self.last_added_frame } @@ -169,7 +169,7 @@ impl InputQueue { frame = std::cmp::min(frame, self.last_frame_requested) } - info!( + debug!( "discarding confirmed frames up to {} (last_added:{} length:{}).", frame, self.last_added_frame, self.length ); @@ -180,7 +180,7 @@ impl InputQueue { let offset = frame - self.inputs[self.tail].frame + 1; let offset = usize::try_from(offset).unwrap(); - info!("difference of {} frames.", offset); + debug!("difference of {} frames.", offset); self.tail = (self.tail + offset) % MAX_ROLLBACK_FRAMES; self.length -= offset; @@ -192,7 +192,7 @@ impl InputQueue { super::is_null(self.first_incorrect_frame) || frame <= self.first_incorrect_frame ); - info!("resetting all prediction errors back to frame {}.", frame); + debug!("resetting all prediction errors back to frame {}.", frame); // There's nothing really to do other than reset our prediction // state and the incorrect frame counter... @@ -210,7 +210,7 @@ impl InputQueue { } pub fn get_input(&mut self, frame: Frame) -> FetchedInput { - info!("requesting input frame {:?}.", frame); + debug!("requesting input frame {:?}.", frame); // No one should ever try to grab any input when we have a prediction // error. Doing so means that we're just going further down the wrong @@ -231,7 +231,7 @@ impl InputQueue { offset = (offset + self.tail) % MAX_ROLLBACK_FRAMES; let input = self.inputs[offset].clone(); debug_assert!(input.frame == frame); - info!("returning confirmed frame number {}.", input.frame); + debug!("returning confirmed frame number {}.", input.frame); return FetchedInput::Normal(input); } @@ -239,13 +239,13 @@ impl InputQueue { // to return a prediction frame. Predict that the user will do the // same thing they did last time. if frame == 0 { - info!("basing new prediction frame from nothing, you're client wants frame 0."); + debug!("basing new prediction frame from nothing, you're client wants frame 0."); self.prediction.clear(); } else if super::is_null(self.last_added_frame) { - info!("basing new prediction frame from nothing, since we have no frames yet."); + debug!("basing new prediction frame from nothing, since we have no frames yet."); self.prediction.clear(); } else { - info!( + debug!( "basing new prediction frame from previously added frame (frame: {}).", self.inputs[previous_frame(self.head)].frame ); @@ -259,7 +259,7 @@ impl InputQueue { // frame number requested by the client, though. let mut prediction = self.prediction.clone(); prediction.frame = frame; - info!( + debug!( "returning prediction frame number {} ({}).", frame, self.prediction.frame ); @@ -274,7 +274,7 @@ impl InputQueue { || input.frame == self.last_user_added_frame + 1 ); self.last_user_added_frame = input.frame; - info!("adding input frame number {} to queue.", input.frame); + debug!("adding input frame number {} to queue.", input.frame); // Move the queue head to the correct point in preparation to // input the frame into the queue. @@ -289,7 +289,7 @@ impl InputQueue { } fn add_delayed_input(&mut self, frame: Frame, input: FrameInput) { - info!("adding delayed input frame number {} to queue.", frame); + debug!("adding delayed input frame number {} to queue.", frame); debug_assert!(super::is_null(self.last_added_frame) || frame == self.last_added_frame + 1); debug_assert!(frame == 0 || self.inputs[previous_frame(self.head)].frame == frame - 1); @@ -308,7 +308,7 @@ impl InputQueue { // remember the first input which was incorrect so we can report it // in first_incorrect_frame() if super::is_null(self.first_incorrect_frame) && self.prediction != input { - info!("frame {} does not match prediction. marking error.", frame); + debug!("frame {} does not match prediction. marking error.", frame); self.first_incorrect_frame = frame; } @@ -319,7 +319,7 @@ impl InputQueue { if self.prediction.frame == self.last_frame_requested && super::is_null(self.first_incorrect_frame) { - info!("prediction is correct! dumping out of prediction mode."); + debug!("prediction is correct! dumping out of prediction mode."); self.prediction.frame = super::NULL_FRAME; } else { self.prediction.frame += 1; @@ -329,7 +329,7 @@ impl InputQueue { } fn advance_queue_head(&mut self, mut frame: Frame) -> Frame { - info!("advancing queue head to frame {}.", frame); + debug!("advancing queue head to frame {}.", frame); let mut expected_frame = if self.first_frame { 0 } else { @@ -341,7 +341,7 @@ impl InputQueue { // This can occur when the frame delay has dropped since the last // time we shoved a frame into the system. In this case, there's // no room on the queue. Toss it. - info!( + debug!( "Dropping input frame {} (expected next frame to be {}).", frame, expected_frame ); @@ -353,7 +353,7 @@ impl InputQueue { // time we shoved a frame into the system. We need to replicate the // last frame in the queue several times in order to fill the space // left. - info!( + debug!( "Adding padding frame {} to account for change in frame delay.", expected_frame ); diff --git a/backroll/src/protocol/mod.rs b/backroll/src/protocol/mod.rs index 2e6a54e..1c46bcb 100644 --- a/backroll/src/protocol/mod.rs +++ b/backroll/src/protocol/mod.rs @@ -16,7 +16,7 @@ use serde::{Deserialize, Serialize}; use std::num::Wrapping; use std::sync::Arc; use std::time::Duration; -use tracing::{debug, error, info}; +use tracing::{debug, error}; pub(crate) use event::Event; @@ -406,7 +406,7 @@ impl Peer { let mut state = self.state.write(); if !state.is_interrupted() && (last_recv_time + notify_start < now) { state.interrupt(); - info!("Endpoint has stopped receiving packets for {} ms. Sending notification.", + debug!("Endpoint has stopped receiving packets for {} ms. Sending notification.", notify_start.as_millis()); self.push_event(Event::::NetworkInterrupted { disconnect_timeout: timeout - notify_start @@ -415,7 +415,7 @@ impl Peer { } if last_recv_time + timeout < now { - info!( + debug!( "Endpoint has stopped receiving packets for {} ms. Disconnecting.", timeout.as_millis() ); @@ -438,7 +438,7 @@ impl Peer { let now = UnixMillis::now(); if let Some(last_send_time) = self.stats.read().last_send_time { if last_send_time + next_interval < now { - info!( + debug!( "No luck syncing after {:?} ms... Re-queueing sync packet.", next_interval ); @@ -522,7 +522,7 @@ impl Peer { // filter out out-of-order packets let skipped = seq - next_recv_seq; if skipped > MAX_SEQ_DISTANCE { - info!( + debug!( "dropping out of order packet (seq: {}, last seq: {})", seq, next_recv_seq ); @@ -604,7 +604,7 @@ impl Peer { let SyncRequest { random } = data; if let PeerState::Running { remote_magic } = *self.state.read() { if magic != remote_magic { - info!( + debug!( "Ignoring sync request from unknown endpoint ({} != {:?}).", magic, remote_magic ); @@ -619,7 +619,7 @@ impl Peer { let mut state = self.state.write(); if let Some(random) = state.random() { if data.random != random { - info!("sync reply {} != {}. Keep looking...", data.random, random); + debug!("sync reply {} != {}. Keep looking...", data.random, random); return Err(PeerError::InvalidMessage); } } @@ -635,14 +635,14 @@ impl Peer { ref mut roundtrips_remaining, .. } => { - info!( + debug!( "Checking sync state ({} round trips remaining).", *roundtrips_remaining ); debug_assert!(*roundtrips_remaining > 0); *roundtrips_remaining -= 1; if *roundtrips_remaining == 0 { - info!("Synchronized queue {}!", self.queue); + debug!("Synchronized queue {}!", self.queue); self.push_event(Event::::Synchronized)?; self.stats.write().last_input_packet_recv_time = UnixMillis::now(); *state = PeerState::Running { @@ -677,7 +677,7 @@ impl Peer { } PeerState::Running { remote_magic } if magic == remote_magic => Ok(()), _ => { - info!("Ignoring SyncReply while not syncing."); + debug!("Ignoring SyncReply while not syncing."); Err(PeerError::InvalidMessage) } } diff --git a/backroll/src/sync.rs b/backroll/src/sync.rs index f7a07fc..9cbda30 100644 --- a/backroll/src/sync.rs +++ b/backroll/src/sync.rs @@ -9,7 +9,7 @@ use parking_lot::{Mutex, RwLock}; use std::collections::HashMap; use std::ops::Deref; use std::sync::Arc; -use tracing::{debug, info, warn}; +use tracing::{debug, warn}; const MAX_PREDICTION_FRAMES: usize = 8; @@ -215,7 +215,7 @@ impl Sync { return Err(BackrollError::ReachedPredictionBarrier); } - info!( + debug!( "Sending undelayed local frame {} to queue {}.", self.frame_count, queue ); @@ -280,7 +280,7 @@ impl Sync { pub fn load_frame(&mut self, commands: &mut Commands, frame: Frame) { // find the frame in question if frame == self.frame_count { - info!("Skipping NOP."); + debug!("Skipping NOP."); return; } @@ -304,7 +304,7 @@ impl Sync { let frame_count = self.frame_count; let count = self.frame_count - seek_to; - info!("Catching up"); + debug!("Catching up"); self.rolling_back = true; // Flush our input queue and load the last frame. @@ -320,7 +320,6 @@ impl Sync { debug_assert!(self.frame_count == frame_count); self.rolling_back = false; - info!("---"); } pub fn check_simulation_consistency(&self) -> Option { diff --git a/backroll/src/time_sync.rs b/backroll/src/time_sync.rs index a554845..4b1cc62 100644 --- a/backroll/src/time_sync.rs +++ b/backroll/src/time_sync.rs @@ -5,7 +5,7 @@ use std::convert::TryFrom; use std::ops::{Add, Sub}; use std::sync::Arc; use std::time::{Duration, SystemTime, UNIX_EPOCH}; -use tracing::info; +use tracing::debug; const FRAME_WINDOW_SIZE: usize = 40; const MIN_UNIQUE_FRAMES: usize = 10; @@ -67,7 +67,7 @@ impl TimeSync { // sleep for. let sleep_frames = (((radvantage - advantage) / 2.0) + 0.5) as Frame; - info!( + debug!( "iteration {}: sleep frames is {}", sync.iteration, sleep_frames ); @@ -85,7 +85,7 @@ impl TimeSync { if require_idle_input { for idx in 0..sync.last_inputs.len() { if sync.last_inputs[idx] != sync.last_inputs[0] { - info!( + debug!( "iteration {}: rejecting due to input stuff at position {}...!!!", sync.iteration, idx );