Rate Limited Logging

May 21, 2025

I want to log messages under exceptional situations. If for some unknown reason, the exceptional situation becomes the common case, I don’t want to flood the logs. So, I want a rate limited logging at the individual log message level.

#[macro_export]
macro_rules! info_every {
    // Count-based with default 1-minute window
    // Convenience pattern that delegates to the full pattern with a preset window
    // This allows simpler syntax when the standard 1-minute window is sufficient
    ($n:expr, $($arg:tt)+) => {{
        // Delegate to the full pattern with the default 1-minute (60 seconds) duration
        info_every!($n, std::time::Duration::from_secs(60), $($arg)+)
    }};

    // Count-based with counter reset at the end of time window.
    ($n:expr, $duration:expr, $($arg:tt)+) => {{
        // Import the necessary atomic types for thread-safe counters and time tracking
        // Atomics are used to ensure thread-safety without locks, even in potentially single-threaded
        // applications.
        use std::sync::atomic::{AtomicU32, AtomicU64, Ordering};
        use std::time::{Duration, Instant};
        use std::sync::Once;

        // Static atomic variables to persist across macro invocations
        // IMPORTANT: These static variables are unique for each macro invocation site in your code.
        // This means each place where info_every!() is called gets its own independent:
        // - counter (different log counts for different log messages)
        // - time window (separate rate limiting for each log point)
        // - its own set of static variables to track these values
        //
        // COUNTER: Tracks how many times this macro has been called at this specific invocation site
        static COUNTER: AtomicU32 = AtomicU32::new(0);
        // TIME_WINDOW_START: Records when the current time window started for this specific invocation site
        static TIME_WINDOW_START: AtomicU64 = AtomicU64::new(0);
        // MONOTONIC_ANCHOR: Reference point for monotonic timing for this specific invocation site
        static mut MONOTONIC_ANCHOR: Option<Instant> = None;
        // INIT: Ensures one-time initialization of MONOTONIC_ANCHOR for this specific invocation site
        static INIT: Once = Once::new();

        // Advantages of using monotonic time (Instant) over system time (SystemTime):
        // 1. Accuracy: Monotonic clocks are specifically designed for measuring elapsed time
        //    and are not affected by system clock adjustments (NTP updates, daylight savings, etc.)
        // 2. Performance: Accessing monotonic time is generally faster as it doesn't require
        //    the same system calls as getting wall-clock time
        // 3. Immunity to time changes: The code continues working correctly even if the
        //    system time changes while the program is running
        // 4. No time-travel: Unlike system time which can jump backward or forward,
        //    monotonic time always increases, avoiding rate-limiting bugs when system time changes

        // Initialize the monotonic anchor point (thread-safe, one-time initialization)
        // This creates a reference point that persists for the lifetime of this particular
        // invocation site's static variable - each place where info_every!() appears in
        // your code will have its own MONOTONIC_ANCHOR with its own reference time
        INIT.call_once(|| {
            unsafe {
                MONOTONIC_ANCHOR = Some(Instant::now());
            }
        });

        // Get current time in seconds since our monotonic anchor
        // Using monotonic time ensures we get reliable elapsed time measurements
        // even if the system clock is changed while the program is running
        let now = unsafe {
            MONOTONIC_ANCHOR.unwrap().elapsed().as_secs()
        };

        // Note on memory ordering (Ordering::Relaxed):
        // We use Relaxed ordering since:
        // 1. For logging, we can tolerate small inconsistencies that don't affect program correctness
        // 2. We don't need to synchronize other memory operations with these counters
        // 3. Even in single-threaded applications, using atomics provides future-proofing
        //    if the code is later used in a multi-threaded context
        // 4. The performance cost of Relaxed atomic operations is minimal even in single-threaded code

        // Parse input parameters
        let n = $n as u32;               // Count threshold
        let window = $duration.as_secs(); // Time window in seconds
        let window_start = TIME_WINDOW_START.load(Ordering::Relaxed); // Time window start timestamp

        // Check if the time window has elapsed since the window start time
        let time_window_elapsed = now >= window_start + window;

        // Reset the counter and update the window start timestamp if the time window has elapsed
        if time_window_elapsed {
            // Reset counter to 0 since we're starting a new time window
            COUNTER.store(0, Ordering::Relaxed);

            // Update the time window start timestamp to mark the beginning of the new window
            // We use store instead of compare_exchange since we've already determined
            // the time window has elapsed and we want to update unconditionally
            TIME_WINDOW_START.store(now, Ordering::Relaxed);
        }

        // Increment counter atomically and get previous value before the increment
        // fetch_add returns the previous value, then adds 1
        let count = COUNTER.fetch_add(1, Ordering::Relaxed);

        // Log only when count threshold is reached:
        // - First call after counter reset: count=0, so 0%n=0 (logs immediately)
        // - Then logs when count=n, 2n, 3n, etc. within the time window
        if count % n == 0 {
            // Log the message with metadata about the rate limiting
            // Note: We've already updated the time window start if needed,
            // and we don't need to update it again when logging due to count threshold
            info!(
                occurences = %count,
                info_every = %n,
                time_window = %window,
                $($arg)*
            );
        }
    }};
}

// Usage examples:
// The semicolon in the examples is NOT required by this macro, but is one way to use
// the structured logging syntax in Rust logging libraries like tracing or log:
//
// Rust logging macros support two main syntax styles for structured fields:
//
// 1. Semicolon style (used in our examples):
//    info!("Main message"; field1 = value1, field2 = ?value2)
//    - Message comes first, followed by semicolon, then key-value pairs
//
// 2. Direct style (also supported):
//    info!(?variable1, %variable2, "Main message")
//    - Fields can come before the message
//    - ?variable includes both the name and debug-formatted value
//    - %variable includes both the name and display-formatted value
//
// Both styles are valid and supported by this macro. The $($arg:tt)+ in the macro
// definition captures all tokens that follow the count/duration parameters and
// passes them directly to the underlying info! macro.

// With explicit duration:
info_every!(
    100,                        // Count threshold (log every 100 occurrences)
    Duration::from_secs(60),    // Time window (reset counter after 60 seconds)
    "Processing batch";         // Main log message (followed by semicolon)
    batch_id = ?id              // Structured field (key-value pair)
);

// With default 1-minute duration:
info_every!(
    100,                        // Count threshold (log every 100 occurrences)
    "Processing batch";         // Main log message (followed by semicolon)
    batch_id = ?id              // Structured field (key-value pair)
);

// Direct style (without semicolon) - also supported:
info_every!(
    100,                        // Count threshold (log every 100 occurrences)
    ?id,                        // Debug-formatted value (includes variable name)
    %count,                     // Display-formatted value (includes variable name)
    "Processing batch"          // Main log message
);

// Understanding multiple invocation sites:
//
// When you use info_every!() in multiple places in your code, each gets its own set of
// static variables:
//
// // In file1.rs - counts & rate-limits this log point independently
// info_every!(100, "Processing orders"; customer_id = ?id);
//
// // In file2.rs - counts & rate-limits this log point independently
// info_every!(50, "Database query completed"; rows = ?count);
//
// Each of these macro expansions will create its own static COUNTER and TIME_WINDOW_START
// variables with unique symbol names. This ensures each log point is independently rate-limited
// based on its own invocation count and timing.