From 0b5cc1e2937cfc59a8a492ae90e56690cd1e75bc Mon Sep 17 00:00:00 2001 From: Alexis Le-Quoc Date: Mon, 5 May 2014 15:50:13 -0700 Subject: [PATCH 01/18] First cut of logger-based statsd --- gunicorn/arbiter.py | 5 ++ gunicorn/config.py | 21 +++++++ gunicorn/instrument/statsd.py | 107 ++++++++++++++++++++++++++++++++++ 3 files changed, 133 insertions(+) create mode 100644 gunicorn/instrument/statsd.py diff --git a/gunicorn/arbiter.py b/gunicorn/arbiter.py index bd2016d2..f0c5f3ac 100644 --- a/gunicorn/arbiter.py +++ b/gunicorn/arbiter.py @@ -480,6 +480,11 @@ class Arbiter(object): (pid, _) = workers.pop(0) self.kill_worker(pid, signal.SIGQUIT) + self.log.info("%d workers", + metric="gunicorn.workers", + value=len(self.WORKERS), + mtype="gauge") + def spawn_worker(self): self.worker_age += 1 worker = self.worker_class(self.worker_age, self.pid, self.LISTENERS, diff --git a/gunicorn/config.py b/gunicorn/config.py index cfafe081..5079aa06 100644 --- a/gunicorn/config.py +++ b/gunicorn/config.py @@ -421,6 +421,15 @@ def validate_file(val): return path +def validate_hostport(val): + val = validate_string(val) + if val is None: + return None + elements = val.split(":") + if len(elements) == 2: + return (elements[0], int(elements[1])) + else: + raise TypeError("Value must consist of: hostname:port") def get_default_config_file(): config_path = os.path.join(os.path.abspath(os.getcwd()), @@ -1554,3 +1563,15 @@ if sys.version_info >= (2, 7): desc = """\ Ciphers to use (see stdlib ssl module's) """ + +# statsD monitoring +class StatsdTo(Setting): + name = "statsd_to" + section = "Logging" + cli = ["--log-statsd-to"] + meta = "STATSD_ADDR" + default = "localhost:8125" + validator = validate_hostport + desc ="""\ + host:port of the statsd server to log to + """ diff --git a/gunicorn/instrument/statsd.py b/gunicorn/instrument/statsd.py new file mode 100644 index 00000000..8b9ce0a0 --- /dev/null +++ b/gunicorn/instrument/statsd.py @@ -0,0 +1,107 @@ +# -*- coding: utf-8 - +# +# This file is part of gunicorn released under the MIT license. +# See the NOTICE for more information. + +"""Bare-bones implementation of statsD's protocol, client-side +""" +import socket +from gunicorn.glogging import Logger + +# Instrumentation constants +STATSD_DEFAULT_PORT = 8125 +METRIC_VAR = "metric" +VALUE_VAR = "value" +MTYPE_VAR = "mtype" +SAMPLING_VAR = "sampling" + +class Statsd(Logger): + """statsD-based instrumentation, that passes as a logger + """ + def __init__(self, cfg): + """host, port: statsD server + """ + Logger.__init__(self, cfg) + try: + host, port = cfg.statsd_to + self.sock = socket.socket(socket.AF_INET, socket.SOCK_DGRAM) + self.sock.connect((host, int(port))) + except Exception: + self.sock = None + + # Log errors and warnings + def critical(self, msg, *args, **kwargs): + Logger.critical(self, msg, *args, **kwargs) + self.increment("gunicorn.log.critical", 1) + + def error(self, msg, *args, **kwargs): + Logger.error(self, msg, *args, **kwargs) + self.increment("gunicorn.log.error", 1) + + def warning(self, msg, *args, **kwargs): + Logger.warning(self, msg, *args, **kwargs) + self.increment("gunicorn.log.warning", 1) + + def exception(self, msg, *args, **kwargs): + Logger.exception(self, msg, *args, **kwargs) + self.increment("gunicorn.log.exception", 1) + + def info(self, msg, *args, **kwargs): + """Log a given statistic if metric, value, sampling are present + """ + Logger.info(self, msg, *args, **kwargs) + metric = kwargs.get(METRIC_VAR, None) + value = kwargs.get(VALUE_VAR, None) + typ = kwargs.get(MTYPE_VAR, None) + if metric and value and typ: + if typ == "gauge": + self.gauge(metric, value) + elif typ == "counter": + sampling = kwargs.get(SAMPLING_VAR, 1.0) + self.increment(metric, value, sampling) + else: + pass + + # skip the run-of-the-mill logs + def debug(self, msg, *args, **kwargs): + Logger.debug(self, msg, *args, **kwargs) + + def log(self, lvl, msg, *args, **kwargs): + Logger.log(self, lvl, msg, *args, **kwargs) + + # access logging + def access(self, resp, req, environ, request_time): + """Measure request duration + """ + Logger.access(self, resp, req, environ, request_time) + self.histogram("gunicorn.request.duration", request_time) + self.increment("gunicorn.requests", 1) + + # statsD methods + def gauge(self, name, value): + try: + if self.sock: + self.sock.send("%s:%s|g\n" % (name, value)) + except Exception: + pass + + def increment(self, name, value, sampling_rate=1.0): + try: + if self.sock: + self.sock.send("%s:%s|c@%s\n" % (name, value, sampling_rate)) + except Exception: + pass + + def decrement(self, name, value, sampling_rate=1.0): + try: + if self.sock: + self.sock.send("%s:-%s|c@%s\n" % (name, value, sampling_rate)) + except Exception: + pass + + def histogram(self, name, value, sampling_rate=1.0): + try: + if self.sock: + self.sock.send("%s:%s|h@%s\n" % (name, value, sampling_rate)) + except Exception: + pass From 35c71474196b588f65b374bfe0d2df4e881ea13d Mon Sep 17 00:00:00 2001 From: Alexis Le-Quoc Date: Wed, 7 May 2014 19:11:55 -0400 Subject: [PATCH 02/18] Metrics sent on request and arbiter --- gunicorn/instrument/__init__.py | 0 gunicorn/instrument/statsd.py | 39 +++++++++++++++++++++++++-------- 2 files changed, 30 insertions(+), 9 deletions(-) create mode 100644 gunicorn/instrument/__init__.py diff --git a/gunicorn/instrument/__init__.py b/gunicorn/instrument/__init__.py new file mode 100644 index 00000000..e69de29b diff --git a/gunicorn/instrument/statsd.py b/gunicorn/instrument/statsd.py index 8b9ce0a0..22d9547f 100644 --- a/gunicorn/instrument/statsd.py +++ b/gunicorn/instrument/statsd.py @@ -14,6 +14,9 @@ METRIC_VAR = "metric" VALUE_VAR = "value" MTYPE_VAR = "mtype" SAMPLING_VAR = "sampling" +GAUGE_TYPE = "gauge" +COUNTER_TYPE = "counter" +HISTOGRAM_TYPE = "histogram" class Statsd(Logger): """statsD-based instrumentation, that passes as a logger @@ -22,6 +25,7 @@ class Statsd(Logger): """host, port: statsD server """ Logger.__init__(self, cfg) + self.trace = cfg.debug try: host, port = cfg.statsd_to self.sock = socket.socket(socket.AF_INET, socket.SOCK_DGRAM) @@ -49,59 +53,76 @@ class Statsd(Logger): def info(self, msg, *args, **kwargs): """Log a given statistic if metric, value, sampling are present """ - Logger.info(self, msg, *args, **kwargs) metric = kwargs.get(METRIC_VAR, None) value = kwargs.get(VALUE_VAR, None) typ = kwargs.get(MTYPE_VAR, None) + sampling = kwargs.get(SAMPLING_VAR, 1.0) if metric and value and typ: - if typ == "gauge": + self._sanitize(kwargs) + if typ == GAUGE_TYPE: self.gauge(metric, value) - elif typ == "counter": - sampling = kwargs.get(SAMPLING_VAR, 1.0) + elif typ == COUNTER_TYPE: self.increment(metric, value, sampling) + elif typ == HISTOGRAM_TYPE: + self.histogram(metric, value, sampling) else: pass + if self.trace: + Logger.debug(self, "statsd {0},{1},{2},{3}".format(metric, value, typ, sampling)) + Logger.info(self, msg, *args, **kwargs) # skip the run-of-the-mill logs def debug(self, msg, *args, **kwargs): + self._sanitize(kwargs) Logger.debug(self, msg, *args, **kwargs) def log(self, lvl, msg, *args, **kwargs): + self._sanitize(kwargs) Logger.log(self, lvl, msg, *args, **kwargs) # access logging def access(self, resp, req, environ, request_time): """Measure request duration + request_time is a datetime.timedelta """ Logger.access(self, resp, req, environ, request_time) - self.histogram("gunicorn.request.duration", request_time) + duration_in_s = request_time.seconds + float(request_time.microseconds)/10**6 + self.histogram("gunicorn.request.duration", duration_in_s) self.increment("gunicorn.requests", 1) + def _sanitize(self, kwargs): + """Drop stasd keywords from the logger""" + for k in (METRIC_VAR, VALUE_VAR, MTYPE_VAR, SAMPLING_VAR): + try: + kwargs.pop(k) + except KeyError: + pass + # statsD methods def gauge(self, name, value): try: if self.sock: - self.sock.send("%s:%s|g\n" % (name, value)) + self.sock.send("{0}:{1}|g\n".format(name, value)) except Exception: pass def increment(self, name, value, sampling_rate=1.0): try: if self.sock: - self.sock.send("%s:%s|c@%s\n" % (name, value, sampling_rate)) + self.sock.send("{0}:{1}|c|@{2}\n".format(name, value, sampling_rate)) except Exception: pass def decrement(self, name, value, sampling_rate=1.0): try: if self.sock: - self.sock.send("%s:-%s|c@%s\n" % (name, value, sampling_rate)) + self.sock.send("{0}:-{1}|c|@{2}\n".format(name, value, sampling_rate)) except Exception: pass def histogram(self, name, value, sampling_rate=1.0): try: if self.sock: - self.sock.send("%s:%s|h@%s\n" % (name, value, sampling_rate)) + self.sock.send("{0}:{1}|h\n".format(name, value, sampling_rate)) except Exception: pass From 9b5d28767c3df43dabb3726749911d546c7f2e27 Mon Sep 17 00:00:00 2001 From: Alexis Le-Quoc Date: Fri, 9 May 2014 21:31:41 -0400 Subject: [PATCH 03/18] Sanitize arguments to not trick regular loggers --- gunicorn/instrument/statsd.py | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/gunicorn/instrument/statsd.py b/gunicorn/instrument/statsd.py index 22d9547f..c42409cc 100644 --- a/gunicorn/instrument/statsd.py +++ b/gunicorn/instrument/statsd.py @@ -35,21 +35,26 @@ class Statsd(Logger): # Log errors and warnings def critical(self, msg, *args, **kwargs): + self._sanitize(kwargs) Logger.critical(self, msg, *args, **kwargs) self.increment("gunicorn.log.critical", 1) def error(self, msg, *args, **kwargs): + self._sanitize(kwargs) Logger.error(self, msg, *args, **kwargs) self.increment("gunicorn.log.error", 1) def warning(self, msg, *args, **kwargs): + self._sanitize(kwargs) Logger.warning(self, msg, *args, **kwargs) self.increment("gunicorn.log.warning", 1) def exception(self, msg, *args, **kwargs): + self._sanitize(kwargs) Logger.exception(self, msg, *args, **kwargs) self.increment("gunicorn.log.exception", 1) + # Special treatement for info, the most common log level def info(self, msg, *args, **kwargs): """Log a given statistic if metric, value, sampling are present """ From d21692456b92bdb42aeed690d2d083270b7178d9 Mon Sep 17 00:00:00 2001 From: Alexis Le-Quoc Date: Fri, 9 May 2014 23:19:22 -0400 Subject: [PATCH 04/18] Tested with mainline statsd --- gunicorn/instrument/statsd.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/gunicorn/instrument/statsd.py b/gunicorn/instrument/statsd.py index c42409cc..54642f4e 100644 --- a/gunicorn/instrument/statsd.py +++ b/gunicorn/instrument/statsd.py @@ -107,27 +107,27 @@ class Statsd(Logger): def gauge(self, name, value): try: if self.sock: - self.sock.send("{0}:{1}|g\n".format(name, value)) + self.sock.send("{0}:{1}|g".format(name, value)) except Exception: pass def increment(self, name, value, sampling_rate=1.0): try: if self.sock: - self.sock.send("{0}:{1}|c|@{2}\n".format(name, value, sampling_rate)) + self.sock.send("{0}:{1}|c|@{2}".format(name, value, sampling_rate)) except Exception: pass def decrement(self, name, value, sampling_rate=1.0): try: if self.sock: - self.sock.send("{0}:-{1}|c|@{2}\n".format(name, value, sampling_rate)) + self.sock.send("{0}:-{1}|c|@{2}".format(name, value, sampling_rate)) except Exception: pass def histogram(self, name, value, sampling_rate=1.0): try: if self.sock: - self.sock.send("{0}:{1}|h\n".format(name, value, sampling_rate)) + self.sock.send("{0}:{1}|ms".format(name, value, sampling_rate)) except Exception: pass From af06c54e5b8449e277b14ca91750900867a54103 Mon Sep 17 00:00:00 2001 From: Alexis Le-Quoc Date: Fri, 9 May 2014 23:44:47 -0400 Subject: [PATCH 05/18] Drop tracing and sampling to keep the code tight --- gunicorn/instrument/statsd.py | 17 ++++++----------- 1 file changed, 6 insertions(+), 11 deletions(-) diff --git a/gunicorn/instrument/statsd.py b/gunicorn/instrument/statsd.py index 54642f4e..de348a17 100644 --- a/gunicorn/instrument/statsd.py +++ b/gunicorn/instrument/statsd.py @@ -13,7 +13,6 @@ STATSD_DEFAULT_PORT = 8125 METRIC_VAR = "metric" VALUE_VAR = "value" MTYPE_VAR = "mtype" -SAMPLING_VAR = "sampling" GAUGE_TYPE = "gauge" COUNTER_TYPE = "counter" HISTOGRAM_TYPE = "histogram" @@ -25,7 +24,6 @@ class Statsd(Logger): """host, port: statsD server """ Logger.__init__(self, cfg) - self.trace = cfg.debug try: host, port = cfg.statsd_to self.sock = socket.socket(socket.AF_INET, socket.SOCK_DGRAM) @@ -56,24 +54,21 @@ 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, sampling are present + """Log a given statistic if metric, value and type are present """ metric = kwargs.get(METRIC_VAR, None) value = kwargs.get(VALUE_VAR, None) typ = kwargs.get(MTYPE_VAR, None) - sampling = kwargs.get(SAMPLING_VAR, 1.0) if metric and value and typ: self._sanitize(kwargs) if typ == GAUGE_TYPE: self.gauge(metric, value) elif typ == COUNTER_TYPE: - self.increment(metric, value, sampling) + self.increment(metric, value) elif typ == HISTOGRAM_TYPE: - self.histogram(metric, value, sampling) + self.histogram(metric, value) else: pass - if self.trace: - Logger.debug(self, "statsd {0},{1},{2},{3}".format(metric, value, typ, sampling)) Logger.info(self, msg, *args, **kwargs) # skip the run-of-the-mill logs @@ -97,7 +92,7 @@ class Statsd(Logger): def _sanitize(self, kwargs): """Drop stasd keywords from the logger""" - for k in (METRIC_VAR, VALUE_VAR, MTYPE_VAR, SAMPLING_VAR): + for k in (METRIC_VAR, VALUE_VAR, MTYPE_VAR): try: kwargs.pop(k) except KeyError: @@ -125,9 +120,9 @@ class Statsd(Logger): except Exception: pass - def histogram(self, name, value, sampling_rate=1.0): + def histogram(self, name, value): try: if self.sock: - self.sock.send("{0}:{1}|ms".format(name, value, sampling_rate)) + self.sock.send("{0}:{1}|ms".format(name, value)) except Exception: pass From ae984132721ad807aa56a7a0b4a9081b74355f9a Mon Sep 17 00:00:00 2001 From: Alexis Le-Quoc Date: Mon, 12 May 2014 18:26:51 +0200 Subject: [PATCH 06/18] More in-depth documentation of the new instrumentation layer --- README.rst | 30 ++++++++++++++++++++++++++++++ gunicorn/instrument/statsd.py | 1 + 2 files changed, 31 insertions(+) diff --git a/README.rst b/README.rst index e0a06b5b..1ad7fbed 100644 --- a/README.rst +++ b/README.rst @@ -142,6 +142,35 @@ For example: It is all here. No configuration files nor additional python modules to write !! +Instrumentation +--------------- + +Gunicorn provides an optional instrumentation of the arbiter and +workers using the statsD_ protocol over UDP. Thanks to the +`gunicorn.instrument.statsd` module, Gunicorn becomes a statsD client +The use of UDP cleanly isolates Gunicorn from the receiving end of the statsD +metrics so that instrumentation does not cause Gunicorn to be heldeup by a slow +statsD consumer. + +To use this instrumentation mechanism, simply use a new logger:: + + $ gunicorn --logging-class gunicorn.instrument.statsd.Statsd ... + +The `Statsd` logger overrides `gunicorn.glogging.Logger` to track +all requests. The following metrics are generated: + + * `gunicorn.requests`: request rate per second + * `gunicorn.request.duration`: histogram of request duration + * `gunicorn.workers`: number of workers managed by the arbiter (gauge) + * `gunicorn.log.critical`: rate of critical log messages + * `gunicorn.log.error`: rate of error log messages + * `gunicorn.log.warning`: rate of warning log messages + * `gunicorn.log.exception`: rate of exceptional log messages + +To generate new metrics you can `log.info` with a few additional keywords:: + + log.info("...", metric="my.metric", value=1.2, mtype="gauge") + LICENSE ------- @@ -159,4 +188,5 @@ details. .. _`production page`: http://docs.gunicorn.org/en/latest/deploy.html .. _`config file`: http://docs.gunicorn.org/en/latest/configure.html .. _setproctitle: http://pypi.python.org/pypi/setproctitle/ +.. _statsD: http://github.com/etsy/statsd .. _LICENSE: http://github.com/benoitc/gunicorn/blob/master/LICENSE diff --git a/gunicorn/instrument/statsd.py b/gunicorn/instrument/statsd.py index de348a17..ec7f9697 100644 --- a/gunicorn/instrument/statsd.py +++ b/gunicorn/instrument/statsd.py @@ -99,6 +99,7 @@ class Statsd(Logger): pass # statsD methods + # you can use those directly if you want def gauge(self, name, value): try: if self.sock: From d2610dc4830c89fd4d8418499ef060fd5f110b0b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Alexis=20L=C3=AA-Qu=C3=B4c?= Date: Mon, 12 May 2014 18:31:37 +0200 Subject: [PATCH 07/18] Cosmetic cleanup --- README.rst | 14 +++++++------- 1 file changed, 7 insertions(+), 7 deletions(-) diff --git a/README.rst b/README.rst index 1ad7fbed..00c4a433 100644 --- a/README.rst +++ b/README.rst @@ -159,13 +159,13 @@ To use this instrumentation mechanism, simply use a new logger:: The `Statsd` logger overrides `gunicorn.glogging.Logger` to track all requests. The following metrics are generated: - * `gunicorn.requests`: request rate per second - * `gunicorn.request.duration`: histogram of request duration - * `gunicorn.workers`: number of workers managed by the arbiter (gauge) - * `gunicorn.log.critical`: rate of critical log messages - * `gunicorn.log.error`: rate of error log messages - * `gunicorn.log.warning`: rate of warning log messages - * `gunicorn.log.exception`: rate of exceptional log messages + * ``gunicorn.requests``: request rate per second + * ``gunicorn.request.duration``: histogram of request duration + * ``gunicorn.workers``: number of workers managed by the arbiter (gauge) + * ``gunicorn.log.critical``: rate of critical log messages + * ``gunicorn.log.error``: rate of error log messages + * ``gunicorn.log.warning``: rate of warning log messages + * ``gunicorn.log.exception``: rate of exceptional log messages To generate new metrics you can `log.info` with a few additional keywords:: From e6b696b6f034183872b362a61418cf39bad07ada Mon Sep 17 00:00:00 2001 From: Yue Du Date: Tue, 13 May 2014 10:37:56 +0800 Subject: [PATCH 08/18] Fix: logger_class can be undefined. --- gunicorn/config.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/gunicorn/config.py b/gunicorn/config.py index 64219a2f..27d3b5a0 100644 --- a/gunicorn/config.py +++ b/gunicorn/config.py @@ -123,10 +123,10 @@ class Config(object): if uri == "simple": # support the default uri = "gunicorn.glogging.Logger" - else: - logger_class = util.load_class(uri, - default="gunicorn.glogging.Logger", - section="gunicorn.loggers") + + logger_class = util.load_class(uri, + default="gunicorn.glogging.Logger", + section="gunicorn.loggers") if hasattr(logger_class, "install"): logger_class.install() From 07a7e5b9e58160072987f46563b6df6c3a5cdc22 Mon Sep 17 00:00:00 2001 From: Nick Pillitteri Date: Sat, 10 May 2014 21:47:55 -0400 Subject: [PATCH 09/18] Move setting of environmental variables before preload_app start. Move setting of env vars from Arbiter.start to Arbiter.setup so that they are available during application start up when 'preload_app' is used. Closes #735 --- gunicorn/arbiter.py | 10 +++--- tests/test_008-arbiter-env.py | 57 +++++++++++++++++++++++++++++++++++ 2 files changed, 62 insertions(+), 5 deletions(-) create mode 100644 tests/test_008-arbiter-env.py diff --git a/gunicorn/arbiter.py b/gunicorn/arbiter.py index 441f8da1..a21274b4 100644 --- a/gunicorn/arbiter.py +++ b/gunicorn/arbiter.py @@ -106,6 +106,11 @@ class Arbiter(object): in sorted(self.cfg.settings.items(), key=lambda setting: setting[1])))) + # set enviroment' variables + if self.cfg.env: + for k, v in self.cfg.env.items(): + os.environ[k] = v + if self.cfg.preload_app: self.app.wsgi() @@ -121,11 +126,6 @@ class Arbiter(object): self.pidfile.create(self.pid) self.cfg.on_starting(self) - # set enviroment' variables - if self.cfg.env: - for k, v in self.cfg.env.items(): - os.environ[k] = v - self.init_signals() if not self.LISTENERS: self.LISTENERS = create_sockets(self.cfg, self.log) diff --git a/tests/test_008-arbiter-env.py b/tests/test_008-arbiter-env.py new file mode 100644 index 00000000..880824d4 --- /dev/null +++ b/tests/test_008-arbiter-env.py @@ -0,0 +1,57 @@ +# -*- coding: utf-8 - +# +# This file is part of gunicorn released under the MIT license. +# See the NOTICE for more information. + +import t +import os +from gunicorn.app.base import BaseApplication +import gunicorn.arbiter + + +class PreloadedAppWithEnvSettings(BaseApplication): + """ + Simple application that makes use of the 'preload' feature to + start the application before spawning worker processes and sets + environmental variable configuration settings. + """ + + def init(self, parser, opts, args): + """No-op""" + pass + + def load(self): + """No-op""" + pass + + def load_config(self): + """Set the 'preload_app' and 'raw_env' settings in order to verify their + interaction below. + """ + self.cfg.set('raw_env', [ + 'SOME_PATH=/tmp/something', 'OTHER_PATH=/tmp/something/else']) + self.cfg.set('preload_app', True) + + def wsgi(self): + """Assert that the expected environmental variables are set when + the main entry point of this application is called as part of a + 'preloaded' application. + """ + verify_env_vars() + return super(PreloadedAppWithEnvSettings, self).wsgi() + + +def verify_env_vars(): + t.eq(os.getenv('SOME_PATH'), '/tmp/something') + t.eq(os.getenv('OTHER_PATH'), '/tmp/something/else') + + +def test_env_vars_available_during_preload(): + """Ensure that configured environmental variables are set during the + initial set up of the application (called from the .setup() method of + the Arbiter) such that they are available during the initial loading + of the WSGI application. + """ + # Note that we aren't making any assertions here, they are made in the + # dummy application object being loaded here instead. + gunicorn.arbiter.Arbiter(PreloadedAppWithEnvSettings()) From f1fc2710f894156c8c0af5b7bec02dbc5c149810 Mon Sep 17 00:00:00 2001 From: Yue Du Date: Wed, 14 May 2014 14:08:18 +0800 Subject: [PATCH 10/18] Remove unused imports --- gunicorn/config.py | 1 - gunicorn/reloader.py | 1 - gunicorn/workers/base.py | 1 - 3 files changed, 3 deletions(-) diff --git a/gunicorn/config.py b/gunicorn/config.py index 27d3b5a0..2a9e90c9 100644 --- a/gunicorn/config.py +++ b/gunicorn/config.py @@ -15,7 +15,6 @@ import pwd import ssl import sys import textwrap -import types from gunicorn import __version__ from gunicorn.errors import ConfigError diff --git a/gunicorn/reloader.py b/gunicorn/reloader.py index 4333ef7f..219ffa83 100644 --- a/gunicorn/reloader.py +++ b/gunicorn/reloader.py @@ -5,7 +5,6 @@ import os import re -import signal import sys import time import threading diff --git a/gunicorn/workers/base.py b/gunicorn/workers/base.py index d2b07090..5be83efd 100644 --- a/gunicorn/workers/base.py +++ b/gunicorn/workers/base.py @@ -7,7 +7,6 @@ from datetime import datetime import os import signal import sys -import traceback from gunicorn import util From d29b937c08f10e84428d74ad3be0f44c335086dc Mon Sep 17 00:00:00 2001 From: WooParadog Date: Wed, 14 May 2014 17:45:30 +0800 Subject: [PATCH 11/18] Stop all servers --- gunicorn/workers/ggevent.py | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/gunicorn/workers/ggevent.py b/gunicorn/workers/ggevent.py index 167a0a54..c7c4dfba 100644 --- a/gunicorn/workers/ggevent.py +++ b/gunicorn/workers/ggevent.py @@ -121,10 +121,11 @@ class GeventWorker(AsyncWorker): except KeyboardInterrupt: pass except: - try: - server.stop() - except: - pass + for server in servers: + try: + server.stop() + except: + pass raise try: From 89a3c96700c312debf37c83ff516c9a29157d16d Mon Sep 17 00:00:00 2001 From: Alexis Le-Quoc Date: Sat, 31 May 2014 00:10:51 -0400 Subject: [PATCH 12/18] Incorporate feedback from PR Use extra keyword in logger, more pythonic capture response code as a rate metric --- gunicorn/arbiter.py | 6 ++-- gunicorn/instrument/statsd.py | 46 +++++++++++------------------ tests/test_009-statsd.py | 54 +++++++++++++++++++++++++++++++++++ 3 files changed, 74 insertions(+), 32 deletions(-) create mode 100644 tests/test_009-statsd.py diff --git a/gunicorn/arbiter.py b/gunicorn/arbiter.py index 44ae5061..a390c9ca 100644 --- a/gunicorn/arbiter.py +++ b/gunicorn/arbiter.py @@ -479,9 +479,9 @@ class Arbiter(object): self.kill_worker(pid, signal.SIGQUIT) self.log.info("%d workers", - metric="gunicorn.workers", - value=len(self.WORKERS), - mtype="gauge") + extra={"metric": "gunicorn.workers", + "value": len(self.WORKERS), + "mtype": "gauge"}) def spawn_worker(self): self.worker_age += 1 diff --git a/gunicorn/instrument/statsd.py b/gunicorn/instrument/statsd.py index ec7f9697..85e195e2 100644 --- a/gunicorn/instrument/statsd.py +++ b/gunicorn/instrument/statsd.py @@ -3,8 +3,8 @@ # This file is part of gunicorn released under the MIT license. # See the NOTICE for more information. -"""Bare-bones implementation of statsD's protocol, client-side -""" +"Bare-bones implementation of statsD's protocol, client-side" + import socket from gunicorn.glogging import Logger @@ -33,22 +33,18 @@ class Statsd(Logger): # Log errors and warnings def critical(self, msg, *args, **kwargs): - self._sanitize(kwargs) Logger.critical(self, msg, *args, **kwargs) self.increment("gunicorn.log.critical", 1) def error(self, msg, *args, **kwargs): - self._sanitize(kwargs) Logger.error(self, msg, *args, **kwargs) self.increment("gunicorn.log.error", 1) def warning(self, msg, *args, **kwargs): - self._sanitize(kwargs) Logger.warning(self, msg, *args, **kwargs) self.increment("gunicorn.log.warning", 1) def exception(self, msg, *args, **kwargs): - self._sanitize(kwargs) Logger.exception(self, msg, *args, **kwargs) self.increment("gunicorn.log.exception", 1) @@ -56,28 +52,27 @@ class Statsd(Logger): def info(self, msg, *args, **kwargs): """Log a given statistic if metric, value and type are present """ - metric = kwargs.get(METRIC_VAR, None) - value = kwargs.get(VALUE_VAR, None) - typ = kwargs.get(MTYPE_VAR, None) - if metric and value and typ: - self._sanitize(kwargs) - 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 + 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 Logger.info(self, msg, *args, **kwargs) # skip the run-of-the-mill logs def debug(self, msg, *args, **kwargs): - self._sanitize(kwargs) Logger.debug(self, msg, *args, **kwargs) def log(self, lvl, msg, *args, **kwargs): - self._sanitize(kwargs) Logger.log(self, lvl, msg, *args, **kwargs) # access logging @@ -89,14 +84,7 @@ class Statsd(Logger): duration_in_s = request_time.seconds + float(request_time.microseconds)/10**6 self.histogram("gunicorn.request.duration", duration_in_s) self.increment("gunicorn.requests", 1) - - def _sanitize(self, kwargs): - """Drop stasd keywords from the logger""" - for k in (METRIC_VAR, VALUE_VAR, MTYPE_VAR): - try: - kwargs.pop(k) - except KeyError: - pass + self.increment("gunicorn.request.status.%d" % int(resp.status), 1) # statsD methods # you can use those directly if you want diff --git a/tests/test_009-statsd.py b/tests/test_009-statsd.py new file mode 100644 index 00000000..24bb6f57 --- /dev/null +++ b/tests/test_009-statsd.py @@ -0,0 +1,54 @@ +from datetime import timedelta + +import t + +from gunicorn.config import Config +from gunicorn.instrument.statsd import Statsd + +class TestException(Exception): pass + +class MockSocket(object): + "Pretend to be a UDP socket" + def __init__(self, failp): + self.failp = failp + self.msgs = [] # accumulate messages for later inspection + + def send(self, msg): + if self.failp: + raise TestException("Should not interrupt the logger") + self.msgs.append(msg) + + def reset(self): + self.msgs = [] + +class MockResponse(object): + def __init__(self, status): + self.status = status + +def test_statsd_fail(): + "UDP socket fails" + logger = Statsd(Config()) + logger.sock = MockSocket(True) + logger.info("No impact on logging") + logger.debug("No impact on logging") + logger.critical("No impact on logging") + logger.error("No impact on logging") + logger.warning("No impact on logging") + logger.exception("No impact on logging") + +def test_instrument(): + logger = Statsd(Config()) + logger.sock = MockSocket(False) + + logger.info("Blah", extra={"mtype": "gauge", "metric": "gunicorn.test", "value": 666}) + t.eq(logger.sock.msgs[0], "gunicorn.test:666|g") + logger.sock.reset() + + logger.critical("Boom") + t.eq(logger.sock.msgs[0], "gunicorn.log.critical:1|c|@1.0") + logger.sock.reset() + + logger.access(MockResponse(200), None, {}, timedelta(seconds=7)) + t.eq(logger.sock.msgs[0], "gunicorn.request.duration:7.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") From 4bf1e1d46893476c6b223654565fdf261730c7fe Mon Sep 17 00:00:00 2001 From: Alexis Le-Quoc Date: Sat, 31 May 2014 00:48:27 -0400 Subject: [PATCH 13/18] Fix silent exception in response code capture --- gunicorn/arbiter.py | 4 ++-- gunicorn/instrument/statsd.py | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/gunicorn/arbiter.py b/gunicorn/arbiter.py index a390c9ca..d6243a33 100644 --- a/gunicorn/arbiter.py +++ b/gunicorn/arbiter.py @@ -478,9 +478,9 @@ class Arbiter(object): (pid, _) = workers.pop(0) self.kill_worker(pid, signal.SIGQUIT) - self.log.info("%d workers", + self.log.info("{0} workers".format(len(workers)), extra={"metric": "gunicorn.workers", - "value": len(self.WORKERS), + "value": len(workers), "mtype": "gauge"}) def spawn_worker(self): diff --git a/gunicorn/instrument/statsd.py b/gunicorn/instrument/statsd.py index 85e195e2..fcd38311 100644 --- a/gunicorn/instrument/statsd.py +++ b/gunicorn/instrument/statsd.py @@ -84,7 +84,7 @@ class Statsd(Logger): duration_in_s = request_time.seconds + float(request_time.microseconds)/10**6 self.histogram("gunicorn.request.duration", duration_in_s) self.increment("gunicorn.requests", 1) - self.increment("gunicorn.request.status.%d" % int(resp.status), 1) + self.increment("gunicorn.request.status.%d" % int(resp.status.split()[0]), 1) # statsD methods # you can use those directly if you want From 3c3c52fb6a9a9fe020971d293d565a283de068b8 Mon Sep 17 00:00:00 2001 From: Alexis Le-Quoc Date: Sat, 31 May 2014 13:14:05 -0400 Subject: [PATCH 14/18] Fix failing test and reorder logging to always log --- gunicorn/instrument/statsd.py | 2 +- tests/test_009-statsd.py | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/gunicorn/instrument/statsd.py b/gunicorn/instrument/statsd.py index fcd38311..daae4026 100644 --- a/gunicorn/instrument/statsd.py +++ b/gunicorn/instrument/statsd.py @@ -52,6 +52,7 @@ class Statsd(Logger): 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) @@ -66,7 +67,6 @@ class Statsd(Logger): self.histogram(metric, value) else: pass - Logger.info(self, msg, *args, **kwargs) # skip the run-of-the-mill logs def debug(self, msg, *args, **kwargs): diff --git a/tests/test_009-statsd.py b/tests/test_009-statsd.py index 24bb6f57..aaf75dd5 100644 --- a/tests/test_009-statsd.py +++ b/tests/test_009-statsd.py @@ -48,7 +48,7 @@ def test_instrument(): t.eq(logger.sock.msgs[0], "gunicorn.log.critical:1|c|@1.0") logger.sock.reset() - logger.access(MockResponse(200), None, {}, timedelta(seconds=7)) + logger.access(MockResponse("200 OK"), None, {}, timedelta(seconds=7)) t.eq(logger.sock.msgs[0], "gunicorn.request.duration:7.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") From 05051aa8b27839443cb25b43c2c31f634d25a9f3 Mon Sep 17 00:00:00 2001 From: Alexis Le-Quoc Date: Wed, 18 Jun 2014 21:33:04 -0400 Subject: [PATCH 15/18] Simpler statsd integration No need to specify a logger class. --statsd-to is enough to trigger the Statsd logger automatically --- README.rst | 2 +- gunicorn/config.py | 11 ++++++++--- tests/{test_009-statsd.py => test_010-statsd.py} | 0 3 files changed, 9 insertions(+), 4 deletions(-) rename tests/{test_009-statsd.py => test_010-statsd.py} (100%) diff --git a/README.rst b/README.rst index 1085feff..9e935f68 100644 --- a/README.rst +++ b/README.rst @@ -154,7 +154,7 @@ statsD consumer. To use this instrumentation mechanism, simply use a new logger:: - $ gunicorn --logging-class gunicorn.instrument.statsd.Statsd ... + $ gunicorn --statsd-to localhost:8125 ... The `Statsd` logger overrides `gunicorn.glogging.Logger` to track all requests. The following metrics are generated: diff --git a/gunicorn/config.py b/gunicorn/config.py index ba6116ac..c6dbdbfe 100644 --- a/gunicorn/config.py +++ b/gunicorn/config.py @@ -142,8 +142,13 @@ class Config(object): if uri == "simple": # support the default uri = "gunicorn.glogging.Logger" - - logger_class = util.load_class(uri, + + # if statsd is on, automagically switch to the statsd logger + if 'statsd_to' in self.settings: + logger_class = util.load_class("gunicorn.instrument.statsd.Statsd", + section="gunicorn.loggers") + else: + logger_class = util.load_class(uri, default="gunicorn.glogging.Logger", section="gunicorn.loggers") @@ -1639,7 +1644,7 @@ if sys.version_info >= (2, 7): class StatsdTo(Setting): name = "statsd_to" section = "Logging" - cli = ["--log-statsd-to"] + cli = ["--statsd-to"] meta = "STATSD_ADDR" default = "localhost:8125" validator = validate_hostport diff --git a/tests/test_009-statsd.py b/tests/test_010-statsd.py similarity index 100% rename from tests/test_009-statsd.py rename to tests/test_010-statsd.py From 3c9b9e3218d7fa6ae766c052a4adbfbe65103f38 Mon Sep 17 00:00:00 2001 From: Alexis Le-Quoc Date: Wed, 18 Jun 2014 21:50:50 -0400 Subject: [PATCH 16/18] Change --statsd-to to --statsd-host --- gunicorn/config.py | 8 ++++---- gunicorn/instrument/statsd.py | 2 +- 2 files changed, 5 insertions(+), 5 deletions(-) diff --git a/gunicorn/config.py b/gunicorn/config.py index c6dbdbfe..656448c7 100644 --- a/gunicorn/config.py +++ b/gunicorn/config.py @@ -144,7 +144,7 @@ class Config(object): uri = "gunicorn.glogging.Logger" # if statsd is on, automagically switch to the statsd logger - if 'statsd_to' in self.settings: + if 'statsd_host' in self.settings: logger_class = util.load_class("gunicorn.instrument.statsd.Statsd", section="gunicorn.loggers") else: @@ -1641,10 +1641,10 @@ if sys.version_info >= (2, 7): """ # statsD monitoring -class StatsdTo(Setting): - name = "statsd_to" +class StatsdHost(Setting): + name = "statsd_host" section = "Logging" - cli = ["--statsd-to"] + cli = ["--statsd-host"] meta = "STATSD_ADDR" default = "localhost:8125" validator = validate_hostport diff --git a/gunicorn/instrument/statsd.py b/gunicorn/instrument/statsd.py index daae4026..e712c47f 100644 --- a/gunicorn/instrument/statsd.py +++ b/gunicorn/instrument/statsd.py @@ -25,7 +25,7 @@ class Statsd(Logger): """ Logger.__init__(self, cfg) try: - host, port = cfg.statsd_to + host, port = cfg.statsd_host self.sock = socket.socket(socket.AF_INET, socket.SOCK_DGRAM) self.sock.connect((host, int(port))) except Exception: From 3b63a6418bc8929d85a8a54dc3808e77fff0cd1b Mon Sep 17 00:00:00 2001 From: Alexis Le-Quoc Date: Wed, 18 Jun 2014 23:58:59 -0400 Subject: [PATCH 17/18] Documentation reflect new option name --- README.rst | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/README.rst b/README.rst index 9e935f68..94369e8b 100644 --- a/README.rst +++ b/README.rst @@ -152,9 +152,9 @@ The use of UDP cleanly isolates Gunicorn from the receiving end of the statsD metrics so that instrumentation does not cause Gunicorn to be heldeup by a slow statsD consumer. -To use this instrumentation mechanism, simply use a new logger:: +To use statsD, just tell gunicorn where the statsD server is: - $ gunicorn --statsd-to localhost:8125 ... + $ gunicorn --statsd-host=localhost:8125 ... The `Statsd` logger overrides `gunicorn.glogging.Logger` to track all requests. The following metrics are generated: From 7f33e36ce01b5e0631eb856e0c83ddc7889f33bf Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Alexis=20L=C3=AA-Qu=C3=B4c?= Date: Sat, 21 Jun 2014 22:01:30 -0400 Subject: [PATCH 18/18] Update instructions to log arbitrary metrics --- README.rst | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/README.rst b/README.rst index 94369e8b..1ec18b8b 100644 --- a/README.rst +++ b/README.rst @@ -169,7 +169,7 @@ all requests. The following metrics are generated: To generate new metrics you can `log.info` with a few additional keywords:: - log.info("...", metric="my.metric", value=1.2, mtype="gauge") + log.info("...", extra={"metric": "my.metric", "value": "1.2", "mtype": "gauge"}) LICENSE -------