From db74ce9aa9ca7ffae9eb93b2037c4311805d3132 Mon Sep 17 00:00:00 2001 From: Will Maier Date: Thu, 6 Jan 2011 10:27:04 -0600 Subject: add logging boilerplate --- redis/client.py | 11 +++++++++++ 1 file changed, 11 insertions(+) diff --git a/redis/client.py b/redis/client.py index 967bcee..c473444 100644 --- a/redis/client.py +++ b/redis/client.py @@ -1,5 +1,6 @@ import datetime import errno +import logging import socket import threading import time @@ -8,6 +9,16 @@ from itertools import chain, imap from redis.exceptions import ConnectionError, ResponseError, InvalidResponse, WatchError from redis.exceptions import RedisError, AuthenticationError +try: + NullHandler = logging.NullHandler +except AttributeError: + class NullHandler(logging.Handler): + def emit(self, record): pass + +log = logging.getLogger("redis") +# Add a no-op handler to avoid error messages if the importing module doesn't +# configure logging. +log.addHandler(NullHandler()) class ConnectionPool(threading.local): "Manages a list of connections on the local thread" -- cgit v1.2.1 From 518801e263d2c014eb3dfb76201ba8015c1bd1e1 Mon Sep 17 00:00:00 2001 From: Will Maier Date: Thu, 6 Jan 2011 10:37:31 -0600 Subject: add repr_command(), a function to consistently represent commands --- redis/client.py | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/redis/client.py b/redis/client.py index c473444..56d5af9 100644 --- a/redis/client.py +++ b/redis/client.py @@ -159,6 +159,14 @@ def dict_merge(*dicts): [merged.update(d) for d in dicts] return merged +def repr_command(args): + "Represents a command as a string." + command = [args[0]] + if len(args) > 1: + command.extend(repr(x) for x in args[1:]) + + return ' '.join(command) + def parse_info(response): "Parse the result of Redis's INFO command into a Python dict" info = {} -- cgit v1.2.1 From 2dee8e9ae6ba516ba70014030fdd6b6002061128 Mon Sep 17 00:00:00 2001 From: Will Maier Date: Thu, 6 Jan 2011 12:41:50 -0600 Subject: encode commands at the last possible moment to make logging easier later --- redis/client.py | 18 +++++++++++------- 1 file changed, 11 insertions(+), 7 deletions(-) diff --git a/redis/client.py b/redis/client.py index 56d5af9..9eeac78 100644 --- a/redis/client.py +++ b/redis/client.py @@ -336,6 +336,7 @@ class Redis(threading.local): if self.subscribed and not subscription_command: raise RedisError("Cannot issue commands other than SUBSCRIBE and " "UNSUBSCRIBE while channels are open") + command = self._encode_command(command) try: self.connection.send(command, self) if subscription_command: @@ -347,14 +348,17 @@ class Redis(threading.local): if subscription_command: return None return self.parse_response(command_name, **options) + + def _encode_command(self, args): + cmds = ['$%s\r\n%s\r\n' % (len(enc_value), enc_value) + for enc_value in imap(self.encode, args)] + return '*%s\r\n%s' % (len(cmds), ''.join(cmds)) def execute_command(self, *args, **options): "Sends the command to the redis server and returns it's response" - cmds = ['$%s\r\n%s\r\n' % (len(enc_value), enc_value) - for enc_value in imap(self.encode, args)] return self._execute_command( args[0], - '*%s\r\n%s' % (len(cmds), ''.join(cmds)), + args, **options ) @@ -1426,10 +1430,10 @@ class Pipeline(Redis): def _execute_transaction(self, commands): # wrap the commands in MULTI ... EXEC statements to indicate an # atomic operation - all_cmds = ''.join([c for _1, c, _2 in chain( - (('', 'MULTI\r\n', ''),), + all_cmds = ''.join([self._encode_command(c) for _1, c, _2 in chain( + (('', ('MULTI',), ''),), commands, - (('', 'EXEC\r\n', ''),) + (('', ('EXEC',), ''),) )]) self.connection.send(all_cmds, self) # parse off the response for MULTI and all commands prior to EXEC @@ -1455,7 +1459,7 @@ class Pipeline(Redis): def _execute_pipeline(self, commands): # build up all commands into a single request to increase network perf - all_cmds = ''.join([c for _1, c, _2 in commands]) + all_cmds = ''.join([self._encode_command(c) for _1, c, _2 in commands]) self.connection.send(all_cmds, self) data = [] for command_name, _, options in commands: -- cgit v1.2.1 From f90768d412e0a0eda54d2ecd9a92fef78f1d331d Mon Sep 17 00:00:00 2001 From: Will Maier Date: Thu, 6 Jan 2011 12:46:35 -0600 Subject: log commands sent to the server add tests, too --- redis/client.py | 7 +++++++ tests/__init__.py | 3 ++- tests/server_commands.py | 54 ++++++++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 63 insertions(+), 1 deletion(-) diff --git a/redis/client.py b/redis/client.py index 9eeac78..89b97aa 100644 --- a/redis/client.py +++ b/redis/client.py @@ -336,6 +336,7 @@ class Redis(threading.local): if self.subscribed and not subscription_command: raise RedisError("Cannot issue commands other than SUBSCRIBE and " "UNSUBSCRIBE while channels are open") + log.debug(repr_command(command)) command = self._encode_command(command) try: self.connection.send(command, self) @@ -1435,6 +1436,10 @@ class Pipeline(Redis): commands, (('', ('EXEC',), ''),) )]) + log.debug("MULTI") + for command in commands: + log.debug("TRANSACTION> "+ repr_command(command[1])) + log.debug("EXEC") self.connection.send(all_cmds, self) # parse off the response for MULTI and all commands prior to EXEC for i in range(len(commands)+1): @@ -1460,6 +1465,8 @@ class Pipeline(Redis): def _execute_pipeline(self, commands): # build up all commands into a single request to increase network perf all_cmds = ''.join([self._encode_command(c) for _1, c, _2 in commands]) + for command in commands: + log.debug("PIPELINE> " + repr_command(command[1])) self.connection.send(all_cmds, self) data = [] for command_name, _, options in commands: diff --git a/tests/__init__.py b/tests/__init__.py index 8931b07..63d6741 100644 --- a/tests/__init__.py +++ b/tests/__init__.py @@ -1,5 +1,5 @@ import unittest -from server_commands import ServerCommandsTestCase +from server_commands import ServerCommandsTestCase, LoggingTestCase from connection_pool import ConnectionPoolTestCase from pipeline import PipelineTestCase from lock import LockTestCase @@ -10,4 +10,5 @@ def all_tests(): suite.addTest(unittest.makeSuite(ConnectionPoolTestCase)) suite.addTest(unittest.makeSuite(PipelineTestCase)) suite.addTest(unittest.makeSuite(LockTestCase)) + suite.addTest(unittest.makeSuite(LoggingTestCase)) return suite diff --git a/tests/server_commands.py b/tests/server_commands.py index 2738e91..5e96dcf 100644 --- a/tests/server_commands.py +++ b/tests/server_commands.py @@ -3,6 +3,8 @@ import unittest import datetime import threading import time +import logging +import logging.handlers from distutils.version import StrictVersion class ServerCommandsTestCase(unittest.TestCase): @@ -1257,3 +1259,55 @@ class ServerCommandsTestCase(unittest.TestCase): # check that it is possible to get list content by key name for key in mapping.keys(): self.assertEqual(self.client.lrange(key, 0, -1), list(mapping[key])) + +class BufferingHandler(logging.handlers.BufferingHandler): + + def __init__(self): + logging.handlers.BufferingHandler.__init__(self, None) + + def shouldFlush(self, record): + return False + +class LoggingTestCase(unittest.TestCase): + + def get_client(self): + return redis.Redis(host='localhost', port=6379, db=9) + + def setUp(self): + self.client = self.get_client() + self.client.flushdb() + + self.log = logging.getLogger("redis") + self.log.setLevel(logging.DEBUG) + self.handler = BufferingHandler() + self.log.addHandler(self.handler) + self.buffer = self.handler.buffer + + def tearDown(self): + self.client.flushdb() + for c in self.client.connection_pool.get_all_connections(): + c.disconnect() + + def test_command_logging(self): + self.client.get("foo") + + self.assertEqual(len(self.buffer), 1) + self.assertEqual(self.buffer[0].msg, "GET 'foo'") + + def test_command_logging_pipeline(self): + pipe = self.client.pipeline(transaction=False) + pipe.get("foo") + pipe.execute() + + self.assertEqual(len(self.buffer), 1) + self.assertEqual(self.buffer[0].msg, "PIPELINE> GET 'foo'") + + def test_command_logging_transaction(self): + txn = self.client.pipeline(transaction=True) + txn.get("foo") + txn.execute() + + self.assertEqual(len(self.buffer), 3) + messages = [x.msg for x in self.buffer] + self.assertEqual(messages, + ["MULTI", "TRANSACTION> GET 'foo'", "EXEC"]) -- cgit v1.2.1 From 40ca9c27c2136bd0b4c85fa5fb012b3cd87e974a Mon Sep 17 00:00:00 2001 From: Will Maier Date: Thu, 6 Jan 2011 13:01:11 -0600 Subject: log connects/disconnects --- redis/client.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/redis/client.py b/redis/client.py index 89b97aa..b02716e 100644 --- a/redis/client.py +++ b/redis/client.py @@ -58,6 +58,7 @@ class Connection(object): "Connects to the Redis server if not already connected" if self._sock: return + log.debug("connecting to %s:%d/%d", self.host, self.port, self.db) try: sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM) sock.settimeout(self.socket_timeout) @@ -81,6 +82,7 @@ class Connection(object): "Disconnects from the Redis server" if self._sock is None: return + log.debug("disconnecting from %s:%d/%d", self.host, self.port, self.db) try: self._sock.close() except socket.error: -- cgit v1.2.1 From c098f3214cca90f41456aee836257dc356ac709c Mon Sep 17 00:00:00 2001 From: Will Maier Date: Fri, 7 Jan 2011 14:26:47 -0600 Subject: shield logging with isEnabledFor. --- redis/client.py | 14 ++++++++------ 1 file changed, 8 insertions(+), 6 deletions(-) diff --git a/redis/client.py b/redis/client.py index b02716e..81e977c 100644 --- a/redis/client.py +++ b/redis/client.py @@ -1438,10 +1438,11 @@ class Pipeline(Redis): commands, (('', ('EXEC',), ''),) )]) - log.debug("MULTI") - for command in commands: - log.debug("TRANSACTION> "+ repr_command(command[1])) - log.debug("EXEC") + if log.isEnabledFor(logging.DEBUG): + log.debug("MULTI") + for command in commands: + log.debug("TRANSACTION> "+ repr_command(command[1])) + log.debug("EXEC") self.connection.send(all_cmds, self) # parse off the response for MULTI and all commands prior to EXEC for i in range(len(commands)+1): @@ -1467,8 +1468,9 @@ class Pipeline(Redis): def _execute_pipeline(self, commands): # build up all commands into a single request to increase network perf all_cmds = ''.join([self._encode_command(c) for _1, c, _2 in commands]) - for command in commands: - log.debug("PIPELINE> " + repr_command(command[1])) + if log.isEnabledFor(logging.DEBUG): + for command in commands: + log.debug("PIPELINE> " + repr_command(command[1])) self.connection.send(all_cmds, self) data = [] for command_name, _, options in commands: -- cgit v1.2.1 From dfde2fc04868849f2a1db62bd29821810bd9168d Mon Sep 17 00:00:00 2001 From: Will Maier Date: Fri, 7 Jan 2011 15:44:18 -0600 Subject: Guard all log statements with log_enabled(). Checking log.isEnabledFor() once avoids the often expensive repr_command() calls as well as calls to log.debug() itself. This is a especially large savings in _execute_{pipeline,transaction}(). --- redis/client.py | 16 +++++++++++----- 1 file changed, 11 insertions(+), 5 deletions(-) diff --git a/redis/client.py b/redis/client.py index 81e977c..93607d0 100644 --- a/redis/client.py +++ b/redis/client.py @@ -58,7 +58,8 @@ class Connection(object): "Connects to the Redis server if not already connected" if self._sock: return - log.debug("connecting to %s:%d/%d", self.host, self.port, self.db) + if log_enabled(log): + log.debug("connecting to %s:%d/%d", self.host, self.port, self.db) try: sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM) sock.settimeout(self.socket_timeout) @@ -82,7 +83,8 @@ class Connection(object): "Disconnects from the Redis server" if self._sock is None: return - log.debug("disconnecting from %s:%d/%d", self.host, self.port, self.db) + if log_enabled(log): + log.debug("disconnecting from %s:%d/%d", self.host, self.port, self.db) try: self._sock.close() except socket.error: @@ -161,6 +163,9 @@ def dict_merge(*dicts): [merged.update(d) for d in dicts] return merged +def log_enabled(log, level=logging.DEBUG): + return log.isEnabledFor(log, level) + def repr_command(args): "Represents a command as a string." command = [args[0]] @@ -338,7 +343,8 @@ class Redis(threading.local): if self.subscribed and not subscription_command: raise RedisError("Cannot issue commands other than SUBSCRIBE and " "UNSUBSCRIBE while channels are open") - log.debug(repr_command(command)) + if log_enabled(log): + log.debug(repr_command(command)) command = self._encode_command(command) try: self.connection.send(command, self) @@ -1438,7 +1444,7 @@ class Pipeline(Redis): commands, (('', ('EXEC',), ''),) )]) - if log.isEnabledFor(logging.DEBUG): + if log_enabled(log): log.debug("MULTI") for command in commands: log.debug("TRANSACTION> "+ repr_command(command[1])) @@ -1468,7 +1474,7 @@ class Pipeline(Redis): def _execute_pipeline(self, commands): # build up all commands into a single request to increase network perf all_cmds = ''.join([self._encode_command(c) for _1, c, _2 in commands]) - if log.isEnabledFor(logging.DEBUG): + if log_enabled(log): for command in commands: log.debug("PIPELINE> " + repr_command(command[1])) self.connection.send(all_cmds, self) -- cgit v1.2.1