remove some trace! in network which a) was only spam and b) could be replaced by a metric way better.

added a span for disconnecting on the gameserver side. also added more debug! tracing there
Just keeping a trace! all 10000ms active to have a keep alive feeling.

network/src/metrics.rs

@@ -34,6 +34,8 @@ pub struct NetworkMetrics {
     pub message_out_total: IntCounterVec,
     // send(prio) Messages throughput, seperated by STREAM AND PARTICIPANT,
     pub message_out_throughput: IntCounterVec,
+    // flushed(prio) stream count, seperated by PARTICIPANT,
+    pub streams_flushed: IntCounterVec,
     // TODO: queued Messages, seperated by STREAM (add PART, CHANNEL),
     // queued Messages, seperated by PARTICIPANT
     pub queued_count: IntGaugeVec,
@@ -167,6 +169,13 @@ impl NetworkMetrics {
             ),
             &["participant", "stream"],
         )?;
+        let streams_flushed = IntCounterVec::new(
+            Opts::new(
+                "stream_flushed",
+                "Number of flushed streams requested to PrioManager at participant level",
+            ),
+            &["participant"],
+        )?;
         let queued_count = IntGaugeVec::new(
             Opts::new(
                 "queued_count",
@@ -207,6 +216,7 @@ impl NetworkMetrics {
             wire_in_throughput,
             message_out_total,
             message_out_throughput,
+            streams_flushed,
             queued_count,
             queued_bytes,
             participants_ping,

network/src/participant.rs

@@ -206,13 +206,11 @@ impl BParticipant {
         #[cfg(feature = "metrics")]
         let mut send_cache =
             PidCidFrameCache::new(self.metrics.frames_out_total.clone(), self.remote_pid);
+        let mut i: u64 = 0;
         loop {
             let mut frames = VecDeque::new();
             prios.fill_frames(FRAMES_PER_TICK, &mut frames).await;
             let len = frames.len();
-            if len > 0 {
-                trace!("Tick {}", len);
-            }
             for (_, frame) in frames {
                 self.send_frame(
                     frame,
@@ -226,6 +224,10 @@ impl BParticipant {
                 .await
                 .unwrap();
             async_std::task::sleep(TICK_TIME).await;
+            i += 1;
+            if i.rem_euclid(1000) == 0 {
+                trace!("Did 1000 ticks");
+            }
             //shutdown after all msg are send!
             if closing_up && (len == 0) {
                 break;

network/src/prios.rs

@@ -16,8 +16,6 @@ use futures::channel::oneshot;
 use std::collections::{HashMap, HashSet, VecDeque};
 #[cfg(feature = "metrics")] use std::sync::Arc;
 
-use tracing::*;
-
 const PRIO_MAX: usize = 64;
 
 #[derive(Default)]
@@ -148,11 +146,8 @@ impl PrioManager {
 
     async fn tick(&mut self) {
         // Check Range
-        let mut messages = 0;
-        let mut closed = 0;
         for (prio, sid, msg) in self.messages_rx.try_iter() {
             debug_assert!(prio as usize <= PRIO_MAX);
-            messages += 1;
             #[cfg(feature = "metrics")]
             {
                 let sid_string = sid.to_string();
@@ -173,7 +168,11 @@ impl PrioManager {
         }
         //this must be AFTER messages
         for (sid, return_sender) in self.sid_flushed_rx.try_iter() {
-            closed += 1;
+            #[cfg(feature = "metrics")]
+            self.metrics
+                .streams_flushed
+                .with_label_values(&[&self.pid])
+                .inc();
             if let Some(cnt) = self.sid_owned.get_mut(&sid) {
                 // register sender
                 cnt.empty_notify = Some(return_sender);
@@ -182,9 +181,6 @@ impl PrioManager {
                 return_sender.send(()).unwrap();
             }
         }
-        if messages > 0 || closed > 0 {
-            trace!(?messages, ?closed, "tick");
-        }
     }
 
     //if None returned, we are empty!
@@ -256,7 +252,6 @@ impl PrioManager {
                             }
                         }
                     } else {
-                        trace!(?msg.mid, "Repush message");
                         self.messages[prio as usize].push_front((sid, msg));
                     }
                 },

server/src/events/player.rs

@@ -79,18 +79,19 @@ pub fn handle_exit_ingame(server: &mut Server, entity: EcsEntity) {
 
 pub fn handle_client_disconnect(server: &mut Server, entity: EcsEntity) -> Event {
     if let Some(client) = server.state().read_storage::<Client>().get(entity) {
-        trace!("Closing participant of client");
         let participant = match client.participant.try_lock() {
             Ok(mut p) => p.take().unwrap(),
             Err(e) => {
-                error!(?e, "coudln't lock participant for removal");
+                error!(?e, ?entity, "coudln't lock participant for removal");
                 return Event::ClientDisconnected { entity };
             },
         };
-        std::thread::spawn(|| {
+        let pid = participant.remote_pid();
-            let pid = participant.remote_pid();
+        std::thread::spawn(move || {
+            let span = tracing::span!(tracing::Level::DEBUG, "client_disconnect", ?pid, ?entity);
+            let _enter = span.enter();
             let now = std::time::Instant::now();
-            trace!(?pid, "start disconnect");
+            debug!(?pid, ?entity, "Start handle disconnect of client");
             if let Err(e) = block_on(participant.disconnect()) {
                 debug!(
                     ?e,

server/src/sys/message.rs

@@ -25,6 +25,7 @@ use hashbrown::HashMap;
 use specs::{
     Entities, Join, Read, ReadExpect, ReadStorage, System, Write, WriteExpect, WriteStorage,
 };
+use tracing::{debug, error, info, warn};
 
 impl Sys {
     ///We needed to move this to a async fn, if we would use a async closures
@@ -267,17 +268,13 @@ impl Sys {
                                     let msg = mode.new_message(*from, message);
                                     new_chat_msgs.push((Some(entity), msg));
                                 } else {
-                                    tracing::error!("Could not send message. Missing player uid");
+                                    error!("Could not send message. Missing player uid");
                                 }
                             },
                             Err(ChatMsgValidationError::TooLong) => {
                                 let max = MAX_BYTES_CHAT_MSG;
                                 let len = message.len();
-                                tracing::warn!(
+                                warn!(?len, ?max, "Recieved a chat message that's too long")
-                                    ?len,
-                                    ?max,
-                                    "Recieved a chat message that's too long"
-                                )
                             },
                         }
                     },
@@ -342,7 +339,9 @@ impl Sys {
                     client.notify(ServerMsg::Disconnect);
                 },
                 ClientMsg::Terminate => {
+                    debug!(?entity, "Client send message to termitate session");
                     server_emitter.emit(ServerEvent::ClientDisconnect(entity));
+                    break Ok(());
                 },
                 ClientMsg::RequestCharacterList => {
                     if let Some(player) = players.get(entity) {
@@ -351,11 +350,7 @@ impl Sys {
                 },
                 ClientMsg::CreateCharacter { alias, tool, body } => {
                     if let Err(error) = alias_validator.validate(&alias) {
-                        tracing::debug!(
+                        debug!(?error, ?alias, "denied alias as it contained a banned word");
-                            ?error,
-                            ?alias,
-                            "denied alias as it contained a banned word"
-                        );
                         client.notify(ServerMsg::CharacterActionError(error.to_string()));
                     } else if let Some(player) = players.get(entity) {
                         character_loader.create_character(
@@ -522,10 +517,15 @@ impl<'a> System<'a> for Sys {
             // Update client ping.
             if cnt > 0 {
                 client.last_ping = time.0
-            } else if time.0 - client.last_ping > CLIENT_TIMEOUT // Timeout
+            } else if time.0 - client.last_ping > CLIENT_TIMEOUT
-                || network_err.is_err()
+            // Timeout
+            {
+                info!(?entity, "timeout error with client, disconnecting");
+                server_emitter.emit(ServerEvent::ClientDisconnect(entity));
+            } else if network_err.is_err()
             // Postbox error
             {
+                debug!(?entity, "postbox error with client, disconnecting");
                 server_emitter.emit(ServerEvent::ClientDisconnect(entity));
             } else if time.0 - client.last_ping > CLIENT_TIMEOUT * 0.5 {
                 // Try pinging the client if the timeout is nearing.