Module: DatabaseLogger

Defined in:
lib/middleware/database_logger.rb

Overview

DatabaseLogger is redis-rb middleware for command logging and capture.

Provides detailed Redis command logging for development and debugging. Familia uses the redis-rb gem (v4.8.1 to <6.0), which internally uses RedisClient infrastructure for middleware. Users work with Redis.new connections and Redis:: exceptions - RedisClient is an implementation detail.

User-Facing API

Enable via Familia configuration: Familia.enable_database_logging = true

Familia automatically calls RedisClient.register(DatabaseLogger) internally.

Critical: Uses super not yield for middleware chaining

Internal: RedisClient Middleware Architecture

RedisClient middlewares are modules that are included into the RedisClient::Middlewares class, which inherits from BasicMiddleware. The middleware chain works through Ruby's method lookup and super.

Middleware Chain Flow (Internal)

# Internal registration order (last registered is called first):
RedisClient.register(DatabaseLogger)         # Called second (internal)
RedisClient.register(DatabaseCommandCounter)  # Called first (internal)

# Execution flow when client.call('SET', 'key', 'value') is invoked:
DatabaseCommandCounter.call(cmd, config) { |result| ... }
  └─> super  # Implicitly passes block to next middleware
      └─> DatabaseLogger.call(cmd, config)
          └─> super  # Implicitly passes block to next middleware
              └─> BasicMiddleware.call(cmd, config)
                  └─> yield command  # Executes actual Redis command
                      └─> Returns result
                  ← result flows back up
              ← result flows back up
          ← result flows back up
      ← result flows back up

Critical Implementation Detail: super vs yield

MUST use super to properly chain middlewares. Using yield breaks the chain because it executes the original block directly, bypassing other middlewares in the chain.

# ✅ CORRECT - Chains to next middleware
def call(command, config)
  result = super  # Calls next middleware, block passes implicitly
  result
end

# ❌ WRONG - Breaks middleware chain
def call(command, config)
  result = yield  # Executes block directly, skips other middlewares!
  result
end

When super is called:

  1. Ruby automatically passes the block to the next method in the chain
  2. The next middleware's call method executes
  3. Eventually reaches BasicMiddleware.call which does yield command
  4. The actual Redis command executes
  5. Results flow back up through each middleware

Usage Examples

rubocop:disable ThreadSafety/ClassInstanceVariable

Examples:

Enable Redis command logging (recommended user-facing API)

Familia.enable_database_logging = true

Capture commands for testing

commands = DatabaseLogger.capture_commands do
  redis.set('key', 'value')
  redis.get('key')
end
puts commands.first.command  # => "SET key value"

Use with DatabaseCommandCounter

Familia.enable_database_logging = true
Familia.enable_database_counter = true
# Both middlewares registered automatically and execute correctly in sequence

See Also:

Defined Under Namespace

Classes: CommandMessage

Class Attribute Summary collapse

Class Method Summary collapse

Instance Method Summary collapse

Class Attribute Details

.capture_enabled ⇒ Boolean

Note:

When false, a command that is also not sampled for logging and has no registered instrumentation hook skips timing entirely. Log output still follows sample_rate, and instrumentation hooks still fire at full rate (timing is measured whenever a hook is registered).

Gets/sets whether commands are captured into the buffer.

This toggle is independent of #sample_rate, which governs only log output. Capture controls whether each command pays the cost of timing, CommandMessage allocation, and the buffer append.

Examples:

Development / test (default) — full capture for assertions

DatabaseLogger.capture_enabled = true
# every command captured; capture_commands works as usual

Production — sampled logging, no buffer/timing overhead

DatabaseLogger.sample_rate = 0.01
DatabaseLogger.capture_enabled = false
# 1% of commands logged; unsampled commands take the zero-overhead
# fast path (no clock_gettime, no allocation, no buffer append) unless
# an instrumentation hook is registered

Returns:

  • (Boolean) —

    Whether command capture is enabled (default true)



216
217
218
 
# File 'lib/middleware/database_logger.rb', line 216

def capture_enabled
  @capture_enabled
end

.commands ⇒ Array<CommandMessage> (readonly)

Gets the captured commands for testing purposes.

Returns:



220
221
222
 
# File 'lib/middleware/database_logger.rb', line 220

def commands
  @commands
end

.logger ⇒ Logger?

Gets/sets the logger instance used by DatabaseLogger.

Returns:

  • (Logger, nil) —

    The current logger instance or nil if not set.



119
120
121
 
# File 'lib/middleware/database_logger.rb', line 119

def logger
  @logger
end

.max_commands ⇒ Integer

Gets/sets the maximum number of commands to capture.

Returns:

  • (Integer) —

    The maximum number of commands to capture.



123
124
125
 
# File 'lib/middleware/database_logger.rb', line 123

def max_commands
  @max_commands
end

.process_start ⇒ Float (readonly)

Gets the timestamp when DatabaseLogger was loaded.

Returns:

  • (Float) —

    The timestamp when DatabaseLogger was loaded.



224
225
226
 
# File 'lib/middleware/database_logger.rb', line 224

def process_start
  @process_start
end

.sample_rate ⇒ Float?

Note:

Command capture is unaffected - only logger output is sampled. This means tests can still verify commands while production logs stay clean.

Gets the sampling rate for logging. Controls what percentage of commands are logged to reduce noise.

Examples:

Log 10% of commands

DatabaseLogger.sample_rate = 0.1

Log 1% of commands (high-traffic production)

DatabaseLogger.sample_rate = 0.01

Disable sampling (log everything)

DatabaseLogger.sample_rate = nil

Returns:

  • (Float, nil) —

    Sample rate in (0.0, 1.0] or nil for no sampling



156
157
158
 
# File 'lib/middleware/database_logger.rb', line 156

def sample_rate
  @sample_rate
end

.structured_logging ⇒ Boolean

Gets/sets structured logging mode. When enabled, outputs Redis commands with structured key=value context instead of formatted string output.

Examples:

Enable structured logging

DatabaseLogger.structured_logging = true
# Outputs: "Redis command cmd=SET args=[key, value] duration_ms=0.42 db=0"

Disable (default formatted output)

DatabaseLogger.structured_logging = false
# Outputs: "[123] 0.001234 567μs > SET key value"

Returns:

  • (Boolean) —

    Whether structured logging is enabled



138
139
140
 
# File 'lib/middleware/database_logger.rb', line 138

def structured_logging
  @structured_logging
end

Class Method Details

.append_command(message) ⇒ Array<CommandMessage>

This method is part of a private API. You should avoid using this method if possible, as it may be removed or be changed in the future.

Appends a command message to the captured commands array.

When the array reaches max_commands capacity, the oldest command is removed before adding the new one.

Parameters:

Returns:



270
271
272
273
274
275
276
277
 
# File 'lib/middleware/database_logger.rb', line 270

def append_command(message)
  # We can throw away commands and not worry about thread race conditions
  # since no one is going to mind if the command list is +/- a few
  # commands. Unlike how we care about the order that the commands
  # appear in the list, we don't care about exact count when trimming.
  @commands.shift if @commands.size >= @max_commands
  @commands << message # this is threadsafe thanks to Concurrent::Array
end

.capture_commands { ... } ⇒ Array<CommandMessage>

Captures commands in a block and returns them. This is useful for testing to see what commands were executed.

Examples:

Test what Redis commands your code executes

commands = DatabaseLogger.capture_commands do
  my_library_method()
end
assert_equal "SET", commands.first.command.split.first
assert commands.first.μs > 0

Yields:

  • [] The block of code to execute while capturing commands.

Returns:



250
251
252
253
254
 
# File 'lib/middleware/database_logger.rb', line 250

def capture_commands
  clear_commands
  yield
  @commands.to_a
end

.clear_commands ⇒ nil

Clears the captured commands array.

Thread-safe via mutex to ensure test isolation.

Returns:

  • (nil) 


231
232
233
234
235
236
 
# File 'lib/middleware/database_logger.rb', line 231

def clear_commands
  @commands_mutex.synchronize do
    @commands.clear
  end
  nil
end

.command_string(raw, mode) ⇒ Object

This method is part of a private API. You should avoid using this method if possible, as it may be removed or be changed in the future. 



415
416
417
418
419
420
421
 
# File 'lib/middleware/database_logger.rb', line 415

def command_string(raw, mode)
  if mode == :pipeline
    raw.map { |cmd| cmd.join(' ') }.join(' | ')
  else
    raw.join(' ')
  end
end

.connection_meta(config) ⇒ Object

This method is part of a private API. You should avoid using this method if possible, as it may be removed or be changed in the future.

Extracts [db, connection_id] from either a RedisClient::Config or a Hash.



425
426
427
428
429
430
431
432
433
434
435
436
437
 
# File 'lib/middleware/database_logger.rb', line 425

def connection_meta(config)
  db = if config.respond_to?(:db)
         config.db
       elsif config.is_a?(Hash)
         config[:db]
       end
  conn_id = if config.respond_to?(:custom)
              config.custom&.dig(:id)
            elsif config.is_a?(Hash)
              config.dig(:custom, :id)
            end
  [db, conn_id]
end

.emit_log(raw, config, duration, lifetime, mode, msgpack) ⇒ Object

This method is part of a private API. You should avoid using this method if possible, as it may be removed or be changed in the future.

Emits a single sampled log line: structured key=value context, or the legacy "[index] timeline durationμs > command" format.



405
406
407
408
409
410
411
412
 
# File 'lib/middleware/database_logger.rb', line 405

def emit_log(raw, config, duration, lifetime, mode, msgpack)
  message = if @structured_logging
              structured_log_message(raw, config, duration, lifetime, mode)
            else
              format('[%s] %s', index, msgpack.inspect)
            end
  @logger.trace(message)
end

.hook_type_for(mode) ⇒ Symbol?

This method is part of a private API. You should avoid using this method if possible, as it may be removed or be changed in the future.

Maps a middleware mode to the instrumentation hook type it reports to, or nil when that mode emits no instrumentation.

This is the SINGLE SOURCE OF TRUTH for the per-mode instrumentation contract. Both the fast-path decision (#measure?) and the notify step (#record) consult it, so a mode can never end up measuring without notifying (wasted work) or notifying from a fast-pathed call (a silently dropped hook). +:once+ returns nil because +call_once+ does not emit instrumentation today; to change that, flip this one method and both the fast path and the notify step update together.

Parameters:

  • mode (Symbol) —

    :call, :once, or :pipeline

Returns:

  • (Symbol, nil) —

    :command, :pipeline, or nil



331
332
333
334
335
336
337
 
# File 'lib/middleware/database_logger.rb', line 331

def hook_type_for(mode)
  case mode
  when :pipeline then :pipeline
  when :call then :command
  when :once then nil # call_once emits no instrumentation today
  end
end

.hooks_active?(type) ⇒ Boolean

This method is part of a private API. You should avoid using this method if possible, as it may be removed or be changed in the future.

Whether any instrumentation hooks are registered for +type+.

Guards against +Familia::Instrumentation+ being undefined, then defers to its +hooks?+ predicate. A +defined?+ check alone cannot gate the fast path because the module is always loaded.

Parameters:

  • type (Symbol, nil) —

    hook type, or nil for "no instrumentation"

Returns:

  • (Boolean) 


348
349
350
351
352
 
# File 'lib/middleware/database_logger.rb', line 348

def hooks_active?(type)
  return false if type.nil?

  defined?(Familia::Instrumentation) && Familia::Instrumentation.hooks?(type)
end

.index ⇒ Integer

Gets the current count of captured commands.

Returns:

  • (Integer) —

    The number of commands currently captured



258
259
260
 
# File 'lib/middleware/database_logger.rb', line 258

def index
  @commands.size
end

.measure?(should_log:, mode:) ⇒ Boolean

This method is part of a private API. You should avoid using this method if possible, as it may be removed or be changed in the future.

Decide whether an invocation needs the measured (non-fast) path.

Returns true when capture is enabled, the command is sampled for logging, or a relevant instrumentation hook is registered. When all three are false the caller takes the zero-overhead fast path (no clock_gettime, no CommandMessage allocation, no buffer append).

Parameters:

  • should_log (Boolean) —

    result of the single per-command should_log? call (passed in so the sampling counter is advanced exactly once)

  • mode (Symbol) —

    :call, :once, or :pipeline

Returns:

  • (Boolean) 


366
367
368
 
# File 'lib/middleware/database_logger.rb', line 366

def measure?(should_log:, mode:)
  @capture_enabled || should_log || hooks_active?(hook_type_for(mode))
end

.notify_hook(raw, config, duration, hook) ⇒ Object

This method is part of a private API. You should avoid using this method if possible, as it may be removed or be changed in the future. 



457
458
459
460
461
462
463
464
465
466
467
468
469
470
471
 
# File 'lib/middleware/database_logger.rb', line 457

def notify_hook(raw, config, duration, hook)
  duration_ms = (duration / 1000.0).round(2)
  db_num, conn_id = connection_meta(config)

  if hook == :pipeline
    Familia::Instrumentation.notify_pipeline(
      raw.size, duration_ms, db: db_num, connection_id: conn_id
    )
  else
    Familia::Instrumentation.notify_command(
      raw.first, duration_ms,
      full_command: raw, db: db_num, connection_id: conn_id
    )
  end
end

.now_in_μs ⇒ Integer Also known as: now_in_microseconds

Returns the current time in microseconds. This is used to measure the duration of Redis commands.

Returns:

  • (Integer) —

    The current time in microseconds



283
284
285
 
# File 'lib/middleware/database_logger.rb', line 283

def now_in_μs
  Process.clock_gettime(Process::CLOCK_MONOTONIC, :microsecond)
end

.record(raw, config, duration, mode:, should_log:) ⇒ nil

This method is part of a private API. You should avoid using this method if possible, as it may be removed or be changed in the future.

Record a measured command: buffer it, emit a sampled log line, and fire the instrumentation hook. Called only on the measured path, after the wrapped command has executed and been timed.

Parameters:

  • raw (Array) —

    the single command array (:call/:once) or the array of command arrays (:pipeline)

  • config —

    connection configuration

  • duration (Integer) —

    measured execution time in microseconds

  • mode (Symbol) —

    :call, :once, or :pipeline

  • should_log (Boolean) —

    the per-command should_log? result

Returns:

  • (nil) 


382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
 
# File 'lib/middleware/database_logger.rb', line 382

def record(raw, config, duration, mode:, should_log:)
  lifetime = (Familia.now.to_f - @process_start).round(6)

  # Build the CommandMessage only when capturing or logging needs it; append
  # to the buffer only when capture is enabled. The hook-only path (capture
  # off, not sampled, but a hook is registered) skips the buffer entirely.
  msgpack = nil
  if @capture_enabled || should_log
    msgpack = CommandMessage.new(command_string(raw, mode), duration, lifetime)
    append_command(msgpack) if @capture_enabled
  end

  emit_log(raw, config, duration, lifetime, mode, msgpack) if should_log && @logger

  hook = hook_type_for(mode)
  notify_hook(raw, config, duration, hook) if hooks_active?(hook)

  nil
end

.should_log? ⇒ Boolean

This method is part of a private API. You should avoid using this method if possible, as it may be removed or be changed in the future.

Determines if this command should be logged based on sampling rate.

Uses deterministic modulo-based sampling for consistent behavior. Thread-safe via atomic counter increment.

Returns:

  • (Boolean) —

    true if command should be logged



295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
 
# File 'lib/middleware/database_logger.rb', line 295

def should_log?
  # No logger means no log line can be emitted -- bail before the rate
  # check so nil-rate + nil-logger configs keep the zero-overhead path.
  return false if @logger.nil?

  # Read once: a concurrent `sample_rate = nil` between checks must not
  # raise on the hot path.
  rate = @sample_rate
  return true if rate.nil?

  # The writer validates, but the ivar can still be set directly (subclass,
  # instance_variable_set), so guard against a non-finite interval here too
  # (e.g. a subnormal rate where 1.0 / rate overflows to Infinity).
  interval = 1.0 / rate
  return false unless interval.finite?

  # Deterministic sampling: every Nth command where N = 1/sample_rate
  # e.g., 0.1 = every 10th, 0.01 = every 100th; rates >= 1.0 clamp the
  # interval to 1, so every call increments the counter and logs.
  (@sample_counter.increment % [1, interval.to_i].max).zero?
end

.structured_log_message(raw, config, duration, lifetime, mode) ⇒ Object

This method is part of a private API. You should avoid using this method if possible, as it may be removed or be changed in the future. 



440
441
442
443
444
445
446
447
448
449
450
451
452
453
454
 
# File 'lib/middleware/database_logger.rb', line 440

def structured_log_message(raw, config, duration, lifetime, mode)
  duration_ms = (duration / 1000.0).round(2)
  db_num, = connection_meta(config)
  common = "duration_μs=#{duration} duration_ms=#{duration_ms} " \
           "timeline=#{lifetime} db=#{db_num} index=#{index}"

  case mode
  when :pipeline
    "Redis pipeline commands=#{raw.size} #{common}"
  when :once
    "Redis command_once cmd=#{raw.first} args=#{raw[1..].inspect} #{common}"
  else
    "Redis command cmd=#{raw.first} args=#{raw[1..].inspect} #{common}"
  end
end

Instance Method Details

#call(command, config) ⇒ Object

Note:

should_log? is evaluated exactly once per command to keep the sampling counter deterministic. On the fast path nothing is timed or allocated.

Logs the Redis command and its execution time.

This method is part of the RedisClient middleware chain. It MUST use super instead of yield to properly chain with other middlewares. The shared decision/record logic lives in measure? and record; only the execution+timing skeleton stays here so the fast path remains allocation-free and super keeps chaining.

Parameters:

  • command (Array) —

    The Redis command and its arguments

  • config (RedisClient::Config, Hash) —

    Connection configuration

Returns:

  • (Object) —

    The result of the Redis command execution



488
489
490
491
492
493
494
495
496
497
498
 
# File 'lib/middleware/database_logger.rb', line 488

def call(command, config)
  should_log = DatabaseLogger.should_log?
  return super unless DatabaseLogger.measure?(should_log: should_log, mode: :call)

  block_start = DatabaseLogger.now_in_μs
  result = super  # CRITICAL: Must use super, not yield, to chain middlewares
  duration = DatabaseLogger.now_in_μs - block_start

  DatabaseLogger.record(command, config, duration, mode: :call, should_log: should_log)
  result
end

#call_once(command, config) ⇒ Object

Note:

call_once shares the same record path as #call. Whether it emits instrumentation is governed entirely by hook_type_for (currently :once => nil), so the fast-path decision and the notify step stay in lockstep.

Handle call_once for commands requiring dedicated connection handling:

  • Blocking commands (BLPOP, BRPOP, BRPOPLPUSH)
  • Pub/sub operations (SUBSCRIBE, PSUBSCRIBE)
  • Commands requiring connection affinity
  • Explicit non-pooled command execution

Parameters:

  • command (Array) —

    The Redis command and its arguments

  • config (RedisClient::Config, Hash) —

    Connection configuration

Returns:

  • (Object) —

    The result of the Redis command execution



536
537
538
539
540
541
542
543
544
545
546
 
# File 'lib/middleware/database_logger.rb', line 536

def call_once(command, config)
  should_log = DatabaseLogger.should_log?
  return yield unless DatabaseLogger.measure?(should_log: should_log, mode: :once)

  block_start = DatabaseLogger.now_in_μs
  result = yield  # CRITICAL: For call_once, yield is correct (not chaining)
  duration = DatabaseLogger.now_in_μs - block_start

  DatabaseLogger.record(command, config, duration, mode: :once, should_log: should_log)
  result
end

#call_pipelined(commands, config) ⇒ Array

Handle pipelined commands (including MULTI/EXEC transactions)

Captures MULTI/EXEC and shows you the full transaction. The WATCH and EXISTS appear separately because they're executed as individual commands before the transaction starts.

Parameters:

  • commands (Array<Array>) —

    Array of command arrays

  • config (RedisClient::Config, Hash) —

    Connection configuration

Returns:

  • (Array) —

    Results from pipelined commands



509
510
511
512
513
514
515
516
517
518
519
 
# File 'lib/middleware/database_logger.rb', line 509

def call_pipelined(commands, config)
  should_log = DatabaseLogger.should_log?
  return yield unless DatabaseLogger.measure?(should_log: should_log, mode: :pipeline)

  block_start = DatabaseLogger.now_in_μs
  results = yield  # CRITICAL: For call_pipelined, yield is correct (not chaining)
  duration = DatabaseLogger.now_in_μs - block_start

  DatabaseLogger.record(commands, config, duration, mode: :pipeline, should_log: should_log)
  results
end