feat: add debug-level per-op, session and link metrics

src/rns.rs

@@ -280,6 +280,7 @@ extern "C" fn smolmail_rns_on_link_opened(link_id: *const u8) -> i32 {
         return 1;
     }
     links.insert(link);
+    log::debug!("link {} opened ({} open)", data_encoding::HEXLOWER.encode(&link), links.len());
     0
 }
 
@@ -289,6 +290,7 @@ extern "C" fn smolmail_rns_on_link_closed(link_id: *const u8) {
         let link: [u8; 16] = unsafe { std::slice::from_raw_parts(link_id, 16).try_into().unwrap() };
         state.links.lock().unwrap().remove(&link);
         state.sessions.lock().unwrap().remove(&link);
+        log::debug!("link {} closed", data_encoding::HEXLOWER.encode(&link));
     }
 }
 

src/server.rs

@@ -103,6 +103,7 @@ fn handle_connection(
 ) -> anyhow::Result<()> {
     stream.set_read_timeout(Some(Duration::from_secs(IDLE_TIMEOUT_SECS)))?;
 
+    let handshake_started = std::time::Instant::now();
     let (transport, handshake_hash) = match handshake(&mut stream, static_key) {
         Ok(v) => v,
         Err(e) => {
@@ -110,6 +111,17 @@ fn handle_connection(
             return Ok(());
         }
     };
+    log::debug!(
+        "handshake from {peer_ip} in {:?}",
+        handshake_started.elapsed()
+    );
+
+    // Drop logs the summary once, whatever return path closes the session.
+    let summary = SessionSummary {
+        peer_ip,
+        started: std::time::Instant::now(),
+        ops: std::cell::Cell::new(0),
+    };
 
     let store = Store::open(db_path)?;
     let server_static = derive_public(static_key);
@@ -129,6 +141,7 @@ fn handle_connection(
                 return Ok(());
             }
         };
+        summary.ops.set(summary.ops.get() + 1);
 
         let (status, payload) = session.dispatch(op, &body);
         let mut response = Vec::with_capacity(1 + payload.len());
@@ -140,6 +153,23 @@ fn handle_connection(
     }
 }
 
+struct SessionSummary<'a> {
+    peer_ip: &'a str,
+    started: std::time::Instant,
+    ops: std::cell::Cell<u64>,
+}
+
+impl Drop for SessionSummary<'_> {
+    fn drop(&mut self) {
+        log::debug!(
+            "session {} closed: {} op(s) in {:?}",
+            self.peer_ip,
+            self.ops.get(),
+            self.started.elapsed()
+        );
+    }
+}
+
 fn is_eof_like(e: &anyhow::Error) -> bool {
     if let Some(io_err) = e.downcast_ref::<std::io::Error>() {
         return matches!(

src/session.rs

@@ -44,6 +44,19 @@ impl From<rusqlite::Error> for HandlerError {
 
 type OpResult = Result<(u8, Vec<u8>), HandlerError>;
 
+/// Wire op byte to log name; unknown bytes are logged as dispatched too.
+fn op_name(op: u8) -> &'static str {
+    match op {
+        OP_AUTH => "AUTH",
+        OP_RESOLVE => "RESOLVE",
+        OP_SEND => "SEND",
+        OP_FETCH => "FETCH",
+        OP_DELETE => "DELETE",
+        OP_REGISTER => "REGISTER",
+        _ => "UNKNOWN",
+    }
+}
+
 pub struct Session<'a> {
     config: &'a ServerConfig,
     store: Store,
@@ -72,7 +85,25 @@ impl<'a> Session<'a> {
     /// panicking or propagating errors to the caller: a bad frame or a
     /// storage error both become a response, and the caller decides
     /// separately whether to keep the connection open.
+    ///
+    /// Timing lives in this wrapper because both carriers dispatch through
+    /// it, so the metrics flag covers TCP and RNS from one place.
     pub fn dispatch(&mut self, op: u8, body: &[u8]) -> (u8, Vec<u8>) {
+        let started = std::time::Instant::now();
+        let (status, payload) = self.dispatch_op(op, body);
+        log::debug!(
+            "op {} from {} in {:?}: status {}, {}B request, {}B response",
+            op_name(op),
+            self.peer_ip,
+            started.elapsed(),
+            status,
+            body.len(),
+            payload.len()
+        );
+        (status, payload)
+    }
+
+    fn dispatch_op(&mut self, op: u8, body: &[u8]) -> (u8, Vec<u8>) {
         if matches!(op, OP_FETCH | OP_DELETE) && self.username.is_none() {
             return (AUTH_REQUIRED, Vec::new());
         }