Actix-web tracing-subscriber does not write to log file from other modules

help
1

Hi,

Please help with the following problem. I have been struggling with it:

For my actix-web web server application, I am logging using tracing and rolling file appender crates:

It logs only for the first time when the subscriber was initialised before the web server.

When I call tracing::debug! in my middleware, nothing gets logged. These were println! before.

Relevant content of .env:

...
RUST_LOG=debug

Relevant content of Cargo.toml:

[dependencies]
dotenv = "0.15.0"
time = {version = "0.3", default-features = false, features = ["formatting", "macros", "serde", "parsing", "local-offset"]}
...
actix-web = {version = "4.4.0", features = ["openssl"]}
tracing = "0.1"
tracing-appender = "0.2"
tracing-subscriber = {version = "0.3", features = ["fmt", "std", "local-time", "time"]}

Content of src/helper/app_logger.rs ( WORK IN PROGRESS ):

use time::macros::format_description;
use tracing::Level;
use tracing_appender::{non_blocking::WorkerGuard, rolling::{self, RollingFileAppender, Rotation}};
use tracing_subscriber::fmt::writer::MakeWriterExt;

use tracing_subscriber::{
    fmt::{time::LocalTime, Layer},
    layer::SubscriberExt,
};

pub fn init_app_logger1() -> (WorkerGuard, WorkerGuard) {
    let info_appender = RollingFileAppender::builder()
        .rotation(Rotation::DAILY) // rotate log files once every hour
        .filename_prefix("info") // log file names will be prefixed with `myapp.`
        .filename_suffix("log") // log file names will be suffixed with `.log`
        .build("./log") // try to build an appender that stores log files in `/var/log`
        .expect("initializing rolling file appender failed");
    let (info_appender, info_guard) = tracing_appender::non_blocking(info_appender);

    let warn_appender = rolling::daily("./log", "warn");
    let (warn_appender, warn_guard) = tracing_appender::non_blocking(warn_appender);

    let timer1 = LocalTime::new(format_description!("[year][month][day]-[hour]:[minute]:[second]"));
    let timer2 = LocalTime::new(format_description!("[year][month][day]-[hour]:[minute]:[second]"));

    let subscriber = tracing_subscriber::registry()
        .with(
            Layer::new()
                .with_timer(timer1)
                .with_ansi(false)
                .with_writer(info_appender.with_min_level(Level::INFO).with_max_level(Level::DEBUG))
        )
        .with(
            Layer::new()
                .with_timer(timer2)
                .with_ansi(false)
                .with_writer(warn_appender.with_max_level(Level::WARN))
        );        

    tracing::subscriber::set_global_default(subscriber)
        .expect("Unable to set a global subscriber");

    (info_guard, warn_guard)
}

The skeleton of src/main.rs:

async fn main() -> Result<(), std::io::Error> {
    dotenv().ok();
    ...
    let _guards = helper::app_logger::init_app_logger1();

    tracing::warn!("tracing warn lib.rs");
    tracing::debug!("tracing debug lib.rs");

    let server = HttpServer::new(move || {
        ...	
    })
    .listen_openssl(listener, ssl_builder())?
    .run();

    Ok(server)	
}

When run, regardless of how many times I am accessing the routes. Nothing get logged. The content of the log files stays fixed, they are always:

Content of log/info.2024-03-08.log:

20240308-23:59:41 DEBUG learn_actix_web: tracing debug lib.rs
20240308-23:59:41 DEBUG sqlx::query: summary="SET sql_mode=(SELECT CONCAT(@@sql_mode, ',PIPES_AS_CONCAT,NO_ENGINE_SUBSTITUTION')),time_zone='+00:00',NAMES …" db.statement="\n\nSET\n  sql_mode =(\n    SELECT\n      CONCAT(\n        @ @sql_mode,\n        ',PIPES_AS_CONCAT,NO_ENGINE_SUBSTITUTION'\n      )\n  ),\n  time_zone = '+00:00',\n  NAMES utf8mb4 COLLATE utf8mb4_unicode_ci;\n" rows_affected=0 rows_returned=0 elapsed=1.565ms
20240308-23:59:41  INFO actix_server::builder: starting 8 workers

Content of log/warn.2024-03-08:

20240308-23:59:41  WARN learn_actix_web: tracing warn lib.rs

So the two initial logs:

    tracing::warn!("tracing warn lib.rs");
    tracing::debug!("tracing debug lib.rs");

Work as expected. But repeated calls to tracing::debug! in my middleware module does not do anything.

I understand that, we should keep the WorkerGuard, _guards for the life of the application.

    let _guards = helper::app_logger::init_app_logger1();

Does _guards gets out of scope and dropped in this case, please?

If so, how do we keep it alive, please?

Or have I got the code completely wrong? Could you please point to some relevant documentation, please?

Thank you and best regards,

...behai.

2

Maybe the file is just not flushed yet? Can you set the rotation to Rotation::MINUTELY and see if the logs show up in the files?

3

Hi @jofas,

Thank you for your suggestion. I have just now tried that. The file name changed to info.2024-03-08-23-51.log.

I accessed the routes where there should debug logs.

Then I waited for more than a minute, I terminated the application. The content of info.2024-03-08-23-51.log remains unchanged.

Thank you and best regards,

...behai.

4

Hi,

Just an update on a small "progress" I have made with ChatGPT assistance.

Loggings from multiple modules get written to target log file.

I have asked ChatGPT for example code. My request to ChatGPT is:

For my Rust actix-web server application, I need to do logging in multiple modules.

For logging, I am using the following crates: tracing, tracing-appender and tracing-subscriber.

Would you please give me an example code?

The code ChatGPT gave works as expected, but it writes to the console only. I tweaked it little to write to file. I'm listing the complete code.

Please note, the code is not clean, there are un-used imports etc...

Relevant content of .env:

...
RUST_LOG=debug

Relevant content of Cargo.toml:

...
[dependencies]
dotenv = "0.15.0"
time = {version = "0.3", default-features = false, features = ["formatting", "macros", "serde", "parsing", "local-offset"]}
...
actix-web = {version = "4.4.0", features = ["openssl"]}
tracing = "0.1"
tracing-appender = "0.2"
tracing-subscriber = {version = "0.3", features = ["fmt", "std", "local-time", "time", "env-filter"]}

-- I am not actually using env-filter.

Content of src/main.rs:

use dotenv::dotenv;
use actix_web::{web, App, HttpServer};
use tracing::{info, debug};
use tracing_subscriber::{EnvFilter, FmtSubscriber};
// behai added this.
use time::macros::format_description;
use tracing::Level;
use tracing_appender::{non_blocking::WorkerGuard, rolling::{self, RollingFileAppender, Rotation}};
use tracing_subscriber::fmt::writer::MakeWriterExt;

use tracing_subscriber::{
    fmt::{time::LocalTime, Layer},
    layer::SubscriberExt,
};
//

mod handler_yy;
mod service_yy;

#[actix_web::main]
async fn main() -> std::io::Result<()> {
    dotenv().ok();

    // Initialize tracing subscriber
    /* ChatGPT code.
    let subscriber = FmtSubscriber::builder()
        .with_env_filter(EnvFilter::from_default_env())
        .finish();
    */

    // behai code.
    let info_appender = RollingFileAppender::builder()
        .rotation(Rotation::DAILY) // rotate log files once every hour
        .filename_prefix("info") // log file names will be prefixed with `myapp.`
        .filename_suffix("log") // log file names will be suffixed with `.log`
        .build("./log") // try to build an appender that stores log files in `/var/log`
        .expect("initializing rolling file appender failed");
    let (info_appender, _info_guard) = tracing_appender::non_blocking(info_appender);

    let timer1 = LocalTime::new(format_description!("[year][month][day]-[hour]:[minute]:[second]"));

    let subscriber = tracing_subscriber::registry()
        .with(
            Layer::new()
                .with_timer(timer1)
                .with_ansi(false)
                .with_writer(info_appender.with_min_level(Level::INFO).with_max_level(Level::DEBUG))
        );
    //

    tracing::subscriber::set_global_default(subscriber).expect("setting default subscriber failed");

    // behai code.
    info!("I am main.rs info!!");
    debug!("I am main.rs debug!!");
    //

    // Start HTTP server
    HttpServer::new(|| {
        App::new()
            .service(web::resource("/").route(web::get().to(handler_yy::index)))
    })
    .bind("127.0.0.1:5000")?
    .run()
    .await
}

Content of src/handler_yy.rs:

use actix_web::HttpResponse;
use tracing::info;

use crate::service_yy::some_function;

pub async fn index() -> HttpResponse {
    info!("Handling index request");

    // behai added.
    some_function();

    HttpResponse::Ok().body("Hello, world!")
}

Content of src/service_yy:

use tracing::info;

pub fn some_function() {
    info!("Logging from service module");
}

I started the executable, access http://localhost:5000/ once, then terminated the executable.

Content of log/info.2024-03-09.log:

**20240309-12:26:59  INFO learn_actix_web: I am main.rs info!!
**20240309-12:26:59 DEBUG learn_actix_web: I am main.rs debug!!
20240309-12:26:59  INFO actix_server::builder: starting 8 workers
20240309-12:26:59  INFO actix_server::server: Actix runtime found; starting in Actix runtime
**20240309-12:27:18  INFO learn_actix_web::handler_yy: Handling index request
**20240309-12:27:18  INFO learn_actix_web::service_yy: Logging from service module
**20240309-12:27:19  INFO learn_actix_web::handler_yy: Handling index request
**20240309-12:27:19  INFO learn_actix_web::service_yy: Logging from service module
20240309-12:27:30  INFO actix_server::server: SIGINT received; starting forced shutdown
20240309-12:27:30  INFO actix_server::worker: shutting down idle worker
20240309-12:27:30  INFO actix_server::worker: shutting down idle worker
20240309-12:27:30  INFO actix_server::worker: shutting down idle worker
20240309-12:27:30  INFO actix_server::worker: shutting down idle worker
20240309-12:27:30  INFO actix_server::worker: shutting down idle worker
20240309-12:27:30  INFO actix_server::worker: shutting down idle worker
20240309-12:27:30 DEBUG actix_server::accept: paused accepting connections on 127.0.0.1:5000
20240309-12:27:30  INFO actix_server::accept: accept thread stopped
20240309-12:27:30  INFO actix_server::worker: shutting down idle worker
20240309-12:27:30  INFO actix_server::worker: shutting down idle worker

The code looks very similar to my proper project's. I think now I can work my way through this problem.

Thank you and best regards,

...behai.

5

Hi @jofas,

I have finally worked it out! It was a simple overlook which I should have realised after finished writing the post asking for help.

In my original post, src/main.rs is actually src/lib.rs, and

async fn main() -> Result<(), std::io::Error>

is actually

pub async fn run(listener: TcpListener) -> Result<Server, std::io::Error>

And the skeleton code remains as is:

The full src/main.rs is:

use std::net::TcpListener;
use learn_actix_web::run;

#[actix_web::main]
async fn main() -> Result<(), std::io::Error> {
    let listener = TcpListener::bind("0.0.0.0:5000").expect("Failed to bind port 5000");
    // We retrieve the port assigned to us by the OS
    let port = listener.local_addr().unwrap().port();
    println!("Server is listening on port {}", port);

    let server = run(listener).await.unwrap();
    server.await
}

Cargo.toml has the following declaration also:

...
[lib]
path = "src/lib.rs"

[[bin]]
path = "src/main.rs"
name = "learn_actix_web"
...

I thought I could reduce sample code to make the post a little simpler. I completely forgot this module.

Move let _guards = helper::app_logger::init_app_logger1(); to src/main.rs and it works as expected:

...
use learn_actix_web::helper::app_logger::init_app_logger1;

#[actix_web::main]
async fn main() -> Result<(), std::io::Error> {
    let _guards = init_app_logger1();

    let listener = TcpListener::bind("0.0.0.0:5000").expect("Failed to bind port 5000");
...

This would explain it. run gets out of scope, while main is not, therefore _guards is still around.

Thank you for your helps and best regards,

...behai.