Fix statsd logging to work on Python 3

Bytes must be passed to socket.send.

Update tests to ensure an actual socket is used, so that errors like
this can be caught in unit tests in the future.

gunicorn/glogging.py

@@ -224,8 +224,8 @@ def info(self, msg, *args, **kwargs):
     def debug(self, msg, *args, **kwargs):
         self.error_log.debug(msg, *args, **kwargs)
 
-    def exception(self, msg, *args):
-        self.error_log.exception(msg, *args)
+    def exception(self, msg, *args, **kwargs):
+        self.error_log.exception(msg, *args, **kwargs)
 
     def log(self, lvl, msg, *args, **kwargs):
         if isinstance(lvl, string_types):

gunicorn/instrument/statsd.py

@@ -8,7 +8,9 @@
 import socket
 import logging
 from re import sub
+
 from gunicorn.glogging import Logger
+from gunicorn import six
 
 # Instrumentation constants
 STATSD_DEFAULT_PORT = 8125
@@ -82,7 +84,7 @@ def log(self, lvl, msg, *args, **kwargs):
             if msg is not None and len(msg) > 0:
                 Logger.log(self, lvl, msg, *args, **kwargs)
         except Exception:
-            pass
+            Logger.warning(self, "Failed to log to statsd", exc_info=True)
 
     # access logging
     def access(self, resp, req, environ, request_time):
@@ -98,29 +100,22 @@ def access(self, resp, req, environ, request_time):
     # statsD methods
     # you can use those directly if you want
     def gauge(self, name, value):
-        try:
-            if self.sock:
-                self.sock.send("{0}{1}:{2}|g".format(self.prefix, name, value))
-        except Exception:
-            pass
+        self._sock_send("{0}{1}:{2}|g".format(self.prefix, name, value))
 
     def increment(self, name, value, sampling_rate=1.0):
-        try:
-            if self.sock:
-                self.sock.send("{0}{1}:{2}|c|@{3}".format(self.prefix, name, value, sampling_rate))
-        except Exception:
-            pass
+        self._sock_send("{0}{1}:{2}|c|@{3}".format(self.prefix, name, value, sampling_rate))
 
     def decrement(self, name, value, sampling_rate=1.0):
-        try:
-            if self.sock:
-                self.sock.send("{0){1}:-{2}|c|@{3}".format(self.prefix, name, value, sampling_rate))
-        except Exception:
-            pass
+        self._sock_send("{0){1}:-{2}|c|@{3}".format(self.prefix, name, value, sampling_rate))
 
     def histogram(self, name, value):
+        self._sock_send("{0}{1}:{2}|ms".format(self.prefix, name, value))
+
+    def _sock_send(self, msg):
         try:
+            if isinstance(msg, six.text_type):
+                msg = msg.encode("ascii")
             if self.sock:
-                self.sock.send("{0}{1}:{2}|ms".format(self.prefix, name, value))
+                self.sock.send(msg)
         except Exception:
-            pass
+            Logger.warning(self, "Error sending message to statsd", exc_info=True)

tests/test_010-statsd.py

@@ -1,4 +1,5 @@
 from datetime import timedelta
+import socket
 
 import t
 
@@ -8,12 +9,18 @@
     from io import StringIO
 
 import logging
+import tempfile
+import shutil
+import os
 
 from gunicorn.config import Config
 from gunicorn.instrument.statsd import Statsd
 
 
-class TestException(Exception): pass
+
+
+class TestException(Exception):
+    pass
 
 class MockSocket(object):
     "Pretend to be a UDP socket"
@@ -24,7 +31,25 @@ def __init__(self, failp):
     def send(self, msg):
         if self.failp:
             raise TestException("Should not interrupt the logger")
-        self.msgs.append(msg)
+
+        sock_dir = tempfile.mkdtemp()
+        sock_file = os.path.join(sock_dir, "test.sock")
+
+        server = socket.socket(socket.AF_UNIX, socket.SOCK_DGRAM)
+        client = socket.socket(socket.AF_UNIX, socket.SOCK_DGRAM)
+
+        try:
+            server.bind(sock_file)
+            client.connect(sock_file)
+
+            client.send(msg)
+            self.msgs.append(server.recv(1024))
+
+        finally:
+            client.close()
+            server.close()
+            shutil.rmtree(sock_dir)
+
 
     def reset(self):
         self.msgs = []
@@ -53,30 +78,30 @@ def test_instrument():
 
     # 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(logger.sock.msgs[0], b"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(logger.sock.msgs[0], b"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(logger.sock.msgs[0], b"gunicorn.debug:667|g")
     t.eq(sio.getvalue(), "Blah\n")  # log is unchanged
     logger.sock.reset()
 
     logger.critical("Boom")
-    t.eq(logger.sock.msgs[0], "gunicorn.log.critical:1|c|@1.0")
+    t.eq(logger.sock.msgs[0], b"gunicorn.log.critical:1|c|@1.0")
     logger.sock.reset()
 
     logger.access(MockResponse("200 OK"), None, {}, timedelta(seconds=7))
-    t.eq(logger.sock.msgs[0], "gunicorn.request.duration:7000.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")
+    t.eq(logger.sock.msgs[0], b"gunicorn.request.duration:7000.0|ms")
+    t.eq(logger.sock.msgs[1], b"gunicorn.requests:1|c|@1.0")
+    t.eq(logger.sock.msgs[2], b"gunicorn.request.status.200:1|c|@1.0")
 
 def test_prefix():
     c = Config()
@@ -85,7 +110,7 @@ def test_prefix():
     logger.sock = MockSocket(False)
 
     logger.info("Blah", extra={"mtype": "gauge", "metric": "gunicorn.test", "value": 666})
-    t.eq(logger.sock.msgs[0], "test.gunicorn.test:666|g")
+    t.eq(logger.sock.msgs[0], b"test.gunicorn.test:666|g")
 
 def test_prefix_no_dot():
     c = Config()
@@ -94,7 +119,7 @@ def test_prefix_no_dot():
     logger.sock = MockSocket(False)
 
     logger.info("Blah", extra={"mtype": "gauge", "metric": "gunicorn.test", "value": 666})
-    t.eq(logger.sock.msgs[0], "test.gunicorn.test:666|g")
+    t.eq(logger.sock.msgs[0], b"test.gunicorn.test:666|g")
 
 def test_prefix_multiple_dots():
     c = Config()
@@ -103,7 +128,7 @@ def test_prefix_multiple_dots():
     logger.sock = MockSocket(False)
 
     logger.info("Blah", extra={"mtype": "gauge", "metric": "gunicorn.test", "value": 666})
-    t.eq(logger.sock.msgs[0], "test.gunicorn.test:666|g")
+    t.eq(logger.sock.msgs[0], b"test.gunicorn.test:666|g")
 
 def test_prefix_nested():
     c = Config()
@@ -112,4 +137,4 @@ def test_prefix_nested():
     logger.sock = MockSocket(False)
 
     logger.info("Blah", extra={"mtype": "gauge", "metric": "gunicorn.test", "value": 666})
-    t.eq(logger.sock.msgs[0], "test.asdf.gunicorn.test:666|g")
+    t.eq(logger.sock.msgs[0], b"test.asdf.gunicorn.test:666|g")