From 410bcfa6e1bb1001f8afb851f8a80e346aa3046e Mon Sep 17 00:00:00 2001 From: Thomas Orozco Date: Mon, 20 Apr 2015 20:23:23 +0200 Subject: [PATCH] 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 | 4 +-- gunicorn/instrument/statsd.py | 31 +++++++++------------ tests/test_010-statsd.py | 51 ++++++++++++++++++++++++++--------- 3 files changed, 53 insertions(+), 33 deletions(-) diff --git a/gunicorn/glogging.py b/gunicorn/glogging.py index 2c0bb5746..9faa5a8a1 100644 --- a/gunicorn/glogging.py +++ b/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): diff --git a/gunicorn/instrument/statsd.py b/gunicorn/instrument/statsd.py index 0baf34317..58bccdf82 100644 --- a/gunicorn/instrument/statsd.py +++ b/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) diff --git a/tests/test_010-statsd.py b/tests/test_010-statsd.py index 56a295cd4..6ef4fb47b 100644 --- a/tests/test_010-statsd.py +++ b/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")