Skip to content

Commit 8e9d1f0

Browse files
committed
Shopify style logging which doesn't hate the terminal
Use key=value sets in log messages to make logs simpler to parse; ensure output is always properly escaped. Resolves #428 Contributors: - Ryan Biesemeyer (@yaauie) - Harry Brundage (@airhorns) - Oren Mazor (@orenmazor)
1 parent 831cccf commit 8e9d1f0

File tree

3 files changed

+18
-8
lines changed

3 files changed

+18
-8
lines changed

CHANGELOG.md

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,6 @@
1-
# (unreleased)
1+
# 3.1.x (unreleased)
22

3-
...
3+
* Added debug log sanitization (@airhorns, @orenmazor, @yaauie)
44

55
# 3.0.7
66

lib/redis/client.rb

Lines changed: 12 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -274,13 +274,23 @@ def logging(commands)
274274

275275
begin
276276
commands.each do |name, *args|
277-
@logger.debug("Redis >> #{name.to_s.upcase} #{args.map(&:to_s).join(" ")}")
277+
logged_args = args.map do |a|
278+
case
279+
when a.respond_to?(:inspect) then a.inspect
280+
when a.respond_to?(:to_s) then a.to_s
281+
else
282+
# handle poorly-behaved descendants of BasicObject
283+
klass = a.instance_exec { (class << self; self end).superclass }
284+
"\#<#{klass}:#{a.__id__}>"
285+
end
286+
end
287+
@logger.debug("[Redis] command=#{name.to_s.upcase} args=#{logged_args.join(' ')}")
278288
end
279289

280290
t1 = Time.now
281291
yield
282292
ensure
283-
@logger.debug("Redis >> %0.2fms" % ((Time.now - t1) * 1000)) if t1
293+
@logger.debug("[Redis] call_time=%0.2f ms" % ((Time.now - t1) * 1000)) if t1
284294
end
285295
end
286296

test/internals_test.rb

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -9,8 +9,8 @@ class TestInternals < Test::Unit::TestCase
99
def test_logger
1010
r.ping
1111

12-
assert log.string =~ /Redis >> PING/
13-
assert log.string =~ /Redis >> \d+\.\d+ms/
12+
assert log.string["[Redis] command=PING"]
13+
assert log.string =~ /\[Redis\] call_time=\d+\.\d+ ms/
1414
end
1515

1616
def test_logger_with_pipelining
@@ -19,8 +19,8 @@ def test_logger_with_pipelining
1919
r.get "foo"
2020
end
2121

22-
assert log.string["SET foo bar"]
23-
assert log.string["GET foo"]
22+
assert log.string[" command=SET args=\"foo\" \"bar\""]
23+
assert log.string[" command=GET args=\"foo\""]
2424
end
2525

2626
def test_recovers_from_failed_commands

0 commit comments

Comments
 (0)