rust - ensure actix logging in chronological order // pre-process

Question

I have actix-web and struggle debugging, as the logger writes at the end only, and if something fails, it doesnt write at all.

RUST_LOG=actix_web=debug,actix_server=debug

let server = HttpServer::new(move || {
        App::new()
            .wrap(Logger::default())
            .wrap(Logger::new(
                "Request Pre",
                )
            )
            .wrap(add_service())
            .configure(add_routes)        

[2021-02-05T14:29:02Z INFO  my_lib::middleware::foo] Foo Middleware Finished
[2021-02-05T14:29:02Z INFO  my_lib::middleware::bar] Bar Middleware Finished
[2021-02-05T14:29:01Z INFO  actix_web::middleware::logger] Request Pre
[2021-02-05T14:29:01Z INFO  actix_web::middleware::logger] 127.0.0.1:54321 "POST /call/me HTTP/1.1"

How can I control the Pre-Processing (and add logs in there), so to ensure that first thing a log is written when a request arrives?

question from:https://stackoverflow.com/questions/66065426/ensure-actix-logging-in-chronological-order-pre-process

Answer 1

You can use a tracing logger which logs twice for a request: upon arrival and when a response is sent out. Often requests are logged when sending the response, this way we can add context like the response's status code to the log event. However, if we receive a problematic incoming request our service might crash before logging occured.

In those cases 2 log events per requests are useful to identify harmful incoming workload:

use actix_service::Service;
use actix_web::{web, App, HttpServer};
use actix_web_opentelemetry::RequestTracing;
use log;
use tracing::subscriber::set_global_default;
use tracing_actix_web::TracingLogger;
use tracing_bunyan_formatter::{BunyanFormattingLayer, JsonStorageLayer};
use tracing_log::LogTracer;
use tracing_subscriber::{layer::SubscriberExt, EnvFilter, Registry};

const PKG_NAME: &str = env!("CARGO_PKG_NAME");

async fn index() -> &'static str {
    "Hello!"
}

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

    let env_filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("info"));
    let formatting_layer = BunyanFormattingLayer::new(PKG_NAME.into(), std::io::stdout);

    let subscriber = Registry::default()
        .with(env_filter)
        .with(JsonStorageLayer)
        .with(formatting_layer);

    LogTracer::init().expect("Failed to set logger");
    set_global_default(subscriber).expect("Failed to set subscriber");

    HttpServer::new(|| {
        App::new()
            .wrap_fn(|req, srv| {
                log::info!("hello from middleware!");
                srv.call(req)
            })
            .wrap(RequestTracing::new())
            .wrap(TracingLogger)
            .service(web::resource("/").to(index))
    })
    .bind("127.0.0.1:8080")?
    .run()
    .await
}

In the output we see the middleware is logging between REQUEST - START and REQUEST - END:

./target/debug/log-test | jq -cr '.msg'
Starting 4 workers
Starting "actix-web-service-127.0.0.1:8080" service on 127.0.0.1:8080
[REQUEST - START]
hello from middleware!
[REQUEST - END]