fix(tracing): actually use span on permissioning (#48)

We were not actually entering the span, so the logs show up pretty empty.

Author: Evalir

src/perms/builders.rs

@@ -20,7 +20,7 @@ fn now() -> u64 {
 }
 
 /// Possible errors when permissioning a builder.
-#[derive(Debug, thiserror::Error, Clone, Copy, PartialEq, Eq)]
+#[derive(Debug, thiserror::Error, Clone, PartialEq, Eq)]
 pub enum BuilderPermissionError {
     /// Action attempt too early.
     #[error("action attempt too early")]
@@ -31,8 +31,10 @@ pub enum BuilderPermissionError {
     ActionAttemptTooLate,
 
     /// Builder not permissioned for this slot.
-    #[error("builder not permissioned for this slot")]
-    NotPermissioned,
+    #[error(
+        "builder not permissioned for this slot: requesting builder {0}, permissioned builder {1}"
+    )]
+    NotPermissioned(String, String),
 }
 
 /// An individual builder.
@@ -178,7 +180,10 @@ impl Builders {
                 permissioned_builder = %self.current_builder().sub,
                 "Builder not permissioned for this slot"
             );
-            return Err(BuilderPermissionError::NotPermissioned);
+            return Err(BuilderPermissionError::NotPermissioned(
+                sub.to_owned(),
+                self.current_builder().sub.to_owned(),
+            ));
         }
 
         Ok(())

src/perms/middleware.rs

@@ -160,25 +160,32 @@ where
                 "builder::permissioning",
                 builder = tracing::field::Empty,
                 permissioned_builder = this.builders.current_builder().sub(),
+                requesting_builder = tracing::field::Empty,
                 current_slot = this.builders.calc().current_slot(),
+                current_timepoint_within_slot =
+                    this.builders.calc().current_timepoint_within_slot(),
                 permissioning_error = tracing::field::Empty,
             );
 
+            let guard = span.enter();
+
             info!("builder permissioning check started");
 
             // Check if the sub is in the header.
             let sub = match validate_header_sub(req.headers().get("x-jwt-claim-sub")) {
                 Ok(sub) => sub,
                 Err(err) => {
-                    info!(api_err = %err.1.message, "permission denied");
                     span.record("permissioning_error", err.1.message);
+                    info!(api_err = %err.1.message, "permission denied");
                     return Ok(err.into_response());
                 }
             };
 
+            span.record("requesting_builder", sub);
+
             if let Err(err) = this.builders.is_builder_permissioned(sub) {
-                info!(api_err = %err, "permission denied");
                 span.record("permissioning_error", err.to_string());
+                info!(api_err = %err, "permission denied");
 
                 let hint = builder_permissioning_hint(&err);
 
@@ -187,6 +194,8 @@ where
 
             info!("builder permissioned successfully");
 
+            drop(guard);
+
             this.inner.call(req).await
         })
     }
@@ -218,7 +227,7 @@ const fn builder_permissioning_hint(
         crate::perms::BuilderPermissionError::ActionAttemptTooLate => {
             Some("Action attempted too late in the slot.")
         }
-        crate::perms::BuilderPermissionError::NotPermissioned => {
+        crate::perms::BuilderPermissionError::NotPermissioned(_, _) => {
             Some("Builder is not permissioned for this slot.")
         }
     }