diff --git a/bin/swift-bench b/bin/swift-bench index 3c167ee06f..0554782a06 100755 --- a/bin/swift-bench +++ b/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) diff --git a/etc/proxy-server.conf-sample b/etc/proxy-server.conf-sample index fad511ca30..3af7db0f8a 100644 --- a/etc/proxy-server.conf-sample +++ b/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 diff --git a/swift/common/utils.py b/swift/common/utils.py index 8da3d1f8f4..4df8b624bc 100644 --- a/swift/common/utils.py +++ b/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) diff --git a/swift/common/wsgi.py b/swift/common/wsgi.py index 9450bcf439..e1e6e0c8f1 100644 --- a/swift/common/wsgi.py +++ b/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') diff --git a/swift/proxy/server.py b/swift/proxy/server.py index 1eae0dfc30..b2b41d6434 100644 --- a/swift/proxy/server.py +++ b/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()), diff --git a/test/unit/common/test_utils.py b/test/unit/common/test_utils.py index 0c81b15698..959caa8919 100644 --- a/test/unit/common/test_utils.py +++ b/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 diff --git a/test/unit/proxy/test_server.py b/test/unit/proxy/test_server.py index e991d84084..71b61e1e2c 100644 --- a/test/unit/proxy/test_server.py +++ b/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