Skip to main content

Rust Debugging & SQL Logging

TeaQL Rust provides a built-in, request-scoped SQL debug logging system. Instead of global logger toggles that clutter logs in multi-threaded environments, TeaQL binds logging control directly to UserContext. This allows you to toggle query and mutation logging per request, inspect bound parameters, measure query execution times, and programmatically assert or output SQL traces.

Key Logging Structs​

Logging features in teaql-runtime are centered around three main types:

1. SqlLogOperation​

An enum that classifies the database operation:

  • SqlLogOperation::Select
  • SqlLogOperation::Insert
  • SqlLogOperation::Update
  • SqlLogOperation::Delete
  • SqlLogOperation::Recover

2. SqlLogOptions​

A control struct that specifies which query types should be logged. It can be instantiated using convenient constructor methods:

  • SqlLogOptions::disabled() — Disables all logging (default).
  • SqlLogOptions::select_only() — Logs only SELECT operations.
  • SqlLogOptions::mutation_only() — Logs mutations (INSERT, UPDATE, DELETE, RECOVER).
  • SqlLogOptions::all() — Logs all database operations.

3. SqlLogEntry​

An immutable snapshot of a completed SQL execution. It contains:

  • operation: The SqlLogOperation executed.
  • sql: The raw parameterized SQL statement.
  • params: The bound parameters (Vec<Value>).
  • debug_sql: The query compiled with bound parameters inline (suitable for copy-pasting to database clients).
  • pretty_sql: A beautifully formatted version of the debug SQL.
  • started_at & ended_at: Start and end SystemTime timestamps.
  • elapsed: Duration of database execution.
  • result_count: Option<usize> of returned rows (for queries).
  • affected_rows: Option<u64> of affected rows (for mutations).
  • result_summary: A clean, readable summary string (e.g., "12 x Candidate" or "1 affected row").

Programmatic Log Control​

UserContext provides direct methods to configure, enable, or inspect SQL logs during a request's lifecycle.

Configuring Logging Options​

use teaql_runtime::{UserContext, SqlLogOptions};

// Method 1: Builder pattern during UserContext construction
let mut ctx = UserContext::new()
    .with_sql_log_options(SqlLogOptions::all());

// Method 2: Imperative state change on mutable reference
ctx.set_sql_log_options(SqlLogOptions::select_only());

Logging Toggles​

// Enable select query logging
ctx.enable_select_sql_log();

// Enable write/mutation logging (insert, update, delete, recover)
ctx.enable_mutation_sql_log();

// Enable all database logging
ctx.enable_all_sql_log();

// Disable all logging and clear recorded logs
ctx.disable_sql_log();

Retrieving and Utilizing Logs​

All logged operations are stored in a thread-safe repository trace buffer inside UserContext and can be retrieved or cleared at any time.

// Fetch all recorded SQL logs in the current context
let logs = ctx.sql_logs();

for log in logs {
    println!("[SQL Log] Operation: {:?}", log.operation);
    println!("  Elapsed: {:?}", log.elapsed);
    println!("  Pretty SQL:\n{}", log.pretty_sql);
    println!("  Summary: {}", log.result_summary);
}

// Clear all recorded logs to reset the buffer
ctx.clear_sql_logs();

Concrete Example: Request Logging & Assertion​

Below is a complete pattern showing how to use the SQL logging framework to log query execution stats in an API handler or unit test:

use teaql_runtime::{UserContext, SqlLogOptions};
use std::time::Duration;
use my_domain::Q;

async fn get_premium_merchants(ctx: &mut UserContext) -> Result<(), Box<dyn std::error::Error>> {
    // 1. Enable logging for selects only
    ctx.set_sql_log_options(SqlLogOptions::select_only());
    ctx.clear_sql_logs(); // Ensure clean buffer

    // 2. Run your business query
    let merchants = Q::merchants()
        .select_name()
        .with_status_is_premium()
        .execute_for_list(ctx)
        .await?;

    // 3. Inspect and log query performance
    let logs = ctx.sql_logs();
    if let Some(query_log) = logs.first() {
        // Log query and elapsed time using standard logging facilities
        log::info!("Executed query: {}", query_log.result_summary);
        log::info!("Execution time: {:?}", query_log.elapsed);
        
        // Log full copy-pasteable SQL statement for debugging
        log::debug!("Debug SQL:\n{}", query_log.debug_sql);
        
        // Alert if query exceeds SLA threshold (e.g., 200ms)
        if query_log.elapsed > Duration::from_millis(200) {
            log::warn!("Performance SLA violated for query: {}", query_log.debug_sql);
        }
    }

    Ok(())
}

SQL Trace Comments (Request Tracing & User Identity)​

In production environments, identifying which business method, request, or user session triggered a slow database query is notoriously difficult. To solve this, TeaQL Rust features Request & User Tracing via SQL comments.

When a query is compiled and executed, the TeaQL runtime dynamically captures both the request's User Identifier (representing the currently authenticated user, API key, or process OS thread/PID context) and the Business calling stack trace (e.g., Get all tasks->Count status->count_tasks). It automatically formats them into a single trace comment and populates the CompiledQuery's comment field:

  • Format: [user_identifier] business_trace
  • Example: /* [philip@pid-2012809.tid-1] Get all tasks->Count status->count_tasks */

This architecture keeps the main CompiledQuery::sql field perfectly clean and free of comments for programmatic use (such as in local logs, trace asserts, and metrics), while the database execution drivers automatically use CompiledQuery::sql_with_comment() to prepend the combined trace comment to the SQL sent to the database.

This means both the user identity and business calling trace are fully visible in database process lists, slow logs, and query statistics!

How it works under the hood​

  1. Compilation & Resolution: The comment("...") builder method on queries (or automatic request/job tracing) populates a raw comment, which is combined with UserContext::user_identifier at execution time to populate CompiledQuery.comment: Option<String>.
  2. Database Driver Execution: 
    // When executing, drivers call `sql_with_comment()`
    let sql_to_send = query.sql_with_comment(); 
    // Result: "/* [philip] audit */ SELECT * FROM orders"
  3. Application Logs: Standard logging facilities can still log the clean query.sql alongside query.comment separately, preventing noisy or cluttered log lines.

How to Query/Inspect Traces in Various Databases​

Once SQL comments are pushed to the database, you can query running processes or inspect performance tables to see exactly which TeaQL business context ran each statement.

1. PostgreSQL​

PostgreSQL preserves SQL comments in active processes and query statistics.

Find currently running queries with traces:​
SELECT pid, query_start, state, query
FROM pg_stat_activity
WHERE query LIKE '%/*%*/%' AND state = 'active';
Analyze slow/frequent queries with pg_stat_statements:​

If you have the pg_stat_statements extension enabled, you can locate cumulative query execution metrics grouped by their trace comments:

SELECT query, calls, total_exec_time, mean_exec_time
FROM pg_stat_statements
WHERE query LIKE '%/*%*/%'
ORDER BY total_exec_time DESC
LIMIT 10;
Server Logs / Slow Query Log:​

In postgresql.conf, if you configure log_min_duration_statement = 200 (log queries taking longer than 200ms), the generated server logs will print the query complete with its /* comment */ prefix.

2. MySQL / MariaDB​

MySQL captures and indexes comments in both its process lists and performance schema.

[!WARNING] By default, the MySQL command-line client (mysql) strips comments before sending queries to the server. Always run the client with the -c (or --comments) flag to prevent comment stripping:

mysql -u root -p -c
View current running queries via process list:​
SELECT ID, USER, HOST, DB, COMMAND, TIME, STATE, INFO
FROM information_schema.processlist
WHERE INFO LIKE '%/*%*/%';
Inspect the Performance Schema:​
SELECT THREAD_ID, EVENT_ID, SQL_TEXT, TIMER_WAIT / 1000000000000 AS duration_seconds
FROM performance_schema.events_statements_current
WHERE SQL_TEXT LIKE '%/*%*/%';
Slow Query Log:​

When slow_query_log is enabled in MySQL, all query comments are written into the slow log file (e.g., mysql-slow.log) or the mysql.slow_log table:

SELECT start_time, user_host, query_time, sql_text
FROM mysql.slow_log
WHERE sql_text LIKE '%/*%*/%';

3. SQLite​

Since SQLite is an embedded engine run inside your process, tracing comments is done via application-level hooks or SQLite's CLI debugger.

Using tracing callbacks in Rust (e.g., with rusqlite):​

You can subscribe to execution tracing using SQLite's trace interface:

connection.trace_v2(sqlite::TraceEvent::Statement, |event| {
    if let sqlite::TraceEvent::Statement(stmt) = event {
        println!("Executing SQL: {}", stmt.sql());
    }
});
Inspecting in SQLite CLI:​

If you are logging queries in the SQLite CLI, the trace comment will be output alongside the executed statement:

.log stdout
-- The output will show:
-- /* comment */ SELECT ...

Summary​

By coupling SQL debug logging to the request's UserContext rather than system-wide global variables, TeaQL Rust gives you:

  1. Observability without Clutter: Trace queries only for the request or session you are debugging.
  2. Performance Auditing: Measure exact database latency (elapsed) per statement dynamically.
  3. Simple Diagnostics: Fetch beautifully formatted (pretty_sql) and copy-pasteable prepared SQL statements directly from the context.