tracing user

[nicolasauler]

Hi there,

I was wondering if there was any way we could trace the user.
I found this: tokio-rs/axum#1706 and also tried messing with request extensions, but I'm not familiar enough and can't get it to work.

My section of the code that I think would change is:

        .layer(auth_layer)
        .layer(
            ServiceBuilder::new()
                .layer(HandleErrorLayer::new(|error: BoxError| {
                    return async move {
                        if error.is::<Elapsed>() {
                            return Ok(StatusCode::REQUEST_TIMEOUT);
                        }
                        return Err((
                            StatusCode::INTERNAL_SERVER_ERROR,
                            format!("Unhandled internal error: {error}"),
                        ));
                    };
                }))
                .timeout(Duration::from_secs(10))
                .layer(TraceLayer::new_for_http())
                .into_inner(),
        )

I appreciate any help!
Thanks in advance 🙏

[maxcountryman]

Are you hoping to trace the full user as represented by e.g. a Display implementation or would just the ID suffice?

If the latter, I think we could attach that to the trace span in the call method itself: I have #160 open to that end.

[maxcountryman]

That's correct. It's worth pointing out that we already instrument the user ID for the session methods, so subscribing now will give you user ID visibility for those.

[maxcountryman]

#160 is available in 0.13.1 now.

[nicolasauler]

Hey Max and everyone.
Sorry again if it's something obvious that I'm missing, but I've been trying and haven't really been able to solve it on my own.
I noticed that every time authenticate is called, a log is printed with the userid (that's great!).
And I saw that that's because of this:

#[tracing::instrument(level = "debug", skip_all, fields(user.id), ret, err)]
pub async fn authenticate(
    &self,
    creds: Backend::Credentials,
) -> Result<Option<Backend::User>, Error<Backend>> {
    let result = self
        .backend
        .authenticate(creds)
        .await
        .map_err(Error::Backend);

    if let Ok(Some(ref user)) = result {
        tracing::Span::current().record("user.id", user.id().to_string());
    }

    result
}

And I've added the subscriber in:

.with(EnvFilter::try_from_default_env().unwrap_or_else(|_| {
    return "finnish=debug,tower_http=debug,axum::rejection=trace,axum_login=debug,tower_sessions=debug,sqlx=warn".into();
}))

However, I have the following in my TraceLayer config:

.layer(TraceLayer::new_for_http().on_request(
    |request: &Request<_>, _span: &Span| {
        // TODO log user_id if logged in
        tracing::debug!("started {} {}", request.method(), request.uri().path());
    },
))

What do I have to add so I can have the user_id in each request? Instead of only in requests that end up calling authenticate method?

[maxcountryman]

You can take the AuthSession off the request and check if there's a user and then log the request if you like

Or you can use the fact that the user ID is now attached to the span of the axum-login middleware itself to see which user IDs are associated with which requests.

Which you choose will depend on what exactly you intend to do with those logs.

For instance, in the case of the latter you'll only "see" the user ID when there's something for trace to log; i.e. you've sent an info, etc event: at this point you should see the user ID as a field of the call span.

[nicolasauler]

Hmm, are there any examples of this?

[maxcountryman]

Sure, if we were to augment the sqlite example with a diff like this:

diff --git a/examples/sqlite/Cargo.toml b/examples/sqlite/Cargo.toml
index 28d4aaf..9261a74 100644
--- a/examples/sqlite/Cargo.toml
+++ b/examples/sqlite/Cargo.toml
@@ -22,3 +22,4 @@ tower = "0.4.13"
 tracing-subscriber = { version = "0.3.18", features = ["env-filter"] }
 tower-sessions = { version = "0.10.0", default-features = false }
 tower-sessions-sqlx-store = { version = "0.10.0", features = ["sqlite"] }
+tracing = "0.1.40"
diff --git a/examples/sqlite/src/main.rs b/examples/sqlite/src/main.rs
index fbecc40..05acdce 100644
--- a/examples/sqlite/src/main.rs
+++ b/examples/sqlite/src/main.rs
@@ -14,7 +14,11 @@ mod web;
 async fn main() -> Result<(), Box<dyn std::error::Error>> {
     tracing_subscriber::registry()
         .with(EnvFilter::new(std::env::var("RUST_LOG").unwrap_or_else(
-            |_| "axum_login=debug,tower_sessions=debug,sqlx=warn,tower_http=debug".into(),
+            |_| {
+                "example_sqlite=debug,axum_login=debug,tower_sessions=debug,sqlx=warn,\
+                 tower_http=debug"
+                    .into()
+            },
         )))
         .with(tracing_subscriber::fmt::layer())
         .try_init()?;
diff --git a/examples/sqlite/src/web/protected.rs b/examples/sqlite/src/web/protected.rs
index 520f096..d4c10d5 100644
--- a/examples/sqlite/src/web/protected.rs
+++ b/examples/sqlite/src/web/protected.rs
@@ -19,6 +19,8 @@ mod get {
     use super::*;
 
     pub async fn protected(auth_session: AuthSession, messages: Messages) -> impl IntoResponse {
+        tracing::debug!("In protected handler");
+
         match auth_session.user {
             Some(user) => ProtectedTemplate {
                 messages: messages.into_iter().collect(),

Then we'd see output when visiting the protected route that looks something like this:

2024-01-28T22:37:55.588873Z DEBUG call:call{user.id="1"}: example_sqlite::web::protected::get: In protected handler

Note how the user ID is present on the span already.

[nicolasauler]

Max... you're the man!
Thanks a lot!