Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

register fns for custom request-derived logging units #1749

Merged
merged 14 commits into from
Oct 29, 2020

Conversation

jdeepee
Copy link
Contributor

@jdeepee jdeepee commented Oct 21, 2020

PR Type

Feature

PR Checklist

  • Tests for the changes have been added / updated.
  • Documentation comments have been added / updated.
  • A changelog entry has been made for the appropriate packages.
  • Format code with the latest stable rustfmt

Overview

Adds possibility to register a closure to be executed in request middleware logging. Closure is implemented to work in the request scope and thus takes ServiceRequest as input.

Our use case:

We wanted to log the UserID associated with all incoming requests to our API. UserID's in our case are stored inside JWT tokens. This means we cannot log the header directly but need to make some operations on it to get the internal encoded UserId. By allow the injection of this closure we can do the following:

Logger::new().custom_request_replace("jwt", |req: &ServiceRequest| {
      let user_token = req.headers().get("authorization");
      decode_jwt(user_token)
    }
)

@robjtede
Copy link
Member

For this to be considered, I need to know how this is different from just using a middleware function (App::wrap_fn) apart from it being on the same line as the Logger output.

@codecov-io
Copy link

codecov-io commented Oct 21, 2020

Codecov Report

Merging #1749 into master will increase coverage by 0.15%.
The diff coverage is 80.43%.

Impacted file tree graph

@@            Coverage Diff             @@
##           master    #1749      +/-   ##
==========================================
+ Coverage   53.82%   53.98%   +0.15%     
==========================================
  Files         126      125       -1     
  Lines       12073    12104      +31     
==========================================
+ Hits         6498     6534      +36     
+ Misses       5575     5570       -5     
Impacted Files Coverage Δ
src/middleware/logger.rs 77.66% <80.43%> (+0.68%) ⬆️
actix-http/src/header/common/if_none_match.rs
actix-http/src/header/common/accept_language.rs
...ctix-http/src/header/common/if_unmodified_since.rs
actix-http/src/header/common/allow.rs 0.00% <0.00%> (ø)
actix-http/src/header/common/last_modified.rs 0.00% <0.00%> (ø)
actix-http/src/header/common/mod.rs 16.66% <0.00%> (+6.66%) ⬆️

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 7030bf5...ec78458. Read the comment docs.

@jdeepee
Copy link
Contributor Author

jdeepee commented Oct 22, 2020

Ah, I didn't think about using App::wrap_fn. Is there someway that inside the wrap_fn closure I can call the logger? If there is not then the fact the logs are output in two different lines is a game breaker for our intended implementation.

If I have a middleware logging incoming requests and a wrap_fn() logging our user_id's there is no way to guarantee that other requests do not arrive in between middleware logging and wrap_fn() logging. Ive validated this problem with the following simple hello world app and a bash script that sends requests in parallel.

Actix app

#[actix_web::main]
async fn main() -> std::io::Result<()> {
    std::env::set_var("RUST_LOG", "actix_web=info");
    env_logger::init();

    HttpServer::new(|| {
        App::new()
            // enable logger
            .wrap(middleware::Logger::new(r#"%a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T "#).register_request_closure(|req: &ServiceRequest| {
                req.headers().get("Test").unwrap().to_str().unwrap().to_owned()
            }))
            .wrap_fn(|req, srv| {
                let header = req.headers().get("Test").unwrap().to_str().unwrap().to_owned();
                let fut = srv.call(req);
                async move {
                    let res = fut.await?;
                    println!("{:#?}", header);
                    Ok(res)
                }
            })
            .service(web::resource("/").to(|| async { "Hello world!" }))
    })
    .bind("127.0.0.1:8080")?
    .run()
    .await
}

Bash script

#!/bin/bash

curl -H 'Test: test1' localhost:8080 && echo "done1" &
curl -H 'Test: test3' localhost:8080 && echo "done2" &
curl -H 'Test: test2' localhost:8080 && echo "done3" &

wait

Actix-web Output

"test2"
"test3"
"test1"
[2020-10-22T09:57:53Z INFO  actix_web::middleware::logger] 127.0.0.1:51172 "GET / HTTP/1.1" 200 12 "-" "curl/7.68.0" 0.000057 test2
[2020-10-22T09:57:53Z INFO  actix_web::middleware::logger] 127.0.0.1:51170 "GET / HTTP/1.1" 200 12 "-" "curl/7.68.0" 0.000062 test3
[2020-10-22T09:57:53Z INFO  actix_web::middleware::logger] 127.0.0.1:51174 "GET / HTTP/1.1" 200 12 "-" "curl/7.68.0" 0.000052 test1

Here you can see the headers being printed in a way that causes a disjoint between the middleware logger and the wrap_fn().
I could of course implement a custom logger in the wrap_fn() closure but would prefer to use an existing solution.

@robjtede
Copy link
Member

Alright, there is a reasonable use case for this to exist as you've demonstrated with log lines being disjoint. I think there is a more flexible way to achieve this: being able to define custom replacements to use in the format string.

We can currently use %{FOO}i to log the request header FOO. I think a map of string keys to closures (using a similar (&ServiceRequest) -> String) would be better as you could then add these parameters anywhere in the output.

Proposal:

Allow the format syntax %{jwt}xi (x => custom, i => incoming/request) to call the registered closure. (we should leave open the possibility for %{FOO}xo in the future).

Logger::custom_request_replace(&mut self, label: &str, f: Fn(&ServiceRequest) -> String) -> Self

(Open to better method name.)

@robjtede robjtede added A-web project: actix-web B-semver-minor labels Oct 24, 2020
@jdeepee
Copy link
Contributor Author

jdeepee commented Oct 27, 2020

Okay above proposal has been implemented. Thanks for the outline; this is working quite nicely.

You may notice that I have removed Debug from FormatText. There is a few reasons for this; some of which may not be valid, some verification/assistance here would be greatly appreciated.

Firstly when trying to add the CustomLog(String, Option<fn(req: &ServiceRequest) -> String>) variant I was getting a rather strange error:

error: implementation of `std::fmt::Debug` is not general enough
   --> src/middleware/logger.rs:424:23
    |
424 |       CustomLog(String, Option<fn(req: &ServiceRequest) -> String>),
    |                         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ implementation of `std::fmt::Debug` is not general enough
    | 
   ::: /home/josh/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/fmt/mod.rs:552:1
    |
552 | / pub trait Debug {
553 | |     /// Formats the value using the given formatter.
554 | |     ///
555 | |     /// # Examples
...   |
583 | |     fn fmt(&self, f: &mut Formatter<'_>) -> Result;
584 | | }
    | |_- trait `std::fmt::Debug` defined here
    |
    = note: `std::fmt::Debug` would have to be implemented for the type `for<'r> fn(&'r ServiceRequest) -> std::string::String`
    = note: ...but `std::fmt::Debug` is actually implemented for the type `fn(&'0 ServiceRequest) -> std::string::String`, for some specific lifetime `'0`
    = note: this error originates in a derive macro (in Nightly builds, run with -Z macro-backtrace for more info)

error: aborting due to previous error

error: could not compile `actix-web`

I tried messing around with lifetimes in order to create a more "specific" lifetime but had no luck in getting this to work. I also stumbled across this issue whilst researching this problem. This made my wonder if the problem is caused by my shallow knowledge of lifetimes or if its a rust issue.

In any case I noticed that Debug is being used anywhere so for now have removed this to test other functionality. Please let me know if Debug should be added again.

Copy link
Member

@robjtede robjtede left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm liking how this is turning out. Good work. LMK if you have time to fix up these tweaks or not :)

src/middleware/logger.rs Outdated Show resolved Hide resolved
src/middleware/logger.rs Outdated Show resolved Hide resolved
src/middleware/logger.rs Outdated Show resolved Hide resolved
src/middleware/logger.rs Outdated Show resolved Hide resolved
@jdeepee
Copy link
Contributor Author

jdeepee commented Oct 27, 2020

Ive added most of the changes you outlined. Thanks for the assistance with that; was nice to go a little deeper into the world of closures.

Right now in custom_request_replace() I am cloning the Fn into Rc as to satisfy the 'static lifetime? There might be a way to do this without clone, but I don't know it...

Also didn't add any test for capturing env for the Fn. If you could take care of these pieces that would be much appreciated :)

@robjtede
Copy link
Member

robjtede commented Oct 27, 2020

np.. nice update. actix-cors managed to avoid require the Clone bound on the closure because it's being put in a Rc wrapper anyway (see https://github.com/actix/actix-extras/blob/master/actix-cors/src/builder.rs#L185). I'd need to have a mess with the code but it's forsure possible.

still would like that enum variant to elude to it referencing Requests, since it's public this will be locked as a name for at least the next major version

@jdeepee jdeepee requested a review from robjtede October 28, 2020 10:57
Copy link
Member

@robjtede robjtede left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I've tweaked and cleaned up a few things. This is looking ready.

@robjtede
Copy link
Member

Quick Q for @actix/contributors? Strictly this is breaking change to anyone who is exhaustively matching over the Logger format types. I would consider it harmless since it has always been hidden from docs.

Ergo, I would propose our policy should be server exemptions for doc(hidden) items. Can I get a 👍 or 👎 on that?

@robjtede robjtede requested a review from a team October 29, 2020 03:22
@robjtede robjtede changed the title Adds possibility to register a closure to be executed in request middleware logging register fns for custom request-derived logging units Oct 29, 2020
@robjtede robjtede merged commit 4519db3 into actix:master Oct 29, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
A-web project: actix-web B-semver-minor
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants