From ee3886f2ca45e8983b13af04a06fee000aab61bb Mon Sep 17 00:00:00 2001 From: Clay Gerrard Date: Thu, 3 Feb 2011 13:46:28 -0600 Subject: [PATCH 1/6] moved warning messages out of proxy.logger.info A few warning/client error messages were useing the .info log level which we reserve for access logs. They were changed to warnings. --- swift/proxy/server.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/swift/proxy/server.py b/swift/proxy/server.py index 1eae0dfc30..14f79a2c61 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 = [] From f9fa63686c802ce8d3f2e4e29ecc7fb686835ba9 Mon Sep 17 00:00:00 2001 From: Clay Gerrard Date: Thu, 3 Feb 2011 15:23:07 -0600 Subject: [PATCH 2/6] Moved proxy server access log messages into their own log level Added new "access" log level available on swift loggers that will be routed to the LOG_NOTICE priority in syslog for easy redirection of access log messages via rsyslog and syslog-ng. --- doc/source/overview_stats.rst | 15 ++++++++------- swift/common/utils.py | 15 +++++++++++++++ swift/proxy/server.py | 2 +- test/unit/common/test_utils.py | 6 ++++++ test/unit/proxy/test_server.py | 2 +- 5 files changed, 31 insertions(+), 9 deletions(-) diff --git a/doc/source/overview_stats.rst b/doc/source/overview_stats.rst index 6364de4611..40a5dd01af 100644 --- a/doc/source/overview_stats.rst +++ b/doc/source/overview_stats.rst @@ -15,9 +15,10 @@ Access logs *********** Access logs are the proxy server logs. Rackspace uses syslog-ng to redirect -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. +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. ****************** Account stats logs @@ -99,11 +100,11 @@ Running the stats system on SAIO destination df_local1 { file("/var/log/swift/proxy.log" owner() group()); }; destination df_local1_err { file("/var/log/swift/proxy.error" owner() group()); }; destination df_local1_hourly { file("/var/log/swift/hourly/$YEAR$MONTH$DAY$HOUR" owner() group()); }; - filter f_local1 { facility(local1) and level(info); }; + filter f_local1 { facility(local1) and level(notice); }; - filter f_local1_err { facility(local1) and not level(info); }; + filter f_local1_err { facility(local1) and not level(notice); }; - # local1.info -/var/log/swift/proxy.log + # local1.notice -/var/log/swift/proxy.log # write to local file and to remove log server log { source(s_all); @@ -181,4 +182,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. \ No newline at end of file +`log-processing.conf-sample` for more details. diff --git a/swift/common/utils.py b/swift/common/utils.py index 8da3d1f8f4..5c462b5d08 100644 --- a/swift/common/utils.py +++ b/swift/common/utils.py @@ -48,6 +48,11 @@ import logging logging.thread = eventlet.green.thread logging.threading = eventlet.green.threading logging._lock = logging.threading.RLock() +# setup access level logging +ACCESS = 25 +logging._levelNames[ACCESS] = 'ACCESS' +# syslog priority "notice" is used for proxy access log lines +SysLogHandler.priority_map['ACCESS'] = 'notice' # These are lazily pulled from libc elsewhere _sys_fallocate = None @@ -310,6 +315,16 @@ class LogAdapter(object): def getEffectiveLevel(self): return self.logger.getEffectiveLevel() + def access(self, msg, *args): + """ + Convenience function for proxy access request log level. Only + proxy access log messages should use this method. 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(ACCESS, msg, *args) + def exception(self, msg, *args): _junk, exc, _junk = sys.exc_info() call = self.logger.error diff --git a/swift/proxy/server.py b/swift/proxy/server.py index 14f79a2c61..dc501faba5 100644 --- a/swift/proxy/server.py +++ b/swift/proxy/server.py @@ -1790,7 +1790,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.logger.access(' '.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..1fd18b6ee6 100644 --- a/test/unit/common/test_utils.py +++ b/test/unit/common/test_utils.py @@ -303,9 +303,15 @@ 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 access lvl logs by default + logger.access('test6') + self.assertEquals(sio.getvalue(), + 'test1\ntest3\ntest4\ntest6\n') + def test_storage_directory(self): self.assertEquals(utils.storage_directory('objects', '1', 'ABCDEF'), diff --git a/test/unit/proxy/test_server.py b/test/unit/proxy/test_server.py index e991d84084..4b0404454f 100644 --- a/test/unit/proxy/test_server.py +++ b/test/unit/proxy/test_server.py @@ -1802,7 +1802,7 @@ class TestObjectController(unittest.TestCase): class Logger(object): - def info(self, msg): + def access(self, msg): self.msg = msg orig_logger = prosrv.logger From 461bf8df712f1b03ed547bdf0a068aae434d50ef Mon Sep 17 00:00:00 2001 From: Clay Gerrard Date: Sat, 5 Feb 2011 15:38:49 -0600 Subject: [PATCH 3/6] added new proxy-server configuration options for access_log_facility and access_log_name --- swift/common/utils.py | 15 +++++++-------- swift/common/wsgi.py | 8 ++++---- swift/proxy/server.py | 12 +++++++++++- test/unit/common/test_utils.py | 4 ++-- test/unit/proxy/test_server.py | 10 +++++++--- 5 files changed, 31 insertions(+), 18 deletions(-) diff --git a/swift/common/utils.py b/swift/common/utils.py index 5c462b5d08..595ad3ac03 100644 --- a/swift/common/utils.py +++ b/swift/common/utils.py @@ -48,11 +48,11 @@ import logging logging.thread = eventlet.green.thread logging.threading = eventlet.green.threading logging._lock = logging.threading.RLock() -# setup access level logging -ACCESS = 25 -logging._levelNames[ACCESS] = 'ACCESS' +# setup notice level logging +NOTICE = 25 +logging._levelNames[NOTICE] = 'NOTICE' # syslog priority "notice" is used for proxy access log lines -SysLogHandler.priority_map['ACCESS'] = 'notice' +SysLogHandler.priority_map['NOTICE'] = 'notice' # These are lazily pulled from libc elsewhere _sys_fallocate = None @@ -315,15 +315,14 @@ class LogAdapter(object): def getEffectiveLevel(self): return self.logger.getEffectiveLevel() - def access(self, msg, *args): + def notice(self, msg, *args): """ - Convenience function for proxy access request log level. Only - proxy access log messages should use this method. The python + 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(ACCESS, msg, *args) + self.logger.log(NOTICE, msg, *args) def exception(self, msg, *args): _junk, exc, _junk = sys.exc_info() 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 dc501faba5..c4d8178c61 100644 --- a/swift/proxy/server.py +++ b/swift/proxy/server.py @@ -1612,6 +1612,16 @@ class BaseApplication(object): 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) + else: + self.access_logger = self.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 +1800,7 @@ class Application(BaseApplication): if getattr(req, 'client_disconnect', False) or \ getattr(response, 'client_disconnect', False): status_int = 499 - self.logger.access(' '.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 1fd18b6ee6..d709c65d3e 100644 --- a/test/unit/common/test_utils.py +++ b/test/unit/common/test_utils.py @@ -307,8 +307,8 @@ Error: unable to locate %s logger.debug('test5') self.assertEquals(sio.getvalue(), 'test1\ntest3\ntest4\n') - # make sure access lvl logs by default - logger.access('test6') + # make sure notice lvl logs by default + logger.notice('test7') self.assertEquals(sio.getvalue(), 'test1\ntest3\ntest4\ntest6\n') diff --git a/test/unit/proxy/test_server.py b/test/unit/proxy/test_server.py index 4b0404454f..9e49b09e74 100644 --- a/test/unit/proxy/test_server.py +++ b/test/unit/proxy/test_server.py @@ -1802,11 +1802,12 @@ class TestObjectController(unittest.TestCase): class Logger(object): - def access(self, msg): + def info(self, msg): self.msg = msg orig_logger = prosrv.logger - prosrv.logger = Logger() + orig_access_logger = prosrv.access_logger + prosrv.logger = prosrv.access_logger = Logger() sock = connect_tcp(('localhost', prolis.getsockname()[1])) fd = sock.makefile() fd.write( @@ -1822,11 +1823,13 @@ 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 - prosrv.logger = Logger() + orig_access_logger = prosrv.access_logger + prosrv.logger = prosrv.access_logger = Logger() prosrv.log_headers = True sock = connect_tcp(('localhost', prolis.getsockname()[1])) fd = sock.makefile() @@ -1840,6 +1843,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 def test_chunked_put_utf8_all_the_way_down(self): From 5d0bc6b9c76756a07648f04b4a309677fbec3635 Mon Sep 17 00:00:00 2001 From: Clay Gerrard Date: Thu, 10 Feb 2011 14:59:52 -0600 Subject: [PATCH 4/6] 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. --- bin/swift-bench | 8 +- doc/source/overview_stats.rst | 15 +-- swift/common/utils.py | 149 +++++++++------------ swift/proxy/server.py | 24 ++-- test/unit/common/test_utils.py | 234 +++++++++++++++++++++++++++------ test/unit/proxy/test_server.py | 141 ++++++++++++++++++-- 6 files changed, 412 insertions(+), 159 deletions(-) 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/doc/source/overview_stats.rst b/doc/source/overview_stats.rst index 40a5dd01af..6364de4611 100644 --- a/doc/source/overview_stats.rst +++ b/doc/source/overview_stats.rst @@ -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() group()); }; destination df_local1_err { file("/var/log/swift/proxy.error" owner() group()); }; destination df_local1_hourly { file("/var/log/swift/hourly/$YEAR$MONTH$DAY$HOUR" owner() group()); }; - 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. \ No newline at end of file diff --git a/swift/common/utils.py b/swift/common/utils.py index 595ad3ac03..3ba291e266 100644 --- a/swift/common/utils.py +++ b/swift/common/utils.py @@ -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) diff --git a/swift/proxy/server.py b/swift/proxy/server.py index c4d8178c61..b2b41d6434 100644 --- a/swift/proxy/server.py +++ b/swift/proxy/server.py @@ -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)) diff --git a/test/unit/common/test_utils.py b/test/unit/common/test_utils.py index d709c65d3e..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 """ @@ -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 diff --git a/test/unit/proxy/test_server.py b/test/unit/proxy/test_server.py index 9e49b09e74..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,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 From 5082b6d38958234351756757385f0301ff704087 Mon Sep 17 00:00:00 2001 From: Clay Gerrard Date: Thu, 10 Feb 2011 15:05:53 -0600 Subject: [PATCH 5/6] updated proxy-server.conf-sample to include access_log_* defaults --- etc/proxy-server.conf-sample | 3 +++ 1 file changed, 3 insertions(+) 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 From c973bf53fb08efd93943511f367b1fb5075fde41 Mon Sep 17 00:00:00 2001 From: Clay Gerrard Date: Thu, 10 Feb 2011 15:23:59 -0600 Subject: [PATCH 6/6] cleaned up some comments --- swift/common/utils.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/swift/common/utils.py b/swift/common/utils.py index 3ba291e266..4df8b624bc 100644 --- a/swift/common/utils.py +++ b/swift/common/utils.py @@ -51,7 +51,6 @@ logging._lock = logging.threading.RLock() # setup notice level logging NOTICE = 25 logging._levelNames[NOTICE] = 'NOTICE' -# syslog priority "notice" is used for proxy access log lines SysLogHandler.priority_map['NOTICE'] = 'notice' # These are lazily pulled from libc elsewhere @@ -289,7 +288,7 @@ class LoggerFileObject(object): return self -# double inhereitence to support property with setter +# double inheritance to support property with setter class LogAdapter(logging.LoggerAdapter, object): """ A Logger like object which performs some reformatting on calls to @@ -391,6 +390,7 @@ 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 = {} @@ -400,10 +400,10 @@ def get_logger(conf, name=None, log_to_console=False, log_route=None, log_route = name logger = logging.getLogger(log_route) logger.propagate = False - # all swift new handlers will get the same formatter + # all new handlers will get the same formatter formatter = TxnFormatter(fmt) - # a single swift logger will only get one SysLog Handler + # 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: