sqlx::pool doesn't log acquire times

[svanharmelen]

Bug Description

It seems there is code that should log the pool acquire times, but whatever settings I try I does not log anything.

I tried using env_logger and tracing_subscriber (both set to max log level trace) but both only log statements from the sqlx::query package. Trace logs of other (non-sqlx) crates are written to stdout, so I guess its a problem with the logging logic in sqlx::pool?

Minimal Reproduction

use sqlx::sqlite::{SqliteConnectOptions, SqlitePoolOptions};

#[tokio::main]
async fn main() {
    tracing_subscriber::fmt()
        .with_max_level(tracing::Level::TRACE)
        .init();

    let pool = SqlitePoolOptions::new()
        .max_connections(1)
        .connect_with(
            SqliteConnectOptions::new()
                .filename("test.db")
                .create_if_missing(true)
                .to_owned(),
        )
        .await
        .expect("failed to create pool for database");

    sqlx::query(
        r#"
        CREATE TABLE IF NOT EXISTS dummy (
            id INTEGER NOT NULL PRIMARY KEY,
            value INTEGER
        )
        "#,
    )
    .execute(&pool)
    .await
    .expect("failed to create dummy table");

    let pool2 = pool.clone();
    tokio::spawn(async move {
        loop {
            insert_dummy_data(&pool2).await;
            tokio::time::sleep(tokio::time::Duration::from_secs(1)).await;
        }
    });

    tokio::spawn(async move {
        loop {
            insert_dummy_data(&pool).await;
            tokio::time::sleep(tokio::time::Duration::from_secs(1)).await;
        }
    });

    tokio::time::sleep(tokio::time::Duration::from_secs(20)).await;
}

async fn insert_dummy_data(pool: &sqlx::SqlitePool) {
    let random = rand::random::<u8>();
    sqlx::query("INSERT INTO dummy (value) VALUES (?)")
        .bind(random)
        .execute(pool)
        .await
        .expect("failed to insert dummy data");
}

When running this example code (all with latest versions of the used crates), the only logging you will get is this:

2024-11-17T14:05:38.840508Z DEBUG sqlx::query: summary="INSERT INTO dummy (value) …" db.statement="\n\nINSERT INTO\n  dummy (value)\nVALUES\n  (?)\n" rows_affected=1 rows_returned=0 elapsed=608.167µs elapsed_secs=0.000608167
2024-11-17T14:05:38.841270Z DEBUG sqlx::query: summary="INSERT INTO dummy (value) …" db.statement="\n\nINSERT INTO\n  dummy (value)\nVALUES\n  (?)\n" rows_affected=1 rows_returned=0 elapsed=387.25µs elapsed_secs=0.00038725
2024-11-17T14:05:39.843580Z DEBUG sqlx::query: summary="INSERT INTO dummy (value) …" db.statement="\n\nINSERT INTO\n  dummy (value)\nVALUES\n  (?)\n" rows_affected=1 rows_returned=0 elapsed=468.75µs elapsed_secs=0.00046875
2024-11-17T14:05:39.844231Z DEBUG sqlx::query: summary="INSERT INTO dummy (value) …" db.statement="\n\nINSERT INTO\n  dummy (value)\nVALUES\n  (?)\n" rows_affected=1 rows_returned=0 elapsed=279µs elapsed_secs=0.000279
2024-11-17T14:05:40.845948Z DEBUG sqlx::query: summary="INSERT INTO dummy (value) …" db.statement="\n\nINSERT INTO\n  dummy (value)\nVALUES\n  (?)\n" rows_affected=1 rows_returned=0 elapsed=553.833µs elapsed_secs=0.000553833
2024-11-17T14:05:40.846868Z DEBUG sqlx::query: summary="INSERT INTO dummy (value) …" db.statement="\n\nINSERT INTO\n  dummy (value)\nVALUES\n  (?)\n" rows_affected=1 rows_returned=0 elapsed=455.375µs elapsed_secs=0.000455375
2024-11-17T14:05:41.847775Z DEBUG sqlx::query: summary="INSERT INTO dummy (value) …" db.statement="\n\nINSERT INTO\n  dummy (value)\nVALUES\n  (?)\n" rows_affected=1 rows_returned=0 elapsed=568.125µs elapsed_secs=0.000568125
2024-11-17T14:05:41.848685Z DEBUG sqlx::query: summary="INSERT INTO dummy (value) …" db.statement="\n\nINSERT INTO\n  dummy (value)\nVALUES\n  (?)\n" rows_affected=1 rows_returned=0 elapsed=454.833µs elapsed_secs=0.000454833
2024-11-17T14:05:42.851150Z DEBUG sqlx::query: summary="INSERT INTO dummy (value) …" db.statement="\n\nINSERT INTO\n  dummy (value)\nVALUES\n  (?)\n" rows_affected=1 rows_returned=0 elapsed=502.375µs elapsed_secs=0.000502375
2024-11-17T14:05:42.851946Z DEBUG sqlx::query: summary="INSERT INTO dummy (value) …" db.statement="\n\nINSERT INTO\n  dummy (value)\nVALUES\n  (?)\n" rows_affected=1 rows_returned=0 elapsed=349.917µs elapsed_secs=0.000349917

Info

• SQLx version: 0.8.2
• SQLx features enabled: ["runtime-tokio", "sqlite"]
• Database server and version: SQLite (bundled)
• Operating system: Tested on macOS and Ubuntu
• rustc --version: rustc 1.82.0 (f6e511eec 2024-10-15)

[joeydewaal]

Have you tried acquire_time_level? Your minimal reproducible example worked for me after I set it to LevelFilter::Warn.

[svanharmelen]

How on earth can I have missed that 🙈 Thanks so much for the pointer!