Module: DatabaseLogger

Defined in:
lib/middleware/database_logger.rb

Overview

Note:

While there were concerns about the performance impact of logging in the redis-rb gem, this middleware is designed to be optional and can be easily enabled or disabled as needed. The performance impact is minimal when logging is disabled, and the benefits during development and debugging often outweigh the slight performance cost when enabled.

DatabaseLogger is Valkey/RedisClient middleware.

This middleware addresses the need for detailed Database command logging, which was removed from the redis-rb gem due to performance concerns. However, in many development and debugging scenarios, the ability to log Database commands can be invaluable.

Examples:

Enable Database command logging

DatabaseLogger.logger = Logger.new(STDOUT)
RedisClient.register(DatabaseLogger)

Capture commands for testing

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

See Also:

Constant Summary collapse

CommandMessage = 
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 (readonly)

Gets the captured commands for testing purposes.

Returns:

  • (Array) —

    Array of command hashes with :command, :duration, :timeline



55
56
57
 
# File 'lib/middleware/database_logger.rb', line 55

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.



47
48
49
 
# File 'lib/middleware/database_logger.rb', line 47

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.



51
52
53
 
# File 'lib/middleware/database_logger.rb', line 51

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.



59
60
61
 
# File 'lib/middleware/database_logger.rb', line 59

def process_start
  @process_start
end

Class Method Details

.append_command(message) ⇒ Array

Thread-safe append with bounded size

Parameters:

  • message (String) —

    The message to append.

Returns:

  • (Array) —

    The updated array of commands.



97
98
99
100
 
# File 'lib/middleware/database_logger.rb', line 97

def append_command(message)
  @commands.shift if @commands.size >= @max_commands
  @commands << message
end

.capture_commands { ... } ⇒ Array

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][0]
assert commands.first[:duration] > 0

Yields:

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

Returns:

  • (Array) —

    Array of captured commands with timing information. Each command is a hash with :command, :duration, :timestamp keys.



81
82
83
84
85
 
# File 'lib/middleware/database_logger.rb', line 81

def capture_commands
  clear_commands
  yield
  @commands.to_a
end

.clear_commands ⇒ Array

Clears the captured commands array.

Returns:

  • (Array) —

    Empty array



63
64
65
66
 
# File 'lib/middleware/database_logger.rb', line 63

def clear_commands
  @commands.clear
  nil
end

.index ⇒ Integer

Gets the current count of Database commands executed.

Returns:

  • (Integer) —

    The number of Database commands executed.



89
90
91
 
# File 'lib/middleware/database_logger.rb', line 89

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 Database commands.

Alias: now_in_microseconds

Returns:

  • (Integer) —

    The current time in microseconds.



108
109
110
 
# File 'lib/middleware/database_logger.rb', line 108

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

Instance Method Details

#call(command, _config) ⇒ Object

Note:

Commands are always captured with minimal overhead for testing purposes. Logging only occurs when DatabaseLogger.logger is set.

Logs the Database command and its execution time.

This method is called for each Database command when the middleware is active. It always captures commands for testing and logs them if a logger is set.

Parameters:

  • command (Array) —

    The Database command and its arguments.

  • _config (Hash) —

    The configuration options for the Valkey/Redis connection.

Returns:

  • (Object) —

    The result of the Database command execution.



126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
 
# File 'lib/middleware/database_logger.rb', line 126

def call(command, _config)
  block_start = DatabaseLogger.now_in_μs
  result = yield
  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)

  # Log if logger is set
  message = format('[%s] %s', DatabaseLogger.index, msgpack.inspect)
  DatabaseLogger.logger&.trace(message)

  result
end

#call_once(command, _config) ⇒ Object

call_once is used for commands that need dedicated connection handling:

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


175
176
177
178
179
180
181
182
183
184
185
186
187
188
 
# File 'lib/middleware/database_logger.rb', line 175

def call_once(command, _config)
  block_start = DatabaseLogger.now_in_μs
  result = yield
  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)

  message = format('[%s] %s', DatabaseLogger.index, msgpack.inspect)
  DatabaseLogger.logger&.trace(message)

  result
end

#call_pipelined(commands, _config) ⇒ Object

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.



151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
 
# File 'lib/middleware/database_logger.rb', line 151

def call_pipelined(commands, _config)
  block_start = DatabaseLogger.now_in_μs
  results = yield
  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)

  message = format('[%s] %s', DatabaseLogger.index, msgpack.inspect)
  DatabaseLogger.logger&.trace(message)

  results
end