Repository: getlogbook/logbook

Issue:
logged_if_slow API
I think the logged_if_slow API is a bit awkard. I think we should change it for v1.0.

Current API:
```
def logged_if_slow(message, threshold=1, func=logbook_debug, args=None, kwargs=None)
```

Problems:
- Always uses default logger
- Have to pass log function, why not a level?
- args and kwargs are normal parameters (rather than `*args`, `**kwargs`).

Proposed API:
```
def logged_if_slow(*args, **kwargs):
    threshold = kwargs.pop('threshold', 1)
    logger = kwargs.pop('logger', _default_logger)
    level = kwargs.pop('level', logbook.DEBUG)
    # Context manager would call:
    logger.log(level, *args, **kwargs)
```

Then the context manager can simply call

```
logger.log(level, *args, **kwargs)
```

Also: are there valid reasons to use threading and events to handle the threshold rather than just storing a `time.time()` value and comparing in `__exit__`? I don't know how the threading timeout works, so I'm just curious about the implementation!

Discussion:

Patch:
diff --git a/logbook/utils.py b/logbook/utils.py
index 5416c52..7851f48 100644
--- a/logbook/utils.py
+++ b/logbook/utils.py
@@ -3,17 +3,14 @@ import functools
 import sys
 import threading
 
-from .base import Logger
+from .base import Logger, DEBUG
 from .helpers import string_types
-from logbook import debug as logbook_debug
 
 
 class _SlowContextNotifier(object):
 
-    def __init__(self, threshold, logger_func, args, kwargs):
-        self.logger_func = logger_func
-        self.args = args
-        self.kwargs = kwargs or {}
+    def __init__(self, threshold, func):
+        self.func = func
         self.evt = threading.Event()
         self.threshold = threshold
         self.thread = threading.Thread(target=self._notifier)
@@ -21,7 +18,7 @@ class _SlowContextNotifier(object):
     def _notifier(self):
         self.evt.wait(timeout=self.threshold)
         if not self.evt.is_set():
-            self.logger_func(*self.args, **self.kwargs)
+            self.func()
 
     def __enter__(self):
         self.thread.start()
@@ -32,18 +29,36 @@ class _SlowContextNotifier(object):
         self.thread.join()
 
 
-def logged_if_slow(message, threshold=1, func=logbook_debug, args=None,
-                   kwargs=None):
-    """Logs a message (by default using the global debug logger) if a certain
-       context containing a set of operations is too slow
+_slow_logger = Logger('Slow')
 
-    >>> with logged_if_slow('too slow!'):
-    ...     ...
 
-    .. versionadded:: 0.12
+def logged_if_slow(*args, **kwargs):
+    """Context manager that logs if operations within take longer than
+    `threshold` seconds.
+
+    :param threshold: Number of seconds (or fractions thereof) allwoed before
+                      logging occurs. The default is 1 second.
+    :param logger: :class:`~logbook.Logger` to use. The default is a 'slow'
+                   logger.
+    :param level: Log level. The default is `DEBUG`.
+    :param func: (Deprecated). Function to call to perform logging.
+
+    The remaining parameters are passed to the
+    :meth:`~logbook.base.LoggerMixin.log` method.
     """
-    full_args = (message, ) if args is None else (message, ) + tuple(args)
-    return _SlowContextNotifier(threshold, func, full_args, kwargs)
+    threshold = kwargs.pop('threshold', 1)
+    func = kwargs.pop('func', None)
+    if func is None:
+        logger = kwargs.pop('logger', _slow_logger)
+        level = kwargs.pop('level', DEBUG)
+        func = functools.partial(logger.log, level, *args, **kwargs)
+    else:
+        if 'logger' in kwargs or 'level' in kwargs:
+            raise TypeError("If using deprecated func parameter, 'logger' and"
+                            " 'level' arguments cannot be passed.")
+        func = functools.partial(func, *args, **kwargs)
+
+    return _SlowContextNotifier(threshold, func)
 
 
 class _Local(threading.local):
diff --git a/tox.ini b/tox.ini
index b3d3493..07a3f90 100644
--- a/tox.ini
+++ b/tox.ini
@@ -6,6 +6,7 @@ skipsdist=True
 whitelist_externals=
    rm
 deps=
+   py{26,27}: mock
    pytest
    Cython
 changedir={toxinidir}
@@ -18,6 +19,7 @@ commands=
 
 [testenv:pypy]
 deps=
+   mock
    pytest
 commands=
    {envpython} {toxinidir}/setup.py develop


Test patch:
diff --git a/tests/test_utils.py b/tests/test_utils.py
index 3d1443f..f4ca5b8 100644
--- a/tests/test_utils.py
+++ b/tests/test_utils.py
@@ -8,23 +8,59 @@ from time import sleep
 
 _THRESHOLD = 0.1
 
+try:
+    from unittest.mock import Mock, call
+except ImportError:
+    from mock import Mock, call
 
-def test_logged_if_slow_reached(logger, test_handler):
+
+def test_logged_if_slow_reached(test_handler):
     with test_handler.applicationbound():
         with logged_if_slow('checking...', threshold=_THRESHOLD):
-            sleep(2*_THRESHOLD)
+            sleep(2 * _THRESHOLD)
         assert len(test_handler.records) == 1
         [record] = test_handler.records
         assert record.message == 'checking...'
 
 
-def test_logged_if_slow_did_not_reached(logger, test_handler):
+def test_logged_if_slow_did_not_reached(test_handler):
     with test_handler.applicationbound():
         with logged_if_slow('checking...', threshold=_THRESHOLD):
-            sleep(_THRESHOLD/2)
+            sleep(_THRESHOLD / 2)
         assert len(test_handler.records) == 0
 
 
+def test_logged_if_slow_logger():
+    logger = Mock()
+
+    with logged_if_slow('checking...', threshold=_THRESHOLD, logger=logger):
+        sleep(2 * _THRESHOLD)
+
+    assert logger.log.call_args == call(logbook.DEBUG, 'checking...')
+
+
+def test_logged_if_slow_level(test_handler):
+    with test_handler.applicationbound():
+        with logged_if_slow('checking...', threshold=_THRESHOLD,
+                            level=logbook.WARNING):
+            sleep(2 * _THRESHOLD)
+
+    assert test_handler.records[0].level == logbook.WARNING
+
+
+def test_logged_if_slow_deprecated(logger, test_handler):
+    with test_handler.applicationbound():
+        with logged_if_slow('checking...', threshold=_THRESHOLD,
+                            func=logbook.error):
+            sleep(2 * _THRESHOLD)
+
+    assert test_handler.records[0].level == logbook.ERROR
+    assert test_handler.records[0].message == 'checking...'
+
+    with pytest.raises(TypeError):
+        logged_if_slow('checking...', logger=logger, func=logger.error)
+
+
 def test_deprecated_func_called(capture):
     assert deprecated_func(1, 2) == 3