Upating proxy-server StatsD logging.

Removed many StatsD logging calls in proxy-server and added
swift-informant-style catch-all logging in the proxy-logger middleware.
Many errors previously rolled into the "proxy-server.<type>.errors"
counter will now appear broken down by response code and with timing
data at: "proxy-server.<type>.<verb>.<status>.timing".  Also, bytes
transferred (sum of in + out) will be at:
"proxy-server.<type>.<verb>.<status>.xfer".  The proxy-logging
middleware can get its StatsD config from standard vars in [DEFAULT] or
from access_log_statsd_* config vars in its config section.

Similarly to Swift Informant, request methods ("verbs") are filtered
using the new proxy-logging config var, "log_statsd_valid_http_methods"
which defaults to GET, HEAD, POST, PUT, DELETE, and COPY.  Requests with
methods not in this list use "BAD_METHOD" for <verb> in the metric name.
To avoid user error, access_log_statsd_valid_http_methods is also
accepted.

Previously, proxy-server metrics used "Account", "Container", and
"Object" for the <type>, but these are now all lowercase.

Updated the admin guide's StatsD docs to reflect the above changes and
also include the "proxy-server.<type>.handoff_count" and
"proxy-server.<type>.handoff_all_count" metrics.

The proxy server now saves off the original req.method and proxy_logging
will use this if it can (both for request logging and as the "<verb>" in
the statsd timing metric).  This fixes bug 1025433.

Removed some stale access_log_* related code in proxy/server.py.  Also
removed the BaseApplication/Application distinction as it's no longer
necessary.

Fixed up the sample config files a bit (logging lines, mostly).

Fixed typo in SAIO development guide.

Got proxy_logging.py test coverage to 100%.

Fixed proxy_logging.py for PEP8 v1.3.2.

Enhanced test.unit.FakeLogger to track more calls to enable testing
StatsD metric calls.

Change-Id: I45d94cb76450be96d66fcfab56359bdfdc3a2576

doc/source/admin_guide.rst

@@ -759,55 +759,57 @@ Metric Name                   Description
 `object-updater.failures`     Count of failed continer updates.
 ============================  ====================================================
 
-Metrics for `proxy-server` (in the table, `<type>` may be `Account`, `Container`,
-or `Object`, and corresponds to the internal Controller object which handled the
-request):
-
-=========================================  ====================================================
-Metric Name                                Description
------------------------------------------  ----------------------------------------------------
-`proxy-server.errors`                      Count of errors encountered while serving requests
-                                           before the controller type is determined.  Includes
-                                           invalid Content-Length, errors finding the internal
-                                           controller to handle the request, invalid utf8, and
-                                           bad URLs.
-`proxy-server.<type>.errors`               Count of errors encountered after the controller
-                                           type is known.  The details of which responses are
-                                           errors depend on the controller type and request
-                                           type (GET, PUT, etc.).  Failed
-                                           authentication/authorization and "Not Found"
-                                           responses are not counted as errors.
-`proxy-server.<type>.client_timeouts`      Count of client timeouts (client did not read from
-                                           queue within `client_timeout` seconds).
-`proxy-server.<type>.client_disconnects`   Count of detected client disconnects.
-`proxy-server.<type>.method_not_allowed`   Count of MethodNotAllowed responses sent by the
-`proxy-server.<type>.auth_short_circuits`  Count of requests which short-circuited with an
-                                           authentication/authorization failure.
-`proxy-server.<type>.GET.timing`           Timing data for GET requests (excluding requests
-                                           with errors or failed authentication/authorization).
-`proxy-server.<type>.HEAD.timing`          Timing data for HEAD requests (excluding requests
-                                           with errors or failed authentication/authorization).
-`proxy-server.<type>.POST.timing`          Timing data for POST requests (excluding requests
-                                           with errors or failed authentication/authorization).
-                                           Requests with a client disconnect ARE included in
-                                           the timing data.
-`proxy-server.<type>.PUT.timing`           Timing data for PUT requests (excluding requests
-                                           with errors or failed authentication/authorization).
-                                           Account PUT requests which return MethodNotAllowed
-                                           because allow_account_management is disabled ARE
-                                           included.
-`proxy-server.<type>.DELETE.timing`        Timing data for DELETE requests (excluding requests
-                                           with errors or failed authentication/authorization).
-                                           Account DELETE requests which return
-                                           MethodNotAllowed because allow_account_management is
-                                           disabled ARE included.
-`proxy-server.Object.COPY.timing`          Timing data for object COPY requests (excluding
-                                           requests with errors or failed
-                                           authentication/authorization).
-=========================================  ====================================================
-
-Metrics for `tempauth` (in the table, `<reseller_prefix>` represents the actual configured
-reseller_prefix or "`NONE`" if the reseller_prefix is the empty string):
+Metrics for `proxy-server` (in the table, `<type>` is the proxy-server
+controller responsible for the request and will be one of "account",
+"container", or "object"):
+
+========================================  ====================================================
+Metric Name                               Description
+----------------------------------------  ----------------------------------------------------
+`proxy-server.errors`                     Count of errors encountered while serving requests
+                                          before the controller type is determined.  Includes
+                                          invalid Content-Length, errors finding the internal
+                                          controller to handle the request, invalid utf8, and
+                                          bad URLs.
+`proxy-server.<type>.handoff_count`       Count of node hand-offs; only tracked if log_handoffs
+                                          is set in the proxy-server config.
+`proxy-server.<type>.handoff_all_count`   Count of times *only* hand-off locations were
+                                          utilized; only tracked if log_handoffs is set in the
+                                          proxy-server config.
+`proxy-server.<type>.client_timeouts`     Count of client timeouts (client did not read within
+                                          `client_timeout` seconds during a GET or did not
+                                          supply data within `client_timeout` seconds during
+                                          a PUT).
+`proxy-server.<type>.client_disconnects`  Count of detected client disconnects during PUT
+                                          operations (does NOT include caught Exceptions in
+                                          the proxy-server which caused a client disconnect).
+========================================  ====================================================
+
+Metrics for `proxy-logging` middleware (in the table, `<type>` is either the
+proxy-server controller responsible for the request: "account", "container",
+"object", or the string "SOS" if the request came from the `Swift Origin Server`_
+middleware.  The `<verb>` portion will be one of "GET", "HEAD", "POST", "PUT",
+"DELETE", "COPY", or "BAD_METHOD".  The list of valid HTTP methods is
+configurable via the `log_statsd_valid_http_methods` config variable and the
+default setting yields the above behavior.
+
+.. _Swift Origin Server: https://github.com/dpgoetz/sos
+
+============================================  ====================================================
+Metric Name                                   Description
+--------------------------------------------  ----------------------------------------------------
+`proxy-server.<type>.<verb>.<status>.timing`  Timing data for requests.  The <status> portion is
+                                              the numeric HTTP status code for the request (eg.
+                                              "200" or "404")
+`proxy-server.<type>.<verb>.<status>.xfer`    The count of the sum of bytes transferred in (from
+                                              clients) and out (to clients) for requests.  The
+                                              <type>, <verb>, and <status> portions of the metric
+                                              are just like the timing metric.
+============================================  ====================================================
+
+Metrics for `tempauth` middleware (in the table, `<reseller_prefix>` represents
+the actual configured reseller_prefix or "`NONE`" if the reseller_prefix is the
+empty string):
 
 =========================================  ====================================================
 Metric Name                                Description

doc/source/development_saio.rst

@@ -680,7 +680,7 @@ Setting up scripts for running Swift
         sudo chown <your-user-name>:<your-group-name> /mnt/sdb1/*
         mkdir -p /srv/1/node/sdb1 /srv/2/node/sdb2 /srv/3/node/sdb3 /srv/4/node/sdb4
         sudo rm -f /var/log/debug /var/log/messages /var/log/rsyncd.log /var/log/syslog
-        find /var/cache/swift* -type f -name *.recon -exec -rm -f {} \;
+        find /var/cache/swift* -type f -name *.recon -exec rm -f {} \;
         sudo service rsyslog restart
         sudo service memcached restart
 

etc/account-server.conf-sample

@@ -13,8 +13,10 @@
 # log_facility = LOG_LOCAL0
 # log_level = INFO
 # log_address = /dev/log
-# You can enable default statsD logging here and/or override it in sections
-# below:
+# If set, log_udp_host will override log_address
+# log_udp_host =
+# log_udp_port = 514
+# You can enable StatsD logging here:
 # log_statsd_host = localhost
 # log_statsd_port = 8125
 # log_statsd_default_sample_rate = 1

etc/container-server.conf-sample

@@ -16,8 +16,10 @@
 # log_facility = LOG_LOCAL0
 # log_level = INFO
 # log_address = /dev/log
-# You can enable default statsD logging here and/or override it in sections
-# below:
+# If set, log_udp_host will override log_address
+# log_udp_host =
+# log_udp_port = 514
+# You can enable StatsD logging here:
 # log_statsd_host = localhost
 # log_statsd_port = 8125
 # log_statsd_default_sample_rate = 1

etc/object-expirer.conf-sample

@@ -6,7 +6,10 @@
 # log_facility = LOG_LOCAL0
 # log_level = INFO
 # log_address = /dev/log
-# You can enable default statsD logging here if you want:
+# If set, log_udp_host will override log_address
+# log_udp_host =
+# log_udp_port = 514
+# You can enable StatsD logging here:
 # log_statsd_host = localhost
 # log_statsd_port = 8125
 # log_statsd_default_sample_rate = 1

etc/object-server.conf-sample

@@ -14,8 +14,10 @@
 # log_facility = LOG_LOCAL0
 # log_level = INFO
 # log_address = /dev/log
-# You can enable default statsD logging here and/or override it in sections
-# below:
+# If set, log_udp_host will override log_address
+# log_udp_host =
+# log_udp_port = 514
+# You can enable StatsD logging here:
 # log_statsd_host = localhost
 # log_statsd_port = 8125
 # log_statsd_default_sample_rate = 1

etc/proxy-server.conf-sample

@@ -13,9 +13,12 @@
 # log_name = swift
 # log_facility = LOG_LOCAL0
 # log_level = INFO
+# log_headers = False
 # log_address = /dev/log
-# You can enable default statsD logging here and/or override it in sections
-# below:
+# If set, log_udp_host will override log_address
+# log_udp_host =
+# log_udp_port = 514
+# You can enable StatsD logging here:
 # log_statsd_host = localhost
 # log_statsd_port = 8125
 # log_statsd_default_sample_rate = 1
@@ -31,11 +34,7 @@ use = egg:swift#proxy
 # set log_facility = LOG_LOCAL0
 # set log_level = INFO
 # set log_address = /dev/log
-# set access_log_name = proxy-server
-# set access_log_facility = LOG_LOCAL0
-# set access_log_level = INFO
-# set log_headers = False
-# set log_handoffs = True
+# log_handoffs = True
 # recheck_account_existence = 60
 # recheck_container_existence = 60
 # object_chunk_size = 8192
@@ -306,3 +305,20 @@ use = egg:swift#name_check
 
 [filter:proxy-logging]
 use = egg:swift#proxy_logging
+# If not set, logging directives from [DEFAULT] without "access_" will be # used
+# access_log_name = swift
+# access_log_facility = LOG_LOCAL0
+# access_log_level = INFO
+# access_log_address = /dev/log
+# If set, access_log_udp_host will override access_log_address
+# access_log_udp_host =
+# access_log_udp_port = 514
+# You can use log_statsd_* from [DEFAULT] or override them here:
+# access_log_statsd_host = localhost
+# access_log_statsd_port = 8125
+# access_log_statsd_default_sample_rate = 1
+# access_log_statsd_metric_prefix =
+# access_log_headers = False
+# What HTTP methods are allowed for StatsD logging (comma-sep); request methods
+# not in this list will have "BAD_METHOD" for the <verb> portion of the metric.
+# log_statsd_valid_http_methods = GET,HEAD,POST,PUT,DELETE,COPY

swift/common/middleware/proxy_logging.py

@@ -94,14 +94,27 @@ class ProxyLoggingMiddleware(object):
     def __init__(self, app, conf):
         self.app = app
         self.log_hdrs = conf.get('log_headers', 'no').lower() in TRUE_VALUES
+
+        # The leading access_* check is in case someone assumes that
+        # log_statsd_valid_http_methods behaves like the other log_statsd_*
+        # settings.
+        self.valid_methods = conf.get(
+            'access_log_statsd_valid_http_methods',
+            conf.get('log_statsd_valid_http_methods',
+                     'GET,HEAD,POST,PUT,DELETE,COPY'))
+        self.valid_methods = [m.strip().upper() for m in
+                              self.valid_methods.split(',') if m.strip()]
         access_log_conf = {}
         for key in ('log_facility', 'log_name', 'log_level', 'log_udp_host',
-                    'log_udp_port'):
+                    'log_udp_port', 'log_statsd_host', 'log_statsd_port',
+                    'log_statsd_default_sample_rate',
+                    'log_statsd_metric_prefix'):
             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')
+                                        log_route='proxy-access')
+        self.access_logger.set_statsd_prefix('proxy-server')
 
     def log_request(self, env, status_int, bytes_received, bytes_sent,
                     request_time, client_disconnect):
@@ -124,13 +137,15 @@ def log_request(self, env, status_int, bytes_received, bytes_sent,
         logged_headers = None
         if self.log_hdrs:
             logged_headers = '\n'.join('%s: %s' % (k, v)
-                for k, v in req.headers.items())
-        self.access_logger.info(' '.join(quote(str(x) if x else '-')
+                                       for k, v in req.headers.items())
+        method = req.environ.get('swift.orig_req_method', req.method)
+        self.access_logger.info(' '.join(
+            quote(str(x) if x else '-')
             for x in (
                 get_remote_client(req),
                 req.remote_addr,
                 time.strftime('%d/%b/%Y/%H/%M/%S', time.gmtime()),
-                req.method,
+                method,
                 the_request,
                 req.environ.get('SERVER_PROTOCOL'),
                 status_int,
@@ -145,7 +160,25 @@ def log_request(self, env, status_int, bytes_received, bytes_sent,
                 '%.4f' % request_time,
                 req.environ.get('swift.source'),
             )))
-        self.access_logger.txn_id = None
+        # Log timing and bytes-transfered data to StatsD
+        if req.path.startswith('/v1/'):
+            try:
+                stat_type = [None, 'account', 'container',
+                             'object'][req.path.strip('/').count('/')]
+            except IndexError:
+                stat_type = 'object'
+        else:
+            stat_type = env.get('swift.source')
+        # Only log data for valid controllers (or SOS) to keep the metric count
+        # down (egregious errors will get logged by the proxy server itself).
+        if stat_type:
+            stat_method = method if method in self.valid_methods \
+                else 'BAD_METHOD'
+            metric_name = '.'.join((stat_type, stat_method, str(status_int)))
+            self.access_logger.timing(metric_name + '.timing',
+                                      request_time * 1000)
+            self.access_logger.update_stats(metric_name + '.xfer',
+                                            bytes_received + bytes_sent)
 
     def __call__(self, env, start_response):
         start_response_args = [None]
@@ -175,8 +208,8 @@ def iter_response(iterable):
                         ('content-length', str(sum(len(i) for i in iterable))))
                 else:
                     raise Exception('WSGI [proxy-logging]: No content-length '
-                        'or transfer-encoding header sent and there is '
-                        'content! %r' % chunk)
+                                    'or transfer-encoding header sent and '
+                                    'there is content! %r' % chunk)
             start_response(*start_response_args[0])
             bytes_sent = 0
             client_disconnect = False
@@ -190,16 +223,17 @@ def iter_response(iterable):
                 raise
             finally:
                 status_int = int(start_response_args[0][0].split(' ', 1)[0])
-                self.log_request(env, status_int,
-                        input_proxy.bytes_received, bytes_sent,
-                        time.time() - start_time,
-                        client_disconnect or input_proxy.client_disconnect)
+                self.log_request(
+                    env, status_int, input_proxy.bytes_received, bytes_sent,
+                    time.time() - start_time,
+                    client_disconnect or input_proxy.client_disconnect)
 
         try:
             iterable = self.app(env, my_start_response)
         except Exception:
-            self.log_request(env, 500, input_proxy.bytes_received, 0,
-                    time.time() - start_time, input_proxy.client_disconnect)
+            self.log_request(
+                env, 500, input_proxy.bytes_received, 0,
+                time.time() - start_time, input_proxy.client_disconnect)
             raise
         else:
             return iter_response(iterable)

swift/common/middleware/staticweb.py

@@ -523,7 +523,7 @@ def __init__(self, app, conf):
         self.access_logger = get_logger(access_log_conf,
                                         log_route='staticweb-access')
         #: Indicates whether full HTTP headers should be logged or not.
-        self.log_headers = conf.get('log_headers', 'f').lower() in TRUE_VALUES
+        self.log_headers = conf.get('log_headers', 'no').lower() in TRUE_VALUES
 
     def __call__(self, env, start_response):
         """

swift/common/utils.py

@@ -561,9 +561,11 @@ def get_logger(conf, name=None, log_to_console=False, log_route=None,
         log_name = swift
         log_udp_host = (disabled)
         log_udp_port = logging.handlers.SYSLOG_UDP_PORT
+        log_address = /dev/log
         log_statsd_host = (disabled)
         log_statsd_port = 8125
         log_statsd_default_sample_rate = 1
+        log_statsd_metric_prefix = (empty-string)
 
     :param conf: Configuration dict to read settings from
     :param name: Name of the logger