From 006802454b01f6f20168e55cb2427db7b89039a1 Mon Sep 17 00:00:00 2001
From: Jesse Luehrs <doy@tozt.net>
Date: Thu, 17 Oct 2019 03:58:43 -0400
Subject: improve logging a bit

---
 src/client.rs   | 24 ++++++++++++------------
 src/protocol.rs | 22 +++++++---------------
 src/server.rs   |  7 ++++++-
 3 files changed, 25 insertions(+), 28 deletions(-)

diff --git a/src/client.rs b/src/client.rs
index 26ed108..0fa0254 100644
--- a/src/client.rs
+++ b/src/client.rs
@@ -246,6 +246,8 @@ impl<S: tokio::io::AsyncRead + tokio::io::AsyncWrite + Send + 'static>
     fn handle_successful_connection(&mut self, s: S) -> Result<()> {
         self.last_server_time = std::time::Instant::now();
 
+        log::info!("connected to server");
+
         let (rs, ws) = s.split();
         self.rsock = ReadSocket::Connected(
             crate::protocol::FramedReader::new(rs, self.buffer_size),
@@ -278,7 +280,7 @@ impl<S: tokio::io::AsyncRead + tokio::io::AsyncWrite + Send + 'static>
             >,
         >,
     )> {
-        msg.log("recv");
+        log::debug!("recv_message({})", msg.format_log());
 
         match msg {
             crate::protocol::Message::OauthRequest { url, id } => {
@@ -298,7 +300,8 @@ impl<S: tokio::io::AsyncRead + tokio::io::AsyncWrite + Send + 'static>
                     )?),
                 ))
             }
-            crate::protocol::Message::LoggedIn { .. } => {
+            crate::protocol::Message::LoggedIn { username } => {
+                log::info!("successfully logged into server as {}", username);
                 self.reset_reconnect_timer();
                 for msg in &self.on_login {
                     self.to_send.push_back(msg.clone());
@@ -447,10 +450,7 @@ impl<S: tokio::io::AsyncRead + tokio::io::AsyncWrite + Send + 'static>
                     return Ok(crate::component_future::Poll::NotReady);
                 }
                 Err(e) => {
-                    log::debug!(
-                        "error while connecting, reconnecting: {}",
-                        e
-                    );
+                    log::warn!("error while connecting, reconnecting: {}", e);
                     self.reconnect();
                     // not sending a disconnect event here because we never
                     // actually connected, so it'd just be spammy
@@ -460,7 +460,7 @@ impl<S: tokio::io::AsyncRead + tokio::io::AsyncWrite + Send + 'static>
                 if self.has_seen_server_recently() {
                     return Ok(crate::component_future::Poll::NothingToDo);
                 } else {
-                    log::debug!(
+                    log::warn!(
                         "haven't seen server in a while, reconnecting",
                     );
                     self.reconnect();
@@ -506,7 +506,7 @@ impl<S: tokio::io::AsyncRead + tokio::io::AsyncWrite + Send + 'static>
                             Ok(poll)
                         }
                         Err(e) => {
-                            log::debug!(
+                            log::warn!(
                                 "error handling message, reconnecting: {}",
                                 e
                             );
@@ -521,7 +521,7 @@ impl<S: tokio::io::AsyncRead + tokio::io::AsyncWrite + Send + 'static>
                     Ok(crate::component_future::Poll::NotReady)
                 }
                 Err(e) => {
-                    log::debug!("error reading message, reconnecting: {}", e);
+                    log::warn!("error reading message, reconnecting: {}", e);
                     self.reconnect();
                     Ok(crate::component_future::Poll::Event(
                         Event::Disconnect,
@@ -545,7 +545,7 @@ impl<S: tokio::io::AsyncRead + tokio::io::AsyncWrite + Send + 'static>
                     Ok(crate::component_future::Poll::NotReady)
                 }
                 Err(e) => {
-                    log::debug!(
+                    log::warn!(
                         "error processing message, reconnecting: {}",
                         e
                     );
@@ -575,7 +575,7 @@ impl<S: tokio::io::AsyncRead + tokio::io::AsyncWrite + Send + 'static>
                     WriteSocket::NotConnected,
                 ) {
                     let msg = self.to_send.pop_front().unwrap();
-                    msg.log("send");
+                    log::debug!("send_message({})", msg.format_log());
                     let fut = msg.write_async(s);
                     self.wsock = WriteSocket::Writing(Box::new(fut));
                 } else {
@@ -593,7 +593,7 @@ impl<S: tokio::io::AsyncRead + tokio::io::AsyncWrite + Send + 'static>
                     Ok(crate::component_future::Poll::NotReady)
                 }
                 Err(e) => {
-                    log::debug!("error writing message, reconnecting: {}", e);
+                    log::warn!("error writing message, reconnecting: {}", e);
                     self.reconnect();
                     Ok(crate::component_future::Poll::Event(
                         Event::Disconnect,
diff --git a/src/protocol.rs b/src/protocol.rs
index 324fffd..d574f26 100644
--- a/src/protocol.rs
+++ b/src/protocol.rs
@@ -347,25 +347,17 @@ impl Message {
     // it'd be nice if i could just override the Debug implementation for
     // specific enum variants, but writing the whole impl Debug by hand just
     // to make this one change would be super obnoxious
-    pub fn log(&self, id: &str) {
+    pub fn format_log(&self) -> String {
         match self {
             Self::TerminalOutput { data } => {
-                log::debug!(
-                    "{}: message(TerminalOutput {{ data: ({} bytes) }})",
-                    id,
-                    data.len()
-                );
+                format!("TerminalOutput {{ data: ({} bytes) }}", data.len())
             }
+
             // these are security-sensitive, keep them out of logs
-            Self::OauthRequest { .. } => {
-                log::debug!("{}: message(OauthRequest {{ .. }})", id);
-            }
-            Self::OauthResponse { .. } => {
-                log::debug!("{}: message(OauthResponse {{ .. }})", id);
-            }
-            message => {
-                log::debug!("{}: message({:?})", id, message);
-            }
+            Self::OauthRequest { .. } => format!("OauthRequest {{ .. }})"),
+            Self::OauthResponse { .. } => format!("OauthResponse {{ .. }})"),
+
+            _ => format!("{:?}", self),
         }
     }
 }
diff --git a/src/server.rs b/src/server.rs
index 0116fff..b760812 100644
--- a/src/server.rs
+++ b/src/server.rs
@@ -792,7 +792,7 @@ impl<S: tokio::io::AsyncRead + tokio::io::AsyncWrite + Send + 'static>
             }
         }
 
-        message.log(&conn.id);
+        log::debug!("{}: recv({})", conn.id, message.format_log());
 
         match conn.state {
             ConnectionState::Accepted { .. } => {
@@ -883,6 +883,11 @@ impl<S: tokio::io::AsyncRead + tokio::io::AsyncWrite + Send + 'static>
                 if let Some(msg) = conn.to_send.pop_front() {
                     if let Some(WriteSocket::Connected(s)) = conn.wsock.take()
                     {
+                        log::debug!(
+                            "{}: send({})",
+                            conn.id,
+                            msg.format_log()
+                        );
                         let fut = msg
                             .write_async(s)
                             .timeout(self.read_timeout)
-- 
cgit v1.2.3-54-g00ecf