moniof 1.0.1

//! Tests for `instrumentation::sql_events::MOFSqlEvents`.
//!
//! These replay the *exact* tracing events sqlx 0.8 emits (see
//! `sqlx-core-0.8.x/src/logger.rs`), so they stay honest without a live database.
//!
//! Two facts about sqlx that drive every test here:
//!
//!   1. sqlx emits **events**, never spans. There is no `span!` or `#[instrument]`
//!      anywhere in `sqlx-core`. So `MOFSqlEvents::on_new_span` / `on_close` can
//!      never fire, and only `on_event` runs.
//!   2. `db.statement` is the **empty string** for short queries — sqlx only
//!      populates it when the 4-word `summary` differs from the full SQL. The
//!      query text for short queries lives in `summary`.
//!
//! Run with: `cargo test --features sqlx`
#![cfg(feature = "sqlx")]

use moniof::core::stats::{QueryStatsHandle};
use moniof::core::task_ctx::MONIOF_HANDLE;
use moniof::instrumentation::sql_events::MOFSqlEvents;
use tracing_subscriber::{prelude::*, EnvFilter};

/// Install `MOFSqlEvents` on a scoped (thread-local) subscriber, run `f` inside a
/// request scope, and hand back the stats it collected.
fn capture(f: impl FnOnce()) -> QueryStatsHandle {
    capture_with(tracing_subscriber::registry().with(MOFSqlEvents::new()), f)
}

fn capture_with<S>(subscriber: S, f: impl FnOnce()) -> QueryStatsHandle
where
    S: tracing::Subscriber + Send + Sync + 'static,
{
    let handle = QueryStatsHandle::new();
    let read = handle.clone();
    tracing::subscriber::with_default(subscriber, || {
        MONIOF_HANDLE.sync_scope(handle, f);
    });
    read
}

/// A long query: sqlx puts the full SQL in `db.statement` (with padding newlines)
/// and an abbreviated, ellipsised `summary`.
macro_rules! sqlx_long_query {
    ($level:expr, $sql:expr, $secs:expr) => {
        tracing::event!(
            target: "sqlx::query",
            $level,
            summary = "SELECT id, name, email …",
            db.statement = concat!("\n\n", $sql, "\n"),
            rows_affected = 0u64,
            rows_returned = 0u64,
            elapsed_secs = $secs,
        )
    };
}

/// A short query: `summary == sql`, so sqlx leaves `db.statement` EMPTY.
macro_rules! sqlx_short_query {
    ($level:expr, $summary:expr, $secs:expr) => {
        tracing::event!(
            target: "sqlx::query",
            $level,
            summary = $summary,
            db.statement = "",
            rows_affected = 0u64,
            rows_returned = 0u64,
            elapsed_secs = $secs,
        )
    };
}

// ---------------------------------------------------------------------------
// Behaviour that works today
// ---------------------------------------------------------------------------

#[test]
fn long_query_is_counted_under_its_normalized_statement() {
    let read = capture(|| {
        sqlx_long_query!(
            tracing::Level::INFO,
            "SELECT id, name, email FROM users WHERE tenant = $1",
            0.004f64
        );
    });

    let s = read.0.lock();
    assert_eq!(s.total, 1);
    assert_eq!(s.per_key["sql/select id, name, email from users where tenant = $1"], 1);
}

#[test]
fn repeated_query_accumulates_its_count() {
    let read = capture(|| {
        for _ in 0..7 {
            sqlx_long_query!(
                tracing::Level::INFO,
                "SELECT id, name, email FROM users WHERE tenant = $1",
                0.004f64
            );
        }
    });

    let s = read.0.lock();
    assert_eq!(s.total, 7);
    assert_eq!(s.per_key.len(), 1, "one logical query must occupy one bucket");
}

#[test]
fn non_sqlx_events_are_ignored() {
    let read = capture(|| {
        tracing::info!(target: "my_app::handlers", "unrelated log line");
        tracing::info!(target: "sqlx::pool", "pool acquired");
    });

    assert_eq!(read.0.lock().total, 0);
}

// ---------------------------------------------------------------------------
// Known bugs — these assert the CORRECT behaviour and fail today.
// Run with: cargo test --features sqlx -- --ignored
// ---------------------------------------------------------------------------

/// BUG: SQL latency is never recorded.
///
/// `on_event` (sql_events.rs:131) calls `mark()` but never `mark_latency()`.
/// The real latency arrives on the event as `elapsed_secs: f64`, but `SqlVisitor`
/// only implements `record_str`/`record_debug`, so it cannot see an f64 field.
///
/// Consequences: `x-moniof-db-total-ms` is always 0 for SQL apps, the
/// `moniof_db_total_latency_seconds` histogram is always 0, and — because
/// `n_plus_one_min_total_ms` defaults to `Some(5)` — the latency gate rejects
/// every SQL N+1 candidate, so SQL N+1 detection can never fire.
///
/// Fix: add `record_f64` to `SqlVisitor`, capture `elapsed_secs`, and call
/// `mark_latency(QueryKind::Sql, &key, (secs * 1000.0) as u128)` from `on_event`.
#[test]
#[ignore = "known bug: on_event never calls mark_latency; elapsed_secs is dropped"]
fn sql_latency_is_recorded_from_elapsed_secs() {
    let read = capture(|| {
        sqlx_long_query!(
            tracing::Level::INFO,
            "SELECT id, name, email FROM users WHERE tenant = $1",
            0.004f64
        );
        sqlx_long_query!(
            tracing::Level::INFO,
            "SELECT id, name, email FROM users WHERE tenant = $1",
            0.006f64
        );
    });

    let s = read.0.lock();
    assert_eq!(s.total_db_latency_ms, 10, "4ms + 6ms must accumulate");
    assert_eq!(
        s.per_key_latency_ms["sql/select id, name, email from users where tenant = $1"],
        10
    );
}

/// BUG: every short query collapses into a single `sql/` bucket.
///
/// sqlx leaves `db.statement` empty when the query is short. `SqlVisitor` matches
/// `db.statement` (sql_events.rs:33), reads `""`, and normalizes it to `""` — so
/// the key becomes `sql/` for *every* short query in the app. The actual text is
/// in the `summary` field, which the visitor never looks at.
///
/// Fix: prefer `db.statement` when non-empty, else fall back to `summary`.
#[test]
#[ignore = "known bug: short queries all key to `sql/` because db.statement is empty"]
fn short_queries_do_not_collapse_into_one_key() {
    let read = capture(|| {
        sqlx_short_query!(tracing::Level::INFO, "SELECT id FROM users", 0.001f64);
        sqlx_short_query!(tracing::Level::INFO, "SELECT id FROM orders", 0.001f64);
    });

    let s = read.0.lock();
    assert_eq!(s.total, 2);
    assert!(
        !s.per_key.contains_key("sql/"),
        "empty key means the query text was lost; got {:?}",
        s.per_key
    );
    assert_eq!(s.per_key.len(), 2, "two distinct tables => two buckets, got {:?}", s.per_key);
    assert_eq!(s.per_key["sql/select id from users"], 1);
    assert_eq!(s.per_key["sql/select id from orders"], 1);
}

/// BUG: under the filter `initiate()` installs, moniof observes **zero** queries.
///
/// `config/global.rs:41` adds a `sqlx=info` directive, but sqlx's default
/// `statements_level` is `DEBUG` (`sqlx-core/src/connection.rs:197`). The events
/// are discarded by the filter before `MOFSqlEvents` ever sees them. Out of the
/// box, on an untouched sqlx pool, moniof's SQL support is inert.
///
/// Fix: use `sqlx=debug` in the directive (and say so in the README), or document
/// that callers must set `.log_statements(LevelFilter::Info)` on their connect options.
#[test]
#[ignore = "known bug: initiate() filters sqlx at info, but sqlx logs statements at debug"]
fn default_filter_observes_sqlx_statements_at_their_default_level() {
    // Exactly the directives initiate() builds.
    let filter = EnvFilter::new("moniof=debug,moniof::sql=debug,sqlx=info");
    let subscriber = tracing_subscriber::registry()
        .with(filter)
        .with(MOFSqlEvents::new());

    let read = capture_with(subscriber, || {
        // sqlx's default statements_level is DEBUG.
        sqlx_long_query!(
            tracing::Level::DEBUG,
            "SELECT id, name, email FROM users WHERE tenant = $1",
            0.004f64
        );
    });

    assert_eq!(
        read.0.lock().total,
        1,
        "a sqlx statement logged at its default DEBUG level must reach the layer"
    );
}