Merge lp:~gholt/swift/logroutes into lp:~hudson-openstack/swift/trunk

[gholt]

logging: use routes to separate logging configurations

logging: use routes to separate logging configurations

Specifically, this fixes using different log_level settings even if the same log_name is used.

[lp:~gholt/swift/logroutes]

209. By gholt on 2011-02-09

Merge from trunk

[clayg (clay-gerrard)]

Calling get_logger with a log_route kwarg instead of name as a positional argument isn't really the same thing. It may even have some side-effects that weren't intended?

e.g.
the drive-audit script logs as "swift" instead of "drive-audit"
swift-account-stats-logger logs as "log-processor-stats" instead of "swift-account-stats-logger" or just "account-stats"

I think things mostly sorta "work" because these conf dicts are coming out of readconf and run_wsgi which will both throw in a log_name key set to the section_name if there isn't something there already.

On the other hand... with this branch I can finally set a log_name for the auditors, updaters and replicators... so maybe it's a net gain?

[gholt (gholt)]

No, all that was intended. This separates the naming from the routing, then tries to get the naming defaults configured back to what they originally were, or what I thought was intended. I just missed some naming on items apparently.

I'll get the drive-audit name fixed. With the log processing stuff, I got lost pretty quick on what was intended to be named what and meant to tap you and John on that (but obviously forgot). Most everything in the system logs with no "swift-" prefix, but some of the log stuff was previously.

[lp:~gholt/swift/logroutes]

210. By gholt on 2011-02-10

Fix drive-audit's default log_name

[gholt (gholt)]

Fixed the drive-audit log name.

Maybe this comment doesn't belong here, but it's logging related so maybe it does, I dunno. :)

The log processing stuff is a bit confusing to me since it doesn't follow the model the rest of the code does. i.e. binary name ~= section name == default log name. It doesn't even seem to have consistency on it's own, really.

From trunk it seems to be:

The bin/swift-account-stats-logger uses the section log-processor-stats and logs as swift-account-stats-logger. Apparently this thing needs write access to my logs directory as well, but that's another discussion. :P

The bin/swift-log-stats-collector uses the section log-processor and logs as swift and log-stats-collector.

The bin/swift-log-uploader uses the section log-processor and logs as swift or just the plugin name (such as "access").

So, perhaps I can be forgiven for not knowing what to do with these during this logging refactor? I really don't want to mimic this behavior in this branch, unless that's really, really what's needed.

[gholt (gholt)]

Desnarkified by clayg and ready for re-review!

[lp:~gholt/swift/logroutes]

211. By gholt on 2011-02-10

Merge from ~clay-gerrard/swift/logroutes

[clayg (clay-gerrard)]

you are forgiven

review: Approve

[lp:~gholt/swift/logroutes]

212. By gholt on 2011-02-10

Merge from trunk

213. By gholt on 2011-02-10

PEP8 Fixes

=== modified file 'bin/swift-account-stats-logger'
--- bin/swift-account-stats-logger	2011-01-04 23:34:43 +0000
+++ bin/swift-account-stats-logger	2011-02-10 23:12:47 +0000
@@ -23,4 +23,4 @@
     # currently AccountStat only supports run_once
     options['once'] = True
     run_daemon(AccountStat, conf_file, section_name='log-processor-stats',
-               **options)
+               log_name="account-stats", **options)
 
=== modified file 'bin/swift-drive-audit'
--- bin/swift-drive-audit	2011-01-26 22:31:33 +0000
+++ bin/swift-drive-audit	2011-02-10 23:12:47 +0000
@@ -99,7 +99,8 @@
     device_dir = conf.get('device_dir', '/srv/node')
     minutes = int(conf.get('minutes', 60))
     error_limit = int(conf.get('error_limit', 1))
-    logger = get_logger(conf, 'drive-audit')
+    conf['log_name'] = conf.get('log_name', 'drive-audit')
+    logger = get_logger(conf, log_route='drive-audit')
     devices = get_devices(device_dir, logger)
     logger.debug("Devices found: %s" % str(devices))
     if not devices:
 
=== modified file 'bin/swift-log-uploader'
--- bin/swift-log-uploader	2011-01-04 23:34:43 +0000
+++ bin/swift-log-uploader	2011-02-10 23:12:47 +0000
@@ -34,7 +34,7 @@
     uploader_conf.update(plugin_conf)
 
     # pre-configure logger
-    logger = utils.get_logger(uploader_conf, plugin,
+    logger = utils.get_logger(uploader_conf, log_route='log-uploader',
                               log_to_console=options.get('verbose', False))
     # currently LogUploader only supports run_once
     options['once'] = True
 
=== modified file 'swift/account/auditor.py'
--- swift/account/auditor.py	2011-01-04 23:34:43 +0000
+++ swift/account/auditor.py	2011-02-10 23:12:47 +0000
@@ -28,7 +28,7 @@
 
     def __init__(self, conf):
         self.conf = conf
-        self.logger = get_logger(conf, 'account-auditor')
+        self.logger = get_logger(conf, log_route='account-auditor')
         self.devices = conf.get('devices', '/srv/node')
         self.mount_check = conf.get('mount_check', 'true').lower() in \
                               ('true', 't', '1', 'on', 'yes', 'y')
 
=== modified file 'swift/account/reaper.py'
--- swift/account/reaper.py	2011-01-19 23:21:57 +0000
+++ swift/account/reaper.py	2011-02-10 23:12:47 +0000
@@ -53,7 +53,7 @@
 
     def __init__(self, conf):
         self.conf = conf
-        self.logger = get_logger(conf)
+        self.logger = get_logger(conf, log_route='account-reaper')
         self.devices = conf.get('devices', '/srv/node')
         self.mount_check = conf.get('mount_check', 'true').lower() in \
                               ('true', 't', '1', 'on', 'yes', 'y')
 
=== modified file 'swift/account/server.py'
--- swift/account/server.py	2011-01-29 19:26:06 +0000
+++ swift/account/server.py	2011-02-10 23:12:47 +0000
@@ -42,7 +42,7 @@
     """WSGI controller for the account server."""
 
     def __init__(self, conf):
-        self.logger = get_logger(conf)
+        self.logger = get_logger(conf, log_route='account-server')
         self.root = conf.get('devices', '/srv/node')
         self.mount_check = conf.get('mount_check', 'true').lower() in \
                               ('true', 't', '1', 'on', 'yes', 'y')
 
=== modified file 'swift/auth/server.py'
--- swift/auth/server.py	2011-01-26 22:38:13 +0000
+++ swift/auth/server.py	2011-02-10 23:12:47 +0000
@@ -90,7 +90,7 @@
     """
 
     def __init__(self, conf):
-        self.logger = get_logger(conf)
+        self.logger = get_logger(conf, log_route='auth-server')
         self.super_admin_key = conf.get('super_admin_key')
         if not self.super_admin_key:
             msg = _('No super_admin_key set in conf file! Exiting.')
 
=== modified file 'swift/common/daemon.py'
--- swift/common/daemon.py	2011-01-04 23:34:43 +0000
+++ swift/common/daemon.py	2011-02-10 23:12:47 +0000
@@ -26,7 +26,7 @@
 
     def __init__(self, conf):
         self.conf = conf
-        self.logger = utils.get_logger(conf, 'swift-daemon')
+        self.logger = utils.get_logger(conf, log_route='daemon')
 
     def run_once(self):
         """Override this to run the script once"""
@@ -84,7 +84,7 @@
         logger = kwargs.pop('logger')
     else:
         logger = utils.get_logger(conf, conf.get('log_name', section_name),
-                                  log_to_console=kwargs.pop('verbose', False))
+           log_to_console=kwargs.pop('verbose', False), log_route=section_name)
     try:
         klass(conf).run(once=once, **kwargs)
     except KeyboardInterrupt:
 
=== modified file 'swift/common/db.py'
--- swift/common/db.py	2011-02-04 19:50:30 +0000
+++ swift/common/db.py	2011-02-10 23:12:47 +0000
@@ -287,7 +287,7 @@
         self.conn = None
         orig_isolation_level = conn.isolation_level
         conn.isolation_level = None
-        conn.execute('PRAGMA journal_mode = DELETE') # remove any journal files
+        conn.execute('PRAGMA journal_mode = DELETE')  # remove journal files
         conn.execute('BEGIN IMMEDIATE')
         try:
             yield True
@@ -295,7 +295,7 @@
             pass
         try:
             conn.execute('ROLLBACK')
-            conn.execute('PRAGMA journal_mode = WAL') # back to WAL mode
+            conn.execute('PRAGMA journal_mode = WAL')  # back to WAL mode
             conn.isolation_level = orig_isolation_level
             self.conn = conn
         except Exception:
 
=== modified file 'swift/common/db_replicator.py'
--- swift/common/db_replicator.py	2011-01-29 19:26:06 +0000
+++ swift/common/db_replicator.py	2011-02-10 23:12:47 +0000
@@ -92,7 +92,7 @@
 
     def __init__(self, conf):
         self.conf = conf
-        self.logger = get_logger(conf)
+        self.logger = get_logger(conf, log_route='replicator')
         self.root = conf.get('devices', '/srv/node')
         self.mount_check = conf.get('mount_check', 'true').lower() in \
                               ('true', 't', '1', 'on', 'yes', 'y')
 
=== modified file 'swift/common/middleware/catch_errors.py'
--- swift/common/middleware/catch_errors.py	2011-01-07 21:17:29 +0000
+++ swift/common/middleware/catch_errors.py	2011-02-10 23:12:47 +0000
@@ -26,11 +26,7 @@
 
     def __init__(self, app, conf):
         self.app = app
-        # 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)
+        self.logger = get_logger(conf, log_route='catch-errors')
 
     def __call__(self, env, start_response):
         try:
 
=== modified file 'swift/common/middleware/cname_lookup.py'
--- swift/common/middleware/cname_lookup.py	2011-01-20 20:15:05 +0000
+++ swift/common/middleware/cname_lookup.py	2011-02-10 23:12:47 +0000
@@ -53,7 +53,7 @@
             self.storage_domain = '.' + self.storage_domain
         self.lookup_depth = int(conf.get('lookup_depth', '1'))
         self.memcache = None
-        self.logger = get_logger(conf)
+        self.logger = get_logger(conf, log_route='cname-lookup')
 
     def __call__(self, env, start_response):
         if not self.storage_domain:
 
=== modified file 'swift/common/middleware/ratelimit.py'
--- swift/common/middleware/ratelimit.py	2011-01-22 00:28:58 +0000
+++ swift/common/middleware/ratelimit.py	2011-02-10 23:12:47 +0000
@@ -39,7 +39,7 @@
         if logger:
             self.logger = logger
         else:
-            self.logger = get_logger(conf)
+            self.logger = get_logger(conf, log_route='ratelimit')
         self.account_ratelimit = float(conf.get('account_ratelimit', 0))
         self.max_sleep_time_seconds = \
             float(conf.get('max_sleep_time_seconds', 60))
 
=== modified file 'swift/common/middleware/swauth.py'
--- swift/common/middleware/swauth.py	2011-02-02 18:23:01 +0000
+++ swift/common/middleware/swauth.py	2011-02-10 23:12:47 +0000
@@ -51,7 +51,7 @@
     def __init__(self, app, conf):
         self.app = app
         self.conf = conf
-        self.logger = get_logger(conf)
+        self.logger = get_logger(conf, log_route='swauth')
         self.log_headers = conf.get('log_headers') == 'True'
         self.reseller_prefix = conf.get('reseller_prefix', 'AUTH').strip()
         if self.reseller_prefix and self.reseller_prefix[-1] != '_':
 
=== modified file 'swift/common/utils.py'
--- swift/common/utils.py	2011-02-10 21:23:59 +0000
+++ swift/common/utils.py	2011-02-10 23:12:47 +0000
@@ -390,6 +390,8 @@
     :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 log_route: Route for the logging, not emitted to the log, just used
+                      to separate logging configurations
     :param fmt: Override log format
     """
     if not conf:
 
=== modified file 'swift/common/wsgi.py'
--- swift/common/wsgi.py	2011-02-05 21:38:49 +0000
+++ swift/common/wsgi.py	2011-02-10 23:12:47 +0000
@@ -113,7 +113,7 @@
         logger = kwargs.pop('logger')
     else:
         logger = get_logger(conf, log_name,
-                            log_to_console=kwargs.pop('verbose', False))
+            log_to_console=kwargs.pop('verbose', False), log_route='wsgi')
 
     # redirect errors to logger and close stdio
     capture_stdio(logger)
 
=== modified file 'swift/container/auditor.py'
--- swift/container/auditor.py	2011-01-04 23:34:43 +0000
+++ swift/container/auditor.py	2011-02-10 23:12:47 +0000
@@ -28,7 +28,7 @@
 
     def __init__(self, conf):
         self.conf = conf
-        self.logger = get_logger(conf, 'container-auditor')
+        self.logger = get_logger(conf, log_route='container-auditor')
         self.devices = conf.get('devices', '/srv/node')
         self.mount_check = conf.get('mount_check', 'true').lower() in \
                               ('true', 't', '1', 'on', 'yes', 'y')
 
=== modified file 'swift/container/server.py'
--- swift/container/server.py	2011-01-29 19:26:06 +0000
+++ swift/container/server.py	2011-02-10 23:12:47 +0000
@@ -49,7 +49,7 @@
     save_headers = ['x-container-read', 'x-container-write']
 
     def __init__(self, conf):
-        self.logger = get_logger(conf)
+        self.logger = get_logger(conf, log_route='container-server')
         self.root = conf.get('devices', '/srv/node/')
         self.mount_check = conf.get('mount_check', 'true').lower() in \
                               ('true', 't', '1', 'on', 'yes', 'y')
 
=== modified file 'swift/container/updater.py'
--- swift/container/updater.py	2011-01-26 22:38:13 +0000
+++ swift/container/updater.py	2011-02-10 23:12:47 +0000
@@ -37,7 +37,7 @@
 
     def __init__(self, conf):
         self.conf = conf
-        self.logger = get_logger(conf, 'container-updater')
+        self.logger = get_logger(conf, log_route='container-updater')
         self.devices = conf.get('devices', '/srv/node')
         self.mount_check = conf.get('mount_check', 'true').lower() in \
                               ('true', 't', '1', 'on', 'yes', 'y')
 
=== modified file 'swift/obj/auditor.py'
--- swift/obj/auditor.py	2011-01-21 01:05:44 +0000
+++ swift/obj/auditor.py	2011-02-10 23:12:47 +0000
@@ -31,7 +31,7 @@
 
     def __init__(self, conf):
         self.conf = conf
-        self.logger = get_logger(conf, 'object-auditor')
+        self.logger = get_logger(conf, log_route='object-auditor')
         self.devices = conf.get('devices', '/srv/node')
         self.mount_check = conf.get('mount_check', 'true').lower() in \
                               ('true', 't', '1', 'on', 'yes', 'y')
 
=== modified file 'swift/obj/replicator.py'
--- swift/obj/replicator.py	2011-01-27 22:42:36 +0000
+++ swift/obj/replicator.py	2011-02-10 23:12:47 +0000
@@ -207,7 +207,7 @@
         :param logger: logging object
         """
         self.conf = conf
-        self.logger = get_logger(conf, 'object-replicator')
+        self.logger = get_logger(conf, log_route='object-replicator')
         self.devices_dir = conf.get('devices', '/srv/node')
         self.mount_check = conf.get('mount_check', 'true').lower() in \
                               ('true', 't', '1', 'on', 'yes', 'y')
 
=== modified file 'swift/obj/server.py'
--- swift/obj/server.py	2011-01-26 22:38:13 +0000
+++ swift/obj/server.py	2011-02-10 23:12:47 +0000
@@ -266,7 +266,7 @@
         <source-dir>/etc/object-server.conf-sample or
         /etc/swift/object-server.conf-sample.
         """
-        self.logger = get_logger(conf)
+        self.logger = get_logger(conf, log_route='object-server')
         self.devices = conf.get('devices', '/srv/node/')
         self.mount_check = conf.get('mount_check', 'true').lower() in \
                               ('true', 't', '1', 'on', 'yes', 'y')
 
=== modified file 'swift/obj/updater.py'
--- swift/obj/updater.py	2011-01-26 22:31:33 +0000
+++ swift/obj/updater.py	2011-02-10 23:12:47 +0000
@@ -35,7 +35,7 @@
 
     def __init__(self, conf):
         self.conf = conf
-        self.logger = get_logger(conf, 'object-updater')
+        self.logger = get_logger(conf, log_route='object-updater')
         self.devices = conf.get('devices', '/srv/node')
         self.mount_check = conf.get('mount_check', 'true').lower() in \
                               ('true', 't', '1', 'on', 'yes', 'y')
 
=== modified file 'swift/proxy/server.py'
--- swift/proxy/server.py	2011-02-10 20:59:52 +0000
+++ swift/proxy/server.py	2011-02-10 23:12:47 +0000
@@ -1609,7 +1609,7 @@
         if conf is None:
             conf = {}
         if logger is None:
-            self.logger = get_logger(conf)
+            self.logger = get_logger(conf, log_route='proxy-server')
             access_log_conf = {}
             for key in ('log_facility', 'log_name', 'log_level'):
                 value = conf.get('access_' + key, conf.get(key, None))
 
=== modified file 'swift/stats/access_processor.py'
--- swift/stats/access_processor.py	2011-01-17 17:07:58 +0000
+++ swift/stats/access_processor.py	2011-02-10 23:12:47 +0000
@@ -34,7 +34,7 @@
                             conf.get('service_ips', '').split(',')\
                             if x.strip()]
         self.warn_percent = float(conf.get('warn_percent', '0.8'))
-        self.logger = get_logger(conf)
+        self.logger = get_logger(conf, log_route='access-processor')
 
     def log_line_parser(self, raw_log):
         '''given a raw access log line, return a dict of the good parts'''
 
=== modified file 'swift/stats/account_stats.py'
--- swift/stats/account_stats.py	2011-01-30 14:59:35 +0000
+++ swift/stats/account_stats.py	2011-02-10 23:12:47 +0000
@@ -48,7 +48,8 @@
         self.devices = server_conf.get('devices', '/srv/node')
         self.mount_check = server_conf.get('mount_check', 'true').lower() in \
                               ('true', 't', '1', 'on', 'yes', 'y')
-        self.logger = get_logger(stats_conf, 'swift-account-stats-logger')
+        self.logger = \
+            get_logger(stats_conf, log_route='account-stats')
 
     def run_once(self):
         self.logger.info(_("Gathering account stats"))
 
=== modified file 'swift/stats/log_processor.py'
--- swift/stats/log_processor.py	2011-01-26 22:38:13 +0000
+++ swift/stats/log_processor.py	2011-02-10 23:12:47 +0000
@@ -40,7 +40,7 @@
 
     def __init__(self, conf, logger):
         if isinstance(logger, tuple):
-            self.logger = get_logger(*logger)
+            self.logger = get_logger(*logger, log_route='log-processor')
         else:
             self.logger = logger
 
@@ -226,7 +226,7 @@
         c = conf.get('log-processor')
         super(LogProcessorDaemon, self).__init__(c)
         self.total_conf = conf
-        self.logger = get_logger(c)
+        self.logger = get_logger(c, log_route='log-processor')
         self.log_processor = LogProcessor(conf, self.logger)
         self.lookback_hours = int(c.get('lookback_hours', '120'))
         self.lookback_window = int(c.get('lookback_window',
 
=== modified file 'swift/stats/log_uploader.py'
--- swift/stats/log_uploader.py	2011-01-14 08:45:39 +0000
+++ swift/stats/log_uploader.py	2011-02-10 23:12:47 +0000
@@ -64,8 +64,9 @@
         self.container_name = container_name
         self.filename_format = source_filename_format
         self.internal_proxy = InternalProxy(proxy_server_conf)
-        log_name = 'swift-log-uploader-%s' % plugin_name
-        self.logger = utils.get_logger(uploader_conf, plugin_name)
+        log_name = '%s-log-uploader' % plugin_name
+        self.logger = utils.get_logger(uploader_conf, log_name,
+                                       log_route=plugin_name)
 
     def run_once(self):
         self.logger.info(_("Uploading logs"))
 
=== modified file 'swift/stats/stats_processor.py'
--- swift/stats/stats_processor.py	2011-01-19 23:21:57 +0000
+++ swift/stats/stats_processor.py	2011-02-10 23:12:47 +0000
@@ -20,7 +20,7 @@
     """Transform account storage stat logs"""
 
     def __init__(self, conf):
-        self.logger = get_logger(conf)
+        self.logger = get_logger(conf, log_route='stats-processor')
 
     def process(self, obj_stream, data_object_account, data_object_container,
                 data_object_name):
 
=== modified file 'test/unit/auth/test_server.py'
--- test/unit/auth/test_server.py	2011-01-19 23:21:57 +0000
+++ test/unit/auth/test_server.py	2011-02-10 23:12:47 +0000
@@ -456,7 +456,7 @@
     def test_basic_logging(self):
         log = StringIO()
         log_handler = StreamHandler(log)
-        logger = get_logger(self.conf, 'auth')
+        logger = get_logger(self.conf, 'auth-server', log_route='auth-server')
         logger.logger.addHandler(log_handler)
         try:
             auth_server.http_connect = fake_http_connect(201)
@@ -534,7 +534,7 @@
         orig_Request = auth_server.Request
         log = StringIO()
         log_handler = StreamHandler(log)
-        logger = get_logger(self.conf, 'auth')
+        logger = get_logger(self.conf, 'auth-server', log_route='auth-server')
         logger.logger.addHandler(log_handler)
         try:
             auth_server.Request = request_causing_exception
 
=== modified file 'test/unit/common/test_daemon.py'
--- test/unit/common/test_daemon.py	2011-02-02 17:38:17 +0000
+++ test/unit/common/test_daemon.py	2011-02-10 23:12:47 +0000
@@ -28,7 +28,7 @@
 
     def __init__(self, conf):
         self.conf = conf
-        self.logger = utils.get_logger(None, 'server')
+        self.logger = utils.get_logger(None, 'server', log_route='server')
         MyDaemon.forever_called = False
         MyDaemon.once_called = False
 
@@ -99,7 +99,7 @@
             sio = StringIO()
             logger = logging.getLogger('server')
             logger.addHandler(logging.StreamHandler(sio))
-            logger = utils.get_logger(None, 'server')
+            logger = utils.get_logger(None, 'server', log_route='server')
             daemon.run_daemon(MyDaemon, conf_file, logger=logger)
             self.assert_('user quit' in sio.getvalue().lower())
 
 
=== modified file 'test/unit/common/test_utils.py'
--- test/unit/common/test_utils.py	2011-02-10 20:59:52 +0000
+++ test/unit/common/test_utils.py	2011-02-10 23:12:47 +0000
@@ -303,17 +303,19 @@
         sio = StringIO()
         logger = logging.getLogger('server')
         logger.addHandler(logging.StreamHandler(sio))
-        logger = utils.get_logger(None, 'server')
+        logger = utils.get_logger(None, 'server', log_route='server')
         logger.warn('test1')
         self.assertEquals(sio.getvalue(), 'test1\n')
         logger.debug('test2')
         self.assertEquals(sio.getvalue(), 'test1\n')
-        logger = utils.get_logger({'log_level': 'DEBUG'}, 'server')
+        logger = utils.get_logger({'log_level': 'DEBUG'}, 'server',
+                                  log_route='server')
         logger.debug('test3')
         self.assertEquals(sio.getvalue(), 'test1\ntest3\n')
         # Doesn't really test that the log facility is truly being used all the
         # way to syslog; but exercises the code.
-        logger = utils.get_logger({'log_facility': 'LOG_LOCAL3'}, 'server')
+        logger = utils.get_logger({'log_facility': 'LOG_LOCAL3'}, 'server',
+                                  log_route='server')
         logger.warn('test4')
         self.assertEquals(sio.getvalue(),
                           'test1\ntest3\ntest4\n')
 
=== modified file 'test/unit/obj/test_auditor.py'
--- test/unit/obj/test_auditor.py	2011-01-25 01:12:38 +0000
+++ test/unit/obj/test_auditor.py	2011-02-10 23:12:47 +0000
@@ -14,7 +14,7 @@
 # limitations under the License.
 
 # TODO: Tests
-from test import unit as _setup_mocks
+from test import unit
 import unittest
 import tempfile
 import os
@@ -57,6 +57,7 @@
 
     def tearDown(self):
         rmtree(os.path.dirname(self.testdir), ignore_errors=1)
+        unit.xattr_data = {}
 
     def test_object_audit_extra_data(self):
         self.auditor = auditor.ObjectAuditor(self.conf)