Rework logging to allow for empty log message while pushing metrics

benoitc · Aug 3, 2014 · bc2e132 · bc2e132
1 parent 2753aac
commit bc2e132
Show file tree

Hide file tree

Showing 3 changed files with 56 additions and 23 deletions.
diff --git a/gunicorn/arbiter.py b/gunicorn/arbiter.py
@@ -482,10 +482,10 @@ def manage_workers(self):
             (pid, _) = workers.pop(0)
             self.kill_worker(pid, signal.SIGTERM)
 
-        self.log.info("{0} workers".format(len(workers)),
-                      extra={"metric": "gunicorn.workers",
-                          "value": len(workers),
-                          "mtype": "gauge"})
+        self.log.debug("",
+                        extra={ "metric": "gunicorn.workers",
+                                "value": len(workers),
+                                "mtype": "gauge"})
 
     def spawn_worker(self):
         self.worker_age += 1

diff --git a/gunicorn/instrument/statsd.py b/gunicorn/instrument/statsd.py
@@ -6,6 +6,7 @@
 "Bare-bones implementation of statsD's protocol, client-side"
 
 import socket
+import logging
 from gunicorn.glogging import Logger
 
 # Instrumentation constants
@@ -50,30 +51,37 @@ def exception(self, msg, *args, **kwargs):
 
     # Special treatement for info, the most common log level
     def info(self, msg, *args, **kwargs):
-        """Log a given statistic if metric, value and type are present
-        """
-        Logger.info(self, msg, *args, **kwargs)
-        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
+        self.log(logging.INFO, msg, *args, **kwargs)
 
     # skip the run-of-the-mill logs
     def debug(self, msg, *args, **kwargs):
-        Logger.debug(self, msg, *args, **kwargs)
+        self.log(logging.DEBUG, msg, *args, **kwargs)
 
     def log(self, lvl, msg, *args, **kwargs):
-        Logger.log(self, lvl, msg, *args, **kwargs)
+        """Log a given statistic if metric, value and type are present
+        """
+        try:
+            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
+
+            # Log to parent logger only if there is something to say
+            if msg is not None and len(msg) > 0:
+                Logger.log(self, lvl, msg, *args, **kwargs)
+        except Exception:
+            pass
+
 
     # access logging
     def access(self, resp, req, environ, request_time):

diff --git a/tests/test_010-statsd.py b/tests/test_010-statsd.py
@@ -2,9 +2,17 @@
 
 import t
 
+try:
+    from cStringIO import StringIO
+except ImportError:
+    from io import StringIO
+
+import logging
+
 from gunicorn.config import Config
 from gunicorn.instrument.statsd import Statsd
 
+
 class TestException(Exception): pass
 
 class MockSocket(object):
@@ -38,10 +46,27 @@ def test_statsd_fail():
 
 def test_instrument():
     logger = Statsd(Config())
+    # Capture logged messages
+    sio = StringIO()
+    logger.error_log.addHandler(logging.StreamHandler(sio))
     logger.sock = MockSocket(False)
 
+    # Regular message
     logger.info("Blah", extra={"mtype": "gauge", "metric": "gunicorn.test", "value": 666})
     t.eq(logger.sock.msgs[0], "gunicorn.test:666|g")
+    t.eq(sio.getvalue(), "Blah\n")
+    logger.sock.reset()
+
+    # Only metrics, no logging
+    logger.info("", extra={"mtype": "gauge", "metric": "gunicorn.test", "value": 666})
+    t.eq(logger.sock.msgs[0], "gunicorn.test:666|g")
+    t.eq(sio.getvalue(), "Blah\n")  # log is unchanged
+    logger.sock.reset()
+
+    # Debug logging also supports metrics
+    logger.debug("", extra={"mtype": "gauge", "metric": "gunicorn.debug", "value": 667})
+    t.eq(logger.sock.msgs[0], "gunicorn.debug:667|g")
+    t.eq(sio.getvalue(), "Blah\n")  # log is unchanged
     logger.sock.reset()
 
     logger.critical("Boom")