Improve server logging and use central player id counter (close #450)

7 files changed, 78 insertions, 61 deletions

diff --git a/server/src/entity/bot.rs b/server/src/entity/bot.rs
index 26ae77a6..78b300b6 100644
--- a/server/src/entity/bot.rs
+++ b/server/src/entity/bot.rs
@@ -19,8 +19,8 @@ use super::{Entity, EntityContext};
 use anyhow::Result;
 use hurrycurry_bot::{BotAlgo, DynBotAlgo};
 use hurrycurry_protocol::{Character, Hand, PacketS, PlayerClass, PlayerID};
-use log::info;
-use std::{any::Any, random::random};
+use log::debug;
+use std::any::Any;
 
 pub type DynBotDriver = BotDriver<DynBotAlgo>;
 
@@ -49,8 +49,8 @@ impl<T: BotAlgo + Any> Entity for BotDriver<T> {
     }
     fn tick(&mut self, c: EntityContext<'_>) -> Result<()> {
         if let Some((name, character, class)) = self.join_data.take() {
-            self.id = PlayerID(random(..)); // TODO bad code, can collide
-            info!("spawn {:?} ({name:?})", self.id);
+            self.id = c.game.get_unused_player_id(); // TODO clashes when multiple bots join in the same tick
+            debug!("join {}", self.id);
             c.packet_in.push_back(PacketS::Join {
                 name,
                 character,
@@ -62,7 +62,7 @@ impl<T: BotAlgo + Any> Entity for BotDriver<T> {
 
         let input = self.algo.tick(self.id, c.game, c.dt);
         if input.leave {
-            info!("leave {:?}", self.id);
+            debug!("leave {}", self.id);
             c.packet_in.push_back(PacketS::Leave { player: self.id });
             self.left = true;
             return Ok(());
diff --git a/server/src/entity/pedestrians.rs b/server/src/entity/pedestrians.rs
index cc5d6d90..edfe5ca3 100644
--- a/server/src/entity/pedestrians.rs
+++ b/server/src/entity/pedestrians.rs
@@ -38,8 +38,9 @@ impl Entity for Pedestrians {
     fn tick(&mut self, c: EntityContext<'_>) -> Result<()> {
         self.cooldown -= c.dt;
         if self.cooldown <= 0. && self.players.len() < 32 {
-            let id = PlayerID(random(..));
+            let id = c.game.get_unused_player_id();
             c.packet_in.push_back(PacketS::Join {
+                id: Some(id),
                 name: "Pedestrian".to_string(),
                 character: Character {
                     color: random(..),
@@ -47,7 +48,6 @@ impl Entity for Pedestrians {
                     headwear: 0,
                 },
                 class: PlayerClass::Customer,
-                id: Some(id),
                 position: self.points.first().copied(),
             });
             self.players.insert(id, 0);
diff --git a/server/src/entity/tram.rs b/server/src/entity/tram.rs
index 391d16a9..2d6aa8c1 100644
--- a/server/src/entity/tram.rs
+++ b/server/src/entity/tram.rs
@@ -1,5 +1,3 @@
-use std::random::random;
-
 /*
     Hurry Curry! - a game about cooking
     Copyright (C) 2025 Hurry Curry! Contributors
@@ -36,18 +34,16 @@ impl Entity for Tram {
         false
     }
     fn tick(&mut self, c: EntityContext<'_>) -> Result<()> {
-        if self.ids.is_empty() {
-            for i in 0..self.length {
-                let id = PlayerID(random(..));
-                c.packet_in.push_back(PacketS::Join {
-                    name: format!("Tram {i}"),
-                    character: self.character,
-                    class: PlayerClass::Tram,
-                    id: Some(id),
-                    position: self.points.first().copied(),
-                });
-                self.ids.push(id);
-            }
+        if self.ids.len() < self.length {
+            let id = c.game.get_unused_player_id();
+            c.packet_in.push_back(PacketS::Join {
+                id: Some(id),
+                name: format!("Tram {}", self.ids.len()),
+                character: self.character,
+                class: PlayerClass::Tram,
+                position: self.points.first().copied(),
+            });
+            self.ids.push(id);
         }
 
         for (i, id) in self.ids.iter().enumerate() {
diff --git a/server/src/lib.rs b/server/src/lib.rs
index 2d3a62cc..b29de4f4 100644
--- a/server/src/lib.rs
+++ b/server/src/lib.rs
@@ -25,11 +25,17 @@ pub mod server;
 pub mod state;
 
 use hurrycurry_protocol::glam::Vec2;
-use std::random::random;
+use std::{fmt::Display, random::random};
 
 #[derive(Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Hash)]
 pub struct ConnectionID(pub i64);
 
+impl Display for ConnectionID {
+    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+        write!(f, "conn({})", self.0)
+    }
+}
+
 pub trait InterpolateExt {
     fn exp_to(&mut self, target: Self, dt: f32);
 }
diff --git a/server/src/main.rs b/server/src/main.rs
index 93147d45..b5db4859 100644
--- a/server/src/main.rs
+++ b/server/src/main.rs
@@ -199,7 +199,7 @@ async fn run(data_path: PathBuf, args: Args) -> anyhow::Result<()> {
             warn!("Invalid ws handshake");
             continue;
         };
-        info!("{addr} connected via websocket");
+        info!("{id} Client connected ({addr})");
 
         let (mut write, mut read) = sock.split();
         let state = state.clone();
@@ -219,7 +219,7 @@ async fn run(data_path: PathBuf, args: Args) -> anyhow::Result<()> {
                     ))
                     .await
                 {
-                    warn!("WebSocket error when sending initial packets: {e}");
+                    warn!("{id} WebSocket error when sending initial packets: {e}");
                     return;
                 }
             }
@@ -229,7 +229,7 @@ async fn run(data_path: PathBuf, args: Args) -> anyhow::Result<()> {
                         Ok(e) => e,
                         Err(e) => {
                             rx = rx.resubscribe();
-                            warn!("Client was lagging; resubscribed: {e}");
+                            warn!("{id} Client was lagging; resubscribed: {e}");
                             PacketC::ServerMessage {
                                 message: trm!("s.state.overflow_resubscribe"),
                                 error: true,
@@ -238,7 +238,7 @@ async fn run(data_path: PathBuf, args: Args) -> anyhow::Result<()> {
                    }),
                    p = error_rx.recv() => p
                 ) else {
-                    info!("Client outbound sender dropped. closing connection");
+                    info!("{id} Client outbound sender dropped. closing connection");
                     break;
                 };
                 // let message = if supports_binary.load(Ordering::Relaxed) {
@@ -251,20 +251,19 @@ async fn run(data_path: PathBuf, args: Args) -> anyhow::Result<()> {
                 let message = Message::Text(serde_json::to_string(&packet).unwrap().into());
                 // };
                 if let Err(e) = write.send(message).await {
-                    warn!("WebSocket error: {e}");
+                    warn!("{id} WebSocket error: {e}");
                     break;
                 }
             }
         });
 
         spawn(async move {
-            info!("{id:?} connected");
             while let Some(Ok(message)) = read.next().await {
                 let packet = match message {
                     Message::Text(line) if line.len() < 8196 => match serde_json::from_str(&line) {
                         Ok(p) => p,
                         Err(e) => {
-                            warn!("Invalid json packet: {e}");
+                            warn!("{id} Invalid json packet: {e}");
                             break;
                         }
                     },
@@ -287,9 +286,9 @@ async fn run(data_path: PathBuf, args: Args) -> anyhow::Result<()> {
                     packet,
                     PacketS::Movement { .. } | PacketS::ReplayTick { .. }
                 ) {
-                    trace!("<- {id:?} {packet:?}");
+                    trace!("{id} <- {packet:?}");
                 } else {
-                    debug!("<- {id:?} {packet:?}");
+                    debug!("{id} <- {packet:?}");
                 }
                 let packet_out = match state.write().await.packet_in_outer(id, packet).await {
                     Ok(packets) => packets,
@@ -305,7 +304,7 @@ async fn run(data_path: PathBuf, args: Args) -> anyhow::Result<()> {
                     let _ = error_tx.send(packet).await;
                 }
             }
-            info!("{id:?} disconnected");
+            info!("{id} Client disconnected");
             let _ = state.write().await.disconnect(id).await;
         });
     }
diff --git a/server/src/server.rs b/server/src/server.rs
index 9141bc4e..2c01b496 100644
--- a/server/src/server.rs
+++ b/server/src/server.rs
@@ -25,7 +25,11 @@ use crate::{
 use anyhow::{Context, Result};
 use hurrycurry_client_lib::{Game, Involvement, Item, Player, Tile, gamedata_index::GamedataIndex};
 use hurrycurry_data::{Serverdata, index::DataIndex};
-use hurrycurry_locale::{TrError, tre};
+use hurrycurry_locale::{
+    FALLBACK_LOCALE, TrError,
+    message::{COLORED, MessageDisplayExt},
+    tre,
+};
 use hurrycurry_protocol::{
     Character, Gamedata, Hand, ItemLocation, Menu, MessageTimeout, PacketC, PacketS, PlayerClass,
     PlayerID, Score, TileIndex,
@@ -64,7 +68,6 @@ pub struct Server {
 
     pub data: Arc<Serverdata>,
     pub entities: Entities,
-    pub player_id_counter: PlayerID,
     pub score_changed: bool,
     pub packet_loopback: VecDeque<PacketS>,
     pub last_movement_update: HashMap<PlayerID, Instant>,
@@ -345,7 +348,6 @@ impl Server {
             data: Serverdata::default().into(),
             gamedata_index: GamedataIndex::default(),
             entities: Vec::new(),
-            player_id_counter: PlayerID(1),
             score_changed: false,
             packet_loopback: VecDeque::new(),
             last_movement_update: HashMap::default(),
@@ -412,6 +414,7 @@ impl Server {
 
     pub fn packet_in(
         &mut self,
+        conn: Option<ConnectionID>,
         packet: PacketS,
         replies: &mut Vec<PacketC>,
     ) -> Result<(), TrError> {
@@ -419,9 +422,9 @@ impl Server {
             PacketS::Join {
                 name,
                 character,
-                id,
                 class,
                 position,
+                id,
             } => {
                 if name.chars().count() > 32 || name.len() > 64 {
                     return Err(tre!(
@@ -433,13 +436,10 @@ impl Server {
                 if self.game.players.len() > 64 {
                     return Err(tre!("s.error.too_many_players"));
                 }
-                let id = id.unwrap_or_else(|| {
-                    let id = self.player_id_counter;
-                    self.player_id_counter.0 += 1;
-                    id
-                });
+
+                let player = id.unwrap_or_else(|| self.game.get_unused_player_id());
                 self.game.join_player(
-                    id,
+                    player,
                     name,
                     character,
                     class,
@@ -447,9 +447,19 @@ impl Server {
                     position,
                     Some(&mut self.packet_out),
                 );
-                replies.push(PacketC::Joined { id })
+                if let Some(conn) = conn {
+                    info!("{conn} join {player}");
+                } else {
+                    info!("server join {player}");
+                }
+                replies.push(PacketC::Joined { id: player })
             }
             PacketS::Leave { player } => {
+                if let Some(conn) = conn {
+                    info!("{conn} leave {player}");
+                } else {
+                    info!("server leave {player}");
+                }
                 let p = self
                     .game
                     .players
@@ -640,23 +650,28 @@ impl Server {
                 player,
                 pin,
             } => {
-                info!("{player:?} message {message:?}");
+                if let Some(message) = &message {
+                    info!(
+                        "{player} message {}",
+                        message.display_message(&FALLBACK_LOCALE, &self.game.data, &COLORED)
+                    );
+                } else {
+                    info!("{player} clear message");
+                }
                 let pin = pin.unwrap_or(false);
-                let timeout = if let Some(timeout) = timeout {
-                    if let Some(player) = self.game.players.get_mut(&player) {
-                        let mut timeout = MessageTimeout {
-                            initial: timeout,
-                            remaining: timeout,
-                            pinned: pin,
-                        };
-                        if let Some((_, t)) = &player.communicate_persist {
-                            timeout.initial = t.initial;
-                        };
-                        player.communicate_persist = message.clone().map(|m| (m, timeout));
-                        Some(timeout)
-                    } else {
-                        None
-                    }
+                let timeout = if let Some(timeout) = timeout
+                    && let Some(player) = self.game.players.get_mut(&player)
+                {
+                    let mut timeout = MessageTimeout {
+                        initial: timeout,
+                        remaining: timeout,
+                        pinned: pin,
+                    };
+                    if let Some((_, t)) = &player.communicate_persist {
+                        timeout.initial = t.initial;
+                    };
+                    player.communicate_persist = message.clone().map(|m| (m, timeout));
+                    Some(timeout)
                 } else {
                     None
                 };
@@ -776,6 +791,7 @@ impl Server {
         }
         for (player, hand) in players_auto_release.drain(..) {
             let _ = self.packet_in(
+                None,
                 PacketS::Interact {
                     pos: None,
                     player,
@@ -825,7 +841,7 @@ impl Server {
         }
 
         while let Some(p) = self.packet_loopback.pop_front() {
-            if let Err(e) = self.packet_in(p, &mut vec![]) {
+            if let Err(e) = self.packet_in(None, p, &mut vec![]) {
                 warn!("Internal packet errored: {e}");
             }
         }
diff --git a/server/src/state.rs b/server/src/state.rs
index 49b2467a..dfd788ec 100644
--- a/server/src/state.rs
+++ b/server/src/state.rs
@@ -142,7 +142,7 @@ impl Server {
             }
             _ => (),
         }
-        self.packet_in(packet, &mut replies)?;
+        self.packet_in(Some(conn), packet, &mut replies)?;
 
         for p in &replies {
             if let PacketC::Joined { id } = p {