logging refactor to support proxy access logs
New log level "notice" set to python log level 25 maps to syslog priority LOG_NOTICE. Used for some messages in the proxy server, but will be available to all apps using the LogAdapter returned from get_logger. Cleaned up some code in get_logger so that console logging works with log_routes and removed some unneeded bits. NamedFormatter functionality was split between LogAdapter (which now inherits from logging.LoggerAdapter) and TxnFormatter (which now is only responsible for adding the log records txn_id). The proxy server app now configures a separate logger for access line logging. By default it will use the same settings as the regular proxy logger.
This commit is contained in:
Clay Gerrard
parent
4869992732
commit
5d0bc6b9c7
@ -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)
|
||||
|
||||
@ -15,10 +15,9 @@ Access logs
|
||||
***********
|
||||
|
||||
Access logs are the proxy server logs. Rackspace uses syslog-ng to redirect
|
||||
proxy log messages with the syslog priority LOG_NOTICE to an hourly log
|
||||
file. For example, a proxy request that is made on August 4, 2010 at 12:37 gets
|
||||
logged in a file named 2010080412. This allows easy log rotation and easy
|
||||
per-hour log processing.
|
||||
the proxy log output to an hourly log file. For example, a proxy request that
|
||||
is made on August 4, 2010 at 12:37 gets logged in a file named 2010080412.
|
||||
This allows easy log rotation and easy per-hour log processing.
|
||||
|
||||
******************
|
||||
Account stats logs
|
||||
@ -100,11 +99,11 @@ Running the stats system on SAIO
|
||||
destination df_local1 { file("/var/log/swift/proxy.log" owner(<username>) group(<groupname>)); };
|
||||
destination df_local1_err { file("/var/log/swift/proxy.error" owner(<username>) group(<groupname>)); };
|
||||
destination df_local1_hourly { file("/var/log/swift/hourly/$YEAR$MONTH$DAY$HOUR" owner(<username>) group(<groupname>)); };
|
||||
filter f_local1 { facility(local1) and level(notice); };
|
||||
filter f_local1 { facility(local1) and level(info); };
|
||||
|
||||
filter f_local1_err { facility(local1) and not level(notice); };
|
||||
filter f_local1_err { facility(local1) and not level(info); };
|
||||
|
||||
# local1.notice -/var/log/swift/proxy.log
|
||||
# local1.info -/var/log/swift/proxy.log
|
||||
# write to local file and to remove log server
|
||||
log {
|
||||
source(s_all);
|
||||
@ -182,4 +181,4 @@ earlier. This file will have one entry per account per hour for each account
|
||||
with activity in that hour. One .csv file should be produced per hour. Note
|
||||
that the stats will be delayed by at least two hours by default. This can be
|
||||
changed with the new_log_cutoff variable in the config file. See
|
||||
`log-processing.conf-sample` for more details.
|
||||
`log-processing.conf-sample` for more details.
|
||||
@ -289,7 +289,8 @@ class LoggerFileObject(object):
|
||||
return self
|
||||
|
||||
|
||||
class LogAdapter(object):
|
||||
# double inhereitence 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.
|
||||
@ -297,11 +298,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):
|
||||
@ -315,24 +315,34 @@ class LogAdapter(object):
|
||||
def getEffectiveLevel(self):
|
||||
return self.logger.getEffectiveLevel()
|
||||
|
||||
def notice(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.logger.log(NOTICE, msg, *args)
|
||||
self.log(NOTICE, msg, *args, **kwargs)
|
||||
|
||||
def exception(self, msg, *args):
|
||||
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')
|
||||
@ -341,7 +351,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'):
|
||||
@ -350,53 +360,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.
|
||||
|
||||
@ -412,48 +394,46 @@ def get_logger(conf, name=None, log_to_console=False, log_route=None):
|
||||
"""
|
||||
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 swift new handlers will get the same formatter
|
||||
formatter = TxnFormatter(fmt)
|
||||
|
||||
# a single swift logger will only get one SysLog Handler
|
||||
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
|
||||
|
||||
|
||||
@ -486,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)
|
||||
|
||||
@ -1606,22 +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 'access_log_name' in conf or 'access_log_facility' in conf:
|
||||
access_log_conf = {
|
||||
'log_name': conf.get('access_log_name', conf.get('log_name',
|
||||
'proxy-server')),
|
||||
'log_facility': conf.get('access_log_facility',
|
||||
conf.get('log_facility', 'LOG_LOCAL0')),
|
||||
}
|
||||
self.access_logger = get_logger(access_log_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.access_logger = self.logger
|
||||
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))
|
||||
|
||||
@ -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 """
|
||||
|
||||
@ -308,10 +322,131 @@ Error: unable to locate %s
|
||||
self.assertEquals(sio.getvalue(),
|
||||
'test1\ntest3\ntest4\n')
|
||||
# make sure notice lvl logs by default
|
||||
logger.notice('test7')
|
||||
self.assertEquals(sio.getvalue(),
|
||||
'test1\ntest3\ntest4\ntest6\n')
|
||||
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'),
|
||||
@ -397,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
|
||||
|
||||
@ -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,7 @@ class TestObjectController(unittest.TestCase):
|
||||
def info(self, msg):
|
||||
self.msg = msg
|
||||
|
||||
orig_logger = prosrv.logger
|
||||
orig_access_logger = prosrv.access_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()
|
||||
@ -1823,12 +1953,8 @@ class TestObjectController(unittest.TestCase):
|
||||
prosrv.logger.msg)
|
||||
exp = 'host1'
|
||||
self.assertEquals(prosrv.logger.msg[:len(exp)], exp)
|
||||
prosrv.access_logger = orig_access_logger
|
||||
prosrv.logger = orig_logger
|
||||
# Turn on header logging.
|
||||
|
||||
orig_logger = prosrv.logger
|
||||
orig_access_logger = prosrv.access_logger
|
||||
prosrv.logger = prosrv.access_logger = Logger()
|
||||
prosrv.log_headers = True
|
||||
sock = connect_tcp(('localhost', prolis.getsockname()[1]))
|
||||
@ -1843,8 +1969,7 @@ class TestObjectController(unittest.TestCase):
|
||||
self.assert_('Goofy-Header%3A%20True' in prosrv.logger.msg,
|
||||
prosrv.logger.msg)
|
||||
prosrv.log_headers = False
|
||||
prosrv.access_logger = orig_access_logger
|
||||
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
|
||||
|
||||
Loading…
x
Reference in New Issue
Block a user