From 9c2825b9dc0ff894cf0f5122b1098d2f8170b9b6 Mon Sep 17 00:00:00 2001
From: Firstyear <william@blackhats.net.au>
Date: Wed, 5 Feb 2025 11:33:30 +1000
Subject: [PATCH] Improve spans in unixd (#3397)

Some areas of the code were emitting 0 uuids, rather than associating
a client/connection uuid. This improves the startup and client handling
code so that we have stable uuids present during operation.
---
 .../resolver/src/bin/kanidm_unixd.rs          | 25 ++++++++++++++++---
 1 file changed, 21 insertions(+), 4 deletions(-)

diff --git a/unix_integration/resolver/src/bin/kanidm_unixd.rs b/unix_integration/resolver/src/bin/kanidm_unixd.rs
index 414554488..2ce34edad 100644
--- a/unix_integration/resolver/src/bin/kanidm_unixd.rs
+++ b/unix_integration/resolver/src/bin/kanidm_unixd.rs
@@ -197,7 +197,10 @@ async fn handle_client(
     cachelayer: Arc<Resolver>,
     task_channel_tx: &Sender<AsyncTaskRequest>,
 ) -> Result<(), Box<dyn Error>> {
-    debug!("Accepted connection");
+    let conn_id = uuid::Uuid::new_v4();
+
+    let span = span!(Level::DEBUG, "accepted connection", uuid = %conn_id);
+    let _enter = span.enter();
 
     let Ok(ucred) = sock.peer_cred() else {
         return Err(Box::new(IoError::new(
@@ -206,6 +209,8 @@ async fn handle_client(
         )));
     };
 
+    debug!(uid = ?ucred.uid(), gid = ?ucred.gid(), pid = ?ucred.pid());
+
     let mut reqs = Framed::new(sock, ClientCodec);
     let mut pam_auth_session_state = None;
 
@@ -213,9 +218,12 @@ async fn handle_client(
     // tell consumers to stop work.
     let (shutdown_tx, _shutdown_rx) = broadcast::channel(1);
 
-    trace!("Waiting for requests ...");
+    debug!("Waiting for requests ...");
+    // Drop the span here so that there are no parent spans during the request loop.
+    drop(_enter);
+
     while let Some(Ok(req)) = reqs.next().await {
-        let span = span!(Level::DEBUG, "client_request");
+        let span = span!(Level::INFO, "client request", uuid = %conn_id);
         let _enter = span.enter();
 
         let resp = match req {
@@ -405,7 +413,10 @@ async fn handle_client(
     }
 
     // Disconnect them
-    debug!("Disconnecting client ...");
+    let span = span!(Level::DEBUG, "disconnecting client", uuid = %conn_id);
+    let _enter = span.enter();
+    debug!(uid = ?ucred.uid(), gid = ?ucred.gid(), pid = ?ucred.pid());
+
     Ok(())
 }
 
@@ -595,6 +606,9 @@ async fn main() -> ExitCode {
             )
         )
         .on(async {
+            let span = span!(Level::DEBUG, "starting resolver");
+            let _enter = span.enter();
+
             if clap_args.get_flag("skip-root-check") {
                 warn!("Skipping root user check, if you're running this for testing, ensure you clean up temporary files.")
                 // TODO: this wording is not great m'kay.
@@ -1165,6 +1179,9 @@ async fn main() -> ExitCode {
 
             info!("Server started ...");
 
+            // End the startup span, we can now proceed.
+            drop(_enter);
+
             // On linux, notify systemd.
             #[cfg(target_os = "linux")]
             let _ = sd_notify::notify(true, &[sd_notify::NotifyState::Ready]);