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:

Constant Summary collapse

CommandMessage =

Data structure for captured command metadata

Data.define(:command, :μs, :timeline) do
  alias_method :to_a, :deconstruct

  def inspect
    cmd, duration, timeline = to_a
    format('%.6f %4dμs > %s', timeline, duration, cmd)
  end
end

Class Attribute Summary collapse

Class Method Summary collapse

Instance Method Summary collapse

Class Attribute Details

.commands ⇒ Array<CommandMessage> (readonly)

Gets the captured commands for testing purposes.

Returns:



159
160
161
 
# File 'lib/middleware/database_logger.rb', line 159

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.



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

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.



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

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.



163
164
165
 
# File 'lib/middleware/database_logger.rb', line 163

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/sets 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 (0.0-1.0) or nil for no sampling



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

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



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

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:



209
210
211
212
213
214
215
216
 
# File 'lib/middleware/database_logger.rb', line 209

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:



189
190
191
192
193
 
# File 'lib/middleware/database_logger.rb', line 189

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) 


170
171
172
173
174
175
 
# File 'lib/middleware/database_logger.rb', line 170

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

.index ⇒ Integer

Gets the current count of captured commands.

Returns:

  • (Integer) —

    The number of commands currently captured



197
198
199
 
# File 'lib/middleware/database_logger.rb', line 197

def index
  @commands.size
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



222
223
224
 
# File 'lib/middleware/database_logger.rb', line 222

def now_in_μs
  Process.clock_gettime(Process::CLOCK_MONOTONIC, :microsecond)
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



234
235
236
237
238
239
240
241
242
 
# File 'lib/middleware/database_logger.rb', line 234

def should_log?
  return true if @sample_rate.nil?
  return false if @logger.nil?

  # Deterministic sampling: every Nth command where N = 1/sample_rate
  # e.g., 0.1 = every 10th, 0.01 = every 100th
  sample_interval = (1.0 / @sample_rate).to_i
  (@sample_counter.increment % sample_interval).zero?
end

Instance Method Details

#call(command, config) ⇒ Object

Note:

Commands are always captured for testing. Logging only occurs when DatabaseLogger.logger is set and sampling allows it.

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.

Parameters:

  • command (Array) —

    The Redis command and its arguments

  • config (RedisClient::Config, Hash) —

    Connection configuration

Returns:

  • (Object) —

    The result of the Redis command execution



256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
 
# File 'lib/middleware/database_logger.rb', line 256

def call(command, config)
  block_start = DatabaseLogger.now_in_μs
  result = super  # CRITICAL: Must use super, not yield, to chain middlewares
  block_duration = DatabaseLogger.now_in_μs - block_start

  # We intentionally use two different codepaths for getting the
  # time, although they will almost always be so similar that the
  # difference is negligible.
  lifetime_duration = (Time.now.to_f - DatabaseLogger.process_start).round(6)

  msgpack = CommandMessage.new(command.join(' '), block_duration, lifetime_duration)
  DatabaseLogger.append_command(msgpack)

  # Dual-mode logging with sampling
  if DatabaseLogger.should_log?
    if DatabaseLogger.structured_logging && DatabaseLogger.logger
      duration_ms = (block_duration / 1000.0).round(2)
      db_num = if config.respond_to?(:db)
                 config.db
               elsif config.is_a?(Hash)
                 config[:db]
               end
      DatabaseLogger.logger.trace(
        "Redis command cmd=#{command.first} args=#{command[1..-1].inspect} " \
        "duration_μs=#{block_duration} duration_ms=#{duration_ms} " \
        "timeline=#{lifetime_duration} db=#{db_num} index=#{DatabaseLogger.index}"
      )
    elsif DatabaseLogger.logger
      # Existing formatted output
      message = format('[%s] %s', DatabaseLogger.index, msgpack.inspect)
      DatabaseLogger.logger.trace(message)
    end
  end

  # Notify instrumentation hooks
  if defined?(Familia::Instrumentation)
    duration_ms = (block_duration / 1000.0).round(2)
    db_num = 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
    Familia::Instrumentation.notify_command(
      command.first,
      duration_ms,
      full_command: command,
      db: db_num,
      connection_id: conn_id,
    )
  end

  result
end

#call_once(command, config) ⇒ Object

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



389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
 
# File 'lib/middleware/database_logger.rb', line 389

def call_once(command, config)
  block_start = DatabaseLogger.now_in_μs
  result = yield  # CRITICAL: For call_once, yield is correct (not chaining)
  block_duration = DatabaseLogger.now_in_μs - block_start
  lifetime_duration = (Time.now.to_f - DatabaseLogger.process_start).round(6)

  msgpack = CommandMessage.new(command.join(' '), block_duration, lifetime_duration)
  DatabaseLogger.append_command(msgpack)

  # Dual-mode logging with sampling
  if DatabaseLogger.should_log?
    if DatabaseLogger.structured_logging && DatabaseLogger.logger
      duration_ms = (block_duration / 1000.0).round(2)
      db_num = if config.respond_to?(:db)
                 config.db
               elsif config.is_a?(Hash)
                 config[:db]
               end
      DatabaseLogger.logger.trace(
        "Redis command_once cmd=#{command.first} args=#{command[1..-1].inspect} " \
        "duration_μs=#{block_duration} duration_ms=#{duration_ms} " \
        "timeline=#{lifetime_duration} db=#{db_num} index=#{DatabaseLogger.index}"
      )
    elsif DatabaseLogger.logger
      message = format('[%s] %s', DatabaseLogger.index, msgpack.inspect)
      DatabaseLogger.logger.trace(message)
    end
  end

  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



324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
 
# File 'lib/middleware/database_logger.rb', line 324

def call_pipelined(commands, config)
  block_start = DatabaseLogger.now_in_μs
  results = yield  # CRITICAL: For call_pipelined, yield is correct (not chaining)
  block_duration = DatabaseLogger.now_in_μs - block_start
  lifetime_duration = (Time.now.to_f - DatabaseLogger.process_start).round(6)

  # Log the entire pipeline as a single operation
  cmd_string = commands.map { |cmd| cmd.join(' ') }.join(' | ')
  msgpack = CommandMessage.new(cmd_string, block_duration, lifetime_duration)
  DatabaseLogger.append_command(msgpack)

  # Dual-mode logging with sampling
  if DatabaseLogger.should_log?
    if DatabaseLogger.structured_logging && DatabaseLogger.logger
      duration_ms = (block_duration / 1000.0).round(2)
      db_num = if config.respond_to?(:db)
                 config.db
               elsif config.is_a?(Hash)
                 config[:db]
               end
      DatabaseLogger.logger.trace(
        "Redis pipeline commands=#{commands.size} duration_μs=#{block_duration} " \
        "duration_ms=#{duration_ms} timeline=#{lifetime_duration} " \
        "db=#{db_num} index=#{DatabaseLogger.index}"
      )
    elsif DatabaseLogger.logger
      message = format('[%s] %s', DatabaseLogger.index, msgpack.inspect)
      DatabaseLogger.logger.trace(message)
    end
  end

  # Notify instrumentation hooks
  if defined?(Familia::Instrumentation)
    duration_ms = (block_duration / 1000.0).round(2)
    db_num = 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
    Familia::Instrumentation.notify_pipeline(
      commands.size,
      duration_ms,
      db: db_num,
      connection_id: conn_id
    )
  end

  results
end