Add auth{n,z} USDT probes to Nexus (#8566)

Partial fix for #8424

Author: bnaecker

Cargo.lock

@@ -33,6 +33,7 @@ slog.workspace = true
 strum.workspace = true
 thiserror.workspace = true
 tokio = { workspace = true, features = ["full"] }
+usdt.workspace = true
 uuid.workspace = true
 
 authz-macros.workspace = true

nexus/auth/Cargo.toml

@@ -7,6 +7,7 @@
 use super::Details;
 use super::SiloAuthnPolicy;
 use crate::authn;
+use crate::probes;
 use async_trait::async_trait;
 use authn::Reason;
 use slog::trace;
@@ -55,7 +56,10 @@ where
     {
         let log = &rqctx.log;
         let ctx = rqctx.context().borrow();
-        let result = self.authn_request_generic(ctx, log, &rqctx.request).await;
+        let request_id = rqctx.request_id.as_str();
+        let result = self
+            .authn_request_generic(ctx, log, request_id, &rqctx.request)
+            .await;
         trace!(log, "authn result: {:?}", result);
         result
     }
@@ -65,15 +69,25 @@ where
         &self,
         ctx: &T,
         log: &slog::Logger,
+        request_id: &str,
         request: &dropshot::RequestInfo,
     ) -> Result<authn::Context, authn::Error> {
         // For debuggability, keep track of the schemes that we've tried.
         let mut schemes_tried = Vec::with_capacity(self.allowed_schemes.len());
         for scheme_impl in &self.allowed_schemes {
             let scheme_name = scheme_impl.name();
             trace!(log, "authn: trying {:?}", scheme_name);
+            probes::authn__start!(|| {
+                (
+                    request_id,
+                    scheme_name.to_string(),
+                    request.method().to_string(),
+                    request.uri().to_string(),
+                )
+            });
             schemes_tried.push(scheme_name);
             let result = scheme_impl.authn(ctx, log, request).await;
+            probes::authn__done!(|| (request_id, format!("{result:?}")));
             match result {
                 // TODO-security If the user explicitly failed one
                 // authentication scheme (i.e., a signature that didn't match,
@@ -288,6 +302,7 @@ mod test {
             .authn_request_generic(
                 &TestAuthnContext::PolicyNone,
                 &log,
+                "rqid",
                 &dropshot::RequestInfo::new(
                     &request,
                     "0.0.0.0:0".parse().unwrap(),
@@ -310,6 +325,7 @@ mod test {
             .authn_request_generic(
                 &TestAuthnContext::PolicyOk,
                 &log,
+                "rqid",
                 &dropshot::RequestInfo::new(
                     &request,
                     "0.0.0.0:0".parse().unwrap(),
@@ -330,6 +346,7 @@ mod test {
             .authn_request_generic(
                 &TestAuthnContext::PolicyFail,
                 &log,
+                "rqid",
                 &dropshot::RequestInfo::new(
                     &request,
                     "0.0.0.0:0".parse().unwrap(),
@@ -357,6 +374,7 @@ mod test {
             .authn_request_generic(
                 &TestAuthnContext::PolicyNone,
                 &log,
+                "rqid",
                 &dropshot::RequestInfo::new(
                     &request,
                     "0.0.0.0:0".parse().unwrap(),
@@ -381,6 +399,7 @@ mod test {
             .authn_request_generic(
                 &TestAuthnContext::PolicyNone,
                 &log,
+                "rqid",
                 &dropshot::RequestInfo::new(
                     &request,
                     "0.0.0.0:0".parse().unwrap(),
@@ -404,6 +423,7 @@ mod test {
             .authn_request_generic(
                 &TestAuthnContext::PolicyNone,
                 &log,
+                "rqid",
                 &dropshot::RequestInfo::new(
                     &request,
                     "0.0.0.0:0".parse().unwrap(),

nexus/auth/src/authn/external/mod.rs

@@ -8,6 +8,7 @@ use super::authz;
 use crate::authn::ConsoleSessionWithSiloId;
 use crate::authn::external::session_cookie::Session;
 use crate::authz::AuthorizedResource;
+use crate::probes;
 use crate::storage::Storage;
 use chrono::{DateTime, Utc};
 use omicron_common::api::external::Error;
@@ -275,7 +276,23 @@ impl OpContext {
             "action" => ?action,
             "resource" => ?*resource
         );
+        let id = usdt::UniqueId::new();
+        probes::authz__start!(|| {
+            let request_id = self
+                .metadata
+                .get("request_id")
+                .cloned()
+                .unwrap_or_else(|| String::from("none"));
+            (
+                &id,
+                request_id,
+                format!("{:?}", self.authn.actor()),
+                format!("{action:?}"),
+                format!("{resource:?}"),
+            )
+        });
         let result = self.authz.authorize(self, action, resource.clone()).await;
+        probes::authz__done!(|| (&id, format!("{result:?}")));
         debug!(self.log, "authorize result";
             "actor" => ?self.authn.actor(),
             "action" => ?action,

nexus/auth/src/context.rs

@@ -9,3 +9,26 @@ extern crate newtype_derive;
 #[allow(unused_imports)]
 #[macro_use]
 extern crate slog;
+
+#[usdt::provider(provider = "nexus")]
+mod probes {
+    /// Fires just before attempting to authenticate a request using the given
+    /// scheme.
+    fn authn__start(request_id: &str, scheme: &str, method: &str, uri: &str) {}
+
+    /// Fires just after completing the authentication, with the result.
+    fn authn__done(request_id: &str, result: &str) {}
+
+    /// Fires just before attempting to authorize an action on a resource.
+    fn authz__start(
+        id: &usdt::UniqueId,
+        request_id: &str,
+        actor: &str,
+        action: &str,
+        resource: &str,
+    ) {
+    }
+
+    /// Fires just after completing an authorization check on a resource.
+    fn authz__done(id: &usdt::UniqueId, result: &str) {}
+}

nexus/auth/src/lib.rs

@@ -0,0 +1,42 @@
+#!/usr/sbin/dtrace -qZs
+
+/*
+ * This script prints the result of every authentication request. It
+ * includes the scheme, method, URI, duration, and the result of the
+ * authn attempt. Here is an example of the output:
+ * 
+ * scheme=spoof method=DELETE request_id=5fbe4092-1e91-4802-b4ae-0d1c969ed2b7 URI=/v1/disks/disky-mcdiskface?project=springfield-squidport result=Authenticated(Details { actor: Actor::SiloUser { silo_user_id: 001de000-05e4-4000-8000-000000004007, silo_id: 001de000-5110-4000-8000-000000000000, .. } }) duration=24811us
+ * scheme=spoof method=POST request_id=641abbe8-5d16-4f4a-92cf-4b624be557d5 URI=/v1/disks?project=springfield-squidport result=Authenticated(Details { actor: Actor::SiloUser { silo_user_id: 001de000-05e4-4000-8000-000000004007, silo_id: 001de000-5110-4000-8000-000000000000, .. } }) duration=23130us
+ * scheme=spoof method=DELETE request_id=cd21ecb1-0c6b-440d-a2bc-1842121db5bd URI=/v1/disks/disky-mcdiskface?project=springfield-squidport result=Authenticated(Details { actor: Actor::SiloUser { silo_user_id: 001de000-05e4-4000-8000-000000004007, silo_id: 001de000-5110-4000-8000-000000000000, .. } }) duration=20129us
+ */
+
+#pragma D option strsize=4k
+
+nexus*:::authn-start
+{
+        this->rqid = copyinstr(arg0);
+        ts[this->rqid] = timestamp;
+        schemes[this->rqid] = copyinstr(arg1);
+        methods[this->rqid] = copyinstr(arg2);
+        uris[this->rqid] = copyinstr(arg3);
+}
+
+nexus*:::authn-done
+/ts[copyinstr(arg0)]/
+{
+        this->rqid = copyinstr(arg0);
+        this->t = (timestamp - ts[this->rqid]) / 1000;
+        printf(
+            "scheme=%s method=%s request_id=%s URI=%s result=%s duration=%dus\n",
+            schemes[this->rqid],
+            methods[this->rqid],
+            this->rqid,
+            uris[this->rqid],
+            copyinstr(arg1),
+            this->t
+        );
+        ts[this->rqid] = 0;
+        schemes[this->rqid] = 0;
+        methods[this->rqid] = 0;
+        uris[this->rqid] = 0;
+}

tools/dtrace/nexus/trace-authn.d

@@ -0,0 +1,44 @@
+#!/usr/sbin/dtrace -qZs
+
+/*
+ * This script prints the result of every authorization request. It
+ * includes the actor, action, and resource, along with the duration
+ * and result of the authz attempt. Here is an example of the output:
+ *
+ * request_id=none actor=Some(Actor::UserBuiltin { user_builtin_id: 001de000-05e4-4000-8000-000000000003, .. }) action=Query resource=Database result=Ok(()) duration=980us
+ * request_id=none actor=Some(Actor::UserBuiltin { user_builtin_id: 001de000-05e4-4000-8000-000000000002, .. }) action=Query resource=Database result=Ok(()) duration=1067us
+ * request_id=464df995-d044-4c23-a474-3ad3272a0de1 actor=Some(Actor::SiloUser { silo_user_id: 001de000-05e4-4000-8000-000000004007, silo_id: 001de000-5110-4000-8000-000000000000, .. }) action=Query resource=Database result=Ok(()) duration=881us
+ * request_id=none actor=Some(Actor::UserBuiltin { user_builtin_id: 001de000-05e4-4000-8000-000000000002, .. }) action=Query resource=Database result=Ok(()) duration=841us
+ *
+ */
+
+#pragma D option strsize=4k
+
+nexus*:::authz-start
+{
+        ts[arg0] = timestamp;
+        rqids[arg0] = copyinstr(arg1);
+        actors[arg0] = copyinstr(arg2);
+        actions[arg0] = copyinstr(arg3);
+        resources[arg0] = copyinstr(arg4);
+}
+
+nexus*:::authz-done
+/ts[arg0]/
+{
+        t = (timestamp - ts[arg0]);
+        printf(
+            "request_id=%s actor=%s action=%s resource=%s result=%s duration=%dus\n",
+            rqids[arg0],
+            actors[arg0],
+            actions[arg0],
+            resources[arg0],
+            copyinstr(arg1),
+            t / 1000
+        );
+        ts[arg0] = 0;
+        rqids[arg0] = 0;
+        actors[arg0] = 0;
+        actions[arg0] = 0;
+        resources[arg0] = 0;
+}