Incorporate feedback from PR

Use extra keyword in logger, more pythonic
capture response code as a rate metric

gunicorn/arbiter.py

@@ -479,9 +479,9 @@ class Arbiter(object):
             self.kill_worker(pid, signal.SIGQUIT)
 
         self.log.info("%d workers",
-                      metric="gunicorn.workers",
-                      value=len(self.WORKERS),
-                      mtype="gauge")
+                      extra={"metric": "gunicorn.workers",
+                          "value": len(self.WORKERS),
+                          "mtype": "gauge"})
 
     def spawn_worker(self):
         self.worker_age += 1

gunicorn/instrument/statsd.py

@@ -3,8 +3,8 @@
 # This file is part of gunicorn released under the MIT license.
 # See the NOTICE for more information.
 
-"""Bare-bones implementation of statsD's protocol, client-side
-"""
+"Bare-bones implementation of statsD's protocol, client-side"
+
 import socket
 from gunicorn.glogging import Logger
 
@@ -33,22 +33,18 @@ class Statsd(Logger):
 
     # Log errors and warnings
     def critical(self, msg, *args, **kwargs):
-        self._sanitize(kwargs)
         Logger.critical(self, msg, *args, **kwargs)
         self.increment("gunicorn.log.critical", 1)
 
     def error(self, msg, *args, **kwargs):
-        self._sanitize(kwargs)
         Logger.error(self, msg, *args, **kwargs)
         self.increment("gunicorn.log.error", 1)
 
     def warning(self, msg, *args, **kwargs):
-        self._sanitize(kwargs)
         Logger.warning(self, msg, *args, **kwargs)
         self.increment("gunicorn.log.warning", 1)
 
     def exception(self, msg, *args, **kwargs):
-        self._sanitize(kwargs)
         Logger.exception(self, msg, *args, **kwargs)
         self.increment("gunicorn.log.exception", 1)
 
@@ -56,28 +52,27 @@ class Statsd(Logger):
     def info(self, msg, *args, **kwargs):
         """Log a given statistic if metric, value and type are present
         """
-        metric = kwargs.get(METRIC_VAR, None)
-        value = kwargs.get(VALUE_VAR, None)
-        typ = kwargs.get(MTYPE_VAR, None)
-        if metric and value and typ:
-            self._sanitize(kwargs)
-            if typ == GAUGE_TYPE:
-                self.gauge(metric, value)
-            elif typ == COUNTER_TYPE:
-                self.increment(metric, value)
-            elif typ == HISTOGRAM_TYPE:
-                self.histogram(metric, value)
-            else:
-                pass
+        extra = kwargs.get("extra", None)
+        if extra is not None:
+            metric = extra.get(METRIC_VAR, None)
+            value = extra.get(VALUE_VAR, None)
+            typ = extra.get(MTYPE_VAR, None)
+            if metric and value and typ:
+                if typ == GAUGE_TYPE:
+                    self.gauge(metric, value)
+                elif typ == COUNTER_TYPE:
+                    self.increment(metric, value)
+                elif typ == HISTOGRAM_TYPE:
+                    self.histogram(metric, value)
+                else:
+                    pass
         Logger.info(self, msg, *args, **kwargs)
 
     # skip the run-of-the-mill logs
     def debug(self, msg, *args, **kwargs):
-        self._sanitize(kwargs)
         Logger.debug(self, msg, *args, **kwargs)
 
     def log(self, lvl, msg, *args, **kwargs):
-        self._sanitize(kwargs)
         Logger.log(self, lvl, msg, *args, **kwargs)
 
     # access logging
@@ -89,14 +84,7 @@ class Statsd(Logger):
         duration_in_s = request_time.seconds + float(request_time.microseconds)/10**6
         self.histogram("gunicorn.request.duration", duration_in_s)
         self.increment("gunicorn.requests", 1)
-
-    def _sanitize(self, kwargs):
-        """Drop stasd keywords from the logger"""
-        for k in (METRIC_VAR, VALUE_VAR, MTYPE_VAR):
-            try:
-                kwargs.pop(k)
-            except KeyError:
-                pass
+        self.increment("gunicorn.request.status.%d" % int(resp.status), 1)
 
     # statsD methods
     # you can use those directly if you want

tests/test_009-statsd.py

@@ -0,0 +1,54 @@
+from datetime import timedelta
+
+import t
+
+from gunicorn.config import Config
+from gunicorn.instrument.statsd import Statsd
+
+class TestException(Exception): pass
+
+class MockSocket(object):
+    "Pretend to be a UDP socket"
+    def __init__(self, failp):
+        self.failp = failp
+        self.msgs = []  # accumulate messages for later inspection
+
+    def send(self, msg):
+        if self.failp:
+            raise TestException("Should not interrupt the logger")
+        self.msgs.append(msg)
+
+    def reset(self):
+        self.msgs = []
+
+class MockResponse(object):
+    def __init__(self, status):
+        self.status = status
+
+def test_statsd_fail():
+    "UDP socket fails"
+    logger = Statsd(Config())
+    logger.sock = MockSocket(True)
+    logger.info("No impact on logging")
+    logger.debug("No impact on logging")
+    logger.critical("No impact on logging")
+    logger.error("No impact on logging")
+    logger.warning("No impact on logging")
+    logger.exception("No impact on logging")
+
+def test_instrument():
+    logger = Statsd(Config())
+    logger.sock = MockSocket(False)
+
+    logger.info("Blah", extra={"mtype": "gauge", "metric": "gunicorn.test", "value": 666})
+    t.eq(logger.sock.msgs[0], "gunicorn.test:666|g")
+    logger.sock.reset()
+
+    logger.critical("Boom")
+    t.eq(logger.sock.msgs[0], "gunicorn.log.critical:1|c|@1.0")
+    logger.sock.reset()
+
+    logger.access(MockResponse(200), None, {}, timedelta(seconds=7))
+    t.eq(logger.sock.msgs[0], "gunicorn.request.duration:7.0|ms")
+    t.eq(logger.sock.msgs[1], "gunicorn.requests:1|c|@1.0")
+    t.eq(logger.sock.msgs[2], "gunicorn.request.status.200:1|c|@1.0")