#[instrument] - must refer to _self instead of self when instrumenting an async-trait instance method

[kaitlinsm]

Bug Report

Version

tracing v0.1.16
tracing-attributes v0.1.9
tracing-core v0.1.11

Platform

n/a

Description

I have a struct SomeStruct with one important method that I care about when tracing/logging:

struct SomeStruct {
}

impl SomeStruct {
    pub fn get_value() -> String {
        "some important string I need to log/trace".to_string()
    }
}

I need to implement an async-trait method that needs instrumentation. In this case, since it's a method, the first argument is self. I want to use instrument on this method.

I cannot refer to self when setting fields() in the #[instrument()] proc macro. The instrument macro re-writes self as _self (and then back again, I think).

I can successfully use _self.get_value(), but this is a bit weird looking as it's not immediately obvious what _self is.

For an example, the code below currently works:

#[async_trait]
impl SomeTrait for SomeStruct {

    #[instrument(fields(traceId = %_self.get_value()), skip(self))]
    async fn do_magic(&self, some_arg: &str) -> Result<()> {
    [...]
    }
}

It would be nice to be able to refer to self instead of _self, if at all possible.

cheers bigears x

[hawkw]

Yup, this is because async-trait renames the self value to _self, and processes the code inside the trait method so that references to self are transformed into _self. However, this doesn't apply to attributes on the function.

We're already detecting when #[instrument] is used on an async-trait method. I think we just need to add a step to process the field expressions and rewrite self as _self when that's the case.

[hawkw]

@nightmared do you have time to take a look at fixing this? Otherwise, I will hopefully get to it eventually.

[nightmared]

After taking a quick look, I believe it's not very easy to do, as _self/self is contained in a arbitrary expression whose form we do not control, as it is supplied by the user. We need to either:
a) replace all instances of _self by self in field.value (the expression provided by the user).
b) insert a fake variable { let self = _self; <FIELDS_CODE> } to make it work nonetheless, but that means you can still use _self, and that's more of a hack than anything else.

I will try to think a little more about it (I started taking a tiny look at it, mainly adding a test for this behavior, master...nightmared:self-instrument-fields) when I have some time (this week-end ?).

[hawkw]

After taking a quick look, I believe it's not very easy to do, as _self/self is contained in a arbitrary expression whose form we do not control, as it is supplied by the user. We need to either:
a) replace all instances of _self by self in field.value (the expression provided by the user).

I think we want to do this one.

I imagine we should be able to use syn::visit_mut to traverse the elements of each field value expr and replace all self idents with _self. I believe we would do this by writing a type implementing the VisitMut trait that overrides the VisitMut::visit_ident_mut method with an implementation that checks if the ident is self and replaces it with _self if it is. The syn docs show an example of how a VisitMut might be used to mutate a block of code.

It looks like async-trait does this slightly differently, by iterating over the whole token stream and replacing any self tokens with _self. But, they also use VisitMut for other replacements. I think what we will need to do is a bit less complicated than async_trait, since we are only preprocessing individual exprs. However, we might also want to handle transforming Self types, etc, in case someone wants to use, say std::any::type_name::<Self>() as a field value.

[nightmared]

Nice, I didn't know about syn::visit_mut. I updated master...nightmared:self-instrument-fields to use that.

The main concern is while this allows to support the following code:

#[instrument(fields(val=self.foo(), test=%v+5))]
async fn foo(&mut self, v: usize) {}

#[instrument(fields(Self=std::any::type_name::<Self>()))]
async fn call_with_self(&self) {}

This one won't work:

#[instrument(fields(Self=std::any::type_name::<Self>()))]
async fn call() {}

Because I'm getting the Self type by reading the type of the _self argument, and I don't think we have any "clean" way of getting that information. I say clean because I believe we could probably still obtain this information through type aliases, declared outside the scope of the function, something like:

type __TRACING_SELF_<RANDOM_VALUE> = Self;
<Current implementation but where Self is replaced in fields by __TRACING_SELF_<RANDOM_VALUE>>

(the random value (could also be a monotonic unique counter) is used to prevent name redefinitions if multiple async functions are annotated in the same impl block)

Do you want me to open a PR or do you think we need to go in another direction in order to achieve this ?

[hawkw]

Because I'm getting the Self type by reading the type of the _self argument, and I don't think we have any "clean" way of getting that information. I say clean because I believe we could probably still obtain this information through type aliases, declared outside the scope of the function, something like:

Hmm...I guess async-trait can handle this case just fine, since its attribute is placed on the trait impl, and it knows the type name of the implementing type from that. Hmm, that's a bummer.

I think the approach you proposed with a type alias is perhaps the best way to make this work, even though it's pretty ugly.

(the random value (could also be a monotonic unique counter) is used to prevent name redefinitions if multiple async functions are annotated in the same impl block)

I wouldn't want to rely on a random value for this, since there is the possibility of collisions...and then the proc macro depends on the rand crate, which we wouldn't otherwise need. I'm also not sure if we can do a monotonic counter easily, though, since it would need to persist across multiple invocations of the instrument macro, and there isn't really any way for a proc macro to persist information between multiple invocations. Here's another idea: could we generate a unique identifier by including the line number of the #[instrument] attribute? Like

type __Tracing_Self_<LINE NUMBER> = Self;

that should be unique within the same impl block, without relying on a random ID.

[nightmared]

I answered in the PR (#875). I'm a bit saddened, as I can't really think of a way to extract that information :(