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

Logging in log is bugged, but tracing works #860

Closed
RoDmitry opened this issue Nov 14, 2023 · 9 comments · Fixed by #992
Closed

Logging in log is bugged, but tracing works #860

RoDmitry opened this issue Nov 14, 2023 · 9 comments · Fixed by #992
Assignees

Comments

@RoDmitry
Copy link
Contributor

RoDmitry commented Nov 14, 2023

I was using log + env_logger, and logs from other crates (sqlx and actix_web) didn't print after initialization of scylla::Session.
Also no logs from scylla itself were present.

I mean if you change order of these two blocks, then you will see logs from sqlx (but still no logs from scylla):

        let session = SessionBuilder::new()
            .known_node(&env::var("SCYLLA_URI").expect("SCYLLA_URI must be present in .env"))
            .user("cassandra", "cassandra")
            .build()
            .await
            .unwrap();
        let pool = MySqlPoolOptions::new()
            ....
            .connect(&env::var("DATABASE_URL").expect("DATABASE_URL must be present in .env"))
            .await
            .expect("Mysql Connect error!");

main.rs:

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

    // and here are those blocks from above

    HttpServer::new(move || {
        App::new()
...

Once I replaced logging (log + env_logger) with tracing + tracing-subscriber in my app, logs are printing just fine.

@RoDmitry RoDmitry changed the title Logging in Log is bugged, but Tracing works Logging in log is bugged, but tracing works Nov 14, 2023
@Lorak-mmk Lorak-mmk self-assigned this Nov 15, 2023
@Lorak-mmk
Copy link
Collaborator

Lorak-mmk commented Jan 15, 2024

You don't see logs from our driver because it uses tracing for it's logging and doesn't enable log feature in tracing dependency.
I'd encourage you to use tracing ecosystem for logging - it has a crate allowing it to consume log events, so you'd still be compatible with libraries using log - see https://docs.rs/tracing/latest/tracing/#consuming-log-records

I guess we could enable log feature in tracing so that apps using log ecosystem can receive logs from driver, but the question is if there is any performance penalty for this. According to tracing docs:

This crate provides two feature flags, “log” and “log-always”, which will cause [spans](https://docs.rs/tracing/latest/tracing/span/index.html) and [events](https://docs.rs/tracing/latest/tracing/event/struct.Event.html) to emit log records.
When the “log” feature is enabled, if no tracing Subscriber is active, invoking an event macro or creating a span with fields will emit a log record.
This is intended primarily for use in libraries which wish to emit diagnostics that can be consumed by applications using tracing or log, without paying the additional overhead of emitting both forms of diagnostics when tracing is in use.

So I guess there isn't an overhead of emitting 2 events, but I worry there still may be additional checking or other potential performance problems - it needs a bit more research.

In the meantime, here's a branch with log feature enabled on tracing dependency. Can you check if it allows you to see driver logs using env_logger? https://github.com/Lorak-mmk/scylla-rust-driver/tree/enable-tracing-log
To do it, change the scylla dependency in Cargo.toml as follows: scylla = { git = "https://github.com/Lorak-mmk/scylla-rust-driver.git", branch = "enable-tracing-log" }

Regarding the issue of logs from sqlx not appearing: I looked trough all our usages of tracing crate. The only things we do is emit spans / logs, and use .with_current_subscriber() on futures passed to tokio::spawn, there is nothing weird going on, so I highly doubt that this is our fault. I suspect it has something to do with how log / tracing / sqlx work / interact. Could you provide a self-contained reproducer? I could try to look into it more then.

@RoDmitry
Copy link
Contributor Author

RoDmitry commented Jan 15, 2024

Here is an example. Simple enabling log feature for tracing does not help.
If you comment out this line, then you will see more logs from actix_web.

@Lorak-mmk
Copy link
Collaborator

@RoDmitry thanks for reproducer. It looks like scylla isn't even necessary to reproduce it. Consider the following modifications to your reproducer:

  • Cargo.toml:
[package]
name = "hello-world"
version = "1.0.0"
edition = "2021"

[dependencies]
actix-web = "4.4"
env_logger = "0.10"
log = "0.4"
# scylla = "0.11.1"
# scylla = { git = "https://github.com/Lorak-mmk/scylla-rust-driver", branch = "enable-tracing-log" }
tracing = "0.1.36"
tokio = { version = "1.27" }
  • main.rs:
use actix_web::{middleware, web, App, HttpRequest, HttpServer};
use tracing::instrument::WithSubscriber;

async fn index(req: HttpRequest) -> &'static str {
    println!("REQ: {req:?}");
    "Hello world!"
}

#[actix_web::main]
async fn main() -> std::io::Result<()> {
    env_logger::init_from_env(env_logger::Env::new().default_filter_or("info"));

    log::info!("starting HTTP server at http://localhost:8080");

    tokio::spawn(
        async move {
            tracing::info!("spawned info");
            println!("spawned task");
        }
        .with_current_subscriber(),
    )
    .await
    .unwrap();

    log::info!("more logs");

    HttpServer::new(|| {
        App::new()
            // enable logger
            .wrap(middleware::Logger::default())
            .service(web::resource("/index.html").to(|| async { "Hello world!" }))
            .service(web::resource("/").to(index))
    })
    .bind(("127.0.0.1", 8080))?
    .run()
    .await
}

#[cfg(test)]
mod tests {
    use actix_web::{body::to_bytes, dev::Service, http, test, web, App, Error};

    use super::*;

    #[actix_web::test]
    async fn test_index() -> Result<(), Error> {
        let app = App::new().route("/", web::get().to(index));
        let app = test::init_service(app).await;

        let req = test::TestRequest::get().uri("/").to_request();
        let resp = app.call(req).await?;

        assert_eq!(resp.status(), http::StatusCode::OK);

        let response_body = resp.into_body();
        assert_eq!(to_bytes(response_body).await?, r##"Hello world!"##);

        Ok(())
    }
}

The logs from actix are not printed. They are again if you comment out tokio::spawn usage. The code looks correct to me and according to docs this is the use case for with_current_subscriber: https://docs.rs/tracing/0.1.40/tracing/instrument/trait.WithSubscriber.html#method.with_current_subscriber .
So imo this is an issue in tracing or actix, not in the driver.

@RoDmitry
Copy link
Contributor Author

RoDmitry commented Jan 15, 2024

It might be an issue of the log crate, because with tracing it works as it must. Thanks

@RoDmitry
Copy link
Contributor Author

Maybe add info somewhere in the docs, with recommendation to use tracing, or that log crate is not supported or something? Because it took me a lot of time to find an issue with logs.

@Lorak-mmk
Copy link
Collaborator

There is logging example, but I understand it's not really enough for a proper documentation.
We'll add a section about logging to documentation and leave this issue open until then.

@Lorak-mmk
Copy link
Collaborator

Actually I see there is already a section about logging in our documentation: https://rust-driver.docs.scylladb.com/stable/logging/logging.html and it says that the driver uses tracing to emit logs and you have to use tracing subscriber.
I can edit this doc if something is unclear, @RoDmitry ?

@RoDmitry
Copy link
Contributor Author

RoDmitry commented Jan 25, 2024

It says: "The driver uses", but does not recommend to use tracing over log. Also it would be more clear if it would mention that log crate is not supported, but it's up to you. Maybe it may say: "We recommend using tracing over log, because currently using log breaks logging"

@Lorak-mmk
Copy link
Collaborator

@RoDmitry this should be fixed on current main, can you give it a try?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment