Merge pull request #839 from alq666/master

Cut down logging messages in manage_workers

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)),
+        self.log.debug("{0} workers".format(len(workers)),
-                      extra={"metric": "gunicorn.workers",
+                        extra={ "metric": "gunicorn.workers",
-                          "value": len(workers),
+                                "value": len(workers),
-                          "mtype": "gauge"})
+                                "mtype": "gauge"})
 
     def spawn_worker(self):
         self.worker_age += 1

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
+        self.log(logging.INFO, msg, *args, **kwargs)
-        """
-        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
 
     # 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):

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")