Merge branch 'issue-428/shopify-style-logging'

Author: yaauie

CHANGELOG.md

@@ -1,6 +1,6 @@
-# (unreleased)
+# 3.1.x (unreleased)
 
-...
+* Added debug log sanitization (@airhorns, @orenmazor, @yaauie)
 
 # 3.0.7
 

lib/redis/client.rb

@@ -274,13 +274,23 @@ def logging(commands)
 
       begin
         commands.each do |name, *args|
-          @logger.debug("Redis >> #{name.to_s.upcase} #{args.map(&:to_s).join(" ")}")
+          logged_args = args.map do |a|
+            case
+            when a.respond_to?(:inspect) then a.inspect
+            when a.respond_to?(:to_s)    then a.to_s
+            else
+              # handle poorly-behaved descendants of BasicObject
+              klass = a.instance_exec { (class << self; self end).superclass }
+              "\#<#{klass}:#{a.__id__}>"
+            end
+          end
+          @logger.debug("[Redis] command=#{name.to_s.upcase} args=#{logged_args.join(' ')}")
         end
 
         t1 = Time.now
         yield
       ensure
-        @logger.debug("Redis >> %0.2fms" % ((Time.now - t1) * 1000)) if t1
+        @logger.debug("[Redis] call_time=%0.2f ms" % ((Time.now - t1) * 1000)) if t1
       end
     end
 

test/internals_test.rb

@@ -9,8 +9,8 @@ class TestInternals < Test::Unit::TestCase
   def test_logger
     r.ping
 
-    assert log.string =~ /Redis >> PING/
-      assert log.string =~ /Redis >> \d+\.\d+ms/
+    assert log.string["[Redis] command=PING"]
+    assert log.string =~ /\[Redis\] call_time=\d+\.\d+ ms/
   end
 
   def test_logger_with_pipelining
@@ -19,8 +19,8 @@ def test_logger_with_pipelining
       r.get "foo"
     end
 
-    assert log.string["SET foo bar"]
-    assert log.string["GET foo"]
+    assert log.string[" command=SET args=\"foo\" \"bar\""]
+    assert log.string[" command=GET args=\"foo\""]
   end
 
   def test_recovers_from_failed_commands