From 3f5ae51a4129e5d0f401dd9015d5dfd4da14c300 Mon Sep 17 00:00:00 2001 From: Joscha Date: Sat, 21 Jan 2023 13:46:24 +0100 Subject: [PATCH] Add debug logging to connection --- CHANGELOG.md | 1 + Cargo.toml | 1 + src/conn.rs | 26 +++++++++++++++++++++++--- 3 files changed, 25 insertions(+), 3 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index f8a0a64..6a704fd 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -19,6 +19,7 @@ Procedure when bumping the version number: - Finding, replacing and removing emoji in text - `State` conversion utility methods - `Time::new` constructor +- Debug logging using the `log` crate ### Changed - Rewrite `conn` module (backwards-imcompatible) diff --git a/Cargo.toml b/Cargo.toml index e34e623..2b3213f 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -8,6 +8,7 @@ bot = [] [dependencies] futures-util = { version = "0.3.25", default-features = false, features = ["sink"] } +log = "0.4.17" serde = { version = "1.0.149", features = ["derive"] } serde_json = "1.0.89" time = { version = "0.3.17", features = ["serde"] } diff --git a/src/conn.rs b/src/conn.rs index d6998eb..f8829a3 100644 --- a/src/conn.rs +++ b/src/conn.rs @@ -8,6 +8,7 @@ use std::{error, fmt, result}; use ::time::OffsetDateTime; use futures_util::SinkExt; +use log::debug; use tokio::net::TcpStream; use tokio::select; use tokio::sync::{mpsc, oneshot}; @@ -170,20 +171,24 @@ impl Joined { fn on_data(&mut self, data: &Data) { match data { Data::JoinEvent(p) => { + debug!("Updating listing after join-event"); self.listing .insert(p.0.session_id.clone(), SessionInfo::Full(p.0.clone())); } Data::SendEvent(p) => { + debug!("Updating listing after send-event"); self.listing.insert( p.0.sender.session_id.clone(), SessionInfo::Full(p.0.sender.clone()), ); } Data::PartEvent(p) => { + debug!("Updating listing after part-event"); self.listing.remove(&p.0.session_id); } Data::NetworkEvent(p) => { if p.r#type == "partition" { + debug!("Updating listing after network-event with type partition"); self.listing.retain(|_, s| match s { SessionInfo::Full(s) => { s.server_id != p.server_id && s.server_era != p.server_era @@ -203,6 +208,7 @@ impl Joined { } } Data::NickEvent(p) => { + debug!("Updating listing after nick-event"); self.listing .entry(p.session_id.clone()) .and_modify(|s| match s { @@ -212,6 +218,7 @@ impl Joined { .or_insert_with(|| SessionInfo::Partial(p.clone())); } Data::NickReply(p) => { + debug!("Updating own session after nick-reply"); assert_eq!(self.session.id, p.id); self.session.name = p.to.clone(); } @@ -400,7 +407,9 @@ impl Conn { let msg = msg.ok_or(Error::ConnectionClosed)??; match msg { tungstenite::Message::Text(text) => { - let packet = ParsedPacket::from_packet(serde_json::from_str(&text)?)?; + let packet = serde_json::from_str(&text)?; + debug!("Received {packet:?}"); + let packet = ParsedPacket::from_packet(packet)?; self.on_packet(&packet).await?; return Ok(Some(packet)); } @@ -422,6 +431,7 @@ impl Conn { async fn on_packet(&mut self, packet: &ParsedPacket) -> Result<()> { // Complete pending replies if the packet has an id if let Some(id) = &packet.id { + debug!("Resolving pending reply for id {id}"); self.replies.complete(id, packet.clone()); } @@ -490,11 +500,15 @@ impl Conn { } async fn on_ping(&mut self) -> Result<()> { + debug!("Checking ping replies and sending new pings"); + // Check previous pings if self.last_ws_ping_payload.is_some() && !self.last_ws_ping_replied_to { + debug!("Server did not respond to websocket ping, disconnecting"); self.disconnect().await?; } if self.last_euph_ping_payload.is_some() && !self.last_euph_ping_replied_to { + debug!("Server did not respond to euph ping, disconnecting"); self.disconnect().await?; } @@ -533,6 +547,7 @@ impl Conn { throttled: None, } .into_packet()?; + debug!("Sending {packet:?}"); let msg = tungstenite::Message::Text(serde_json::to_string(&packet)?); self.ws.send(msg).await?; @@ -550,6 +565,7 @@ impl Conn { throttled: None, } .into_packet()?; + debug!("Sending {packet:?}"); let msg = tungstenite::Message::Text(serde_json::to_string(&packet)?); self.ws.send(msg).await?; @@ -558,7 +574,9 @@ impl Conn { } async fn disconnect(&mut self) -> Result { + // TODO Maybe timeout this let _ = self.ws.close(None).await; + debug!("Closed connection gracefully"); Err(Error::ConnectionClosed) } @@ -591,6 +609,7 @@ impl Conn { ) -> tungstenite::Result<(Self, Vec)> { let human = if human { "?h=1" } else { "" }; let uri = format!("wss://{domain}/room/{room}/ws{human}"); + debug!("Connecting to {uri} with cookies: {cookies:?}"); let mut request = uri.into_client_request().expect("valid request"); if let Some(cookies) = cookies { request.headers_mut().append(header::COOKIE, cookies); @@ -598,11 +617,12 @@ impl Conn { let (ws, response) = tokio_tungstenite::connect_async(request).await?; let (mut parts, _) = response.into_parts(); - let set_cookies = match parts.headers.entry(header::SET_COOKIE) { + let cookies_set = match parts.headers.entry(header::SET_COOKIE) { header::Entry::Occupied(entry) => entry.remove_entry_mult().1.collect(), header::Entry::Vacant(_) => vec![], }; + debug!("Received cookies {cookies_set:?}"); let rx = Self::wrap(ws, timeout); - Ok((rx, set_cookies)) + Ok((rx, cookies_set)) } }