refactor logging and error handling

* use an instance logger to log any warnings/errors.
* handle parse errors for rate limit strings specified on decorators
  and fall back to the global limits if encountered.
* improve logging tests.

doc/source/index.rst

@@ -188,6 +188,13 @@ Examples
 * 10/hour;100/day;2000 per year
 * 100/day, 500/7days
 
+.. warning:: If rate limit strings that are provided to the :meth:`Limiter.limit`
+   decorator are malformed and can't be parsed the decorated route will fall back
+   to the global rate limit(s) and an ``ERROR`` log message will be emitted. Refer
+   to :ref:`logging` for more details on capturing this information. Malformed
+   global rate limit strings will howere raise an exception as they are evaluated
+   early enough to not cause disruption to a running application.
+
 
 .. _ratelimit-strategy:
 
@@ -240,16 +247,16 @@ be maintained in memory per resource and rate limit.
 Customization
 =============
 
+
+Rate limit domains
+-------------------------
+
 By default, all rate limits are applied on a per ``remote address`` basis.
 However, you can easily customize your rate limits to be based on any other
 characteristic of the incoming request. Both the :class:`Limiter` constructor
 and the :meth:`Limiter.limit` decorator accept a keyword argument
 ``key_func`` that should return a string (or an object that has a string representation).
 
-
-Examples
---------
-
 Rate limiting a route by current user (using Flask-Login)::
 
 
@@ -275,8 +282,8 @@ Rate limiting all requests by country::
 
 
 
-Error Handling
-==============
+Rate limit exeeded responses
+----------------------------
 The default configuration results in an ``abort(409)`` being called everytime
 a ratelimit is exceeded for a particular route. The exceeded limit is added to
 the response and results in an response body that looks something like::
@@ -299,6 +306,27 @@ json response instead::
         )
 
 
+
+.. _logging:
+
+Logging
+-------
+Each :class:`Limiter` instance has a ``logger`` instance variable that is by
+default **not** configured with a handler. You can add your own handler to obtain
+log messages emitted by :mod:`flask_limiter`.
+
+Simple stdout handler::
+
+    limiter = Limiter(app)
+    limiter.logger.addHandler(StreamHandler())
+
+Reusing all the handlers of the ``logger`` instance of the :class:`flask.Flask` app::
+
+    app = Flask(__name__)
+    limiter = Limiter(app)
+    for handler in app.logger.handlers:
+        limiter.logger.addHandler(handler)
+
 API
 ===
 

flask_limiter/extension.py

@@ -3,20 +3,22 @@
 """
 
 from functools import wraps
+import logging
 
 from flask import request, current_app
 
 from .errors import RateLimitExceeded, ConfigurationError
 from .strategies import STRATEGIES
 from .util import storage_from_string, parse_many, get_ipaddr
 
-
 class Limiter(object):
     """
     :param app: :class:`flask.Flask` instance to initialize the extension
      with.
-    :param global_limits: a variable list of strings denoting global
+    :param list global_limits: a variable list of strings denoting global
      limits to apply to all routes. :ref:`ratelimit-string` for  more details.
+    :param function key_func: a callable that returns the domain to rate limit by.
+     Defaults to the remote address of the request.
     """
 
     def __init__(self, app=None, key_func=get_ipaddr, global_limits=[]):
@@ -34,6 +36,11 @@ def __init__(self, app=None, key_func=get_ipaddr, global_limits=[]):
         self.dynamic_route_limits = {}
         self.storage = self.limiter = None
         self.key_func = key_func
+        self.logger = logging.getLogger("flask-limiter")
+        class BlackHoleHandler(logging.StreamHandler):
+            def emit(*_):
+                return
+        self.logger.addHandler(BlackHoleHandler())
         if app:
             self.init_app(app)
 
@@ -70,18 +77,24 @@ def __check_request_limit(self):
             return
         limits = (
             name in self.route_limits and self.route_limits[name]
-            or [] if name in self.dynamic_route_limits else self.global_limits
+            or []
         )
-        d_limits = []
+        dynamic_limits = []
         if name in self.dynamic_route_limits:
             for key_func, limit_func in self.dynamic_route_limits[name]:
-                d_limits.extend(
-                    [key_func, limit] for limit in parse_many(limit_func())
-                )
+                try:
+                    dynamic_limits.extend(
+                        [key_func, limit] for limit in parse_many(limit_func())
+                    )
+                except ValueError as e:
+                    self.logger.error(
+                        "failed to load ratelimit for view function %s (%s)" % (name, e)
+                    )
+
         failed_limit = None
-        for key_func, limit in limits + d_limits:
+        for key_func, limit in (limits + dynamic_limits or self.global_limits):
             if not self.limiter.hit(limit, key_func(), endpoint):
-                current_app.logger.info(
+                self.logger.warn(
                     "ratelimit %s (%s) exceeded at endpoint: %s" % (
                     limit, key_func(), endpoint))
                 failed_limit = limit
@@ -104,16 +117,21 @@ def _inner(fn):
             @wraps(fn)
             def __inner(*a, **k):
                 return fn(*a, **k)
-            self.route_limits.setdefault(name, [])
-            self.dynamic_route_limits.setdefault(name, [])
             func = key_func or self.key_func
             if callable(limit_value):
-                self.dynamic_route_limits[name].append((func, limit_value))
-
+                self.dynamic_route_limits.setdefault(name, []).append(
+                    (func, limit_value)
+                )
             else:
-                self.route_limits[name].extend(
-                    [(func, limit) for limit in parse_many(limit_value)]
-            )
+                try:
+                    self.route_limits.setdefault(name, []).extend(
+                        [(func, limit) for limit in parse_many(limit_value)]
+                    )
+                except ValueError as e:
+                    self.logger.error(
+                        "failed to configure view function %s (%s)" % (name, e)
+                    )
+
             return __inner
         return _inner
 

tests/test_flask_ext.py

@@ -73,13 +73,11 @@ def t1():
                 self.assertEqual(429, cli.get("/t1").status_code)
 
     def test_logging(self):
-        fake_logger = mock.Mock()
         app = Flask(__name__)
+        limiter = Limiter(app)
         mock_handler = mock.Mock()
         mock_handler.level = logging.INFO
-        app.logger.setLevel(logging.INFO)
-        app.logger.addHandler(mock_handler)
-        limiter = Limiter(app)
+        limiter.logger.addHandler(mock_handler)
         @app.route("/t1")
         @limiter.limit("1/minute")
         def t1():
@@ -89,6 +87,25 @@ def t1():
             self.assertEqual(429,cli.get("/t1").status_code)
         self.assertEqual(mock_handler.handle.call_count, 1)
 
+    def test_reuse_logging(self):
+        app = Flask(__name__)
+        app_handler = mock.Mock()
+        app_handler.level = logging.INFO
+        app.logger.addHandler(app_handler)
+        limiter = Limiter(app)
+        for handler in app.logger.handlers:
+            limiter.logger.addHandler(handler)
+        @app.route("/t1")
+        @limiter.limit("1/minute")
+        def t1():
+            return "42"
+
+        with app.test_client() as cli:
+            cli.get("/t1")
+            cli.get("/t1")
+
+        self.assertEqual(app_handler.handle.call_count, 1)
+
     def test_exempt_routes(self):
 
         app = Flask(__name__)
@@ -152,7 +169,7 @@ def t2():
                 self.assertEqual(cli.get("/t2").status_code, 200)
             self.assertEqual(cli.get("/t2").status_code, 200)
 
-    def test_dynamic_limits(self):
+    def test_decorated_dynamic_limits(self):
         app = Flask(__name__)
         app.config.setdefault("X", "2 per second")
         limiter = Limiter(app, global_limits=["1/second"])
@@ -197,6 +214,46 @@ def t2():
                 timeline.forward(1)
                 self.assertEqual(cli.get("/t2").status_code, 200)
 
+    def test_invalid_decorated_dynamic_limits(self):
+        app = Flask(__name__)
+        app.config.setdefault("X", "2 per sec")
+        limiter = Limiter(app, global_limits=["1/second"])
+        mock_handler = mock.Mock()
+        mock_handler.level = logging.INFO
+        limiter.logger.addHandler(mock_handler)
+        @app.route("/t1")
+        @limiter.limit(lambda: current_app.config.get("X"))
+        def t1():
+            return "42"
+
+        with app.test_client() as cli:
+            with hiro.Timeline().freeze() as timeline:
+                self.assertEqual(cli.get("/t1").status_code, 200)
+                self.assertEqual(cli.get("/t1").status_code, 429)
+        # 2 for invalid limit, 1 for warning.
+        self.assertEqual(mock_handler.handle.call_count, 3)
+        self.assertTrue("couldn't parse rate limit" in mock_handler.handle.call_args_list[0][0][0].msg)
+        self.assertTrue("couldn't parse rate limit" in mock_handler.handle.call_args_list[1][0][0].msg)
+        self.assertTrue("exceeded at endpoint" in mock_handler.handle.call_args_list[2][0][0].msg)
+
+    def test_invalid_decorated_static_limits(self):
+        app = Flask(__name__)
+        limiter = Limiter(app, global_limits=["1/second"])
+        mock_handler = mock.Mock()
+        mock_handler.level = logging.INFO
+        limiter.logger.addHandler(mock_handler)
+        @app.route("/t1")
+        @limiter.limit("2/sec")
+        def t1():
+            return "42"
+
+        with app.test_client() as cli:
+            with hiro.Timeline().freeze() as timeline:
+                self.assertEqual(cli.get("/t1").status_code, 200)
+                self.assertEqual(cli.get("/t1").status_code, 429)
+        self.assertTrue("couldn't parse rate limit" in mock_handler.handle.call_args_list[0][0][0].msg)
+        self.assertTrue("exceeded at endpoint" in mock_handler.handle.call_args_list[1][0][0].msg)
+
 
     def test_multiple_apps(self):
         app1 = Flask("app1")