From 838aafd079171329a08f0d7611029c7d0dc307c7 Mon Sep 17 00:00:00 2001 From: Greg Heartsfield Date: Fri, 16 Dec 2022 15:22:27 -0600 Subject: [PATCH] improvement: consistent log messages for client/sub ids --- src/conn.rs | 15 ++++++++++----- src/db.rs | 16 ++++++++-------- src/server.rs | 28 ++++++++++++++-------------- 3 files changed, 32 insertions(+), 27 deletions(-) diff --git a/src/conn.rs b/src/conn.rs index 71b366d..bd41696 100644 --- a/src/conn.rs +++ b/src/conn.rs @@ -78,8 +78,12 @@ impl ClientConn { // check if an existing subscription exists, and replace if so if self.subscriptions.contains_key(&k) { self.subscriptions.remove(&k); - self.subscriptions.insert(k, s); - debug!("replaced existing subscription"); + self.subscriptions.insert(k, s.clone()); + debug!( + "replaced existing subscription (cid: {}, sub: {:?})", + self.get_client_prefix(), + s.get_id() + ); return Ok(()); } @@ -90,8 +94,9 @@ impl ClientConn { // add subscription self.subscriptions.insert(k, s); debug!( - "registered new subscription, currently have {} active subs", - self.subscriptions.len() + "registered new subscription, currently have {} active subs (cid: {})", + self.subscriptions.len(), + self.get_client_prefix(), ); Ok(()) } @@ -101,7 +106,7 @@ impl ClientConn { // TODO: return notice if subscription did not exist. self.subscriptions.remove(&c.id); debug!( - "removed subscription, currently have {} active subs (cid={})", + "removed subscription, currently have {} active subs (cid: {})", self.subscriptions.len(), self.get_client_prefix(), ); diff --git a/src/db.rs b/src/db.rs index b122995..ae6f077 100644 --- a/src/db.rs +++ b/src/db.rs @@ -632,16 +632,16 @@ pub async fn db_query( // logging for slow queries; show sub and SQL if first_result_elapsed >= slow_cutoff { info!( - "going to query for: {:?} (cid={}, sub={:?})", + "going to query for: {:?} (cid: {}, sub: {:?})", sub, client_id, sub.id ); info!( - "final query string (slow): {} (cid={}, sub={:?})", + "final query string (slow): {} (cid: {}, sub: {:?})", q, client_id, sub.id ); } else { trace!( - "going to query for: {:?} (cid={}, sub={:?})", + "going to query for: {:?} (cid: {}, sub: {:?})", sub, client_id, sub.id @@ -649,7 +649,7 @@ pub async fn db_query( trace!("final query string: {}", q); } debug!( - "time to first result: {:?} (cid={}, sub={:?})", + "first result in {:?} (cid: {}, sub: {:?})", first_result_elapsed, client_id, sub.id ); first_result = false; @@ -657,7 +657,7 @@ pub async fn db_query( // check if this is still active // TODO: check every N rows if abandon_query_rx.try_recv().is_ok() { - debug!("query aborted (sub={:?})", sub.id); + debug!("query aborted (cid: {}, sub: {:?})", client_id, sub.id); return Ok(()); } row_count += 1; @@ -676,11 +676,11 @@ pub async fn db_query( }) .ok(); debug!( - "query completed ({} rows) in {:?} (cid={}, sub={:?})", - row_count, + "query completed in {:?} (cid: {}, sub: {:?}, rows: {})", start.elapsed(), client_id, - sub.id + sub.id, + row_count ); } else { warn!("Could not get a database connection for querying"); diff --git a/src/server.rs b/src/server.rs index c6d569d..5eb4d3b 100644 --- a/src/server.rs +++ b/src/server.rs @@ -466,9 +466,9 @@ async fn nostr_server( // and how many it received from queries. let mut client_published_event_count: usize = 0; let mut client_received_event_count: usize = 0; - debug!("new connection for client: {}, ip: {:?}", cid, conn.ip()); + debug!("new client connection (cid: {}, ip: {:?})", cid, conn.ip()); if let Some(ua) = client_info.user_agent { - debug!("client: {} has user-agent: {:?}", cid, ua); + debug!("cid: {}, user-agent: {:?}", cid, ua); } loop { tokio::select! { @@ -554,17 +554,17 @@ async fn nostr_server( Err(WsError::AlreadyClosed | WsError::ConnectionClosed | WsError::Protocol(tungstenite::error::ProtocolError::ResetWithoutClosingHandshake))) => { - debug!("websocket close from client: {}, ip: {:?}",cid, conn.ip()); + debug!("websocket close from client (cid: {}, ip: {:?})",cid, conn.ip()); break; }, Some(Err(WsError::Io(e))) => { // IO errors are considered fatal - warn!("IO error (client: {}, ip: {:?}): {:?}", cid, conn.ip(), e); + warn!("IO error (cid: {}, ip: {:?}): {:?}", cid, conn.ip(), e); break; } x => { // default condition on error is to close the client connection - info!("unknown error (client: {}, ip: {:?}): {:?} (closing conn)", cid, conn.ip(), x); + info!("unknown error (cid: {}, ip: {:?}): {:?} (closing conn)", cid, conn.ip(), x); break; } }; @@ -579,7 +579,7 @@ async fn nostr_server( match parsed { Ok(e) => { let id_prefix:String = e.id.chars().take(8).collect(); - debug!("successfully parsed/validated event: {:?} from client: {}", id_prefix, cid); + debug!("successfully parsed/validated event: {:?} (cid: {})", id_prefix, cid); // check if the event is too far in the future. if e.is_valid_timestamp(settings.options.reject_future_seconds) { // Write this to the database. @@ -596,13 +596,13 @@ async fn nostr_server( } }, Err(e) => { - info!("client: {} sent an invalid event", cid); + info!("client sent an invalid event (cid: {})", cid); ws_stream.send(make_notice_message(Notice::invalid(evid, &format!("{}", e)))).await.ok(); } } }, Ok(NostrMessage::SubMsg(s)) => { - debug!("client: {} requesting a subscription", cid); + debug!("subscription requested (cid: {}, sub: {:?})", cid, s.id); // subscription handling consists of: // * registering the subscription so future events can be matched // * making a channel to cancel to request later @@ -626,7 +626,7 @@ async fn nostr_server( } } } else { - info!("client send duplicate subscription, ignoring"); + info!("client send duplicate subscription, ignoring (cid: {}, sub: {:?})", cid, s.id); } }, Ok(NostrMessage::CloseMsg(cc)) => { @@ -653,19 +653,19 @@ async fn nostr_server( } }, Err(Error::ConnError) => { - debug!("got connection close/error, disconnecting client: {}, ip: {:?}",cid, conn.ip()); + debug!("got connection close/error, disconnecting cid: {}, ip: {:?}",cid, conn.ip()); break; } Err(Error::EventMaxLengthError(s)) => { - info!("client: {} sent event larger ({} bytes) than max size", cid, s); + info!("client sent event larger ({} bytes) than max size (cid: {})", s, cid); ws_stream.send(make_notice_message(Notice::message("event exceeded max size".into()))).await.ok(); }, Err(Error::ProtoParseError) => { - info!("client {} sent event that could not be parsed", cid); + info!("client sent event that could not be parsed (cid: {})", cid); ws_stream.send(make_notice_message(Notice::message("could not parse command".into()))).await.ok(); }, Err(e) => { - info!("got non-fatal error from client: {}, error: {:?}", cid, e); + info!("got non-fatal error from client (cid: {}, error: {:?}", cid, e); }, } }, @@ -676,7 +676,7 @@ async fn nostr_server( stop_tx.send(()).ok(); } info!( - "stopping connection for client: {}, ip: {:?} (client sent {} event(s), received {})", + "stopping client connection (cid: {}, ip: {:?}, sent: {} events, recv: {} events)", cid, conn.ip(), client_published_event_count,