From bc2e132bce7ac0ca1b851c506dd2810c2650d89a Mon Sep 17 00:00:00 2001
From: Alexis Le-Quoc <alq@datadoghq.com>
Date: Sun, 3 Aug 2014 17:15:13 -0400
Subject: [PATCH] Rework logging to allow for empty log message while pushing
 metrics

---
 gunicorn/arbiter.py           |  8 +++---
 gunicorn/instrument/statsd.py | 46 ++++++++++++++++++++---------------
 tests/test_010-statsd.py      | 25 +++++++++++++++++++
 3 files changed, 56 insertions(+), 23 deletions(-)

diff --git a/gunicorn/arbiter.py b/gunicorn/arbiter.py
index 38b93d54..ae53290d 100644
--- a/gunicorn/arbiter.py
+++ b/gunicorn/arbiter.py
@@ -482,10 +482,10 @@ class Arbiter(object):
             (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
index e712c47f..2d519c47 100644
--- 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 @@ class Statsd(Logger):
 
     # 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
index aaf75dd5..f2ba1a4e 100644
--- a/tests/test_010-statsd.py
+++ b/tests/test_010-statsd.py
@@ -2,9 +2,17 @@ from datetime import timedelta
 
 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")