improvement: consistent log messages for client/sub ids

This commit is contained in:
Greg Heartsfield 2022-12-16 15:22:27 -06:00
parent e554b10ac2
commit 838aafd079
3 changed files with 32 additions and 27 deletions

View File

@ -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(),
);

View File

@ -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");

View File

@ -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,