#[autometrics] does not work well with #[async_trait]

[ragnarula]

When using #[autometrics] to instrument implementations of traits marked with #[async_trait], depending on where you place the macro, either the recorded duration is incorrect or it does not compile.

#[async_trait] is widely used and it would be helpful if it was at least documented that they can't work together.

Some examples...

main

  #[tokio::main]                                                                                                                                                          
  pub async fn main() {                                                                                                                                                   
      prometheus_exporter::init();                                                                                                                                        
                                                                                                                                                                          
      let app = Router::new()                                                                                                                                             
          .route(                                                                                                                                                         
              "/async",                                                                                                                                                   
             get(|| async { <AsyncServiceImpl as AsyncService>::async_function().await }),                                                                               
          )                                                                                                                                                               
          .route(                                                                                                                                                         
              "/metrics",                                                                                                                                                 
              get(|| async { prometheus_exporter::encode_http_response() }),                                                                                              
          );                                                                                                                                                              
      Server::bind(&([127, 0, 0, 1], 8080).into())                                                                                                                        
          .serve(app.into_make_service())                                                                                                                                 
          .await                                                                                                                                                          
          .unwrap();                                                                                                                                                      
  } 

1. #[autometrics] on fn

  #[async_trait::async_trait]                                                                                                                                             
  impl AsyncService for AsyncServiceImpl {                                                                                                                                
      #[autometrics]                                                                                                                                                      
      async fn async_function() -> Result<(), ()> {                                                                                                                       
          tokio::time::sleep(Duration::from_secs(3)).await;                                                                                                               
          Ok(())                                                                                                                                                          
      }                                                                                                                                                                   
  }

This results in the wrong duration reported

function_calls_duration_seconds_sum{function="async_function",module="scratch",objective_latency_threshold="",objective_name="",objective_percentile="",service_name="autometrics"} 0.000000571

2. #[autometrics] on impl block after async_trait

  #[async_trait::async_trait]                                                                                                                                             
  #[autometrics]                                                                                                                                                          
  impl AsyncService for AsyncServiceImpl {                                                                                                                                
      async fn async_function() -> Result<(), ()> {                                                                                                                       
          tokio::time::sleep(Duration::from_secs(3)).await;                                                                                                               
          Ok(())                                                                                                                                                          
      }                                                                                                                                                                   
  } 

This also results in the incorrect duration

function_calls_duration_seconds_sum{function="AsyncServiceImpl::async_function",module="scratch",objective_latency_threshold="",objective_name="",objective_percentile="",service_name="autometrics"} 0.000000671

3. #[autometrics] on impl block before async_trait

  #[autometrics]                                                                                                                                                          
  #[async_trait::async_trait]                                                                                                                                             
  impl AsyncService for AsyncServiceImpl {                                                                                                                                
      async fn async_function() -> Result<(), ()> {                                                                                                                       
          tokio::time::sleep(Duration::from_secs(3)).await;                                                                                                               
          Ok(())                                                                                                                                                          
      }                                                                                                                                                                   
  }

This fails to compile with error:

error: expected `fn`
  --> src/main.rs:25:1
   |
25 | impl AsyncService for AsyncServiceImpl {
   | ^^^^

[gagbo]

Hello!

Thanks for the report! We tracked that there were issues with async_trait, and at least tried to give a better error message in the unreleased next version of the library, but I think we forgot to also oversee that the timing is correct, sorry for that.

Next step to solve this (and we'll do it, I'm writing it here to not forget when we come back to this) is to expand the macro fully to check where the timing advices/hooks are added exactly. I suspect that we'll need to do something special when we detect that the returned value is a boxed future, or when most/all of the work is happening in an anonymous async block

[kykosic]

This may also be fixed when timings are fixed, but this issue also causes the result="ok" and result="error" to be calculated incorrectly when #[autometrics] is put on an #[async_trait] impl method that returns a Result. It just returns result="".

[mellowagain]

hi, both issues have been fixed. please note that when instrumenting a whole impl block, #[autometrics] needs to be defined BEFORE #[async_trait]. thanks again for reporting

[kykosic]

Hmm I'm still not able to make this work, either for the documented attribute ordering or correct error reporting. Here is a minimal repro that uses the tonic gRPC library as a reference use case.

• #[autometrics] above #[async_trait] => compile error
• #[autometrics] below #[async_trait] => empty result=""
• #[autometrics] on trait method => empty result=""

Versions:

$ cargo tree  | rg '(async-trait|autometrics)'
autometrics-async-trait-repro v0.1.0
├── autometrics v0.6.0 (https://github.com/autometrics-dev/autometrics-rs.git?rev=69e64f851ed7e3668a914a62126eabdfe134ee36#69e64f85)
│   ├── autometrics-macros v0.6.0 (proc-macro) (https://github.com/autometrics-dev/autometrics-rs.git?rev=69e64f851ed7e3668a914a62126eabdfe134ee36#69e64f85)
│   │   │   ├── async-trait v0.1.74 (proc-macro)
│   ├── async-trait v0.1.74 (proc-macro) (*)
│   │   ├── async-trait v0.1.74 (proc-macro) (*)
    ├── async-trait v0.1.74 (proc-macro) (*)

[mellowagain]

Hmm I'm still not able to make this work, either for the documented attribute ordering or correct error reporting. Here is a minimal repro that uses the tonic gRPC library as a reference use case.

* `#[autometrics]` above `#[async_trait]` => compile error

* `#[autometrics]` below `#[async_trait]` => empty `result=""`

* `#[autometrics]` on trait method => empty `result=""`

Versions:

$ cargo tree  | rg '(async-trait|autometrics)'
autometrics-async-trait-repro v0.1.0
├── autometrics v0.6.0 (https://github.com/autometrics-dev/autometrics-rs.git?rev=69e64f851ed7e3668a914a62126eabdfe134ee36#69e64f85)
│   ├── autometrics-macros v0.6.0 (proc-macro) (https://github.com/autometrics-dev/autometrics-rs.git?rev=69e64f851ed7e3668a914a62126eabdfe134ee36#69e64f85)
│   │   │   ├── async-trait v0.1.74 (proc-macro)
│   ├── async-trait v0.1.74 (proc-macro) (*)
│   │   ├── async-trait v0.1.74 (proc-macro) (*)
    ├── async-trait v0.1.74 (proc-macro) (*)

hi, thanks for your report and the minimal reproduceable example! i have gone ahead and fixed this issue in #164. i tried it out with your example and it seems to work so please update it and let me know if it does. please note that #[autometrics] needs to come before #[async_trait]. thank you!

[kykosic]

hi, thanks for your report and the minimal reproduceable example! i have gone ahead and fixed this issue in #164. i tried it out with your example and it seems to work so please update it and let me know if it does. please note that #[autometrics] needs to come before #[async_trait]. thank you!

Yes I can confirm it works now. Thank you for the quick resolution!