cleaned up logging and added new optional proxy access_logger with it's own configuration options that default to default proxy logger's settings.

bin/swift-bench

@@ -22,7 +22,7 @@ import uuid
 from optparse import OptionParser
 
 from swift.common.bench import BenchController
-from swift.common.utils import readconf, LogAdapter, NamedFormatter
+from swift.common.utils import readconf, LogAdapter
 
 # The defaults should be sufficient to run swift-bench on a SAIO
 CONF_DEFAULTS = {
@@ -125,9 +125,9 @@ if __name__ == '__main__':
             options.log_level.lower(), logging.INFO))
     loghandler = logging.StreamHandler()
     logger.addHandler(loghandler)
-    logger = LogAdapter(logger)
-    logformat = NamedFormatter('swift-bench', logger,
-                   fmt='%(server)s %(asctime)s %(levelname)s %(message)s')
+    logger = LogAdapter(logger, 'swift-bench')
+    logformat = logging.Formatter('%(server)s %(asctime)s %(levelname)s '
+                                  '%(message)s')
     loghandler.setFormatter(logformat)
 
     controller = BenchController(logger, options)

etc/proxy-server.conf-sample

@@ -24,6 +24,9 @@ use = egg:swift#proxy
 # set log_name = proxy-server
 # set log_facility = LOG_LOCAL0
 # set log_level = INFO
+# set access_log_name = proxy-server
+# set access_log_facility = LOG_LOCAL0
+# set access_log_level = INFO
 # set log_headers = False
 # recheck_account_existence = 60
 # recheck_container_existence = 60

swift/common/utils.py

@@ -48,6 +48,10 @@ import logging
 logging.thread = eventlet.green.thread
 logging.threading = eventlet.green.threading
 logging._lock = logging.threading.RLock()
+# setup notice level logging
+NOTICE = 25
+logging._levelNames[NOTICE] = 'NOTICE'
+SysLogHandler.priority_map['NOTICE'] = 'notice'
 
 # These are lazily pulled from libc elsewhere
 _sys_fallocate = None
@@ -284,7 +288,8 @@ class LoggerFileObject(object):
         return self
 
 
-class LogAdapter(object):
+# double inheritance to support property with setter
+class LogAdapter(logging.LoggerAdapter, object):
     """
     A Logger like object which performs some reformatting on calls to
     :meth:`exception`.  Can be used to store a threadlocal transaction id.
@@ -292,11 +297,10 @@ class LogAdapter(object):
 
     _txn_id = threading.local()
 
-    def __init__(self, logger):
-        self.logger = logger
-        for proxied_method in ('debug', 'log', 'warn', 'warning', 'error',
-                               'critical', 'info'):
-            setattr(self, proxied_method, getattr(logger, proxied_method))
+    def __init__(self, logger, server):
+        logging.LoggerAdapter.__init__(self, logger, {})
+        self.server = server
+        setattr(self, 'warn', self.warning)
 
     @property
     def txn_id(self):
@@ -310,15 +314,34 @@ class LogAdapter(object):
     def getEffectiveLevel(self):
         return self.logger.getEffectiveLevel()
 
-    def exception(self, msg, *args):
+    def process(self, msg, kwargs):
+        """
+        Add extra info to message
+        """
+        kwargs['extra'] = {'server': self.server, 'txn_id': self.txn_id}
+        return msg, kwargs
+
+    def notice(self, msg, *args, **kwargs):
+        """
+        Convenience function for syslog priority LOG_NOTICE. The python
+        logging lvl is set to 25, just above info.  SysLogHandler is
+        monkey patched to map this log lvl to the LOG_NOTICE syslog
+        priority.
+        """
+        self.log(NOTICE, msg, *args, **kwargs)
+
+    def _exception(self, msg, *args, **kwargs):
+        logging.LoggerAdapter.exception(self, msg, *args, **kwargs)
+
+    def exception(self, msg, *args, **kwargs):
         _junk, exc, _junk = sys.exc_info()
-        call = self.logger.error
+        call = self.error
         emsg = ''
         if isinstance(exc, OSError):
             if exc.errno in (errno.EIO, errno.ENOSPC):
                 emsg = str(exc)
             else:
-                call = self.logger.exception
+                call = self._exception
         elif isinstance(exc, socket.error):
             if exc.errno == errno.ECONNREFUSED:
                 emsg = _('Connection refused')
@@ -327,7 +350,7 @@ class LogAdapter(object):
             elif exc.errno == errno.ETIMEDOUT:
                 emsg = _('Connection timeout')
             else:
-                call = self.logger.exception
+                call = self._exception
         elif isinstance(exc, eventlet.Timeout):
             emsg = exc.__class__.__name__
             if hasattr(exc, 'seconds'):
@@ -336,53 +359,25 @@ class LogAdapter(object):
                 if exc.msg:
                     emsg += ' %s' % exc.msg
         else:
-            call = self.logger.exception
-        call('%s: %s' % (msg, emsg), *args)
+            call = self._exception
+        call('%s: %s' % (msg, emsg), *args, **kwargs)
 
 
-class NamedFormatter(logging.Formatter):
+class TxnFormatter(logging.Formatter):
     """
-    NamedFormatter is used to add additional information to log messages.
-    Normally it will simply add the server name as an attribute on the
-    LogRecord and the default format string will include it at the
-    begining of the log message.  Additionally, if the transaction id is
-    available and not already included in the message, NamedFormatter will
-    add it.
-
-    NamedFormatter may be initialized with a format string which makes use
-    of the standard LogRecord attributes.  In addition the format string
-    may include the following mapping key:
-
-    +----------------+---------------------------------------------+
-    | Format         | Description                                 |
-    +================+=============================================+
-    | %(server)s     | Name of the swift server doing logging      |
-    +----------------+---------------------------------------------+
-
-    :param server: the swift server name, a string.
-    :param logger: a Logger or :class:`LogAdapter` instance, additional
-                   context may be pulled from attributes on this logger if
-                   available.
-    :param fmt: the format string used to construct the message, if none is
-                supplied it defaults to ``"%(server)s %(message)s"``
+    Custom logging.Formatter will append txn_id to a log message if the record
+    has one and the message does not.
     """
-
-    def __init__(self, server, logger,
-                 fmt="%(server)s %(message)s"):
-        logging.Formatter.__init__(self, fmt)
-        self.server = server
-        self.logger = logger
-
     def format(self, record):
-        record.server = self.server
         msg = logging.Formatter.format(self, record)
-        if self.logger.txn_id and (record.levelno != logging.INFO or
-                                   self.logger.txn_id not in msg):
-            msg = "%s (txn: %s)" % (msg, self.logger.txn_id)
+        if (record.txn_id and record.levelno != logging.INFO and
+            record.txn_id not in msg):
+            msg = "%s (txn: %s)" % (msg, record.txn_id)
         return msg
 
 
-def get_logger(conf, name=None, log_to_console=False, log_route=None):
+def get_logger(conf, name=None, log_to_console=False, log_route=None,
+               fmt="%(server)s %(message)s"):
     """
     Get the current system logger using config settings.
 
@@ -395,51 +390,50 @@ def get_logger(conf, name=None, log_to_console=False, log_route=None):
     :param conf: Configuration dict to read settings from
     :param name: Name of the logger
     :param log_to_console: Add handler which writes to console on stderr
+    :param fmt: Override log format
     """
     if not conf:
         conf = {}
-    if not hasattr(get_logger, 'root_logger_configured'):
-        get_logger.root_logger_configured = True
-        get_logger(conf, name, log_to_console, log_route='root')
     if name is None:
         name = conf.get('log_name', 'swift')
     if not log_route:
         log_route = name
-    if log_route == 'root':
-        logger = logging.getLogger()
-    else:
-        logger = logging.getLogger(log_route)
-        logger.propagate = False
-    if not hasattr(get_logger, 'handler4facility'):
-        get_logger.handler4facility = {}
-    facility = getattr(SysLogHandler, conf.get('log_facility', 'LOG_LOCAL0'),
-                       SysLogHandler.LOG_LOCAL0)
-    if facility in get_logger.handler4facility:
-        logger.removeHandler(get_logger.handler4facility[facility])
-        get_logger.handler4facility[facility].close()
-        del get_logger.handler4facility[facility]
-    if log_to_console:
-        # check if a previous call to get_logger already added a console logger
-        if hasattr(get_logger, 'console') and get_logger.console:
-            logger.removeHandler(get_logger.console)
-        get_logger.console = logging.StreamHandler(sys.__stderr__)
-        logger.addHandler(get_logger.console)
-    get_logger.handler4facility[facility] = \
-        SysLogHandler(address='/dev/log', facility=facility)
+    logger = logging.getLogger(log_route)
+    logger.propagate = False
+    # all new handlers will get the same formatter
+    formatter = TxnFormatter(fmt)
+
+    # get_logger will only ever add one SysLog Handler to a logger
     if not hasattr(get_logger, 'handler4logger'):
         get_logger.handler4logger = {}
     if logger in get_logger.handler4logger:
         logger.removeHandler(get_logger.handler4logger[logger])
-    get_logger.handler4logger[logger] = \
-        get_logger.handler4facility[facility]
-    logger.addHandler(get_logger.handler4facility[facility])
+
+    # facility for this logger will be set by last call wins
+    facility = getattr(SysLogHandler, conf.get('log_facility', 'LOG_LOCAL0'),
+                       SysLogHandler.LOG_LOCAL0)
+    handler = SysLogHandler(address='/dev/log', facility=facility)
+    handler.setFormatter(formatter)
+    logger.addHandler(handler)
+    get_logger.handler4logger[logger] = handler
+
+    # setup console logging
+    if log_to_console or hasattr(get_logger, 'console_handler4logger'):
+        # remove pre-existing console handler for this logger
+        if not hasattr(get_logger, 'console_handler4logger'):
+            get_logger.console_handler4logger = {}
+        if logger in get_logger.console_handler4logger:
+            logger.removeHandler(get_logger.console_handler4logger[logger])
+
+        console_handler = logging.StreamHandler(sys.__stderr__)
+        console_handler.setFormatter(formatter)
+        logger.addHandler(console_handler)
+        get_logger.console_handler4logger[logger] = console_handler
+
+    # set the level for the logger
     logger.setLevel(
         getattr(logging, conf.get('log_level', 'INFO').upper(), logging.INFO))
-    adapted_logger = LogAdapter(logger)
-    formatter = NamedFormatter(name, adapted_logger)
-    get_logger.handler4facility[facility].setFormatter(formatter)
-    if hasattr(get_logger, 'console'):
-        get_logger.console.setFormatter(formatter)
+    adapted_logger = LogAdapter(logger, name)
     return adapted_logger
 
 
@@ -472,8 +466,9 @@ def capture_stdio(logger, **kwargs):
 
     # collect stdio file desc not in use for logging
     stdio_fds = [0, 1, 2]
-    if hasattr(get_logger, 'console'):
-        stdio_fds.remove(get_logger.console.stream.fileno())
+    for _junk, handler in getattr(get_logger,
+                                  'console_handler4logger', {}).items():
+        stdio_fds.remove(handler.stream.fileno())
 
     with open(os.devnull, 'r+b') as nullfile:
         # close stdio (excludes fds open for logging)

swift/common/wsgi.py

@@ -168,10 +168,10 @@ def run_wsgi(conf_file, app_section, *args, **kwargs):
                 signal.signal(signal.SIGHUP, signal.SIG_DFL)
                 signal.signal(signal.SIGTERM, signal.SIG_DFL)
                 run_server()
-                logger.info('Child %d exiting normally' % os.getpid())
+                logger.notice('Child %d exiting normally' % os.getpid())
                 return
             else:
-                logger.info('Started child %s' % pid)
+                logger.notice('Started child %s' % pid)
                 children.append(pid)
         try:
             pid, status = os.wait()
@@ -182,8 +182,8 @@ def run_wsgi(conf_file, app_section, *args, **kwargs):
             if err.errno not in (errno.EINTR, errno.ECHILD):
                 raise
         except KeyboardInterrupt:
-            logger.info('User quit')
+            logger.notice('User quit')
             break
     greenio.shutdown_safe(sock)
     sock.close()
-    logger.info('Exited')
+    logger.notice('Exited')

swift/proxy/server.py

@@ -624,7 +624,7 @@ class Controller(object):
                             res.bytes_transferred += len(chunk)
                     except GeneratorExit:
                         res.client_disconnect = True
-                        self.app.logger.info(_('Client disconnected on read'))
+                        self.app.logger.warn(_('Client disconnected on read'))
                     except (Exception, TimeoutError):
                         self.exception_occurred(node, _('Object'),
                             _('Trying to read during GET of %s') % req.path)
@@ -1054,7 +1054,7 @@ class ObjectController(Controller):
                 if req.headers.get('transfer-encoding') and chunk == '':
                     break
         except ChunkReadTimeout, err:
-            self.app.logger.info(
+            self.app.logger.warn(
                 _('ERROR Client read timeout (%ss)'), err.seconds)
             return HTTPRequestTimeout(request=req)
         except Exception:
@@ -1064,7 +1064,7 @@ class ObjectController(Controller):
             return Response(status='499 Client Disconnect')
         if req.content_length and req.bytes_transferred < req.content_length:
             req.client_disconnect = True
-            self.app.logger.info(
+            self.app.logger.warn(
                 _('Client disconnected without sending enough data'))
             return Response(status='499 Client Disconnect')
         statuses = []
@@ -1606,12 +1606,20 @@ class BaseApplication(object):
 
     def __init__(self, conf, memcache=None, logger=None, account_ring=None,
                  container_ring=None, object_ring=None):
-        if logger is None:
-            self.logger = get_logger(conf)
-        else:
-            self.logger = logger
         if conf is None:
             conf = {}
+        if logger is None:
+            self.logger = get_logger(conf)
+            access_log_conf = {}
+            for key in ('log_facility', 'log_name', 'log_level'):
+                value = conf.get('access_' + key, conf.get(key, None))
+                if value:
+                    access_log_conf[key] = value
+            self.access_logger = get_logger(access_log_conf,
+                                            log_route='proxy-access')
+        else:
+            self.logger = self.access_logger = logger
+
         swift_dir = conf.get('swift_dir', '/etc/swift')
         self.node_timeout = int(conf.get('node_timeout', 10))
         self.conn_timeout = float(conf.get('conn_timeout', 0.5))
@@ -1790,7 +1798,7 @@ class Application(BaseApplication):
         if getattr(req, 'client_disconnect', False) or \
                 getattr(response, 'client_disconnect', False):
             status_int = 499
-        self.logger.info(' '.join(quote(str(x)) for x in (
+        self.access_logger.info(' '.join(quote(str(x)) for x in (
                 client or '-',
                 req.remote_addr or '-',
                 time.strftime('%d/%b/%Y/%H/%M/%S', time.gmtime()),

test/unit/common/test_utils.py

@@ -19,6 +19,7 @@ from __future__ import with_statement
 import logging
 import mimetools
 import os
+import errno
 import socket
 import sys
 import time
@@ -31,6 +32,8 @@ from tempfile import NamedTemporaryFile
 
 from eventlet import sleep
 
+from swift.common.exceptions import TimeoutError, MessageTimeout, \
+        ConnectionTimeout
 from swift.common import utils
 
 
@@ -76,6 +79,17 @@ class MockSys():
     __stderr__ = sys.__stderr__
 
 
+def reset_loggers():
+    if hasattr(utils.get_logger, 'handler4logger'):
+        for logger, handler in utils.get_logger.handler4logger.items():
+            logger.removeHandler(handler)
+        delattr(utils.get_logger, 'handler4logger')
+    if hasattr(utils.get_logger, 'console_handler4logger'):
+        for logger, h in utils.get_logger.console_handler4logger.items():
+            logger.removeHandler(h)
+        delattr(utils.get_logger, 'console_handler4logger')
+
+
 class TestUtils(unittest.TestCase):
     """ Tests for swift.common.utils """
 
@@ -303,9 +317,136 @@ Error: unable to locate %s
         logger.warn('test4')
         self.assertEquals(sio.getvalue(),
                           'test1\ntest3\ntest4\n')
+        # make sure debug doesn't log by default
         logger.debug('test5')
         self.assertEquals(sio.getvalue(),
                           'test1\ntest3\ntest4\n')
+        # make sure notice lvl logs by default
+        logger.notice('test6')
+
+    def test_clean_logger_exception(self):
+        # setup stream logging
+        sio = StringIO()
+        logger = utils.get_logger(None)
+        handler = logging.StreamHandler(sio)
+        logger.logger.addHandler(handler)
+
+        def strip_value(sio):
+            v = sio.getvalue()
+            sio.truncate(0)
+            return v
+
+        def log_exception(exc):
+            try:
+                raise exc
+            except (Exception, TimeoutError):
+                logger.exception('blah')
+        try:
+            # establish base case
+            self.assertEquals(strip_value(sio), '')
+            logger.info('test')
+            self.assertEquals(strip_value(sio), 'test\n')
+            self.assertEquals(strip_value(sio), '')
+            logger.info('test')
+            logger.info('test')
+            self.assertEquals(strip_value(sio), 'test\ntest\n')
+            self.assertEquals(strip_value(sio), '')
+
+            # test OSError
+            for en in (errno.EIO, errno.ENOSPC):
+                log_exception(OSError(en, 'my %s error message' % en))
+                log_msg = strip_value(sio)
+                self.assert_('Traceback' not in log_msg)
+                self.assert_('my %s error message' % en in log_msg)
+            # unfiltered
+            log_exception(OSError())
+            self.assert_('Traceback' in strip_value(sio))
+
+            # test socket.error
+            log_exception(socket.error(errno.ECONNREFUSED,
+                                       'my error message'))
+            log_msg = strip_value(sio)
+            self.assert_('Traceback' not in log_msg)
+            self.assert_('errno.ECONNREFUSED message test' not in log_msg)
+            self.assert_('Connection refused' in log_msg)
+            log_exception(socket.error(errno.EHOSTUNREACH,
+                                       'my error message'))
+            log_msg = strip_value(sio)
+            self.assert_('Traceback' not in log_msg)
+            self.assert_('my error message' not in log_msg)
+            self.assert_('Host unreachable' in log_msg)
+            log_exception(socket.error(errno.ETIMEDOUT, 'my error message'))
+            log_msg = strip_value(sio)
+            self.assert_('Traceback' not in log_msg)
+            self.assert_('my error message' not in log_msg)
+            self.assert_('Connection timeout' in log_msg)
+            # unfiltered
+            log_exception(socket.error(0, 'my error message'))
+            log_msg = strip_value(sio)
+            self.assert_('Traceback' in log_msg)
+            self.assert_('my error message' in log_msg)
+
+            # test eventlet.Timeout
+            log_exception(ConnectionTimeout(42, 'my error message'))
+            log_msg = strip_value(sio)
+            self.assert_('Traceback' not in log_msg)
+            self.assert_('ConnectionTimeout' in log_msg)
+            self.assert_('(42s)' in log_msg)
+            self.assert_('my error message' not in log_msg)
+            log_exception(MessageTimeout(42, 'my error message'))
+            log_msg = strip_value(sio)
+            self.assert_('Traceback' not in log_msg)
+            self.assert_('MessageTimeout' in log_msg)
+            self.assert_('(42s)' in log_msg)
+            self.assert_('my error message' in log_msg)
+
+            # test unhandled
+            log_exception(Exception('my error message'))
+            log_msg = strip_value(sio)
+            self.assert_('Traceback' in log_msg)
+            self.assert_('my error message' in log_msg)
+
+        finally:
+            logger.logger.removeHandler(handler)
+            reset_loggers()
+
+    def test_txn_formatter(self):
+        # setup stream logging
+        sio = StringIO()
+        logger = utils.get_logger(None)
+        handler = logging.StreamHandler(sio)
+        handler.setFormatter(utils.TxnFormatter())
+        logger.logger.addHandler(handler)
+
+        def strip_value(sio):
+            v = sio.getvalue()
+            sio.truncate(0)
+            return v
+
+        try:
+            self.assertFalse(logger.txn_id)
+            logger.error('my error message')
+            log_msg = strip_value(sio)
+            self.assert_('my error message' in log_msg)
+            self.assert_('txn' not in log_msg)
+            logger.txn_id = '12345'
+            logger.error('test')
+            log_msg = strip_value(sio)
+            self.assert_('txn' in log_msg)
+            self.assert_('12345' in log_msg)
+            # test no txn on info message
+            self.assertEquals(logger.txn_id, '12345')
+            logger.info('test')
+            log_msg = strip_value(sio)
+            self.assert_('txn' not in log_msg)
+            self.assert_('12345' not in log_msg)
+            # test txn already in message
+            self.assertEquals(logger.txn_id, '12345')
+            logger.warn('test 12345 test')
+            self.assertEquals(strip_value(sio), 'test 12345 test\n')
+        finally:
+            logger.logger.removeHandler(handler)
+            reset_loggers()
 
     def test_storage_directory(self):
         self.assertEquals(utils.storage_directory('objects', '1', 'ABCDEF'),
@@ -391,56 +532,71 @@ log_name = yarr'''
         logger = utils.get_logger(None, 'dummy')
 
         # mock utils system modules
-        utils.sys = MockSys()
-        utils.os = MockOs()
+        _orig_sys = utils.sys
+        _orig_os = utils.os
+        try:
+            utils.sys = MockSys()
+            utils.os = MockOs()
 
-        # basic test
-        utils.capture_stdio(logger)
-        self.assert_(utils.sys.excepthook is not None)
-        self.assertEquals(utils.os.closed_fds, [0, 1, 2])
-        self.assert_(utils.sys.stdout is not None)
-        self.assert_(utils.sys.stderr is not None)
+            # basic test
+            utils.capture_stdio(logger)
+            self.assert_(utils.sys.excepthook is not None)
+            self.assertEquals(utils.os.closed_fds, [0, 1, 2])
+            self.assert_(utils.sys.stdout is not None)
+            self.assert_(utils.sys.stderr is not None)
 
-        # reset; test same args, but exc when trying to close stdio
-        utils.os = MockOs(raise_funcs=('dup2',))
-        utils.sys = MockSys()
+            # reset; test same args, but exc when trying to close stdio
+            utils.os = MockOs(raise_funcs=('dup2',))
+            utils.sys = MockSys()
 
-        # test unable to close stdio
-        utils.capture_stdio(logger)
-        self.assert_(utils.sys.excepthook is not None)
-        self.assertEquals(utils.os.closed_fds, [])
-        self.assert_(utils.sys.stdout is not None)
-        self.assert_(utils.sys.stderr is not None)
+            # test unable to close stdio
+            utils.capture_stdio(logger)
+            self.assert_(utils.sys.excepthook is not None)
+            self.assertEquals(utils.os.closed_fds, [])
+            self.assert_(utils.sys.stdout is not None)
+            self.assert_(utils.sys.stderr is not None)
 
-        # reset; test some other args
-        logger = utils.get_logger(None, log_to_console=True)
-        utils.os = MockOs()
-        utils.sys = MockSys()
+            # reset; test some other args
+            logger = utils.get_logger(None, log_to_console=True)
+            utils.os = MockOs()
+            utils.sys = MockSys()
 
-        # test console log
-        utils.capture_stdio(logger, capture_stdout=False,
-                            capture_stderr=False)
-        self.assert_(utils.sys.excepthook is not None)
-        # when logging to console, stderr remains open
-        self.assertEquals(utils.os.closed_fds, [0, 1])
-        logger.logger.removeHandler(utils.get_logger.console)
-        # stdio not captured
-        self.assertFalse(hasattr(utils.sys, 'stdout'))
-        self.assertFalse(hasattr(utils.sys, 'stderr'))
+            # test console log
+            utils.capture_stdio(logger, capture_stdout=False,
+                                capture_stderr=False)
+            self.assert_(utils.sys.excepthook is not None)
+            # when logging to console, stderr remains open
+            self.assertEquals(utils.os.closed_fds, [0, 1])
+            reset_loggers()
+
+            # stdio not captured
+            self.assertFalse(hasattr(utils.sys, 'stdout'))
+            self.assertFalse(hasattr(utils.sys, 'stderr'))
+            reset_loggers()
+        finally:
+            utils.sys = _orig_sys
+            utils.os = _orig_os
 
     def test_get_logger_console(self):
-        reload(utils)  # reset get_logger attrs
+        reset_loggers()
         logger = utils.get_logger(None)
-        self.assertFalse(hasattr(utils.get_logger, 'console'))
+        console_handlers = [h for h in logger.logger.handlers if
+                            isinstance(h, logging.StreamHandler)]
+        self.assertFalse(console_handlers)
         logger = utils.get_logger(None, log_to_console=True)
-        self.assert_(hasattr(utils.get_logger, 'console'))
-        self.assert_(isinstance(utils.get_logger.console,
-                                logging.StreamHandler))
+        console_handlers = [h for h in logger.logger.handlers if
+                            isinstance(h, logging.StreamHandler)]
+        self.assert_(console_handlers)
         # make sure you can't have two console handlers
-        old_handler = utils.get_logger.console
+        self.assertEquals(len(console_handlers), 1)
+        old_handler = console_handlers[0]
         logger = utils.get_logger(None, log_to_console=True)
-        self.assertNotEquals(utils.get_logger.console, old_handler)
-        logger.logger.removeHandler(utils.get_logger.console)
+        console_handlers = [h for h in logger.logger.handlers if
+                            isinstance(h, logging.StreamHandler)]
+        self.assertEquals(len(console_handlers), 1)
+        new_handler = console_handlers[0]
+        self.assertNotEquals(new_handler, old_handler)
+        reset_loggers()
 
     def test_ratelimit_sleep(self):
         running_time = 0

test/unit/proxy/test_server.py

@@ -16,6 +16,7 @@
 from __future__ import with_statement
 import cPickle as pickle
 import logging
+from logging.handlers import SysLogHandler
 import os
 import sys
 import unittest
@@ -465,8 +466,138 @@ class TestController(unittest.TestCase):
             test(404, 507, 503)
             test(503, 503, 503)
 
+
 class TestProxyServer(unittest.TestCase):
 
+    def test_access_log(self):
+
+        class MyApp(proxy_server.Application):
+
+            def handle_request(self, req):
+                resp = Response(request=req)
+                req.response = resp
+                req.start_time = time()
+                return resp
+
+        def start_response(*args):
+            pass
+
+        class MockLogger():
+
+            def __init__(self):
+                self.buffer = StringIO()
+
+            def info(self, msg, args=None):
+                if args:
+                    msg = msg % args
+                self.buffer.write(msg)
+
+            def strip_value(self):
+                rv = self.buffer.getvalue()
+                self.buffer.truncate(0)
+                return rv
+
+        class SnarfStream(object):
+            # i can't seem to subclass cStringIO
+
+            def __init__(self, *args, **kwargs):
+                self.sio = StringIO()
+
+            def strip_value(self):
+                rv = self.getvalue().strip()
+                self.truncate(0)
+                return rv
+
+            def __getattr__(self, name):
+                try:
+                    return object.__getattr__(self, name)
+                except AttributeError:
+                    try:
+                        return getattr(self.sio, name)
+                    except AttributeError:
+                        return self.__getattribute__(name)
+
+        snarf = SnarfStream()
+        _orig_get_logger = proxy_server.get_logger
+
+        def mock_get_logger(*args, **kwargs):
+            if kwargs.get('log_route') != 'proxy-access':
+                return _orig_get_logger(*args, **kwargs)
+            kwargs['log_route'] = 'snarf'
+            logger = _orig_get_logger(*args, **kwargs)
+            if [h for h in logger.logger.handlers if
+                isinstance(h, logging.StreamHandler) and h.stream is snarf]:
+                # snarf handler already setup!
+                return logger
+            formatter = logger.logger.handlers[0].formatter
+            formatter._fmt += ' %(levelname)s'
+            snarf_handler = logging.StreamHandler(snarf)
+            snarf_handler.setFormatter(formatter)
+            logger.logger.addHandler(snarf_handler)
+            return logger
+
+        def test_conf(conf):
+            app = MyApp(conf, memcache=FakeMemcache(), account_ring=FakeRing(),
+                        container_ring=FakeRing(), object_ring=FakeRing())
+            req = Request.blank('')
+            app(req.environ, start_response)
+
+        try:
+            proxy_server.get_logger = mock_get_logger
+            test_conf({})
+            line = snarf.strip_value()
+            print line
+            self.assert_(line.startswith('swift'))
+            self.assert_(line.endswith('INFO'))
+            test_conf({'log_name': 'snarf-test'})
+            line = snarf.strip_value()
+            print line
+            self.assert_(line.startswith('snarf-test'))
+            self.assert_(line.endswith('INFO'))
+            test_conf({'log_name': 'snarf-test', 'log_level': 'ERROR'})
+            line = snarf.strip_value()
+            print line
+            self.assertFalse(line)
+            test_conf({'log_name': 'snarf-test', 'log_level': 'ERROR',
+                       'access_log_name': 'access-test',
+                       'access_log_level': 'INFO'})
+            line = snarf.strip_value()
+            print line
+            self.assert_(line.startswith('access-test'))
+            self.assert_(line.endswith('INFO'))
+
+            # test facility
+            def get_facility(logger):
+                h = [h for h in logger.logger.handlers if
+                     isinstance(h, SysLogHandler)][0]
+                return h.facility
+
+            conf = {'log_facility': 'LOG_LOCAL0'}
+            app = MyApp(conf, memcache=FakeMemcache(), account_ring=FakeRing(),
+                        container_ring=FakeRing(), object_ring=FakeRing())
+            self.assertEquals(get_facility(app.logger),
+                              SysLogHandler.LOG_LOCAL0)
+            self.assertEquals(get_facility(app.access_logger),
+                              SysLogHandler.LOG_LOCAL0)
+            conf = {'log_facility': 'LOG_LOCAL0',
+                    'access_log_facility': 'LOG_LOCAL1'}
+            app = MyApp(conf, memcache=FakeMemcache(), account_ring=FakeRing(),
+                        container_ring=FakeRing(), object_ring=FakeRing())
+            self.assertEquals(get_facility(app.logger),
+                              SysLogHandler.LOG_LOCAL0)
+            self.assertEquals(get_facility(app.access_logger),
+                              SysLogHandler.LOG_LOCAL1)
+            conf = {'access_log_facility': 'LOG_LOCAL1'}
+            app = MyApp(conf, memcache=FakeMemcache(), account_ring=FakeRing(),
+                        container_ring=FakeRing(), object_ring=FakeRing())
+            self.assertEquals(get_facility(app.logger),
+                              SysLogHandler.LOG_LOCAL0)
+            self.assertEquals(get_facility(app.access_logger),
+                              SysLogHandler.LOG_LOCAL1)
+
+        finally:
+            proxy_server.get_logger = _orig_get_logger
+
     def test_unhandled_exception(self):
 
         class MyApp(proxy_server.Application):
@@ -1805,8 +1936,8 @@ class TestObjectController(unittest.TestCase):
             def info(self, msg):
                 self.msg = msg
 
-        orig_logger = prosrv.logger
-        prosrv.logger = Logger()
+        orig_logger, orig_access_logger = prosrv.logger, prosrv.access_logger
+        prosrv.logger = prosrv.access_logger = Logger()
         sock = connect_tcp(('localhost', prolis.getsockname()[1]))
         fd = sock.makefile()
         fd.write(
@@ -1822,11 +1953,9 @@ class TestObjectController(unittest.TestCase):
                      prosrv.logger.msg)
         exp = 'host1'
         self.assertEquals(prosrv.logger.msg[:len(exp)], exp)
-        prosrv.logger = orig_logger
         # Turn on header logging.
 
-        orig_logger = prosrv.logger
-        prosrv.logger = Logger()
+        prosrv.logger = prosrv.access_logger = Logger()
         prosrv.log_headers = True
         sock = connect_tcp(('localhost', prolis.getsockname()[1]))
         fd = sock.makefile()
@@ -1840,7 +1969,7 @@ class TestObjectController(unittest.TestCase):
         self.assert_('Goofy-Header%3A%20True' in prosrv.logger.msg,
                      prosrv.logger.msg)
         prosrv.log_headers = False
-        prosrv.logger = orig_logger
+        prosrv.logger, prosrv.access_logger = orig_logger, orig_access_logger
 
     def test_chunked_put_utf8_all_the_way_down(self):
         # Test UTF-8 Unicode all the way through the system