Adding StatsD logging to Swift.

Documentation, including a list of metrics reported and their semantics,
is in the Admin Guide in a new section, "Reporting Metrics to StatsD".
An optional "metric prefix" may be configured which will be prepended to
every metric name sent to StatsD.

Here is the rationale for doing a deep integration like this versus only
sending metrics to StatsD in middleware.  It's the only way to report
some internal activities of Swift in a real-time manner. So to have one
way of reporting to StatsD and one place/style of configuration, even
some things (like, say, timing of PUT requests into the proxy-server)
which could be logged via middleware are consistently logged the same
way (deep integration via the logger delegate methods).

When log_statsd_host is configured, get_logger() injects a
swift.common.utils.StatsdClient object into the logger as
logger.statsd_client.  Then a set of delegate methods on LogAdapter
either pass through to the StatsdClient object or become no-ops. This
allows StatsD logging to look like:
    self.logger.increment('some.metric.here')
and do the right thing in all cases and with no messy conditional logic.

I wanted to use the pystatsd module for the StatsD client, but the
version on PyPi is lagging the git repo (and is missing both the prefix
functionality and timing_since() method).  So I wrote my
swift.common.utils.StatsdClient.  The interface is the same as
pystatsd.Client, but the code was written from scratch.  It's pretty
simple, and the tests I added cover it.  This also frees Swift from an
optional dependency on the pystatsd module, making this feature easier
to enable.

There's test coverage for the new code and all existing tests continue
to pass.

Refactored out _one_audit_pass() method in swift/account/auditor.py and
swift/container/auditor.py.

Fixed some misc. PEP8 violations.

Misc test cleanups and refactorings (particularly the way "fake logging"
is handled).

Change-Id: Ie968a9ae8771f59ee7591e2ae11999c44bfe33b2

Author: dbishop

doc/source/admin_guide.rst

@@ -18,36 +18,42 @@
 # Swift documentation build configuration file, created by
 # sphinx-quickstart on Tue May 18 13:50:15 2010.
 #
-# This file is execfile()d with the current directory set to its containing dir.
+# This file is execfile()d with the current directory set to its containing
+# dir.
 #
 # Note that not all possible configuration values are present in this
 # autogenerated file.
 #
 # All configuration values have a default; values that are commented out
 # serve to show the default.
 
-import sys, os
+import sys
+import os
 
 # If extensions (or modules to document with autodoc) are in another directory,
 # add these directories to sys.path here. If the directory is relative to the
 # documentation root, use os.path.abspath to make it absolute, like shown here.
-sys.path.append([os.path.abspath('../swift'), os.path.abspath('..'), os.path.abspath('../bin')])
+sys.path.append([os.path.abspath('../swift'), os.path.abspath('..'),
+                 os.path.abspath('../bin')])
 
-# -- General configuration -----------------------------------------------------
+# -- General configuration ----------------------------------------------------
 
-# Add any Sphinx extension module names here, as strings. They can be extensions
-# coming with Sphinx (named 'sphinx.ext.*') or your custom ones.
-extensions = ['sphinx.ext.autodoc', 'sphinx.ext.intersphinx', 'sphinx.ext.todo', 'sphinx.ext.coverage', 'sphinx.ext.pngmath', 'sphinx.ext.ifconfig']
+# Add any Sphinx extension module names here, as strings. They can be
+# extensions coming with Sphinx (named 'sphinx.ext.*') or your custom ones.
+extensions = ['sphinx.ext.autodoc', 'sphinx.ext.intersphinx',
+              'sphinx.ext.todo', 'sphinx.ext.coverage', 'sphinx.ext.pngmath',
+              'sphinx.ext.ifconfig']
 todo_include_todos = True
 
 # Add any paths that contain templates here, relative to this directory.
-# Changing the path so that the Hudson build output contains GA code and the source
-# docs do not contain the code so local, offline sphinx builds are "clean."
+# Changing the path so that the Hudson build output contains GA code and the
+# source docs do not contain the code so local, offline sphinx builds are
+# "clean."
 templates_path = []
 if os.getenv('HUDSON_PUBLISH_DOCS'):
-  templates_path = ['_ga', '_templates']
+    templates_path = ['_ga', '_templates']
 else:
-  templates_path = ['_templates']
+    templates_path = ['_templates']
 
 # The suffix of source filenames.
 source_suffix = '.rst'
@@ -89,7 +95,8 @@
 # for source files.
 exclude_trees = []
 
-# The reST default role (used for this markup: `text`) to use for all documents.
+# The reST default role (used for this markup: `text`) to use for all
+# documents.
 #default_role = None
 
 # If true, '()' will be appended to :func: etc. cross-reference text.
@@ -110,7 +117,7 @@
 modindex_common_prefix = ['swift.']
 
 
-# -- Options for HTML output ---------------------------------------------------
+# -- Options for HTML output -----------------------------------------------
 
 # The theme to use for HTML and HTML Help pages.  Major themes that come with
 # Sphinx are currently 'default' and 'sphinxdoc'.
@@ -188,7 +195,7 @@
 htmlhelp_basename = 'swiftdoc'
 
 
-# -- Options for LaTeX output --------------------------------------------------
+# -- Options for LaTeX output -------------------------------------------------
 
 # The paper size ('letter' or 'a4').
 #latex_paper_size = 'letter'
@@ -197,7 +204,8 @@
 #latex_font_size = '10pt'
 
 # Grouping the document tree into LaTeX files. List of tuples
-# (source start file, target name, title, author, documentclass [howto/manual]).
+# (source start file, target name, title, author, documentclass
+# [howto/manual]).
 latex_documents = [
   ('index', 'Swift.tex', u'Swift Documentation',
    u'Swift Team', 'manual'),
@@ -224,4 +232,3 @@
 intersphinx_mapping = {'python': ('http://docs.python.org/', None),
                        'nova': ('http://nova.openstack.org', None),
                        'glance': ('http://glance.openstack.org', None)}
-

doc/source/conf.py

@@ -11,6 +11,12 @@
 # log_name = swift
 # log_facility = LOG_LOCAL0
 # log_level = INFO
+# You can enable default statsD logging here and/or override it in sections
+# below:
+# log_statsd_host = localhost
+# log_statsd_port = 8125
+# log_statsd_default_sample_rate = 1
+# log_statsd_metric_prefix =
 # Normally Swift will try to preallocate disk space for new SQLite databases to
 # decrease fragmentation (at the cost of disk usage). You may turn this feature
 # off here.

etc/account-server.conf-sample

@@ -14,6 +14,12 @@
 # log_name = swift
 # log_facility = LOG_LOCAL0
 # log_level = INFO
+# You can enable default statsD logging here and/or override it in sections
+# below:
+# log_statsd_host = localhost
+# log_statsd_port = 8125
+# log_statsd_default_sample_rate = 1
+# log_statsd_metric_prefix =
 # Normally Swift will try to preallocate disk space for new SQLite databases to
 # decrease fragmentation (at the cost of disk usage). You may turn this feature
 # off here.

etc/container-server.conf-sample

@@ -5,6 +5,11 @@
 # log_name = swift
 # log_facility = LOG_LOCAL0
 # log_level = INFO
+# You can enable default statsD logging here if you want:
+# log_statsd_host = localhost
+# log_statsd_port = 8125
+# log_statsd_default_sample_rate = 1
+# log_statsd_metric_prefix =
 
 [object-expirer]
 # interval = 300

etc/object-expirer.conf-sample

@@ -12,6 +12,12 @@
 # log_name = swift
 # log_facility = LOG_LOCAL0
 # log_level = INFO
+# You can enable default statsD logging here and/or override it in sections
+# below:
+# log_statsd_host = localhost
+# log_statsd_port = 8125
+# log_statsd_default_sample_rate = 1
+# log_statsd_metric_prefix =
 
 [pipeline:main]
 pipeline = recon object-server

etc/object-server.conf-sample

@@ -13,6 +13,12 @@
 # log_name = swift
 # log_facility = LOG_LOCAL0
 # log_level = INFO
+# You can enable default statsD logging here and/or override it in sections
+# below:
+# log_statsd_host = localhost
+# log_statsd_port = 8125
+# log_statsd_default_sample_rate = 1
+# log_statsd_metric_prefix =
 
 [pipeline:main]
 pipeline = catch_errors healthcheck cache tempauth proxy-server

etc/proxy-server.conf-sample

@@ -41,29 +41,34 @@ def __init__(self, conf):
         swift.common.db.DB_PREALLOCATION = \
             conf.get('db_preallocation', 't').lower() in TRUE_VALUES
 
+    def _one_audit_pass(self, reported):
+        all_locs = audit_location_generator(self.devices,
+            account_server.DATADIR, mount_check=self.mount_check,
+            logger=self.logger)
+        for path, device, partition in all_locs:
+            self.account_audit(path)
+            if time.time() - reported >= 3600:  # once an hour
+                self.logger.info(_('Since %(time)s: Account audits: '
+                   '%(passed)s passed audit, %(failed)s failed audit'),
+                      {'time': time.ctime(reported),
+                       'passed': self.account_passes,
+                       'failed': self.account_failures})
+                reported = time.time()
+                self.account_passes = 0
+                self.account_failures = 0
+        return reported
+
     def run_forever(self, *args, **kwargs):
         """Run the account audit until stopped."""
         reported = time.time()
         time.sleep(random() * self.interval)
         while True:
-            self.logger.info(_('Begin account audit pass'))
+            self.logger.info(_('Begin account audit pass.'))
             begin = time.time()
             try:
-                all_locs = audit_location_generator(self.devices,
-                    account_server.DATADIR, mount_check=self.mount_check,
-                    logger=self.logger)
-                for path, device, partition in all_locs:
-                    self.account_audit(path)
-                    if time.time() - reported >= 3600:  # once an hour
-                        self.logger.info(_('Since %(time)s: Account audits: '
-                           '%(passed)s passed audit, %(failed)s failed audit'),
-                              {'time': time.ctime(reported),
-                               'passed': self.account_passes,
-                               'failed': self.account_failures})
-                        reported = time.time()
-                        self.account_passes = 0
-                        self.account_failures = 0
+                reported = self._one_audit_pass(reported)
             except (Exception, Timeout):
+                self.logger.increment('errors')
                 self.logger.exception(_('ERROR auditing'))
             elapsed = time.time() - begin
             if elapsed < self.interval:
@@ -75,21 +80,7 @@ def run_once(self, *args, **kwargs):
         """Run the account audit once."""
         self.logger.info(_('Begin account audit "once" mode'))
         begin = reported = time.time()
-        all_locs = audit_location_generator(self.devices,
-                                            account_server.DATADIR,
-                                            mount_check=self.mount_check,
-                                            logger=self.logger)
-        for path, device, partition in all_locs:
-            self.account_audit(path)
-            if time.time() - reported >= 3600:  # once an hour
-                self.logger.info(_('Since %(time)s: Account audits: '
-                    '%(passed)s passed audit, %(failed)s failed audit'),
-                      {'time': time.ctime(reported),
-                       'passed': self.account_passes,
-                       'failed': self.account_failures})
-                reported = time.time()
-                self.account_passes = 0
-                self.account_failures = 0
+        self._one_audit_pass(reported)
         elapsed = time.time() - begin
         self.logger.info(
             _('Account audit "once" mode completed: %.02fs'), elapsed)
@@ -100,15 +91,19 @@ def account_audit(self, path):
 
         :param path: the path to an account db
         """
+        start_time = time.time()
         try:
             if not path.endswith('.db'):
                 return
             broker = AccountBroker(path)
             if not broker.is_deleted():
                 info = broker.get_info()
+                self.logger.increment('passes')
                 self.account_passes += 1
                 self.logger.debug(_('Audit passed for %s') % broker.db_file)
         except (Exception, Timeout):
+            self.logger.increment('failures')
             self.account_failures += 1
             self.logger.exception(_('ERROR Could not get account info %s'),
                 (broker.db_file))
+        self.logger.timing_since('timing', start_time)

swift/account/auditor.py

@@ -119,6 +119,7 @@ def run_once(self, *args, **kwargs):
         for device in os.listdir(self.devices):
             if self.mount_check and \
                     not os.path.ismount(os.path.join(self.devices, device)):
+                self.logger.increment('errors')
                 self.logger.debug(
                     _('Skipping %s as it is not mounted'), device)
                 continue
@@ -162,6 +163,7 @@ def reap_device(self, device):
                         if fname.endswith('.ts'):
                             break
                         elif fname.endswith('.db'):
+                            self.start_time = time()
                             broker = \
                                 AccountBroker(os.path.join(hsh_path, fname))
                             if broker.is_status_deleted() and \
@@ -262,6 +264,7 @@ def reap_account(self, broker, partition, nodes):
             log = log[:-2]
         log += _(', elapsed: %.02fs') % (time() - begin)
         self.logger.info(log)
+        self.logger.timing_since('timing', self.start_time)
         return True
 
     def reap_container(self, account, account_partition, account_nodes,
@@ -313,12 +316,15 @@ def reap_container(self, account, account_partition, account_nodes,
                         response_timeout=self.node_timeout)[1]
                 self.stats_return_codes[2] = \
                     self.stats_return_codes.get(2, 0) + 1
+                self.logger.increment('return_codes.2')
             except ClientException, err:
                 if self.logger.getEffectiveLevel() <= DEBUG:
                     self.logger.exception(
                         _('Exception with %(ip)s:%(port)s/%(device)s'), node)
                 self.stats_return_codes[err.http_status / 100] = \
                     self.stats_return_codes.get(err.http_status / 100, 0) + 1
+                self.logger.increment(
+                    'return_codes.%d' % (err.http_status / 100,))
             if not objects:
                 break
             try:
@@ -348,19 +354,26 @@ def reap_container(self, account, account_partition, account_nodes,
                 successes += 1
                 self.stats_return_codes[2] = \
                     self.stats_return_codes.get(2, 0) + 1
+                self.logger.increment('return_codes.2')
             except ClientException, err:
                 if self.logger.getEffectiveLevel() <= DEBUG:
                     self.logger.exception(
                         _('Exception with %(ip)s:%(port)s/%(device)s'), node)
                 failures += 1
+                self.logger.increment('containers_failures')
                 self.stats_return_codes[err.http_status / 100] = \
                     self.stats_return_codes.get(err.http_status / 100, 0) + 1
+                self.logger.increment(
+                    'return_codes.%d' % (err.http_status / 100,))
         if successes > failures:
             self.stats_containers_deleted += 1
+            self.logger.increment('containers_deleted')
         elif not successes:
             self.stats_containers_remaining += 1
+            self.logger.increment('containers_remaining')
         else:
             self.stats_containers_possibly_remaining += 1
+            self.logger.increment('containers_possibly_remaining')
 
     def reap_object(self, account, container, container_partition,
                     container_nodes, obj):
@@ -399,16 +412,23 @@ def reap_object(self, account, container, container_partition,
                 successes += 1
                 self.stats_return_codes[2] = \
                     self.stats_return_codes.get(2, 0) + 1
+                self.logger.increment('return_codes.2')
             except ClientException, err:
                 if self.logger.getEffectiveLevel() <= DEBUG:
                     self.logger.exception(
                         _('Exception with %(ip)s:%(port)s/%(device)s'), node)
                 failures += 1
+                self.logger.increment('objects_failures')
                 self.stats_return_codes[err.http_status / 100] = \
                     self.stats_return_codes.get(err.http_status / 100, 0) + 1
+                self.logger.increment(
+                    'return_codes.%d' % (err.http_status / 100,))
             if successes > failures:
                 self.stats_objects_deleted += 1
+                self.logger.increment('objects_deleted')
             elif not successes:
                 self.stats_objects_remaining += 1
+                self.logger.increment('objects_remaining')
             else:
                 self.stats_objects_possibly_remaining += 1
+                self.logger.increment('objects_possibly_remaining')