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

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.

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?

1 Like

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.

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.

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.

1 Like

This topic was automatically closed 90 days after the last reply. We invite you to open a new topic if you have further questions or comments.