Merge lp:~clay-gerrard/swift/bench_logger_fix into lp:~hudson-openstack/swift/trunk

[clayg]

reworked tnx logging

fixed import of missing NamedLogger in bin/swift-bench
fixed LogAdapter.tnx_id so that it works with multiple calls to get_logger
fixed common.middleware.catch_errors to reuse self.app.logger if it can
renamed x-cf-trans-id to x-swift-tnx-id

[gholt (gholt)]

bin/swift-bench:130:80: E501 line too long (86 characters)

[gholt (gholt)]

Kinda whiny, but wouldn't the change to catch_errors be cleaner as:
    self.logger = getattr(app, 'logger', get_logger(conf))

Also minor: During an upgrade some transaction ids won't get logged for a short time as one server is upgraded and expecting new x-swift-txn-id headers and an old server is still sending x-cf-trans-id headers.

[clayg (clay-gerrard)]

I guess you *could* use getattr now that the NamedFormatter is looking for the threadlocal variable on the LogAdapter *class* - but if you do it that way get_logger gets called everytime. Which before would cause get_logger.handler's formatter to be set as a new formatter with a new reference to different "adapted_logger" object that couldn't reference the instance variable... I'd rather avoid the issue in the future and leave it as the "ugly" try/except.

I hadn't considered the rolling upgrade across the cluster. I'm tempted to update the code to read 'x-swift-tnx-id' AND 'x-cf-trans-id', but only write 'x-swift-tnx-id'??? After the 1.1 release I'll take it out completely. We'll see how it looks...

[clayg (clay-gerrard)]

Hrmm... I don't think it "looks" that bad, except when I get rid of x-cf-trans-id common.utils.get_txn_id will look kinda silly? Still I'm not sure how much this really helps, since it works both ways. As one server is upgraded and sending x-swift-txn-id headers and an old server is still expecting x-cf-trans-id headers. But I don't know if I really want to read and WRITE both headers?

[gholt (gholt)]

So really, neither of my suggestions are very helpful. You can ignore them.

[lp:~clay-gerrard/swift/bench_logger_fix]

159. By clayg on 2011-01-05

revert x-cf-trans-id rename

[clayg (clay-gerrard)]

so... this is me admitting defeat.

I guess it's not worth the trouble to rename x-cf-trans-id to x-swift-txn-id :(

review: Needs Resubmitting

[Chuck Thier (cthier)]

Thanks for taking care of this clay

review: Approve

=== modified file 'bin/swift-bench'
--- bin/swift-bench	2011-01-04 23:34:43 +0000
+++ bin/swift-bench	2011-01-05 21:29:07 +0000
@@ -22,7 +22,7 @@
 from optparse import OptionParser
 
 from swift.common.bench import BenchController
-from swift.common.utils import readconf, NamedLogger
+from swift.common.utils import readconf, LogAdapter, NamedFormatter
 
 # The defaults should be sufficient to run swift-bench on a SAIO
 CONF_DEFAULTS = {
@@ -124,10 +124,11 @@
         'critical': logging.CRITICAL}.get(
             options.log_level.lower(), logging.INFO))
     loghandler = logging.StreamHandler()
-    logformat = logging.Formatter('%(asctime)s %(levelname)s %(message)s')
+    logger.addHandler(loghandler)
+    logger = LogAdapter(logger)
+    logformat = NamedFormatter('swift-bench', logger,
+                   fmt='%(server)s %(asctime)s %(levelname)s %(message)s')
     loghandler.setFormatter(logformat)
-    logger.addHandler(loghandler)
-    logger = NamedLogger(logger, 'swift-bench')
 
     controller = BenchController(logger, options)
     controller.run()

=== modified file 'swift/common/middleware/catch_errors.py'
--- swift/common/middleware/catch_errors.py	2011-01-04 23:34:43 +0000
+++ swift/common/middleware/catch_errors.py	2011-01-05 21:29:07 +0000
@@ -26,7 +26,11 @@
 
     def __init__(self, app, conf):
         self.app = app
-        self.logger = get_logger(conf)
+        # if the application already has a logger we should use that one
+        self.logger = getattr(app, 'logger', None)
+        if not self.logger:
+            # and only call get_logger if we have to
+            self.logger = get_logger(conf)
 
     def __call__(self, env, start_response):
         try:

=== modified file 'swift/common/utils.py'
--- swift/common/utils.py	2011-01-04 23:34:43 +0000
+++ swift/common/utils.py	2011-01-05 21:29:07 +0000
@@ -284,11 +284,15 @@
 
 
 class LogAdapter(object):
-    """Cheesy version of the LoggerAdapter available in Python 3"""
+    """
+    A Logger like object which performs some reformatting on calls to
+    :meth:`exception`.  Can be used to store a threadlocal transaction id.
+    """
+
+    _txn_id = threading.local()
 
     def __init__(self, logger):
         self.logger = logger
-        self._txn_id = threading.local()
         for proxied_method in ('debug', 'log', 'warn', 'warning', 'error',
                                'critical', 'info'):
             setattr(self, proxied_method, getattr(logger, proxied_method))
@@ -334,18 +338,45 @@
 
 
 class NamedFormatter(logging.Formatter):
-    def __init__(self, server, logger):
-        logging.Formatter.__init__(self)
+    """
+    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"``
+    """
+
+    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):
-            return '%s %s (txn: %s)' % (self.server, msg, self.logger.txn_id)
-        else:
-            return '%s %s' % (self.server, msg)
+            msg = "%s (txn: %s)" % (msg, self.logger.txn_id)
+        return msg
 
 
 def get_logger(conf, name=None, log_to_console=False):
@@ -386,7 +417,10 @@
     root_logger.setLevel(
         getattr(logging, conf.get('log_level', 'INFO').upper(), logging.INFO))
     adapted_logger = LogAdapter(root_logger)
-    get_logger.handler.setFormatter(NamedFormatter(name, adapted_logger))
+    formatter = NamedFormatter(name, adapted_logger)
+    get_logger.handler.setFormatter(formatter)
+    if hasattr(get_logger, 'console'):
+        get_logger.console.setFormatter(formatter)
     return adapted_logger