diff --git a/.travis.yml b/.travis.yml index f380d8a..45ab6fa 100644 --- a/.travis.yml +++ b/.travis.yml @@ -10,6 +10,7 @@ - "3.3" - "3.4" - "pypy" + - "pypy3" install: # this fixes SemLock issues on travis @@ -32,6 +33,8 @@ exclude: - python: "pypy" env: COMMAND="make cybuild test" + - python: "pypy3" + env: COMMAND="make cybuild test" notifications: email: diff --git a/CHANGES b/CHANGES index c9f4cf9..5a2abed 100644 --- a/CHANGES +++ b/CHANGES @@ -2,6 +2,53 @@ ================= Here you can see the full list of changes between each Logbook release. + +Version 0.10.0 +-------------- + +Released on July 14th 2015 + +- Removed the global handler which was installed by default so far. The rationale is to ease adoption for 3rd party libraries who don't want output to go to stderr by default. The old behavior can still be restored by setting the LOGBOOK_INSTALL_DEFAULT_HANDLER environment variable +- Fix small Python 3 compatibility issues + +Version 0.9.1 +------------- + +Released on May 4th 2015 + +- Minor fixes + + +Version 0.9.0 +------------- + +Released on February 12th 2015 + +- Added frame correction option, to properly mark log record origins (Thanks Roey Darwish) +- Fixed MailHandler infinite recursion bug (Thanks Tal Yalon) + + +Version 0.8.1 +------------- + +Released on November 30th 2014 + +- Fix support for gevent, along with various other fixes (Thanks Tal Yalon) + +Version 0.8.0 +------------- + +Released on November 11th 2014. Codename "improve_some_more" + +- Added Pushover handler (thanks @owo) +- Default logging format now includes seconds and microseconds (#110) +- Several fixes regarding possible deadlocks in log formatting (thanks Guy Rozendorn) +- Fixed packaging so that the speedups module now gets packaged by default (#122) +- ThreadedWrapperHandler now supports maxsize (#121) (thanks Ken Jung) +- Fixes in rotating handlers (thanks zhangliyong) +- Added Pushover handler (thanks Ossama W. Obeid) +- RedisHandler now supports lpush as an option (thanks Bruno Rocha) + Version 0.7.0 ------------- diff --git a/Makefile b/Makefile index 4f3b91f..c9258b9 100644 --- a/Makefile +++ b/Makefile @@ -9,7 +9,7 @@ @python scripts/test_setup.py test: - @nosetests -w tests + @py.test tests toxtest: @tox @@ -27,7 +27,7 @@ docs: make -C docs html SPHINXOPTS=-Aonline=1 -release: upload-docs +release: logbook/_speedups.so upload-docs python scripts/make-release.py logbook/_speedups.so: logbook/_speedups.pyx diff --git a/README.rst b/README.rst index f7e4da9..4853f10 100644 --- a/README.rst +++ b/README.rst @@ -14,4 +14,4 @@ It should be easy to setup, use and configure and support web applications :) -For more information look at http://logbook.pocoo.org/ +For more information look at http://pythonhosted.org/Logbook diff --git a/benchmark/run.py b/benchmark/run.py index 45f6041..f946ac2 100644 --- a/benchmark/run.py +++ b/benchmark/run.py @@ -28,22 +28,33 @@ return result -def run_bench(name): +def run_bench(name, use_gevent=False): sys.stdout.write('%-32s' % name) sys.stdout.flush() Popen([sys.executable, '-mtimeit', '-s', 'from bench_%s import run' % name, + 'from logbook.concurrency import enable_gevent', + 'enable_gevent()' if use_gevent else '', 'run()']).wait() -def main(): +def bench_wrapper(use_gevent=False): print '=' * 80 - print 'Running benchmark with Logbook %s' % version + print 'Running benchmark with Logbook %s (gevent enabled=%s)' % (version, use_gevent) print '-' * 80 os.chdir(bench_directory) for bench in list_benchmarks(): - run_bench(bench) + run_bench(bench, use_gevent) print '-' * 80 + + +def main(): + bench_wrapper(False) + try: + import gevent + bench_wrapper(True) + except ImportError: + pass if __name__ == '__main__': diff --git a/docs/api/internal.rst b/docs/api/internal.rst index b57c547..c1aa0d0 100644 --- a/docs/api/internal.rst +++ b/docs/api/internal.rst @@ -20,8 +20,5 @@ .. module:: logbook.handlers -.. autoclass:: RotatingFileHandlerBase - :members: - .. autoclass:: StringFormatterHandlerMixin :members: diff --git a/docs/api/notifiers.rst b/docs/api/notifiers.rst index 4c75e0c..8a1a404 100644 --- a/docs/api/notifiers.rst +++ b/docs/api/notifiers.rst @@ -33,6 +33,9 @@ .. autoclass:: NotifoHandler :members: +.. autoclass:: PushoverHandler + :members: + Base Interface -------------- diff --git a/docs/conf.py b/docs/conf.py index 859877a..409cdd1 100644 --- a/docs/conf.py +++ b/docs/conf.py @@ -48,9 +48,9 @@ # built documents. # # The short X.Y version. -version = '0.7.0' +version = '0.10.0' # The full version, including alpha/beta/rc tags. -release = '0.7.0' +release = '0.10.0' # The language for content autogenerated by Sphinx. Refer to documentation # for a list of supported languages. diff --git a/docs/features.rst b/docs/features.rst index 8d90278..ccec1e1 100644 --- a/docs/features.rst +++ b/docs/features.rst @@ -22,8 +22,9 @@ stack. Setting a handler does not replace existing handlers, but gives it higher priority. Each handler has the ability to prevent records from propagating to lower-priority handlers. -- Logbook comes with a useful default configuration that spits all the - information to stderr in a useful manner. +- Logbook comes with a quick optional configuration that spits all the + information to stderr in a useful manner (by setting the LOGBOOK_INSTALL_DEFAULT_HANDLER + environment variable). This is useful for webapps, for example. - All of the built-in handlers have a useful default configuration applied with formatters that provide all the available information in a format that makes the most sense for the given handler. For example, a default stream diff --git a/docs/quickstart.rst b/docs/quickstart.rst index c2cdff5..3f0c62a 100644 --- a/docs/quickstart.rst +++ b/docs/quickstart.rst @@ -9,7 +9,7 @@ >>> from logbook import Logger >>> log = Logger('My Awesome Logger') >>> log.warn('This is too cool for stdlib') -[2010-07-23 16:34] WARNING: My Awesome Logger: This is too cool for stdlib +[2010-07-23 16:34:42.687111] WARNING: My Awesome Logger: This is too cool for stdlib A logger is a so-called :class:`~logbook.base.RecordDispatcher`, which is commonly referred to as a "logging channel". The name you give such a channel diff --git a/docs/setups.rst b/docs/setups.rst index 7c779c2..d695b6b 100644 --- a/docs/setups.rst +++ b/docs/setups.rst @@ -210,7 +210,7 @@ only accepts loggers of a specific kind. You can also do that with a filter function:: - handler = MyHandler(filter=lambda r: r.channel == 'app.database') + handler = MyHandler(filter=lambda r, h: r.channel == 'app.database') Keep in mind that the channel is intended to be a human readable string and is not necessarily unique. If you really need to keep loggers apart @@ -220,7 +220,7 @@ You can also compare the dispatcher on the log record:: from yourapplication.yourmodule import logger - handler = MyHandler(filter=lambda r: r.dispatcher is logger) + handler = MyHandler(filter=lambda r, h: r.dispatcher is logger) This however has the disadvantage that the dispatcher entry on the log record is a weak reference and might go away unexpectedly and will not be diff --git a/logbook/__init__.py b/logbook/__init__.py index 3ba0b64..acb94f2 100644 --- a/logbook/__init__.py +++ b/logbook/__init__.py @@ -10,7 +10,7 @@ :license: BSD, see LICENSE for more details. """ - +import os from logbook.base import LogRecord, Logger, LoggerGroup, NestedSetup, \ Processor, Flags, get_level_name, lookup_level, dispatch_record, \ CRITICAL, ERROR, WARNING, NOTICE, INFO, DEBUG, NOTSET, \ @@ -23,7 +23,7 @@ LimitingHandlerMixin, WrapperHandler, FingersCrossedHandler, \ GroupHandler -__version__ = '0.7.0' +__version__ = '0.10.0' # create an anonymous default logger and provide all important # methods of that logger as global functions @@ -38,12 +38,11 @@ exception = _default_logger.exception catch_exceptions = _default_logger.catch_exceptions critical = _default_logger.critical -exception = _default_logger.exception -catch_exceptions = _default_logger.catch_exceptions log = _default_logger.log del _default_logger # install a default global handler -default_handler = StderrHandler() -default_handler.push_application() +if os.environ.get('LOGBOOK_INSTALL_DEFAULT_HANDLER'): + default_handler = StderrHandler() + default_handler.push_application() diff --git a/logbook/_fallback.py b/logbook/_fallback.py index da21923..a5f1631 100644 --- a/logbook/_fallback.py +++ b/logbook/_fallback.py @@ -8,16 +8,15 @@ :copyright: (c) 2010 by Armin Ronacher, Georg Brandl. :license: BSD, see LICENSE for more details. """ -import threading from itertools import count -try: - from thread import get_ident as current_thread -except ImportError: - from _thread import get_ident as current_thread from logbook.helpers import get_iterator_next_method +from logbook.concurrency import (thread_get_ident, greenlet_get_ident, + thread_local, greenlet_local, + ThreadLock, GreenletRLock, is_gevent_enabled) _missing = object() _MAX_CONTEXT_OBJECT_CACHE = 256 + def group_reflected_property(name, default, fallback=_missing): """Returns a property for a given name that falls back to the @@ -58,6 +57,14 @@ operations. """ + def push_greenlet(self): + """Pushes the stacked object to the greenlet stack.""" + raise NotImplementedError() + + def pop_greenlet(self): + """Pops the stacked object from the greenlet stack.""" + raise NotImplementedError() + def push_thread(self): """Pushes the stacked object to the thread stack.""" raise NotImplementedError() @@ -75,11 +82,23 @@ raise NotImplementedError() def __enter__(self): - self.push_thread() + if is_gevent_enabled(): + self.push_greenlet() + else: + self.push_thread() return self def __exit__(self, exc_type, exc_value, tb): - self.pop_thread() + if is_gevent_enabled(): + self.pop_greenlet() + else: + self.pop_thread() + + def greenletbound(self, _cls=_StackBound): + """Can be used in combination with the `with` statement to + execute code while the object is bound to the greenlet. + """ + return _cls(self, self.push_greenlet, self.pop_greenlet) def threadbound(self, _cls=_StackBound): """Can be used in combination with the `with` statement to @@ -101,8 +120,10 @@ def __init__(self): self._global = [] - self._context_lock = threading.Lock() - self._context = threading.local() + self._thread_context_lock = ThreadLock() + self._thread_context = thread_local() + self._greenlet_context_lock = GreenletRLock() + self._greenlet_context = greenlet_local() self._cache = {} self._stackop = get_iterator_next_method(count()) @@ -110,40 +131,66 @@ """Returns an iterator over all objects for the combined application and context cache. """ - tid = current_thread() + use_gevent = is_gevent_enabled() + tid = greenlet_get_ident() if use_gevent else thread_get_ident() objects = self._cache.get(tid) if objects is None: if len(self._cache) > _MAX_CONTEXT_OBJECT_CACHE: self._cache.clear() objects = self._global[:] - objects.extend(getattr(self._context, 'stack', ())) + objects.extend(getattr(self._thread_context, 'stack', ())) + if use_gevent: + objects.extend(getattr(self._greenlet_context, 'stack', ())) objects.sort(reverse=True) objects = [x[1] for x in objects] self._cache[tid] = objects return iter(objects) - def push_thread(self, obj): - self._context_lock.acquire() - try: - self._cache.pop(current_thread(), None) + def push_greenlet(self, obj): + self._greenlet_context_lock.acquire() + try: + self._cache.pop(greenlet_get_ident(), None) # remote chance to conflict with thread ids item = (self._stackop(), obj) - stack = getattr(self._context, 'stack', None) + stack = getattr(self._greenlet_context, 'stack', None) if stack is None: - self._context.stack = [item] + self._greenlet_context.stack = [item] else: stack.append(item) finally: - self._context_lock.release() - - def pop_thread(self): - self._context_lock.acquire() - try: - self._cache.pop(current_thread(), None) - stack = getattr(self._context, 'stack', None) + self._greenlet_context_lock.release() + + def pop_greenlet(self): + self._greenlet_context_lock.acquire() + try: + self._cache.pop(greenlet_get_ident(), None) # remote chance to conflict with thread ids + stack = getattr(self._greenlet_context, 'stack', None) assert stack, 'no objects on stack' return stack.pop()[1] finally: - self._context_lock.release() + self._greenlet_context_lock.release() + + def push_thread(self, obj): + self._thread_context_lock.acquire() + try: + self._cache.pop(thread_get_ident(), None) + item = (self._stackop(), obj) + stack = getattr(self._thread_context, 'stack', None) + if stack is None: + self._thread_context.stack = [item] + else: + stack.append(item) + finally: + self._thread_context_lock.release() + + def pop_thread(self): + self._thread_context_lock.acquire() + try: + self._cache.pop(thread_get_ident(), None) + stack = getattr(self._thread_context, 'stack', None) + assert stack, 'no objects on stack' + return stack.pop()[1] + finally: + self._thread_context_lock.release() def push_application(self, obj): self._global.append((self._stackop(), obj)) diff --git a/logbook/_speedups.pyx b/logbook/_speedups.pyx index 6aff93e..02dbc3e 100644 --- a/logbook/_speedups.pyx +++ b/logbook/_speedups.pyx @@ -9,9 +9,9 @@ :license: BSD, see LICENSE for more details. """ -import thread -import threading import platform +from logbook.concurrency import (is_gevent_enabled, thread_get_ident, greenlet_get_ident, thread_local, + GreenletRLock, greenlet_local) from cpython.dict cimport PyDict_Clear, PyDict_SetItem from cpython.list cimport PyList_New, PyList_Append, PyList_Sort, \ @@ -24,18 +24,16 @@ cdef enum: _MAX_CONTEXT_OBJECT_CACHE = 256 -cdef current_thread = thread.get_ident cdef class group_reflected_property: - cdef char* name - cdef char* _name + cdef object name + cdef object _name cdef object default cdef object fallback - def __init__(self, char* name, object default, object fallback=_missing): + def __init__(self, name, object default, object fallback=_missing): self.name = name - _name = '_' + name - self._name = _name + self._name = '_' + name self.default = default self.fallback = fallback @@ -102,6 +100,14 @@ operations. """ + cpdef push_greenlet(self): + """Pushes the stacked object to the greenlet stack.""" + raise NotImplementedError() + + cpdef pop_greenlet(self): + """Pops the stacked object from the greenlet stack.""" + raise NotImplementedError() + cpdef push_thread(self): """Pushes the stacked object to the thread stack.""" raise NotImplementedError() @@ -119,11 +125,23 @@ raise NotImplementedError() def __enter__(self): - self.push_thread() + if is_gevent_enabled(): + self.push_greenlet() + else: + self.push_thread() return self def __exit__(self, exc_type, exc_value, tb): - self.pop_thread() + if is_gevent_enabled(): + self.pop_greenlet() + else: + self.pop_thread() + + cpdef greenletbound(self): + """Can be used in combination with the `with` statement to + execute code while the object is bound to the greenlet. + """ + return _StackBound(self, self.push_greenlet, self.pop_greenlet) cpdef threadbound(self): """Can be used in combination with the `with` statement to @@ -140,15 +158,19 @@ cdef class ContextStackManager: cdef list _global - cdef PyThread_type_lock _context_lock - cdef object _context + cdef PyThread_type_lock _thread_context_lock + cdef object _thread_context + cdef object _greenlet_context_lock + cdef object _greenlet_context cdef dict _cache cdef int _stackcnt def __init__(self): self._global = [] - self._context_lock = PyThread_allocate_lock() - self._context = threading.local() + self._thread_context_lock = PyThread_allocate_lock() + self._thread_context = thread_local() + self._greenlet_context_lock = GreenletRLock() + self._greenlet_context = greenlet_local() self._cache = {} self._stackcnt = 0 @@ -157,40 +179,66 @@ return self._stackcnt cpdef iter_context_objects(self): - tid = current_thread() + use_gevent = is_gevent_enabled() + tid = greenlet_get_ident() if use_gevent else thread_get_ident() objects = self._cache.get(tid) if objects is None: if PyList_GET_SIZE(self._cache) > _MAX_CONTEXT_OBJECT_CACHE: PyDict_Clear(self._cache) objects = self._global[:] - objects.extend(getattr3(self._context, 'stack', ())) + objects.extend(getattr3(self._thread_context, 'stack', ())) + if use_gevent: + objects.extend(getattr3(self._greenlet_context, 'stack', ())) PyList_Sort(objects) objects = [(<_StackItem>x).val for x in objects] PyDict_SetItem(self._cache, tid, objects) return iter(objects) - cpdef push_thread(self, obj): - PyThread_acquire_lock(self._context_lock, WAIT_LOCK) - try: - self._cache.pop(current_thread(), None) + cpdef push_greenlet(self, obj): + self._greenlet_context_lock.acquire() + try: + self._cache.pop(greenlet_get_ident(), None) item = _StackItem(self._stackop(), obj) - stack = getattr3(self._context, 'stack', None) + stack = getattr3(self._greenlet_context, 'stack', None) if stack is None: - self._context.stack = [item] + self._greenlet_context.stack = [item] else: PyList_Append(stack, item) finally: - PyThread_release_lock(self._context_lock) - - cpdef pop_thread(self): - PyThread_acquire_lock(self._context_lock, WAIT_LOCK) - try: - self._cache.pop(current_thread(), None) - stack = getattr3(self._context, 'stack', None) + self._greenlet_context_lock.release() + + cpdef pop_greenlet(self): + self._greenlet_context_lock.acquire() + try: + self._cache.pop(greenlet_get_ident(), None) + stack = getattr3(self._greenlet_context, 'stack', None) assert stack, 'no objects on stack' return (<_StackItem>stack.pop()).val finally: - PyThread_release_lock(self._context_lock) + self._greenlet_context_lock.release() + + cpdef push_thread(self, obj): + PyThread_acquire_lock(self._thread_context_lock, WAIT_LOCK) + try: + self._cache.pop(thread_get_ident(), None) + item = _StackItem(self._stackop(), obj) + stack = getattr3(self._thread_context, 'stack', None) + if stack is None: + self._thread_context.stack = [item] + else: + PyList_Append(stack, item) + finally: + PyThread_release_lock(self._thread_context_lock) + + cpdef pop_thread(self): + PyThread_acquire_lock(self._thread_context_lock, WAIT_LOCK) + try: + self._cache.pop(thread_get_ident(), None) + stack = getattr3(self._thread_context, 'stack', None) + assert stack, 'no objects on stack' + return (<_StackItem>stack.pop()).val + finally: + PyThread_release_lock(self._thread_context_lock) cpdef push_application(self, obj): self._global.append(_StackItem(self._stackop(), obj)) diff --git a/logbook/base.py b/logbook/base.py index 2c47613..474473a 100644 --- a/logbook/base.py +++ b/logbook/base.py @@ -10,16 +10,12 @@ """ import os import sys -try: - import thread -except ImportError: - # for python 3.1,3.2 - import _thread as thread -import threading import traceback from itertools import chain from weakref import ref as weakref from datetime import datetime +from logbook import helpers +from logbook.concurrency import thread_get_name, thread_get_ident, greenlet_get_ident from logbook.helpers import to_safe_json, parse_iso8601, cached_property, \ PY2, u, string_types, iteritems, integer_types @@ -190,6 +186,15 @@ #: subclasses of it. stack_manager = None + def push_greenlet(self): + """Pushes the context object to the greenlet stack.""" + self.stack_manager.push_greenlet(self) + + def pop_greenlet(self): + """Pops the context object from the stack.""" + popped = self.stack_manager.pop_greenlet() + assert popped is self, 'popped unexpected object' + def push_thread(self): """Pushes the context object to the thread stack.""" self.stack_manager.push_thread(self) @@ -232,6 +237,14 @@ def pop_thread(self): for obj in reversed(self.objects): obj.pop_thread() + + def push_greenlet(self): + for obj in self.objects: + obj.push_greenlet() + + def pop_greenlet(self): + for obj in reversed(self.objects): + obj.pop_greenlet() class Processor(ContextObject): @@ -330,7 +343,7 @@ """ _pullable_information = frozenset(( 'func_name', 'module', 'filename', 'lineno', 'process_name', 'thread', - 'thread_name', 'formatted_exception', 'message', 'exception_name', + 'thread_name', 'greenlet', 'formatted_exception', 'message', 'exception_name', 'exception_message' )) _noned_on_close = frozenset(('exc_info', 'frame', 'calling_frame')) @@ -356,7 +369,7 @@ information_pulled = False def __init__(self, channel, level, msg, args=None, kwargs=None, - exc_info=None, extra=None, frame=None, dispatcher=None): + exc_info=None, extra=None, frame=None, dispatcher=None, frame_correction=0): #: the name of the logger that created it or any other textual #: channel description. This is a descriptive name and can be #: used for filtering. @@ -384,6 +397,11 @@ #: Might not be available for all calls and is removed when the log #: record is closed. self.frame = frame + #: A positive integer telling the number of frames to go back from + #: the frame which triggered the log entry. This is mainly useful + #: for decorators that want to show that the log was emitted from + #: form the function they decorate + self.frame_correction = frame_correction #: the PID of the current process self.process = None if dispatcher is not None: @@ -477,6 +495,12 @@ self.extra = ExtraDict(self.extra) return self + def _format_message(self, msg, *args, **kwargs): + """Called if the record's message needs to be formatted. + Subclasses can implement their own formatting. + """ + return msg.format(*args, **kwargs) + @cached_property def message(self): """The formatted message.""" @@ -484,11 +508,11 @@ return self.msg try: try: - return self.msg.format(*self.args, **self.kwargs) + return self._format_message(self.msg, *self.args, **self.kwargs) except UnicodeDecodeError: # Assume an unicode message but mixed-up args msg = self.msg.encode('utf-8', 'replace') - return msg.format(*self.args, **self.kwargs) + return self._format_message(msg, *self.args, **self.kwargs) except (UnicodeEncodeError, AttributeError): # we catch AttributeError since if msg is bytes, it won't have the 'format' method if sys.exc_info()[0] is AttributeError and (PY2 or not isinstance(self.msg, bytes)): @@ -499,7 +523,7 @@ # but this codepath is unlikely (if the message is a constant # string in the caller's source file) msg = self.msg.decode('utf-8', 'replace') - return msg.format(*self.args, **self.kwargs) + return self._format_message(msg, *self.args, **self.kwargs) except Exception: # this obviously will not give a proper error message if the @@ -530,6 +554,10 @@ globs = globals() while frm is not None and frm.f_globals is globs: frm = frm.f_back + + for _ in helpers.xrange(self.frame_correction): + frm = frm.f_back + return frm @cached_property @@ -574,12 +602,20 @@ return cf.f_lineno @cached_property + def greenlet(self): + """The ident of the greenlet. This is evaluated late and means that + if the log record is passed to another greenlet, :meth:`pull_information` + was called in the old greenlet. + """ + return greenlet_get_ident() + + @cached_property def thread(self): """The ident of the thread. This is evaluated late and means that if the log record is passed to another thread, :meth:`pull_information` was called in the old thread. """ - return thread.get_ident() + return thread_get_ident() @cached_property def thread_name(self): @@ -587,7 +623,7 @@ if the log record is passed to another thread, :meth:`pull_information` was called in the old thread. """ - return threading.currentThread().getName() + return thread_get_name() @cached_property def process_name(self): @@ -608,7 +644,7 @@ """The formatted exception which caused this record to be created in case there was any. """ - if self.exc_info is not None: + if self.exc_info is not None and self.exc_info != (None, None, None): rv = ''.join(traceback.format_exception(*self.exc_info)) if PY2: rv = rv.decode('utf-8', 'replace') @@ -632,7 +668,10 @@ if self.exc_info is not None: val = self.exc_info[1] try: - return u(str(val)) + if PY2: + return unicode(val) + else: + return str(val) except UnicodeError: return str(val).decode('utf-8', 'replace') @@ -748,8 +787,9 @@ def _log(self, level, args, kwargs): exc_info = kwargs.pop('exc_info', None) extra = kwargs.pop('extra', None) + frame_correction = kwargs.pop('frame_correction', 0) self.make_record_and_handle(level, args[0], args[1:], kwargs, - exc_info, extra) + exc_info, extra, frame_correction) class RecordDispatcher(object): @@ -786,7 +826,7 @@ self.call_handlers(record) def make_record_and_handle(self, level, msg, args, kwargs, exc_info, - extra): + extra, frame_correction): """Creates a record from some given arguments and heads it over to the handling system. """ @@ -800,7 +840,7 @@ channel = self record = LogRecord(self.name, level, msg, args, kwargs, exc_info, - extra, None, channel) + extra, None, channel, frame_correction) # after handling the log record is closed which will remove some # referenes that would require a GC run on cpython. This includes @@ -843,6 +883,21 @@ if not handler.should_handle(record): continue + # first case of blackhole (without filter). + # this should discard all further processing and we don't have to heavy_init to know that... + if handler.filter is None and handler.blackhole: + break + + # we are about to handle the record. If it was not yet + # processed by context-specific record processors we + # have to do that now and remeber that we processed + # the record already. + if not record_initialized: + record.heavy_init() + self.process_record(record) + record_initialized = True + + # a filter can still veto the handling of the record. This # however is already operating on an initialized and processed # record. The impact is that filters are slower than the @@ -852,26 +907,11 @@ and not handler.filter(record, handler): continue - # if this is a blackhole handler, don't even try to - # do further processing, stop right away. Technically - # speaking this is not 100% correct because if the handler - # is bubbling we shouldn't apply this logic, but then we - # won't enter this branch anyways. The result is that a - # bubbling blackhole handler will never have this shortcut - # applied and do the heavy init at one point. This is fine - # however because a bubbling blackhole handler is not very - # useful in general. + # We might have a filter, so now that we know we *should* handle + # this record, we should consider the case of us being a black hole... if handler.blackhole: break - # we are about to handle the record. If it was not yet - # processed by context-specific record processors we - # have to do that now and remeber that we processed - # the record already. - if not record_initialized: - record.heavy_init() - self.process_record(record) - record_initialized = True # handle the record. If the record was handled and # the record is not bubbling we can abort now. diff --git a/logbook/compat.py b/logbook/compat.py index 548e2a5..0b42caf 100644 --- a/logbook/compat.py +++ b/logbook/compat.py @@ -57,6 +57,13 @@ __enter__ = start __exit__ = end + + +class LoggingCompatRecord(logbook.LogRecord): + + def _format_message(self, msg, *args, **kwargs): + assert not kwargs + return msg % tuple(args) class RedirectLoggingHandler(logging.Handler): @@ -93,7 +100,7 @@ 'pathname', 'filename', 'module', 'exc_info', 'exc_text', 'lineno', 'funcName', 'created', 'msecs', 'relativeCreated', 'thread', 'threadName', - 'processName', 'process'): + 'greenlet', 'processName', 'process'): rv.pop(key, None) return rv @@ -116,10 +123,10 @@ def convert_record(self, old_record): """Converts an old logging record into a logbook log record.""" - record = logbook.LogRecord(old_record.name, + record = LoggingCompatRecord(old_record.name, self.convert_level(old_record.levelno), - old_record.getMessage(), - None, None, old_record.exc_info, + old_record.msg, old_record.args, + None, old_record.exc_info, self.find_extra(old_record), self.find_caller(old_record)) record.time = self.convert_time(old_record.created) diff --git a/logbook/concurrency.py b/logbook/concurrency.py new file mode 100644 index 0000000..80af112 --- /dev/null +++ b/logbook/concurrency.py @@ -0,0 +1,148 @@ +has_gevent = True +use_gevent = False +try: + import gevent + + def enable_gevent(): + global use_gevent + use_gevent = True + + def _disable_gevent(): # for testing + global use_gevent + use_gevent = False + + def is_gevent_enabled(): + global use_gevent + return use_gevent +except ImportError: + has_gevent = False + + def enable_gevent(): + pass + + def _disable_gevent(): + pass + + def is_gevent_enabled(): + return False + + +if has_gevent: + from gevent._threading import (Lock as ThreadLock, + RLock as ThreadRLock, + get_ident as thread_get_ident, + local as thread_local) + from gevent.thread import get_ident as greenlet_get_ident + from gevent.local import local as greenlet_local + from gevent.lock import BoundedSemaphore + from gevent.threading import __threading__ + + def thread_get_name(): + return __threading__.currentThread().getName() + + class GreenletRLock(object): + def __init__(self): + self._thread_local = thread_local() + self._owner = None + self._wait_queue = [] + self._count = 0 + + def __repr__(self): + owner = self._owner + return "<%s owner=%r count=%d>" % (self.__class__.__name__, owner, self._count) + + def acquire(self, blocking=1): + tid = thread_get_ident() + gid = greenlet_get_ident() + tid_gid = (tid, gid) + if tid_gid == self._owner: # We trust the GIL here so we can do this comparison w/o locking. + self._count = self._count + 1 + return True + + greenlet_lock = self._get_greenlet_lock() + + self._wait_queue.append(gid) + # this is a safety in case an exception is raised somewhere and we must make sure we're not in the queue + # otherwise it'll get stuck forever. + remove_from_queue_on_return = True + try: + while True: + if not greenlet_lock.acquire(blocking): + return False # non-blocking and failed to acquire lock + + if self._wait_queue[0] == gid: + # Hurray, we can have the lock. + self._owner = tid_gid + self._count = 1 + remove_from_queue_on_return = False # don't remove us from the queue + return True + else: + # we already hold the greenlet lock so obviously the owner is not in our thread. + greenlet_lock.release() + if blocking: + gevent.sleep(0.0005) # 500 us -> initial delay of 1 ms + else: + return False + finally: + if remove_from_queue_on_return: + self._wait_queue.remove(gid) + + def release(self): + tid_gid = (thread_get_ident(), greenlet_get_ident()) + if tid_gid != self._owner: + raise RuntimeError("cannot release un-acquired lock") + + self._count = self._count - 1 + if not self._count: + self._owner = None + gid = self._wait_queue.pop(0) + assert gid == tid_gid[1] + self._thread_local.greenlet_lock.release() + + __enter__ = acquire + + def __exit__(self, t, v, tb): + self.release() + + def _get_greenlet_lock(self): + if not hasattr(self._thread_local, 'greenlet_lock'): + greenlet_lock = self._thread_local.greenlet_lock = BoundedSemaphore(1) + else: + greenlet_lock = self._thread_local.greenlet_lock + return greenlet_lock + + def _is_owned(self): + return self._owner == (thread_get_ident(), greenlet_get_ident()) +else: + from threading import Lock as ThreadLock, RLock as ThreadRLock, currentThread + try: + from thread import get_ident as thread_get_ident, _local as thread_local + except ImportError: + from _thread import get_ident as thread_get_ident, _local as thread_local + + def thread_get_name(): + return currentThread().getName() + + greenlet_get_ident = thread_get_ident + + greenlet_local = thread_local + + class GreenletRLock(object): + def acquire(self): + pass + + def release(self): + pass + + def __enter__(self): + pass + + def __exit__(self, t, v, tb): + pass + +def new_fine_grained_lock(): + global use_gevent + if use_gevent: + return GreenletRLock() + else: + return ThreadRLock() diff --git a/logbook/handlers.py b/logbook/handlers.py index e89f410..76a9e6c 100644 --- a/logbook/handlers.py +++ b/logbook/handlers.py @@ -18,21 +18,21 @@ from hashlib import sha1 except ImportError: from sha import new as sha1 -import threading import traceback from datetime import datetime, timedelta -from threading import Lock from collections import deque + +from six import add_metaclass from logbook.base import CRITICAL, ERROR, WARNING, NOTICE, INFO, DEBUG, \ NOTSET, level_name_property, _missing, lookup_level, \ Flags, ContextObject, ContextStackManager from logbook.helpers import rename, b, _is_text_stream, is_unicode, PY2, \ zip, xrange, string_types, integer_types, reraise, u - +from logbook.concurrency import new_fine_grained_lock DEFAULT_FORMAT_STRING = ( - u('[{record.time:%Y-%m-%d %H:%M}] ') + + u('[{record.time:%Y-%m-%d %H:%M:%S.%f}] ') + u('{record.level_name}: {record.channel}: {record.message}') ) SYSLOG_FORMAT_STRING = u('{record.channel}: {record.message}') @@ -107,6 +107,7 @@ return type.__new__(cls, name, bases, d) +@add_metaclass(_HandlerType) class Handler(ContextObject): """Handler instances dispatch logging events to specific destinations. @@ -115,10 +116,10 @@ records as desired. By default, no formatter is specified; in this case, the 'raw' message as determined by record.message is logged. - To bind a handler you can use the :meth:`push_application` and - :meth:`push_thread` methods. This will push the handler on a stack of - handlers. To undo this, use the :meth:`pop_application` and - :meth:`pop_thread` methods:: + To bind a handler you can use the :meth:`push_application`, + :meth:`push_thread` or :meth:`push_greenlet` methods. This will push the handler on a stack of + handlers. To undo this, use the :meth:`pop_application`, + :meth:`pop_thread` methods and :meth:`pop_greenlet`:: handler = MyHandler() handler.push_application() @@ -127,16 +128,7 @@ By default messages sent to that handler will not go to a handler on an outer level on the stack, if handled. This can be changed by - setting bubbling to `True`. This setup for example would not have - any effect:: - - handler = NullHandler(bubble=True) - handler.push_application() - - Whereas this setup disables all logging for the application:: - - handler = NullHandler() - handler.push_application() + setting bubbling to `True`. There are also context managers to setup the handler for the duration of a `with`-block:: @@ -147,14 +139,17 @@ with handler.threadbound(): ... + with handler.greenletbound(): + ... + Because `threadbound` is a common operation, it is aliased to a with - on the handler itself:: + on the handler itself if not using gevent:: with handler: ... - """ - __metaclass__ = _HandlerType - + + If gevent is enabled, the handler is aliased to `greenletbound`. + """ stack_manager = ContextStackManager() #: a flag for this handler that can be set to `True` for handlers that @@ -300,8 +295,15 @@ class NullHandler(Handler): - """A handler that does nothing, meant to be inserted in a handler chain - with ``bubble=False`` to stop further processing. + """A handler that does nothing. + + Useful to silence logs above a certain location in the handler stack:: + + handler = NullHandler() + handler.push_application() + + NullHandlers swallow all logs sent to them, and do not bubble them onwards. + """ blackhole = True @@ -451,7 +453,7 @@ def __init__(self, record_limit, record_delta): self.record_limit = record_limit - self._limit_lock = Lock() + self._limit_lock = new_fine_grained_lock() self._record_limits = {} if record_delta is None: record_delta = timedelta(seconds=60) @@ -521,7 +523,7 @@ Handler.__init__(self, level, filter, bubble) StringFormatterHandlerMixin.__init__(self, format_string) self.encoding = encoding - self.lock = threading.Lock() + self.lock = new_fine_grained_lock() if stream is not _missing: self.stream = stream @@ -531,6 +533,12 @@ def __exit__(self, exc_type, exc_value, tb): self.close() return Handler.__exit__(self, exc_type, exc_value, tb) + + def ensure_stream_is_open(self): + """this method should be overriden in sub-classes to ensure that the + inner stream is open + """ + pass def close(self): """The default stream handler implementation is not to close @@ -543,10 +551,10 @@ if self.stream is not None and hasattr(self.stream, 'flush'): self.stream.flush() - def format_and_encode(self, record): - """Formats the record and encodes it to the stream encoding.""" + def encode(self, msg): + """Encodes the message to the stream encoding.""" stream = self.stream - rv = self.format(record) + '\n' + rv = msg + '\n' if (PY2 and is_unicode(rv)) or \ not (PY2 or is_unicode(rv) or _is_text_stream(stream)): enc = self.encoding @@ -560,9 +568,11 @@ self.stream.write(item) def emit(self, record): + msg = self.format(record) self.lock.acquire() try: - self.write(self.format_and_encode(record)) + self.ensure_stream_is_open() + self.write(self.encode(msg)) self.flush() finally: self.lock.release() @@ -596,30 +606,31 @@ self.stream = open(self._filename, mode) def write(self, item): - if self.stream is None: - self._open() + self.ensure_stream_is_open() if not PY2 and isinstance(item, bytes): self.stream.buffer.write(item) else: self.stream.write(item) def close(self): - if self.stream is not None: - self.flush() - self.stream.close() - self.stream = None - - def format_and_encode(self, record): + self.lock.acquire() + try: + if self.stream is not None: + self.flush() + self.stream.close() + self.stream = None + finally: + self.lock.release() + + def encode(self, record): # encodes based on the stream settings, so the stream has to be # open at the time this function is called. + self.ensure_stream_is_open() + return StreamHandler.encode(self, record) + + def ensure_stream_is_open(self): if self.stream is None: self._open() - return StreamHandler.format_and_encode(self, record) - - def emit(self, record): - if self.stream is None: - self._open() - StreamHandler.emit(self, record) class MonitoringFileHandler(FileHandler): @@ -655,12 +666,21 @@ self._last_stat = st[stat.ST_DEV], st[stat.ST_INO] def emit(self, record): - last_stat = self._last_stat - self._query_fd() - if last_stat != self._last_stat: - self.close() - FileHandler.emit(self, record) - self._query_fd() + msg = self.format(record) + self.lock.acquire() + try: + last_stat = self._last_stat + self._query_fd() + if last_stat != self._last_stat and self.stream is not None: + self.flush() + self.stream.close() + self.stream = None + self.ensure_stream_is_open() + self.write(self.encode(msg)) + self.flush() + self._query_fd() + finally: + self.lock.release() class StderrHandler(StreamHandler): @@ -680,49 +700,6 @@ @property def stream(self): return sys.stderr - - -class RotatingFileHandlerBase(FileHandler): - """Baseclass for rotating file handlers. - - .. versionchanged:: 0.3 - This class was deprecated because the interface is not flexible - enough to implement proper file rotations. The former builtin - subclasses no longer use this baseclass. - """ - - def __init__(self, *args, **kwargs): - from warnings import warn - warn(DeprecationWarning('This class is deprecated')) - FileHandler.__init__(self, *args, **kwargs) - - def emit(self, record): - self.lock.acquire() - try: - msg = self.format_and_encode(record) - if self.should_rollover(record, msg): - self.perform_rollover() - self.write(msg) - self.flush() - finally: - self.lock.release() - - def should_rollover(self, record, formatted_record): - """Called with the log record and the return value of the - :meth:`format_and_encode` method. The method has then to - return `True` if a rollover should happen or `False` - otherwise. - - .. versionchanged:: 0.3 - Previously this method was called with the number of bytes - returned by :meth:`format_and_encode` - """ - return False - - def perform_rollover(self): - """Called if :meth:`should_rollover` returns `True` and has - to perform the actual rollover. - """ class RotatingFileHandler(FileHandler): @@ -768,9 +745,10 @@ self._open('w') def emit(self, record): + msg = self.format(record) self.lock.acquire() try: - msg = self.format_and_encode(record) + msg = self.encode(msg) if self.should_rollover(record, len(msg)): self.perform_rollover() self.write(msg) @@ -832,7 +810,8 @@ filename.endswith(self._fn_parts[1]): files.append((os.path.getmtime(filename), filename)) files.sort() - return files[:-self.backup_count + 1] + return files[:-self.backup_count + 1] if self.backup_count > 1\ + else files[:] def perform_rollover(self): self.stream.close() @@ -842,11 +821,12 @@ self._open('w') def emit(self, record): + msg = self.format(record) self.lock.acquire() try: if self.should_rollover(record): self.perform_rollover() - self.write(self.format_and_encode(record)) + self.write(self.encode(msg)) self.flush() finally: self.lock.release() @@ -1199,7 +1179,7 @@ def emit_batch(self, records, reason): if reason not in ('escalation', 'group'): - return MailHandler.emit_batch(self, records, reason) + raise RuntimeError("reason must be either 'escalation' or 'group'") records = list(records) if not records: return @@ -1496,7 +1476,7 @@ handler when a severity theshold was reached with the buffer emitting. This now enables this logger to be properly used with the :class:`~logbook.MailHandler`. You will now only get one mail for - each bfufered record. However once the threshold was reached you would + each buffered record. However once the threshold was reached you would still get a mail for each record which is why the `reset` flag was added. When set to `True`, the handler will instantly reset to the untriggered @@ -1520,7 +1500,7 @@ pull_information=True, reset=False, filter=None, bubble=False): Handler.__init__(self, NOTSET, filter, bubble) - self.lock = Lock() + self.lock = new_fine_grained_lock() self._level = action_level if isinstance(handler, Handler): self._handler = handler @@ -1626,6 +1606,10 @@ Handler.pop_thread(self) self.rollover() + def pop_greenlet(self): + Handler.pop_greenlet(self) + self.rollover() + def emit(self, record): if self.pull_information: record.pull_information() diff --git a/logbook/more.py b/logbook/more.py index 9e65bfb..c43634a 100644 --- a/logbook/more.py +++ b/logbook/more.py @@ -12,6 +12,7 @@ import os from collections import defaultdict from cgi import parse_qsl +from functools import partial from logbook.base import RecordDispatcher, dispatch_record, NOTSET, ERROR, NOTICE from logbook.handlers import Handler, StringFormatter, \ @@ -104,8 +105,8 @@ def __init__(self, name=None, tags=None): RecordDispatcher.__init__(self, name) # create a method for each tag named - list(setattr(self, tag, lambda msg, *args, **kwargs: - self.log(tag, msg, *args, **kwargs)) for tag in (tags or ())) + for tag in (tags or ()): + setattr(self, tag, partial(self.log, tag)) def log(self, tags, msg, *args, **kwargs): if isinstance(tags, string_types): @@ -113,8 +114,9 @@ exc_info = kwargs.pop('exc_info', None) extra = kwargs.pop('extra', {}) extra['tags'] = list(tags) + frame_correction = kwargs.pop('frame_correction', 0) return self.make_record_and_handle(NOTSET, msg, args, kwargs, - exc_info, extra) + exc_info, extra, frame_correction) class TaggingHandler(Handler): @@ -304,9 +306,8 @@ return 'yellow' return 'lightgray' - def format_and_encode(self, record): - rv = super(ColorizingStreamHandlerMixin, self) \ - .format_and_encode(record) + def format(self, record): + rv = super(ColorizingStreamHandlerMixin, self).format(record) if self.should_colorize(record): color = self.get_color(record) if color: @@ -379,7 +380,7 @@ Handler.__init__(self, bubble=False, *args, **kwargs) self._format_string = format_string self.clear() - + def clear(self): self._message_to_count = defaultdict(int) self._unique_ordered_records = [] @@ -390,6 +391,10 @@ def pop_thread(self): Handler.pop_thread(self) + self.flush() + + def pop_greenlet(self): + Handler.pop_greenlet(self) self.flush() def handle(self, record): diff --git a/logbook/notifiers.py b/logbook/notifiers.py index e7a4346..cf94023 100644 --- a/logbook/notifiers.py +++ b/logbook/notifiers.py @@ -259,3 +259,60 @@ self._notifo.send_notification(self.username, self.secret, None, record.message, self.application_name, _level_name, None) + + +class PushoverHandler(NotificationBaseHandler): + """Sends notifications to pushover.net. Can be forwarded to your Desktop, + iPhone, or other compatible device. If `priority` is not one of -2, -1, 0, + or 1, it is set to 0 automatically. + """ + + def __init__(self, application_name=None, apikey=None, userkey=None, + device=None, priority=0, sound=None, record_limit=None, + record_delta=None, level=NOTSET, filter=None, bubble=False): + + super(PushoverHandler, self).__init__(None, record_limit, record_delta, + level, filter, bubble) + + self.application_name = application_name + self.apikey = apikey + self.userkey = userkey + self.device = device + self.priority = priority + self.sound = sound + + if self.application_name is None: + self.title = None + elif len(self.application_name) > 100: + self.title = "%s..." % (self.application_name[:-3],) + else: + self.title = self.application_name + + if self.priority not in [-2, -1, 0, 1]: + self.priority = 0 + + def emit(self, record): + + if len(record.message) > 512: + message = "%s..." % (record.message[:-3],) + else: + message = record.message + + body_dict = { + 'token': self.apikey, + 'user': self.userkey, + 'message': message, + 'priority': self.priority + } + + if self.title is not None: + body_dict['title'] = self.title + if self.device is not None: + body_dict['device'] = self.device + if self.sound is not None: + body_dict['sound'] = self.sound + + body = urlencode(body_dict) + con = http_client.HTTPSConnection('api.pushover.net') + con.request('POST', '/1/messages.json', body=body) + con.close() diff --git a/logbook/queues.py b/logbook/queues.py index 78cdd0e..8c6cb52 100644 --- a/logbook/queues.py +++ b/logbook/queues.py @@ -17,9 +17,9 @@ from logbook.helpers import PY2, u if PY2: - from Queue import Empty, Queue as ThreadQueue + from Queue import Empty, Full, Queue as ThreadQueue else: - from queue import Empty, Queue as ThreadQueue + from queue import Empty, Full, Queue as ThreadQueue class RedisHandler(Handler): @@ -44,7 +44,7 @@ """ def __init__(self, host='127.0.0.1', port=6379, key='redis', extra_fields={}, flush_threshold=128, flush_time=1, level=NOTSET, filter=None, - password=False, bubble=True, context=None): + password=False, bubble=True, context=None, push_method='rpush'): Handler.__init__(self, level, filter, bubble) try: import redis @@ -63,6 +63,7 @@ self.flush_threshold = flush_threshold self.queue = [] self.lock = Lock() + self.push_method = push_method #Set up a thread that flushes the queue every specified seconds self._stop_event = threading.Event() @@ -85,9 +86,11 @@ """Flushes the messaging queue into Redis. All values are pushed at once for the same key. + + The method rpush/lpush is defined by push_method argument """ if self.queue: - self.redis.rpush(self.key, *self.queue) + getattr(self.redis, self.push_method)(self.key, *self.queue) self.queue = [] @@ -108,7 +111,10 @@ are also appended to the message. """ with self.lock: - r = {"message": record.msg, "host": platform.node(), "level": record.level_name} + r = {"message": record.msg, + "host": platform.node(), + "level": record.level_name, + "time": record.time.isoformat()} r.update(self.extra_fields) r.update(record.kwargs) self.queue.append(json.dumps(r)) @@ -208,8 +214,17 @@ def emit(self, record): self.socket.send(json.dumps(self.export_record(record)).encode("utf-8")) - def close(self): - self.socket.close() + def close(self, linger=-1): + self.socket.close(linger) + + def __del__(self): + # When the Handler is deleted we must close our socket in a non-blocking + # fashion (using linger). + # Otherwise it can block indefinitely, for example if the Subscriber is + # not reachable. + # If messages are pending on the socket, we wait 100ms for them to be sent + # then we discard them. + self.close(linger=100) class ThreadController(object): @@ -623,9 +638,9 @@ """ _direct_attrs = frozenset(['handler', 'queue', 'controller']) - def __init__(self, handler): + def __init__(self, handler, maxsize=0): WrapperHandler.__init__(self, handler) - self.queue = ThreadQueue(-1) + self.queue = ThreadQueue(maxsize) self.controller = TWHThreadController(self) self.controller.start() @@ -634,7 +649,11 @@ self.handler.close() def emit(self, record): - self.queue.put_nowait(record) + try: + self.queue.put_nowait(record) + except Full: + # silently drop + pass class GroupMember(ThreadController): diff --git a/scripts/test_setup.py b/scripts/test_setup.py index 8bebeaa..c586d61 100644 --- a/scripts/test_setup.py +++ b/scripts/test_setup.py @@ -13,13 +13,11 @@ deps = [ "execnet>=1.0.9", - "nose", + "pytest", "pyzmq", "sqlalchemy", ] - if python_version < (2, 7): - deps.append("unittest2") if (3, 2) <= python_version < (3, 3): deps.append("markupsafe==0.15") deps.append("Jinja2==2.6") diff --git a/setup.py b/setup.py index 5cf2417..4162d1a 100644 --- a/setup.py +++ b/setup.py @@ -106,7 +106,7 @@ features['speedups'] = speedups setup( name='Logbook', - version='0.7.0', + version='0.10.0', license='BSD', url='http://logbook.pocoo.org/', author='Armin Ronacher, Georg Brandl', @@ -119,6 +119,7 @@ cmdclass=cmdclass, features=features, install_requires=[ + 'six>=1.4.0', ], **extra ) diff --git a/tests/__init__.py b/tests/__init__.py index 8b13789..e69de29 100644 --- a/tests/__init__.py +++ b/tests/__init__.py @@ -1 +0,0 @@ - diff --git a/tests/conftest.py b/tests/conftest.py new file mode 100644 index 0000000..71f24f7 --- /dev/null +++ b/tests/conftest.py @@ -0,0 +1,106 @@ +import logbook +import pytest + +logbook.StderrHandler().push_application() + +@pytest.fixture +def logger(): + return logbook.Logger('testlogger') + + +@pytest.fixture +def active_handler(request, test_handler, activation_strategy): + + s = activation_strategy(test_handler) + s.activate() + + @request.addfinalizer + def deactivate(): + s.deactivate() + + return test_handler + + +@pytest.fixture +def test_handler(): + return logbook.TestHandler() + + +class ActivationStrategy(object): + + def __init__(self, handler): + super(ActivationStrategy, self).__init__() + self.handler = handler + + def activate(self): + raise NotImplementedError() # pragma: no cover + + def deactivate(self): + raise NotImplementedError() # pragma: no cover + + def __enter__(self): + self.activate() + return self.handler + + def __exit__(self, *_): + self.deactivate() + + +class ContextEnteringStrategy(ActivationStrategy): + + def activate(self): + self.handler.__enter__() + + def deactivate(self): + self.handler.__exit__(None, None, None) + + +class PushingStrategy(ActivationStrategy): + + def activate(self): + from logbook.concurrency import is_gevent_enabled + if is_gevent_enabled(): + self.handler.push_greenlet() + else: + self.handler.push_thread() + + def deactivate(self): + from logbook.concurrency import is_gevent_enabled + if is_gevent_enabled(): + self.handler.pop_greenlet() + else: + self.handler.pop_thread() + + +@pytest.fixture(params=[ContextEnteringStrategy, PushingStrategy]) +def activation_strategy(request): + return request.param + + +@pytest.fixture +def logfile(tmpdir): + return str(tmpdir.join('logfile.log')) + + +@pytest.fixture +def default_handler(request): + returned = logbook.StderrHandler() + returned.push_application() + request.addfinalizer(returned.pop_application) + return returned + +try: + import gevent + + @pytest.fixture(scope="module", autouse=True, params=[False, True]) + def gevent(request): + module_name = getattr(request.module, '__name__', '') + if not any(s in module_name for s in ('queues', 'processors')) and request.param: + from logbook.concurrency import enable_gevent, _disable_gevent + enable_gevent() + + @request.addfinalizer + def fin(): + _disable_gevent() +except ImportError: + pass diff --git a/tests/test_deadlock.py b/tests/test_deadlock.py new file mode 100644 index 0000000..bd066f3 --- /dev/null +++ b/tests/test_deadlock.py @@ -0,0 +1,35 @@ +import sys +import logbook + + +class MyObject(object): + def __init__(self, logger_func): + self._logger_func = logger_func + + def __str__(self): + self._logger_func("this debug message produced in __str__") + return "" + + +class FakeLock(object): + def __init__(self): + self._acquired = False + self._deadlock_occurred = False + + def acquire(self): + if self._acquired: + self._deadlock_occurred = True + self._acquired = True + + def release(self): + self._acquired = False + + +def test_deadlock_in_emit(): + logbook_logger = logbook.Logger("logbook") + obj = MyObject(logbook_logger.info) + stream_handler = logbook.StreamHandler(stream=sys.stderr, level=logbook.DEBUG) + stream_handler.lock = FakeLock() + with stream_handler.applicationbound(): + logbook_logger.info("format this: {}", obj) + assert not stream_handler.lock._deadlock_occurred diff --git a/tests/test_file_handler.py b/tests/test_file_handler.py new file mode 100644 index 0000000..6feed07 --- /dev/null +++ b/tests/test_file_handler.py @@ -0,0 +1,123 @@ +import os +import pytest +from datetime import datetime + +import logbook +from logbook.helpers import u, xrange + +from .utils import capturing_stderr_context, LETTERS + + +def test_file_handler(logfile, activation_strategy, logger): + handler = logbook.FileHandler(logfile, + format_string='{record.level_name}:{record.channel}:' + '{record.message}',) + with activation_strategy(handler): + logger.warn('warning message') + handler.close() + with open(logfile) as f: + assert f.readline() == 'WARNING:testlogger:warning message\n' + + +def test_file_handler_unicode(logfile, activation_strategy, logger): + with capturing_stderr_context() as captured: + with activation_strategy(logbook.FileHandler(logfile)): + logger.info(u('\u0431')) + assert (not captured.getvalue()) + + +def test_file_handler_delay(logfile, activation_strategy, logger): + handler = logbook.FileHandler(logfile, + format_string='{record.level_name}:{record.channel}:' + '{record.message}', delay=True) + assert (not os.path.isfile(logfile)) + with activation_strategy(handler): + logger.warn('warning message') + handler.close() + + with open(logfile) as f: + assert f.readline() == 'WARNING:testlogger:warning message\n' + + +def test_monitoring_file_handler(logfile, activation_strategy, logger): + if os.name == 'nt': + pytest.skip('unsupported on windows due to different IO (also unneeded)') + handler = logbook.MonitoringFileHandler(logfile, + format_string='{record.level_name}:{record.channel}:' + '{record.message}', delay=True) + with activation_strategy(handler): + logger.warn('warning message') + os.rename(logfile, logfile + '.old') + logger.warn('another warning message') + handler.close() + with open(logfile) as f: + assert f.read().strip() == 'WARNING:testlogger:another warning message' + + +def test_custom_formatter(activation_strategy, logfile, logger): + def custom_format(record, handler): + return record.level_name + ':' + record.message + + handler = logbook.FileHandler(logfile) + with activation_strategy(handler): + handler.formatter = custom_format + logger.warn('Custom formatters are awesome') + + with open(logfile) as f: + assert f.readline() == 'WARNING:Custom formatters are awesome\n' + + +def test_rotating_file_handler(logfile, activation_strategy, logger): + basename = os.path.basename(logfile) + handler = logbook.RotatingFileHandler(logfile, max_size=2048, + backup_count=3, + ) + handler.format_string = '{record.message}' + with activation_strategy(handler): + for c, x in zip(LETTERS, xrange(32)): + logger.warn(c * 256) + files = [x for x in os.listdir(os.path.dirname(logfile)) + if x.startswith(basename)] + files.sort() + + assert files == [basename, basename + '.1', basename + '.2', basename + '.3'] + with open(logfile) as f: + assert f.readline().rstrip() == ('C' * 256) + assert f.readline().rstrip() == ('D' * 256) + assert f.readline().rstrip() == ('E' * 256) + assert f.readline().rstrip() == ('F' * 256) + + +@pytest.mark.parametrize("backup_count", [1, 3]) +def test_timed_rotating_file_handler(tmpdir, activation_strategy, backup_count): + basename = str(tmpdir.join('trot.log')) + handler = logbook.TimedRotatingFileHandler(basename, backup_count=backup_count) + handler.format_string = '[{record.time:%H:%M}] {record.message}' + + def fake_record(message, year, month, day, hour=0, + minute=0, second=0): + lr = logbook.LogRecord('Test Logger', logbook.WARNING, + message) + lr.time = datetime(year, month, day, hour, minute, second) + return lr + + with activation_strategy(handler): + for x in xrange(10): + handler.handle(fake_record('First One', 2010, 1, 5, x + 1)) + for x in xrange(20): + handler.handle(fake_record('Second One', 2010, 1, 6, x + 1)) + for x in xrange(10): + handler.handle(fake_record('Third One', 2010, 1, 7, x + 1)) + for x in xrange(20): + handler.handle(fake_record('Last One', 2010, 1, 8, x + 1)) + + files = sorted(x for x in os.listdir(str(tmpdir)) if x.startswith('trot')) + + assert files == ['trot-2010-01-0{0}.log'.format(i) for i in xrange(5, 9)][-backup_count:] + with open(str(tmpdir.join('trot-2010-01-08.log'))) as f: + assert f.readline().rstrip() == '[01:00] Last One' + assert f.readline().rstrip() == '[02:00] Last One' + if backup_count > 1: + with open(str(tmpdir.join('trot-2010-01-07.log'))) as f: + assert f.readline().rstrip() == '[01:00] Third One' + assert f.readline().rstrip() == '[02:00] Third One' diff --git a/tests/test_fingers_crossed_handler.py b/tests/test_fingers_crossed_handler.py new file mode 100644 index 0000000..a2644cc --- /dev/null +++ b/tests/test_fingers_crossed_handler.py @@ -0,0 +1,77 @@ +import logbook +import pytest + +from .utils import capturing_stderr_context + + +def test_fingerscrossed(activation_strategy, logger, default_handler): + handler = logbook.FingersCrossedHandler(default_handler, + logbook.WARNING) + + # if no warning occurs, the infos are not logged + with activation_strategy(handler): + with capturing_stderr_context() as captured: + logger.info('some info') + assert captured.getvalue() == '' + assert (not handler.triggered) + + # but if it does, all log messages are output + with activation_strategy(handler): + with capturing_stderr_context() as captured: + logger.info('some info') + logger.warning('something happened') + logger.info('something else happened') + logs = captured.getvalue() + assert 'some info' in logs + assert 'something happened' in logs + assert 'something else happened' in logs + assert handler.triggered + + +def test_fingerscrossed_factory(activation_strategy, logger): + handlers = [] + + def handler_factory(record, fch): + handler = logbook.TestHandler() + handlers.append(handler) + return handler + + def make_fch(): + return logbook.FingersCrossedHandler(handler_factory, + logbook.WARNING) + + fch = make_fch() + with activation_strategy(fch): + logger.info('some info') + assert len(handlers) == 0 + logger.warning('a warning') + assert len(handlers) == 1 + logger.error('an error') + assert len(handlers) == 1 + assert handlers[0].has_infos + assert handlers[0].has_warnings + assert handlers[0].has_errors + assert (not handlers[0].has_notices) + assert (not handlers[0].has_criticals) + assert (not handlers[0].has_debugs) + + fch = make_fch() + with activation_strategy(fch): + logger.info('some info') + logger.warning('a warning') + assert len(handlers) == 2 + + +def test_fingerscrossed_buffer_size(activation_strategy): + logger = logbook.Logger('Test') + test_handler = logbook.TestHandler() + handler = logbook.FingersCrossedHandler(test_handler, buffer_size=3) + + with activation_strategy(handler): + logger.info('Never gonna give you up') + logger.warn('Aha!') + logger.warn('Moar!') + logger.error('Pure hate!') + + assert test_handler.formatted_records == ['[WARNING] Test: Aha!', '[WARNING] Test: Moar!', '[ERROR] Test: Pure hate!'] + diff --git a/tests/test_flags.py b/tests/test_flags.py new file mode 100644 index 0000000..1e333b3 --- /dev/null +++ b/tests/test_flags.py @@ -0,0 +1,32 @@ +import logbook + +import pytest + +from .utils import capturing_stderr_context + + +def test_error_flag(logger): + with capturing_stderr_context() as captured: + with logbook.Flags(errors='print'): + with logbook.Flags(errors='silent'): + logger.warn('Foo {42}', 'aha') + assert captured.getvalue() == '' + + with logbook.Flags(errors='silent'): + with logbook.Flags(errors='print'): + logger.warn('Foo {42}', 'aha') + assert captured.getvalue() != '' + + with pytest.raises(Exception) as caught: + with logbook.Flags(errors='raise'): + logger.warn('Foo {42}', 'aha') + assert 'Could not format message with provided arguments' in str(caught.value) + + +def test_disable_introspection(logger): + with logbook.Flags(introspection=False): + with logbook.TestHandler() as h: + logger.warn('Testing') + assert h.records[0].frame is None + assert h.records[0].calling_frame is None + assert h.records[0].module is None diff --git a/tests/test_groups.py b/tests/test_groups.py new file mode 100644 index 0000000..c021c7e --- /dev/null +++ b/tests/test_groups.py @@ -0,0 +1,15 @@ +import logbook + + +def test_groups(logger): + def inject_extra(record): + record.extra['foo'] = 'bar' + group = logbook.LoggerGroup(processor=inject_extra) + group.level = logbook.ERROR + group.add_logger(logger) + with logbook.TestHandler() as handler: + logger.warn('A warning') + logger.error('An error') + assert (not handler.has_warning('A warning')) + assert handler.has_error('An error') + assert handler.records[0].extra['foo'] == 'bar' diff --git a/tests/test_handler_errors.py b/tests/test_handler_errors.py new file mode 100644 index 0000000..56e055a --- /dev/null +++ b/tests/test_handler_errors.py @@ -0,0 +1,46 @@ +import re +import sys + +import logbook + +import pytest + +from .utils import capturing_stderr_context + +__file_without_pyc__ = __file__ +if __file_without_pyc__.endswith('.pyc'): + __file_without_pyc__ = __file_without_pyc__[:-1] + + +def test_handler_exception(activation_strategy, logger): + class ErroringHandler(logbook.TestHandler): + + def emit(self, record): + raise RuntimeError('something bad happened') + + with capturing_stderr_context() as stderr: + with activation_strategy(ErroringHandler()): + logger.warn('I warn you.') + assert 'something bad happened' in stderr.getvalue() + assert 'I warn you' not in stderr.getvalue() + + +def test_formatting_exception(): + def make_record(): + return logbook.LogRecord('Test Logger', logbook.WARNING, + 'Hello {foo:invalid}', + kwargs={'foo': 42}, + frame=sys._getframe()) + record = make_record() + with pytest.raises(TypeError) as caught: + record.message + + errormsg = str(caught.value) + assert re.search('Could not format message with provided arguments: ' + 'Invalid (?:format specifier)|(?:conversion specification)|(?:format spec)', + errormsg, re.M | re.S) + assert "msg='Hello {foo:invalid}'" in errormsg + assert 'args=()' in errormsg + assert "kwargs={'foo': 42}" in errormsg + assert re.search(r'Happened in file .*%s, line \d+' % re.escape(__file_without_pyc__), + errormsg, re.M | re.S) diff --git a/tests/test_handlers.py b/tests/test_handlers.py new file mode 100644 index 0000000..03fa7de --- /dev/null +++ b/tests/test_handlers.py @@ -0,0 +1,137 @@ +import logbook + +from .utils import capturing_stderr_context, make_fake_mail_handler + + +def test_custom_logger(activation_strategy, logger): + client_ip = '127.0.0.1' + + class CustomLogger(logbook.Logger): + + def process_record(self, record): + record.extra['ip'] = client_ip + + custom_log = CustomLogger('awesome logger') + fmt = '[{record.level_name}] {record.channel}: ' \ + '{record.message} [{record.extra[ip]}]' + handler = logbook.TestHandler(format_string=fmt) + assert handler.format_string == fmt + + with activation_strategy(handler): + custom_log.warn('Too many sounds') + logger.warn('"Music" playing') + + assert handler.formatted_records == [ + '[WARNING] awesome logger: Too many sounds [127.0.0.1]', + '[WARNING] testlogger: "Music" playing []'] + + +def test_custom_handling(activation_strategy, logger): + class MyTestHandler(logbook.TestHandler): + def handle(self, record): + if record.extra.get('flag') != 'testing': + return False + return logbook.TestHandler.handle(self, record) + + # Check metaclass (== cls.__class__) + assert logbook.Handler.__class__ == logbook.handlers._HandlerType + + class MyLogger(logbook.Logger): + def process_record(self, record): + logbook.Logger.process_record(self, record) + record.extra['flag'] = 'testing' + + log = MyLogger() + handler = MyTestHandler() + with capturing_stderr_context() as captured: + with activation_strategy(handler): + log.warn('From my logger') + logger.warn('From another logger') + assert handler.has_warning('From my logger') + assert 'From another logger' in captured.getvalue() + + +def test_nested_setups(activation_strategy): + with capturing_stderr_context() as captured: + logger = logbook.Logger('App') + test_handler = logbook.TestHandler(level='WARNING') + mail_handler = make_fake_mail_handler(bubble=True) + + handlers = logbook.NestedSetup([ + logbook.NullHandler(), + test_handler, + mail_handler + ]) + + with activation_strategy(handlers): + logger.warn('This is a warning') + logger.error('This is also a mail') + try: + 1 / 0 + except Exception: + logger.exception() + logger.warn('And here we go straight back to stderr') + + assert test_handler.has_warning('This is a warning') + assert test_handler.has_error('This is also a mail') + assert len(mail_handler.mails) == 2 + assert 'This is also a mail' in mail_handler.mails[0][2] + assert '1 / 0' in mail_handler.mails[1][2] + assert 'And here we go straight back to stderr' in captured.getvalue() + + with activation_strategy(handlers): + logger.warn('threadbound warning') + + handlers.push_application() + try: + logger.warn('applicationbound warning') + finally: + handlers.pop_application() + + +def test_filtering(activation_strategy): + logger1 = logbook.Logger('Logger1') + logger2 = logbook.Logger('Logger2') + handler = logbook.TestHandler() + outer_handler = logbook.TestHandler() + + def only_1(record, handler): + return record.dispatcher is logger1 + handler.filter = only_1 + + with activation_strategy(outer_handler): + with activation_strategy(handler): + logger1.warn('foo') + logger2.warn('bar') + + assert handler.has_warning('foo', channel='Logger1') + assert (not handler.has_warning('bar', channel='Logger2')) + assert (not outer_handler.has_warning('foo', channel='Logger1')) + assert outer_handler.has_warning('bar', channel='Logger2') + + +def test_different_context_pushing(activation_strategy): + h1 = logbook.TestHandler(level=logbook.DEBUG) + h2 = logbook.TestHandler(level=logbook.INFO) + h3 = logbook.TestHandler(level=logbook.WARNING) + logger = logbook.Logger('Testing') + + with activation_strategy(h1): + with activation_strategy(h2): + with activation_strategy(h3): + logger.warn('Wuuu') + logger.info('still awesome') + logger.debug('puzzled') + + assert h1.has_debug('puzzled') + assert h2.has_info('still awesome') + assert h3.has_warning('Wuuu') + for handler in h1, h2, h3: + assert len(handler.records) == 1 + + +def test_default_handlers(logger): + with capturing_stderr_context() as stream: + logger.warn('Aha!') + captured = stream.getvalue() + assert 'WARNING: testlogger: Aha!' in captured diff --git a/tests/test_helpers.py b/tests/test_helpers.py new file mode 100644 index 0000000..ec2fd67 --- /dev/null +++ b/tests/test_helpers.py @@ -0,0 +1,44 @@ +# -*- coding: utf-8 -*- + +from logbook.helpers import u +from datetime import datetime + +import pytest + + +def test_jsonhelper(): + from logbook.helpers import to_safe_json + + class Bogus(object): + def __str__(self): + return 'bogus' + + rv = to_safe_json([ + None, + 'foo', + u('jäger'), + 1, + datetime(2000, 1, 1), + {'jäger1': 1, u('jäger2'): 2, Bogus(): 3, 'invalid': object()}, + object() # invalid + ]) + + assert rv == [None, u('foo'), u('jäger'), 1, '2000-01-01T00:00:00Z', + {u('jäger1'): 1, u('jäger2'): 2, u('bogus'): 3, + u('invalid'): None}, None] + + +def test_datehelpers(): + from logbook.helpers import format_iso8601, parse_iso8601 + now = datetime.now() + rv = format_iso8601() + assert rv[:4] == str(now.year) + + with pytest.raises(ValueError): + parse_iso8601('foo') + v = parse_iso8601('2000-01-01T00:00:00.12Z') + assert v.microsecond == 120000 + v = parse_iso8601('2000-01-01T12:00:00+01:00') + assert v.hour == 11 + v = parse_iso8601('2000-01-01T12:00:00-01:00') + assert v.hour == 13 diff --git a/tests/test_log_record.py b/tests/test_log_record.py new file mode 100644 index 0000000..865d766 --- /dev/null +++ b/tests/test_log_record.py @@ -0,0 +1,36 @@ +import sys + +import logbook + +from .utils import capturing_stderr_context + + +def test_exc_info_when_no_exceptions_exist(logger): + with capturing_stderr_context() as captured: + with logbook.StreamHandler(sys.stderr): + logger.debug('message', exc_info=True) + assert 'Traceback' not in captured.getvalue() + +def test_extradict(active_handler, logger): + logger.warn('Test warning') + record = active_handler.records[0] + record.extra['existing'] = 'foo' + assert record.extra['nonexisting'] == '' + assert record.extra['existing'] == 'foo' + assert repr(record.extra) == "ExtraDict({'existing': 'foo'})" + + +def test_calling_frame(active_handler, logger): + logger.warn('test') + assert active_handler.records[0].calling_frame == sys._getframe() + +def test_frame_correction(active_handler, logger): + def inner(): + logger.warn('test', frame_correction=+1) + + inner() + assert active_handler.records[0].calling_frame == sys._getframe() + +def test_dispatcher(active_handler, logger): + logger.warn('Logbook is too awesome for stdlib') + assert active_handler.records[0].dispatcher == logger diff --git a/tests/test_logbook.py b/tests/test_logbook.py index e8fbe4a..0408315 100644 --- a/tests/test_logbook.py +++ b/tests/test_logbook.py @@ -1,1487 +1,33 @@ -# -*- coding: utf-8 -*- -from .utils import ( - LogbookTestCase, - activate_via_push_pop, - activate_via_with_statement, - capturing_stderr_context, - get_total_delta_seconds, - make_fake_mail_handler, - missing, - require_module, - require_py3, -) -from contextlib import closing, contextmanager -from datetime import datetime, timedelta -from random import randrange import logbook -from logbook.helpers import StringIO, xrange, iteritems, zip, u -import os -import pickle -import re -import shutil -import socket -import sys -import tempfile -import time -import json -try: - from thread import get_ident -except ImportError: - from _thread import get_ident -import base64 -__file_without_pyc__ = __file__ -if __file_without_pyc__.endswith(".pyc"): - __file_without_pyc__ = __file_without_pyc__[:-1] - -LETTERS = "abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ" - -class _BasicAPITestCase(LogbookTestCase): - def test_basic_logging(self): - with self.thread_activation_strategy(logbook.TestHandler()) as handler: - self.log.warn('This is a warning. Nice hah?') - - self.assert_(handler.has_warning('This is a warning. Nice hah?')) - self.assertEqual(handler.formatted_records, [ - '[WARNING] testlogger: This is a warning. Nice hah?' - ]) - - def test_extradict(self): - with self.thread_activation_strategy(logbook.TestHandler()) as handler: - self.log.warn('Test warning') - record = handler.records[0] - record.extra['existing'] = 'foo' - self.assertEqual(record.extra['nonexisting'], '') - self.assertEqual(record.extra['existing'], 'foo') - self.assertEqual(repr(record.extra), - 'ExtraDict({\'existing\': \'foo\'})') - - def test_custom_logger(self): - client_ip = '127.0.0.1' - - class CustomLogger(logbook.Logger): - def process_record(self, record): - record.extra['ip'] = client_ip - - custom_log = CustomLogger('awesome logger') - fmt = '[{record.level_name}] {record.channel}: ' \ - '{record.message} [{record.extra[ip]}]' - handler = logbook.TestHandler(format_string=fmt) - self.assertEqual(handler.format_string, fmt) - - with self.thread_activation_strategy(handler): - custom_log.warn('Too many sounds') - self.log.warn('"Music" playing') - - self.assertEqual(handler.formatted_records, [ - '[WARNING] awesome logger: Too many sounds [127.0.0.1]', - '[WARNING] testlogger: "Music" playing []' - ]) - - def test_handler_exception(self): - class ErroringHandler(logbook.TestHandler): - def emit(self, record): - raise RuntimeError('something bad happened') - - with capturing_stderr_context() as stderr: - with self.thread_activation_strategy(ErroringHandler()) as handler: - self.log.warn('I warn you.') - self.assert_('something bad happened' in stderr.getvalue()) - self.assert_('I warn you' not in stderr.getvalue()) - - def test_formatting_exception(self): - def make_record(): - return logbook.LogRecord('Test Logger', logbook.WARNING, - 'Hello {foo:invalid}', - kwargs={'foo': 42}, - frame=sys._getframe()) - record = make_record() - with self.assertRaises(TypeError) as caught: - record.message - - errormsg = str(caught.exception) - self.assertRegexpMatches(errormsg, - "Could not format message with provided arguments: Invalid (?:format specifier)|(?:conversion specification)|(?:format spec)") - self.assertIn("msg='Hello {foo:invalid}'", errormsg) - self.assertIn('args=()', errormsg) - self.assertIn("kwargs={'foo': 42}", errormsg) - self.assertRegexpMatches( - errormsg, - r'Happened in file .*%s, line \d+' % __file_without_pyc__) - - def test_exception_catching(self): - logger = logbook.Logger('Test') - with self.thread_activation_strategy(logbook.TestHandler()) as handler: - self.assertFalse(handler.has_error()) - try: - 1 / 0 - except Exception: - logger.exception() - try: - 1 / 0 - except Exception: - logger.exception('Awesome') - self.assert_(handler.has_error('Uncaught exception occurred')) - self.assert_(handler.has_error('Awesome')) - self.assertIsNotNone(handler.records[0].exc_info) - self.assertIn('1 / 0', handler.records[0].formatted_exception) - - def test_exc_info_tuple(self): - self._test_exc_info(as_tuple=True) - - def test_exc_info_true(self): - self._test_exc_info(as_tuple=False) - - def _test_exc_info(self, as_tuple): - logger = logbook.Logger("Test") - with self.thread_activation_strategy(logbook.TestHandler()) as handler: - try: - 1 / 0 - except Exception: - exc_info = sys.exc_info() - logger.info("Exception caught", exc_info=exc_info if as_tuple else True) - self.assertIsNotNone(handler.records[0].exc_info) - self.assertEquals(handler.records[0].exc_info, exc_info) - - def test_exporting(self): - with self.thread_activation_strategy(logbook.TestHandler()) as handler: - try: - 1 / 0 - except Exception: - self.log.exception() - record = handler.records[0] - - exported = record.to_dict() - record.close() - imported = logbook.LogRecord.from_dict(exported) - for key, value in iteritems(record.__dict__): - if key[0] == '_': - continue - self.assertEqual(value, getattr(imported, key)) - - def test_pickle(self): - with self.thread_activation_strategy(logbook.TestHandler()) as handler: - try: - 1 / 0 - except Exception: - self.log.exception() - record = handler.records[0] - record.pull_information() - record.close() - - for p in xrange(pickle.HIGHEST_PROTOCOL): - exported = pickle.dumps(record, p) - imported = pickle.loads(exported) - for key, value in iteritems(record.__dict__): - if key[0] == '_': - continue - imported_value = getattr(imported, key) - if isinstance(value, ZeroDivisionError): - # in Python 3.2, ZeroDivisionError(x) != ZeroDivisionError(x) - self.assert_(type(value) is type(imported_value)) - self.assertEqual(value.args, imported_value.args) - else: - self.assertEqual(value, imported_value) - - def test_timedate_format(self): - """ - tests the logbook.set_datetime_format() function - """ - FORMAT_STRING = '{record.time:%H:%M:%S} {record.message}' - handler = logbook.TestHandler(format_string=FORMAT_STRING) - handler.push_thread() - logbook.set_datetime_format('utc') - try: - self.log.warn('This is a warning.') - time_utc = handler.records[0].time - logbook.set_datetime_format('local') - self.log.warn('This is a warning.') - time_local = handler.records[1].time - finally: - handler.pop_thread() - # put back the default time factory - logbook.set_datetime_format('utc') - - # get the expected difference between local and utc time - t1 = datetime.now() - t2 = datetime.utcnow() - - tz_minutes_diff = get_total_delta_seconds(t1 - t2)/60.0 - - if abs(tz_minutes_diff) < 1: - self.skipTest("Cannot test utc/localtime differences if they vary by less than one minute...") - - # get the difference between LogRecord local and utc times - logbook_minutes_diff = get_total_delta_seconds(time_local - time_utc)/60.0 - self.assertGreater(abs(logbook_minutes_diff), 1, "Localtime does not differ from UTC by more than 1 minute (Local: %s, UTC: %s)" % (time_local, time_utc)) - - ratio = logbook_minutes_diff / tz_minutes_diff - - self.assertGreater(ratio, 0.99) - self.assertLess(ratio, 1.01) - -class BasicAPITestCase_Regular(_BasicAPITestCase): - def setUp(self): - super(BasicAPITestCase_Regular, self).setUp() - self.thread_activation_strategy = activate_via_with_statement - -class BasicAPITestCase_Contextmgr(_BasicAPITestCase): - def setUp(self): - super(BasicAPITestCase_Contextmgr, self).setUp() - self.thread_activation_strategy = activate_via_push_pop - -class _HandlerTestCase(LogbookTestCase): - def setUp(self): - super(_HandlerTestCase, self).setUp() - self.dirname = tempfile.mkdtemp() - self.filename = os.path.join(self.dirname, 'log.tmp') - - def tearDown(self): - shutil.rmtree(self.dirname) - super(_HandlerTestCase, self).tearDown() - - def test_file_handler(self): - handler = logbook.FileHandler(self.filename, - format_string='{record.level_name}:{record.channel}:' - '{record.message}',) - with self.thread_activation_strategy(handler): - self.log.warn('warning message') - handler.close() - with open(self.filename) as f: - self.assertEqual(f.readline(), - 'WARNING:testlogger:warning message\n') - - def test_file_handler_unicode(self): - with capturing_stderr_context() as captured: - with self.thread_activation_strategy(logbook.FileHandler(self.filename)) as h: - self.log.info(u('\u0431')) - self.assertFalse(captured.getvalue()) - - def test_file_handler_delay(self): - handler = logbook.FileHandler(self.filename, - format_string='{record.level_name}:{record.channel}:' - '{record.message}', delay=True) - self.assertFalse(os.path.isfile(self.filename)) - with self.thread_activation_strategy(handler): - self.log.warn('warning message') - handler.close() - - with open(self.filename) as f: - self.assertEqual(f.readline(), - 'WARNING:testlogger:warning message\n') - - def test_monitoring_file_handler(self): - if os.name == "nt": - self.skipTest("unsupported on windows due to different IO (also unneeded)") - handler = logbook.MonitoringFileHandler(self.filename, - format_string='{record.level_name}:{record.channel}:' - '{record.message}', delay=True) - with self.thread_activation_strategy(handler): - self.log.warn('warning message') - os.rename(self.filename, self.filename + '.old') - self.log.warn('another warning message') - handler.close() - with open(self.filename) as f: - self.assertEqual(f.read().strip(), - 'WARNING:testlogger:another warning message') - - def test_custom_formatter(self): - def custom_format(record, handler): - return record.level_name + ':' + record.message - handler = logbook.FileHandler(self.filename) - with self.thread_activation_strategy(handler): - handler.formatter = custom_format - self.log.warn('Custom formatters are awesome') - - with open(self.filename) as f: - self.assertEqual(f.readline(), - 'WARNING:Custom formatters are awesome\n') - - def test_rotating_file_handler(self): - basename = os.path.join(self.dirname, 'rot.log') - handler = logbook.RotatingFileHandler(basename, max_size=2048, - backup_count=3, - ) - handler.format_string = '{record.message}' - with self.thread_activation_strategy(handler): - for c, x in zip(LETTERS, xrange(32)): - self.log.warn(c * 256) - files = [x for x in os.listdir(self.dirname) - if x.startswith('rot.log')] - files.sort() - - self.assertEqual(files, ['rot.log', 'rot.log.1', 'rot.log.2', - 'rot.log.3']) - with open(basename) as f: - self.assertEqual(f.readline().rstrip(), 'C' * 256) - self.assertEqual(f.readline().rstrip(), 'D' * 256) - self.assertEqual(f.readline().rstrip(), 'E' * 256) - self.assertEqual(f.readline().rstrip(), 'F' * 256) - - def test_timed_rotating_file_handler(self): - basename = os.path.join(self.dirname, 'trot.log') - handler = logbook.TimedRotatingFileHandler(basename, backup_count=3) - handler.format_string = '[{record.time:%H:%M}] {record.message}' - - def fake_record(message, year, month, day, hour=0, - minute=0, second=0): - lr = logbook.LogRecord('Test Logger', logbook.WARNING, - message) - lr.time = datetime(year, month, day, hour, minute, second) - return lr - - with self.thread_activation_strategy(handler): - for x in xrange(10): - handler.handle(fake_record('First One', 2010, 1, 5, x + 1)) - for x in xrange(20): - handler.handle(fake_record('Second One', 2010, 1, 6, x + 1)) - for x in xrange(10): - handler.handle(fake_record('Third One', 2010, 1, 7, x + 1)) - for x in xrange(20): - handler.handle(fake_record('Last One', 2010, 1, 8, x + 1)) - - files = sorted( - x for x in os.listdir(self.dirname) if x.startswith('trot') - ) - self.assertEqual(files, ['trot-2010-01-06.log', 'trot-2010-01-07.log', - 'trot-2010-01-08.log']) - with open(os.path.join(self.dirname, 'trot-2010-01-08.log')) as f: - self.assertEqual(f.readline().rstrip(), '[01:00] Last One') - self.assertEqual(f.readline().rstrip(), '[02:00] Last One') - with open(os.path.join(self.dirname, 'trot-2010-01-07.log')) as f: - self.assertEqual(f.readline().rstrip(), '[01:00] Third One') - self.assertEqual(f.readline().rstrip(), '[02:00] Third One') - - def test_mail_handler(self): - subject = u('\xf8nicode') - handler = make_fake_mail_handler(subject=subject) - with capturing_stderr_context() as fallback: - with self.thread_activation_strategy(handler): - self.log.warn('This is not mailed') - try: - 1 / 0 - except Exception: - self.log.exception(u('Viva la Espa\xf1a')) - - if not handler.mails: - # if sending the mail failed, the reason should be on stderr - self.fail(fallback.getvalue()) - - self.assertEqual(len(handler.mails), 1) - sender, receivers, mail = handler.mails[0] - mail = mail.replace("\r", "") - self.assertEqual(sender, handler.from_addr) - self.assert_('=?utf-8?q?=C3=B8nicode?=' in mail) - header, data = mail.split("\n\n", 1) - if "Content-Transfer-Encoding: base64" in header: - data = base64.b64decode(data).decode("utf-8") - self.assertRegexpMatches(data, 'Message type:\s+ERROR') - self.assertRegexpMatches(data, 'Location:.*%s' % __file_without_pyc__) - self.assertRegexpMatches(data, 'Module:\s+%s' % __name__) - self.assertRegexpMatches(data, 'Function:\s+test_mail_handler') - body = u('Viva la Espa\xf1a') - if sys.version_info < (3, 0): - body = body.encode('utf-8') - self.assertIn(body, data) - self.assertIn('\nTraceback (most', data) - self.assertIn('1 / 0', data) - self.assertIn('This is not mailed', fallback.getvalue()) - - def test_mail_handler_record_limits(self): - suppression_test = re.compile('This message occurred additional \d+ ' - 'time\(s\) and was suppressed').search - handler = make_fake_mail_handler(record_limit=1, - record_delta=timedelta(seconds=0.5)) - with self.thread_activation_strategy(handler): - later = datetime.utcnow() + timedelta(seconds=1.1) - while datetime.utcnow() < later: - self.log.error('Over and over...') - - # first mail that is always delivered + 0.5 seconds * 2 - # and 0.1 seconds of room for rounding errors makes 3 mails - self.assertEqual(len(handler.mails), 3) - - # first mail is always delivered - self.assert_(not suppression_test(handler.mails[0][2])) - - # the next two have a supression count - self.assert_(suppression_test(handler.mails[1][2])) - self.assert_(suppression_test(handler.mails[2][2])) - - def test_mail_handler_batching(self): - mail_handler = make_fake_mail_handler() - handler = logbook.FingersCrossedHandler(mail_handler, reset=True) - with self.thread_activation_strategy(handler): - self.log.warn('Testing') - self.log.debug('Even more') - self.log.error('And this triggers it') - self.log.info('Aha') - self.log.error('And this triggers it again!') - - self.assertEqual(len(mail_handler.mails), 2) - mail = mail_handler.mails[0][2] - - pieces = mail.split('Log records that led up to this one:') - self.assertEqual(len(pieces), 2) - body, rest = pieces - rest = rest.replace("\r", "") - - self.assertRegexpMatches(body, 'Message type:\s+ERROR') - self.assertRegexpMatches(body, 'Module:\s+%s' % __name__) - self.assertRegexpMatches(body, 'Function:\s+test_mail_handler_batching') - - related = rest.strip().split('\n\n') - self.assertEqual(len(related), 2) - self.assertRegexpMatches(related[0], 'Message type:\s+WARNING') - self.assertRegexpMatches(related[1], 'Message type:\s+DEBUG') - - self.assertIn('And this triggers it again', mail_handler.mails[1][2]) - - def test_group_handler_mail_combo(self): - mail_handler = make_fake_mail_handler(level=logbook.DEBUG) - handler = logbook.GroupHandler(mail_handler) - with self.thread_activation_strategy(handler): - self.log.error('The other way round') - self.log.warn('Testing') - self.log.debug('Even more') - self.assertEqual(mail_handler.mails, []) - - self.assertEqual(len(mail_handler.mails), 1) - mail = mail_handler.mails[0][2] - - pieces = mail.split('Other log records in the same group:') - self.assertEqual(len(pieces), 2) - body, rest = pieces - rest = rest.replace("\r", "") - - self.assertRegexpMatches(body, 'Message type:\s+ERROR') - self.assertRegexpMatches(body, 'Module:\s+'+__name__) - self.assertRegexpMatches(body, 'Function:\s+test_group_handler_mail_combo') - - related = rest.strip().split('\n\n') - self.assertEqual(len(related), 2) - self.assertRegexpMatches(related[0], 'Message type:\s+WARNING') - self.assertRegexpMatches(related[1], 'Message type:\s+DEBUG') - - def test_syslog_handler(self): - to_test = [ - (socket.AF_INET, ('127.0.0.1', 0)), - ] - if hasattr(socket, 'AF_UNIX'): - to_test.append((socket.AF_UNIX, self.filename)) - for sock_family, address in to_test: - with closing(socket.socket(sock_family, socket.SOCK_DGRAM)) as inc: - inc.bind(address) - inc.settimeout(1) - for app_name in [None, 'Testing']: - handler = logbook.SyslogHandler(app_name, inc.getsockname()) - with self.thread_activation_strategy(handler): - self.log.warn('Syslog is weird') - try: - rv = inc.recvfrom(1024)[0] - except socket.error: - self.fail('got timeout on socket') - self.assertEqual(rv, ( - u('<12>%stestlogger: Syslog is weird\x00') % - (app_name and app_name + u(':') or u(''))).encode('utf-8')) - - def test_handler_processors(self): - handler = make_fake_mail_handler(format_string='''\ -Subject: Application Error for {record.extra[path]} [{record.extra[method]}] - -Message type: {record.level_name} -Location: {record.filename}:{record.lineno} -Module: {record.module} -Function: {record.func_name} -Time: {record.time:%Y-%m-%d %H:%M:%S} -Remote IP: {record.extra[ip]} -Request: {record.extra[path]} [{record.extra[method]}] - -Message: - -{record.message} -''') - - class Request(object): - remote_addr = '127.0.0.1' - method = 'GET' - path = '/index.html' - - def handle_request(request): - def inject_extra(record): - record.extra['ip'] = request.remote_addr - record.extra['method'] = request.method - record.extra['path'] = request.path - - processor = logbook.Processor(inject_extra) - with self.thread_activation_strategy(processor): - handler.push_thread() - try: - try: - 1 / 0 - except Exception: - self.log.exception('Exception happened during request') - finally: - handler.pop_thread() - - handle_request(Request()) - self.assertEqual(len(handler.mails), 1) - mail = handler.mails[0][2] - self.assertIn('Subject: Application Error ' - 'for /index.html [GET]', mail) - self.assertIn('1 / 0', mail) - - def test_regex_matching(self): - test_handler = logbook.TestHandler() - with self.thread_activation_strategy(test_handler): - self.log.warn('Hello World!') - self.assert_(test_handler.has_warning(re.compile('^Hello'))) - self.assert_(not test_handler.has_warning(re.compile('world$'))) - self.assert_(not test_handler.has_warning('^Hello World')) - - def test_custom_handling_test(self): - class MyTestHandler(logbook.TestHandler): - def handle(self, record): - if record.extra.get('flag') != 'testing': - return False - return logbook.TestHandler.handle(self, record) - - class MyLogger(logbook.Logger): - def process_record(self, record): - logbook.Logger.process_record(self, record) - record.extra['flag'] = 'testing' - log = MyLogger() - handler = MyTestHandler() - with capturing_stderr_context() as captured: - with self.thread_activation_strategy(handler): - log.warn('From my logger') - self.log.warn('From another logger') - self.assert_(handler.has_warning('From my logger')) - self.assertIn('From another logger', captured.getvalue()) - - def test_custom_handling_tester(self): - flag = True - - class MyTestHandler(logbook.TestHandler): - def should_handle(self, record): - return flag - null_handler = logbook.NullHandler() - with self.thread_activation_strategy(null_handler): - test_handler = MyTestHandler() - with self.thread_activation_strategy(test_handler): - self.log.warn('1') - flag = False - self.log.warn('2') - self.assert_(test_handler.has_warning('1')) - self.assert_(not test_handler.has_warning('2')) - - def test_null_handler(self): - with capturing_stderr_context() as captured: - with self.thread_activation_strategy(logbook.NullHandler()) as null_handler: - with self.thread_activation_strategy(logbook.TestHandler(level='ERROR')) as handler: - self.log.error('An error') - self.log.warn('A warning') - self.assertEqual(captured.getvalue(), '') - self.assertFalse(handler.has_warning('A warning')) - self.assert_(handler.has_error('An error')) - - def test_test_handler_cache(self): - with self.thread_activation_strategy(logbook.TestHandler()) as handler: - self.log.warn('First line') - self.assertEqual(len(handler.formatted_records),1) - cache = handler.formatted_records # store cache, to make sure it is identifiable - self.assertEqual(len(handler.formatted_records),1) - self.assert_(cache is handler.formatted_records) # Make sure cache is not invalidated without changes to record - self.log.warn('Second line invalidates cache') - self.assertEqual(len(handler.formatted_records),2) - self.assertFalse(cache is handler.formatted_records) # Make sure cache is invalidated when records change - - def test_blackhole_setting(self): - null_handler = logbook.NullHandler() - heavy_init = logbook.LogRecord.heavy_init - with self.thread_activation_strategy(null_handler): - def new_heavy_init(self): - raise RuntimeError('should not be triggered') - logbook.LogRecord.heavy_init = new_heavy_init - try: - with self.thread_activation_strategy(null_handler): - logbook.warn('Awesome') - finally: - logbook.LogRecord.heavy_init = heavy_init - - null_handler.bubble = True - with capturing_stderr_context() as captured: - logbook.warning('Not a blockhole') - self.assertNotEqual(captured.getvalue(), '') - - def test_calling_frame(self): - handler = logbook.TestHandler() - with self.thread_activation_strategy(handler): - logbook.warn('test') - self.assertEqual(handler.records[0].calling_frame, sys._getframe()) - - def test_nested_setups(self): - with capturing_stderr_context() as captured: - logger = logbook.Logger('App') - test_handler = logbook.TestHandler(level='WARNING') - mail_handler = make_fake_mail_handler(bubble=True) - - handlers = logbook.NestedSetup([ - logbook.NullHandler(), - test_handler, - mail_handler - ]) - - with self.thread_activation_strategy(handlers): - logger.warn('This is a warning') - logger.error('This is also a mail') - try: - 1 / 0 - except Exception: - logger.exception() - logger.warn('And here we go straight back to stderr') - - self.assert_(test_handler.has_warning('This is a warning')) - self.assert_(test_handler.has_error('This is also a mail')) - self.assertEqual(len(mail_handler.mails), 2) - self.assertIn('This is also a mail', mail_handler.mails[0][2]) - self.assertIn('1 / 0',mail_handler.mails[1][2]) - self.assertIn('And here we go straight back to stderr', - captured.getvalue()) - - with self.thread_activation_strategy(handlers): - logger.warn('threadbound warning') - - handlers.push_application() - try: - logger.warn('applicationbound warning') - finally: - handlers.pop_application() - - def test_dispatcher(self): - logger = logbook.Logger('App') - with self.thread_activation_strategy(logbook.TestHandler()) as test_handler: - logger.warn('Logbook is too awesome for stdlib') - self.assertEqual(test_handler.records[0].dispatcher, logger) - - def test_filtering(self): - logger1 = logbook.Logger('Logger1') - logger2 = logbook.Logger('Logger2') - handler = logbook.TestHandler() - outer_handler = logbook.TestHandler() - - def only_1(record, handler): - return record.dispatcher is logger1 - handler.filter = only_1 - - with self.thread_activation_strategy(outer_handler): - with self.thread_activation_strategy(handler): - logger1.warn('foo') - logger2.warn('bar') - - self.assert_(handler.has_warning('foo', channel='Logger1')) - self.assertFalse(handler.has_warning('bar', channel='Logger2')) - self.assertFalse(outer_handler.has_warning('foo', channel='Logger1')) - self.assert_(outer_handler.has_warning('bar', channel='Logger2')) - - def test_null_handler_filtering(self): - logger1 = logbook.Logger("1") - logger2 = logbook.Logger("2") - outer = logbook.TestHandler() - inner = logbook.NullHandler() - - inner.filter = lambda record, handler: record.dispatcher is logger1 - - with self.thread_activation_strategy(outer): - with self.thread_activation_strategy(inner): - logger1.warn("1") - logger2.warn("2") - - self.assertTrue(outer.has_warning("2", channel="2")) - self.assertFalse(outer.has_warning("1", channel="1")) - - def test_different_context_pushing(self): - h1 = logbook.TestHandler(level=logbook.DEBUG) - h2 = logbook.TestHandler(level=logbook.INFO) - h3 = logbook.TestHandler(level=logbook.WARNING) - logger = logbook.Logger('Testing') - - with self.thread_activation_strategy(h1): - with self.thread_activation_strategy(h2): - with self.thread_activation_strategy(h3): - logger.warn('Wuuu') - logger.info('still awesome') - logger.debug('puzzled') - - self.assert_(h1.has_debug('puzzled')) - self.assert_(h2.has_info('still awesome')) - self.assert_(h3.has_warning('Wuuu')) - for handler in h1, h2, h3: - self.assertEquals(len(handler.records), 1) - - def test_global_functions(self): - with self.thread_activation_strategy(logbook.TestHandler()) as handler: - logbook.debug('a debug message') - logbook.info('an info message') - logbook.warn('warning part 1') - logbook.warning('warning part 2') - logbook.notice('notice') - logbook.error('an error') - logbook.critical('pretty critical') - logbook.log(logbook.CRITICAL, 'critical too') - - self.assert_(handler.has_debug('a debug message')) - self.assert_(handler.has_info('an info message')) - self.assert_(handler.has_warning('warning part 1')) - self.assert_(handler.has_warning('warning part 2')) - self.assert_(handler.has_notice('notice')) - self.assert_(handler.has_error('an error')) - self.assert_(handler.has_critical('pretty critical')) - self.assert_(handler.has_critical('critical too')) - self.assertEqual(handler.records[0].channel, 'Generic') - self.assertIsNone(handler.records[0].dispatcher) - - def test_fingerscrossed(self): - handler = logbook.FingersCrossedHandler(logbook.default_handler, - logbook.WARNING) - - # if no warning occurs, the infos are not logged - with self.thread_activation_strategy(handler): - with capturing_stderr_context() as captured: - self.log.info('some info') - self.assertEqual(captured.getvalue(), '') - self.assert_(not handler.triggered) - - # but if it does, all log messages are output - with self.thread_activation_strategy(handler): - with capturing_stderr_context() as captured: - self.log.info('some info') - self.log.warning('something happened') - self.log.info('something else happened') - logs = captured.getvalue() - self.assert_('some info' in logs) - self.assert_('something happened' in logs) - self.assert_('something else happened' in logs) - self.assert_(handler.triggered) - - def test_fingerscrossed_factory(self): - handlers = [] - - def handler_factory(record, fch): - handler = logbook.TestHandler() - handlers.append(handler) - return handler - - def make_fch(): - return logbook.FingersCrossedHandler(handler_factory, - logbook.WARNING) - - fch = make_fch() - with self.thread_activation_strategy(fch): - self.log.info('some info') - self.assertEqual(len(handlers), 0) - self.log.warning('a warning') - self.assertEqual(len(handlers), 1) - self.log.error('an error') - self.assertEqual(len(handlers), 1) - self.assert_(handlers[0].has_infos) - self.assert_(handlers[0].has_warnings) - self.assert_(handlers[0].has_errors) - self.assert_(not handlers[0].has_notices) - self.assert_(not handlers[0].has_criticals) - self.assert_(not handlers[0].has_debugs) - - fch = make_fch() - with self.thread_activation_strategy(fch): - self.log.info('some info') - self.log.warning('a warning') - self.assertEqual(len(handlers), 2) - - def test_fingerscrossed_buffer_size(self): - logger = logbook.Logger('Test') - test_handler = logbook.TestHandler() - handler = logbook.FingersCrossedHandler(test_handler, buffer_size=3) - - with self.thread_activation_strategy(handler): - logger.info('Never gonna give you up') - logger.warn('Aha!') - logger.warn('Moar!') - logger.error('Pure hate!') - - self.assertEqual(test_handler.formatted_records, [ - '[WARNING] Test: Aha!', - '[WARNING] Test: Moar!', - '[ERROR] Test: Pure hate!' - ]) +import pytest -class HandlerTestCase_Regular(_HandlerTestCase): - def setUp(self): - super(HandlerTestCase_Regular, self).setUp() - self.thread_activation_strategy = activate_via_push_pop +def test_global_functions(activation_strategy): + with activation_strategy(logbook.TestHandler()) as handler: + logbook.debug('a debug message') + logbook.info('an info message') + logbook.warn('warning part 1') + logbook.warning('warning part 2') + logbook.notice('notice') + logbook.error('an error') + logbook.critical('pretty critical') + logbook.log(logbook.CRITICAL, 'critical too') -class HandlerTestCase_Contextmgr(_HandlerTestCase): - def setUp(self): - super(HandlerTestCase_Contextmgr, self).setUp() - self.thread_activation_strategy = activate_via_with_statement - -class AttributeTestCase(LogbookTestCase): - - def test_level_properties(self): - self.assertEqual(self.log.level, logbook.NOTSET) - self.assertEqual(self.log.level_name, 'NOTSET') - self.log.level_name = 'WARNING' - self.assertEqual(self.log.level, logbook.WARNING) - self.log.level = logbook.ERROR - self.assertEqual(self.log.level_name, 'ERROR') - - def test_reflected_properties(self): - group = logbook.LoggerGroup() - group.add_logger(self.log) - self.assertEqual(self.log.group, group) - group.level = logbook.ERROR - self.assertEqual(self.log.level, logbook.ERROR) - self.assertEqual(self.log.level_name, 'ERROR') - group.level = logbook.WARNING - self.assertEqual(self.log.level, logbook.WARNING) - self.assertEqual(self.log.level_name, 'WARNING') - self.log.level = logbook.CRITICAL - group.level = logbook.DEBUG - self.assertEqual(self.log.level, logbook.CRITICAL) - self.assertEqual(self.log.level_name, 'CRITICAL') - group.remove_logger(self.log) - self.assertEqual(self.log.group, None) - -class LevelLookupTest(LogbookTestCase): - def test_level_lookup_failures(self): - with self.assertRaises(LookupError): - logbook.get_level_name(37) - with self.assertRaises(LookupError): - logbook.lookup_level('FOO') - -class FlagsTestCase(LogbookTestCase): - def test_error_flag(self): - with capturing_stderr_context() as captured: - with logbook.Flags(errors='print'): - with logbook.Flags(errors='silent'): - self.log.warn('Foo {42}', 'aha') - self.assertEqual(captured.getvalue(), '') - - with logbook.Flags(errors='silent'): - with logbook.Flags(errors='print'): - self.log.warn('Foo {42}', 'aha') - self.assertNotEqual(captured.getvalue(), '') - - with self.assertRaises(Exception) as caught: - with logbook.Flags(errors='raise'): - self.log.warn('Foo {42}', 'aha') - self.assertIn('Could not format message with provided ' - 'arguments', str(caught.exception)) - - def test_disable_introspection(self): - with logbook.Flags(introspection=False): - with logbook.TestHandler() as h: - self.log.warn('Testing') - self.assertIsNone(h.records[0].frame) - self.assertIsNone(h.records[0].calling_frame) - self.assertIsNone(h.records[0].module) - -class LoggerGroupTestCase(LogbookTestCase): - def test_groups(self): - def inject_extra(record): - record.extra['foo'] = 'bar' - group = logbook.LoggerGroup(processor=inject_extra) - group.level = logbook.ERROR - group.add_logger(self.log) - with logbook.TestHandler() as handler: - self.log.warn('A warning') - self.log.error('An error') - self.assertFalse(handler.has_warning('A warning')) - self.assertTrue(handler.has_error('An error')) - self.assertEqual(handler.records[0].extra['foo'], 'bar') - -class DefaultConfigurationTestCase(LogbookTestCase): - - def test_default_handlers(self): - with capturing_stderr_context() as stream: - self.log.warn('Aha!') - captured = stream.getvalue() - self.assertIn('WARNING: testlogger: Aha!', captured) - -class LoggingCompatTestCase(LogbookTestCase): - - def test_basic_compat_with_level_setting(self): - self._test_basic_compat(True) - def test_basic_compat_without_level_setting(self): - self._test_basic_compat(False) - - def _test_basic_compat(self, set_root_logger_level): - import logging - from logbook.compat import redirected_logging - - # mimic the default logging setting - self.addCleanup(logging.root.setLevel, logging.root.level) - logging.root.setLevel(logging.WARNING) - - name = 'test_logbook-%d' % randrange(1 << 32) - logger = logging.getLogger(name) - - with logbook.TestHandler(bubble=True) as handler: - with capturing_stderr_context() as captured: - with redirected_logging(set_root_logger_level): - logger.debug('This is from the old system') - logger.info('This is from the old system') - logger.warn('This is from the old system') - logger.error('This is from the old system') - logger.critical('This is from the old system') - self.assertIn(('WARNING: %s: This is from the old system' % name), - captured.getvalue()) - if set_root_logger_level: - self.assertEquals(handler.records[0].level, logbook.DEBUG) - else: - self.assertEquals(handler.records[0].level, logbook.WARNING) - - def test_redirect_logbook(self): - import logging - from logbook.compat import LoggingHandler - out = StringIO() - logger = logging.getLogger() - old_handlers = logger.handlers[:] - handler = logging.StreamHandler(out) - handler.setFormatter(logging.Formatter( - '%(name)s:%(levelname)s:%(message)s')) - logger.handlers[:] = [handler] - try: - with logbook.compat.LoggingHandler() as logging_handler: - self.log.warn("This goes to logging") - pieces = out.getvalue().strip().split(':') - self.assertEqual(pieces, [ - 'testlogger', - 'WARNING', - 'This goes to logging' - ]) - finally: - logger.handlers[:] = old_handlers - -class WarningsCompatTestCase(LogbookTestCase): - - def test_warning_redirections(self): - from logbook.compat import redirected_warnings - with logbook.TestHandler() as handler: - redirector = redirected_warnings() - redirector.start() - try: - from warnings import warn - warn(RuntimeWarning('Testing')) - finally: - redirector.end() - - self.assertEqual(len(handler.records), 1) - self.assertEqual('[WARNING] RuntimeWarning: Testing', - handler.formatted_records[0]) - self.assertIn(__file_without_pyc__, handler.records[0].filename) - -class MoreTestCase(LogbookTestCase): - - @contextmanager - def _get_temporary_file_context(self): - fn = tempfile.mktemp() - try: - yield fn - finally: - try: - os.remove(fn) - except OSError: - pass - - @require_module('jinja2') - def test_jinja_formatter(self): - from logbook.more import JinjaFormatter - fmter = JinjaFormatter('{{ record.channel }}/{{ record.level_name }}') - handler = logbook.TestHandler() - handler.formatter = fmter - with handler: - self.log.info('info') - self.assertIn('testlogger/INFO', handler.formatted_records) - - @missing('jinja2') - def test_missing_jinja2(self): - from logbook.more import JinjaFormatter - # check the RuntimeError is raised - with self.assertRaises(RuntimeError): - JinjaFormatter('dummy') - - def test_colorizing_support(self): - from logbook.more import ColorizedStderrHandler - - class TestColorizingHandler(ColorizedStderrHandler): - def should_colorize(self, record): - return True - stream = StringIO() - with TestColorizingHandler(format_string='{record.message}') as handler: - self.log.error('An error') - self.log.warn('A warning') - self.log.debug('A debug message') - lines = handler.stream.getvalue().rstrip('\n').splitlines() - self.assertEqual(lines, [ - '\x1b[31;01mAn error', - '\x1b[39;49;00m\x1b[33;01mA warning', - '\x1b[39;49;00m\x1b[37mA debug message', - '\x1b[39;49;00m' - ]) - - def test_tagged(self): - from logbook.more import TaggingLogger, TaggingHandler - stream = StringIO() - second_handler = logbook.StreamHandler(stream) - - logger = TaggingLogger('name', ['cmd']) - handler = TaggingHandler(dict( - info=logbook.default_handler, - cmd=second_handler, - both=[logbook.default_handler, second_handler], - )) - handler.bubble = False - - with handler: - with capturing_stderr_context() as captured: - logger.log('info', 'info message') - logger.log('both', 'all message') - logger.cmd('cmd message') - - stderr = captured.getvalue() - - self.assertIn('info message', stderr) - self.assertIn('all message', stderr) - self.assertNotIn('cmd message', stderr) - - stringio = stream.getvalue() - - self.assertNotIn('info message', stringio) - self.assertIn('all message', stringio) - self.assertIn('cmd message', stringio) - - def test_external_application_handler(self): - from logbook.more import ExternalApplicationHandler as Handler - with self._get_temporary_file_context() as fn: - handler = Handler([sys.executable, '-c', r'''if 1: - f = open(%(tempfile)s, 'w') - try: - f.write('{record.message}\n') - finally: - f.close() - ''' % {'tempfile': repr(fn)}]) - with handler: - self.log.error('this is a really bad idea') - with open(fn, 'r') as rf: - contents = rf.read().strip() - self.assertEqual(contents, 'this is a really bad idea') - - def test_external_application_handler_stdin(self): - from logbook.more import ExternalApplicationHandler as Handler - with self._get_temporary_file_context() as fn: - handler = Handler([sys.executable, '-c', r'''if 1: - import sys - f = open(%(tempfile)s, 'w') - try: - f.write(sys.stdin.read()) - finally: - f.close() - ''' % {'tempfile': repr(fn)}], '{record.message}\n') - with handler: - self.log.error('this is a really bad idea') - with open(fn, 'r') as rf: - contents = rf.read().strip() - self.assertEqual(contents, 'this is a really bad idea') - - def test_exception_handler(self): - from logbook.more import ExceptionHandler - - with ExceptionHandler(ValueError) as exception_handler: - with self.assertRaises(ValueError) as caught: - self.log.info('here i am') - self.assertIn('INFO: testlogger: here i am', caught.exception.args[0]) - - def test_exception_handler_specific_level(self): - from logbook.more import ExceptionHandler - with logbook.TestHandler() as test_handler: - with self.assertRaises(ValueError) as caught: - with ExceptionHandler(ValueError, level='WARNING') as exception_handler: - self.log.info('this is irrelevant') - self.log.warn('here i am') - self.assertIn('WARNING: testlogger: here i am', caught.exception.args[0]) - self.assertIn('this is irrelevant', test_handler.records[0].message) - - def test_dedup_handler(self): - from logbook.more import DedupHandler - with logbook.TestHandler() as test_handler: - with DedupHandler(): - self.log.info('foo') - self.log.info('bar') - self.log.info('foo') - self.assertEqual(2, len(test_handler.records)) - self.assertIn('message repeated 2 times: foo', test_handler.records[0].message) - self.assertIn('message repeated 1 times: bar', test_handler.records[1].message) - -class QueuesTestCase(LogbookTestCase): - def _get_zeromq(self, multi=False): - from logbook.queues import ZeroMQHandler, ZeroMQSubscriber - - # Get an unused port - tempsock = socket.socket(socket.AF_INET, socket.SOCK_STREAM) - tempsock.bind(('127.0.0.1', 0)) - host, unused_port = tempsock.getsockname() - tempsock.close() - - # Retrieve the ZeroMQ handler and subscriber - uri = 'tcp://%s:%d' % (host, unused_port) - if multi: - handler = [ZeroMQHandler(uri, multi=True) for _ in range(3)] - else: - handler = ZeroMQHandler(uri) - subscriber = ZeroMQSubscriber(uri, multi=multi) - # Enough time to start - time.sleep(0.1) - return handler, subscriber - - @require_module('zmq') - def test_zeromq_handler(self): - tests = [ - u('Logging something'), - u('Something with umlauts äöü'), - u('Something else for good measure'), - ] - handler, subscriber = self._get_zeromq() - for test in tests: - with handler: - self.log.warn(test) - record = subscriber.recv() - self.assertEqual(record.message, test) - self.assertEqual(record.channel, self.log.name) - - @require_module('zmq') - def test_multi_zeromq_handler(self): - tests = [ - u('Logging something'), - u('Something with umlauts äöü'), - u('Something else for good measure'), - ] - handlers, subscriber = self._get_zeromq(multi=True) - for handler in handlers: - for test in tests: - with handler: - self.log.warn(test) - record = subscriber.recv() - self.assertEqual(record.message, test) - self.assertEqual(record.channel, self.log.name) - - @require_module('zmq') - def test_zeromq_background_thread(self): - handler, subscriber = self._get_zeromq() - test_handler = logbook.TestHandler() - controller = subscriber.dispatch_in_background(test_handler) - - with handler: - self.log.warn('This is a warning') - self.log.error('This is an error') - - # stop the controller. This will also stop the loop and join the - # background process. Before that we give it a fraction of a second - # to get all results - time.sleep(0.2) - controller.stop() - - self.assertTrue(test_handler.has_warning('This is a warning')) - self.assertTrue(test_handler.has_error('This is an error')) - - @missing('zmq') - def test_missing_zeromq(self): - from logbook.queues import ZeroMQHandler, ZeroMQSubscriber - with self.assertRaises(RuntimeError): - ZeroMQHandler('tcp://127.0.0.1:42000') - with self.assertRaises(RuntimeError): - ZeroMQSubscriber('tcp://127.0.0.1:42000') - - @require_module('multiprocessing') - def test_multi_processing_handler(self): - from multiprocessing import Process, Queue - from logbook.queues import MultiProcessingHandler, \ - MultiProcessingSubscriber - queue = Queue(-1) - test_handler = logbook.TestHandler() - subscriber = MultiProcessingSubscriber(queue) - - def send_back(): - handler = MultiProcessingHandler(queue) - handler.push_thread() - try: - logbook.warn('Hello World') - finally: - handler.pop_thread() - - p = Process(target=send_back) - p.start() - p.join() - - with test_handler: - subscriber.dispatch_once() - self.assert_(test_handler.has_warning('Hello World')) - - def test_threaded_wrapper_handler(self): - from logbook.queues import ThreadedWrapperHandler - test_handler = logbook.TestHandler() - with ThreadedWrapperHandler(test_handler) as handler: - self.log.warn('Just testing') - self.log.error('More testing') - - # give it some time to sync up - handler.close() - - self.assertTrue(not handler.controller.running) - self.assertTrue(test_handler.has_warning('Just testing')) - self.assertTrue(test_handler.has_error('More testing')) - - @require_module('execnet') - def test_execnet_handler(self): - def run_on_remote(channel): - import logbook - from logbook.queues import ExecnetChannelHandler - handler = ExecnetChannelHandler(channel) - log = logbook.Logger("Execnet") - handler.push_application() - log.info('Execnet works') - - import execnet - gw = execnet.makegateway() - channel = gw.remote_exec(run_on_remote) - from logbook.queues import ExecnetChannelSubscriber - subscriber = ExecnetChannelSubscriber(channel) - record = subscriber.recv() - self.assertEqual(record.msg, 'Execnet works') - gw.exit() - - @require_module('multiprocessing') - def test_subscriber_group(self): - from multiprocessing import Process, Queue - from logbook.queues import MultiProcessingHandler, \ - MultiProcessingSubscriber, SubscriberGroup - a_queue = Queue(-1) - b_queue = Queue(-1) - test_handler = logbook.TestHandler() - subscriber = SubscriberGroup([ - MultiProcessingSubscriber(a_queue), - MultiProcessingSubscriber(b_queue) - ]) - - def make_send_back(message, queue): - def send_back(): - with MultiProcessingHandler(queue): - logbook.warn(message) - return send_back - - for _ in range(10): - p1 = Process(target=make_send_back('foo', a_queue)) - p2 = Process(target=make_send_back('bar', b_queue)) - p1.start() - p2.start() - p1.join() - p2.join() - messages = [subscriber.recv().message for i in (1, 2)] - self.assertEqual(sorted(messages), ['bar', 'foo']) - - @require_module('redis') - def test_redis_handler(self): - import redis - from logbook.queues import RedisHandler - - KEY = 'redis' - FIELDS = ['message', 'host'] - r = redis.Redis(decode_responses=True) - redis_handler = RedisHandler(level=logbook.INFO, bubble=True) - #We don't want output for the tests, so we can wrap everything in a NullHandler - null_handler = logbook.NullHandler() - - #Check default values - with null_handler.applicationbound(): - with redis_handler: - logbook.info(LETTERS) - - key, message = r.blpop(KEY) - #Are all the fields in the record? - [self.assertTrue(message.find(field)) for field in FIELDS] - self.assertEqual(key, KEY) - self.assertTrue(message.find(LETTERS)) - - #Change the key of the handler and check on redis - KEY = 'test_another_key' - redis_handler.key = KEY - - with null_handler.applicationbound(): - with redis_handler: - logbook.info(LETTERS) - - key, message = r.blpop(KEY) - self.assertEqual(key, KEY) - - #Check that extra fields are added if specified when creating the handler - FIELDS.append('type') - extra_fields = {'type': 'test'} - del(redis_handler) - redis_handler = RedisHandler(key=KEY, level=logbook.INFO, - extra_fields=extra_fields, bubble=True) - - with null_handler.applicationbound(): - with redis_handler: - logbook.info(LETTERS) - - key, message = r.blpop(KEY) - [self.assertTrue(message.find(field)) for field in FIELDS] - self.assertTrue(message.find('test')) - - #And finally, check that fields are correctly added if appended to the - #log message - FIELDS.append('more_info') - with null_handler.applicationbound(): - with redis_handler: - logbook.info(LETTERS, more_info='This works') - - key, message = r.blpop(KEY) - [self.assertTrue(message.find(field)) for field in FIELDS] - self.assertTrue(message.find('This works')) + assert handler.has_debug('a debug message') + assert handler.has_info('an info message') + assert handler.has_warning('warning part 1') + assert handler.has_warning('warning part 2') + assert handler.has_notice('notice') + assert handler.has_error('an error') + assert handler.has_critical('pretty critical') + assert handler.has_critical('critical too') + assert handler.records[0].channel == 'Generic' + assert handler.records[0].dispatcher is None -class TicketingTestCase(LogbookTestCase): - - @require_module('sqlalchemy') - def test_basic_ticketing(self): - from logbook.ticketing import TicketingHandler - with TicketingHandler('sqlite:///') as handler: - for x in xrange(5): - self.log.warn('A warning') - self.log.info('An error') - if x < 2: - try: - 1 / 0 - except Exception: - self.log.exception() - - self.assertEqual(handler.db.count_tickets(), 3) - tickets = handler.db.get_tickets() - self.assertEqual(len(tickets), 3) - self.assertEqual(tickets[0].level, logbook.INFO) - self.assertEqual(tickets[1].level, logbook.WARNING) - self.assertEqual(tickets[2].level, logbook.ERROR) - self.assertEqual(tickets[0].occurrence_count, 5) - self.assertEqual(tickets[1].occurrence_count, 5) - self.assertEqual(tickets[2].occurrence_count, 2) - self.assertEqual(tickets[0].last_occurrence.level, logbook.INFO) - - tickets[0].solve() - self.assert_(tickets[0].solved) - tickets[0].delete() - - ticket = handler.db.get_ticket(tickets[1].ticket_id) - self.assertEqual(ticket, tickets[1]) - - occurrences = handler.db.get_occurrences(tickets[2].ticket_id, - order_by='time') - self.assertEqual(len(occurrences), 2) - record = occurrences[0] - self.assertIn(__file_without_pyc__, record.filename) - # avoid 2to3 destroying our assertion - self.assertEqual(getattr(record, 'func_name'), 'test_basic_ticketing') - self.assertEqual(record.level, logbook.ERROR) - self.assertEqual(record.thread, get_ident()) - self.assertEqual(record.process, os.getpid()) - self.assertEqual(record.channel, 'testlogger') - self.assertIn('1 / 0', record.formatted_exception) - -class HelperTestCase(LogbookTestCase): - - def test_jsonhelper(self): - from logbook.helpers import to_safe_json - - class Bogus(object): - def __str__(self): - return 'bogus' - - rv = to_safe_json([ - None, - 'foo', - u('jäger'), - 1, - datetime(2000, 1, 1), - {'jäger1': 1, u('jäger2'): 2, Bogus(): 3, 'invalid': object()}, - object() # invalid - ]) - self.assertEqual( - rv, [None, u('foo'), u('jäger'), 1, '2000-01-01T00:00:00Z', - {u('jäger1'): 1, u('jäger2'): 2, u('bogus'): 3, - u('invalid'): None}, None]) - - def test_datehelpers(self): - from logbook.helpers import format_iso8601, parse_iso8601 - now = datetime.now() - rv = format_iso8601() - self.assertEqual(rv[:4], str(now.year)) - - self.assertRaises(ValueError, parse_iso8601, 'foo') - v = parse_iso8601('2000-01-01T00:00:00.12Z') - self.assertEqual(v.microsecond, 120000) - v = parse_iso8601('2000-01-01T12:00:00+01:00') - self.assertEqual(v.hour, 11) - v = parse_iso8601('2000-01-01T12:00:00-01:00') - self.assertEqual(v.hour, 13) - -class UnicodeTestCase(LogbookTestCase): - # in Py3 we can just assume a more uniform unicode environment - @require_py3 - def test_default_format_unicode(self): - with capturing_stderr_context() as stream: - self.log.warn('\u2603') - self.assertIn('WARNING: testlogger: \u2603', stream.getvalue()) - - @require_py3 - def test_default_format_encoded(self): - with capturing_stderr_context() as stream: - # it's a string but it's in the right encoding so don't barf - self.log.warn('\u2603') - self.assertIn('WARNING: testlogger: \u2603', stream.getvalue()) - - @require_py3 - def test_default_format_bad_encoding(self): - with capturing_stderr_context() as stream: - # it's a string, is wrong, but just dump it in the logger, - # don't try to decode/encode it - self.log.warn('Русский'.encode('koi8-r')) - self.assertIn("WARNING: testlogger: b'\\xf2\\xd5\\xd3\\xd3\\xcb\\xc9\\xca'", stream.getvalue()) - - @require_py3 - def test_custom_unicode_format_unicode(self): - format_string = ('[{record.level_name}] ' - '{record.channel}: {record.message}') - with capturing_stderr_context() as stream: - with logbook.StderrHandler(format_string=format_string): - self.log.warn("\u2603") - self.assertIn('[WARNING] testlogger: \u2603', stream.getvalue()) - - @require_py3 - def test_custom_string_format_unicode(self): - format_string = ('[{record.level_name}] ' - '{record.channel}: {record.message}') - with capturing_stderr_context() as stream: - with logbook.StderrHandler(format_string=format_string): - self.log.warn('\u2603') - self.assertIn('[WARNING] testlogger: \u2603', stream.getvalue()) - - @require_py3 - def test_unicode_message_encoded_params(self): - with capturing_stderr_context() as stream: - self.log.warn("\u2603 {0}", "\u2603".encode('utf8')) - self.assertIn("WARNING: testlogger: \u2603 b'\\xe2\\x98\\x83'", stream.getvalue()) - - @require_py3 - def test_encoded_message_unicode_params(self): - with capturing_stderr_context() as stream: - self.log.warn('\u2603 {0}'.encode('utf8'), '\u2603') - self.assertIn('WARNING: testlogger: \u2603 \u2603', stream.getvalue()) +def test_level_lookup_failures(): + with pytest.raises(LookupError): + logbook.get_level_name(37) + with pytest.raises(LookupError): + logbook.lookup_level('FOO') diff --git a/tests/test_logger.py b/tests/test_logger.py new file mode 100644 index 0000000..8b6a9fd --- /dev/null +++ b/tests/test_logger.py @@ -0,0 +1,28 @@ +import logbook + + +def test_level_properties(logger): + assert logger.level == logbook.NOTSET + assert logger.level_name == 'NOTSET' + logger.level_name = 'WARNING' + assert logger.level == logbook.WARNING + logger.level = logbook.ERROR + assert logger.level_name == 'ERROR' + + +def test_reflected_properties(logger): + group = logbook.LoggerGroup() + group.add_logger(logger) + assert logger.group == group + group.level = logbook.ERROR + assert logger.level == logbook.ERROR + assert logger.level_name == 'ERROR' + group.level = logbook.WARNING + assert logger.level == logbook.WARNING + assert logger.level_name == 'WARNING' + logger.level = logbook.CRITICAL + group.level = logbook.DEBUG + assert logger.level == logbook.CRITICAL + assert logger.level_name == 'CRITICAL' + group.remove_logger(logger) + assert logger.group is None diff --git a/tests/test_logging_api.py b/tests/test_logging_api.py new file mode 100644 index 0000000..936c147 --- /dev/null +++ b/tests/test_logging_api.py @@ -0,0 +1,92 @@ +import pickle +import sys + +import logbook +from logbook.helpers import iteritems, xrange + +import pytest + + +def test_basic_logging(active_handler, logger): + logger.warn('This is a warning. Nice hah?') + + assert active_handler.has_warning('This is a warning. Nice hah?') + assert active_handler.formatted_records == [ + '[WARNING] testlogger: This is a warning. Nice hah?'] + + +def test_exception_catching(active_handler, logger): + assert not active_handler.has_error() + try: + 1 / 0 + except Exception: + logger.exception() + try: + 1 / 0 + except Exception: + logger.exception('Awesome') + assert active_handler.has_error('Uncaught exception occurred') + assert active_handler.has_error('Awesome') + assert active_handler.records[0].exc_info is not None + assert '1 / 0' in active_handler.records[0].formatted_exception + + +def test_exception_catching_with_unicode(): + """ See https://github.com/mitsuhiko/logbook/issues/104 + """ + try: + raise Exception(u('\u202a test \u202c')) + except: + r = logbook.LogRecord('channel', 'DEBUG', 'test', exc_info=sys.exc_info()) + r.exception_message + + +@pytest.mark.parametrize('as_tuple', [True, False]) +def test_exc_info(as_tuple, logger, active_handler): + try: + 1 / 0 + except Exception: + exc_info = sys.exc_info() + logger.info("Exception caught", exc_info=exc_info if as_tuple else True) + assert active_handler.records[0].exc_info is not None + assert active_handler.records[0].exc_info == exc_info + + +def test_to_dict(logger, active_handler): + try: + 1 / 0 + except Exception: + logger.exception() + record = active_handler.records[0] + + exported = record.to_dict() + record.close() + imported = logbook.LogRecord.from_dict(exported) + for key, value in iteritems(record.__dict__): + if key[0] == '_': + continue + assert value == getattr(imported, key) + + +def test_pickle(active_handler, logger): + try: + 1 / 0 + except Exception: + logger.exception() + record = active_handler.records[0] + record.pull_information() + record.close() + + for p in xrange(pickle.HIGHEST_PROTOCOL): + exported = pickle.dumps(record, p) + imported = pickle.loads(exported) + for key, value in iteritems(record.__dict__): + if key[0] == '_': + continue + imported_value = getattr(imported, key) + if isinstance(value, ZeroDivisionError): + # in Python 3.2, ZeroDivisionError(x) != ZeroDivisionError(x) + assert type(value) is type(imported_value) + assert value.args == imported_value.args + else: + assert value == imported_value diff --git a/tests/test_logging_compat.py b/tests/test_logging_compat.py new file mode 100644 index 0000000..f983078 --- /dev/null +++ b/tests/test_logging_compat.py @@ -0,0 +1,83 @@ +import functools +from random import randrange + +import logbook +import logbook.compat +from logbook.helpers import StringIO + +import pytest + +from .utils import capturing_stderr_context + + +__file_without_pyc__ = __file__ +if __file_without_pyc__.endswith(".pyc"): + __file_without_pyc__ = __file_without_pyc__[:-1] + + +@pytest.mark.parametrize('set_root_logger_level', [True, False]) +def test_basic_compat(request, set_root_logger_level): + import logging + from logbook.compat import redirected_logging + + # mimic the default logging setting + request.addfinalizer(functools.partial(logging.root.setLevel, logging.root.level)) + logging.root.setLevel(logging.WARNING) + + name = 'test_logbook-%d' % randrange(1 << 32) + logger = logging.getLogger(name) + + with logbook.TestHandler(bubble=True) as handler: + with capturing_stderr_context() as captured: + with redirected_logging(set_root_logger_level): + logger.debug('This is from the old system') + logger.info('This is from the old system') + logger.warn('This is from the old %s', 'system') + logger.error('This is from the old system') + logger.critical('This is from the old system') + assert ('WARNING: %s: This is from the old system' % name) in captured.getvalue() + if set_root_logger_level: + assert handler.records[0].level == logbook.DEBUG + else: + assert handler.records[0].level == logbook.WARNING + assert handler.records[0].msg == 'This is from the old %s' + + +def test_redirect_logbook(): + import logging + out = StringIO() + logger = logging.getLogger() + logbook_logger = logbook.Logger('testlogger') + old_handlers = logger.handlers[:] + handler = logging.StreamHandler(out) + handler.setFormatter(logging.Formatter( + '%(name)s:%(levelname)s:%(message)s')) + logger.handlers[:] = [handler] + try: + with logbook.compat.LoggingHandler(): + logbook_logger.warn("This goes to logging") + pieces = out.getvalue().strip().split(':') + assert pieces == ['testlogger', 'WARNING', 'This goes to logging'] + finally: + logger.handlers[:] = old_handlers + + +from itertools import count +test_warning_redirections_i = count() + + +def test_warning_redirections(): + from logbook.compat import redirected_warnings + with logbook.TestHandler() as handler: + redirector = redirected_warnings() + redirector.start() + try: + from warnings import warn, resetwarnings + resetwarnings() + warn(RuntimeWarning('Testing' + str(next(test_warning_redirections_i)))) + finally: + redirector.end() + + assert len(handler.records) == 1 + assert handler.formatted_records[0].startswith('[WARNING] RuntimeWarning: Testing') + assert __file_without_pyc__ in handler.records[0].filename diff --git a/tests/test_logging_times.py b/tests/test_logging_times.py new file mode 100644 index 0000000..758c2f2 --- /dev/null +++ b/tests/test_logging_times.py @@ -0,0 +1,46 @@ +from datetime import datetime + +import logbook + +import pytest + +from .utils import get_total_delta_seconds + + +def test_timedate_format(activation_strategy, logger): + """ + tests the logbook.set_datetime_format() function + """ + FORMAT_STRING = '{record.time:%H:%M:%S.%f} {record.message}' + handler = logbook.TestHandler(format_string=FORMAT_STRING) + with activation_strategy(handler): + logbook.set_datetime_format('utc') + try: + logger.warn('This is a warning.') + time_utc = handler.records[0].time + logbook.set_datetime_format('local') + logger.warn('This is a warning.') + time_local = handler.records[1].time + finally: + # put back the default time factory + logbook.set_datetime_format('utc') + + # get the expected difference between local and utc time + t1 = datetime.now() + t2 = datetime.utcnow() + + tz_minutes_diff = get_total_delta_seconds(t1 - t2)/60.0 + + if abs(tz_minutes_diff) < 1: + pytest.skip('Cannot test utc/localtime differences ' + 'if they vary by less than one minute...') + + # get the difference between LogRecord local and utc times + logbook_minutes_diff = get_total_delta_seconds(time_local - time_utc)/60.0 + assert abs(logbook_minutes_diff) > 1, ('Localtime does not differ from UTC by more than 1 ' + 'minute (Local: %s, UTC: %s)' % (time_local, time_utc)) + + ratio = logbook_minutes_diff / tz_minutes_diff + + assert ratio > 0.99 + assert ratio < 1.01 diff --git a/tests/test_mail_handler.py b/tests/test_mail_handler.py new file mode 100644 index 0000000..18803a4 --- /dev/null +++ b/tests/test_mail_handler.py @@ -0,0 +1,105 @@ +import base64 +import re +import sys + +import logbook +from logbook.helpers import u + +from .utils import capturing_stderr_context, make_fake_mail_handler + +__file_without_pyc__ = __file__ +if __file_without_pyc__.endswith('.pyc'): + __file_without_pyc__ = __file_without_pyc__[:-1] + + +def test_mail_handler(activation_strategy, logger): + subject = u('\xf8nicode') + handler = make_fake_mail_handler(subject=subject) + with capturing_stderr_context() as fallback: + with activation_strategy(handler): + logger.warn('This is not mailed') + try: + 1 / 0 + except Exception: + logger.exception(u('Viva la Espa\xf1a')) + + if not handler.mails: + # if sending the mail failed, the reason should be on stderr + assert False, fallback.getvalue() + + assert len(handler.mails) == 1 + sender, receivers, mail = handler.mails[0] + mail = mail.replace('\r', '') + assert sender == handler.from_addr + assert '=?utf-8?q?=C3=B8nicode?=' in mail + header, data = mail.split('\n\n', 1) + if 'Content-Transfer-Encoding: base64' in header: + data = base64.b64decode(data).decode('utf-8') + assert re.search('Message type:\s+ERROR', data) + assert re.search('Location:.*%s' % re.escape(__file_without_pyc__), data) + assert re.search('Module:\s+%s' % __name__, data) + assert re.search('Function:\s+test_mail_handler', data) + body = u('Viva la Espa\xf1a') + if sys.version_info < (3, 0): + body = body.encode('utf-8') + assert body in data + assert '\nTraceback (most' in data + assert '1 / 0' in data + assert 'This is not mailed' in fallback.getvalue() + + +def test_mail_handler_batching(activation_strategy, logger): + mail_handler = make_fake_mail_handler() + handler = logbook.FingersCrossedHandler(mail_handler, reset=True) + with activation_strategy(handler): + logger.warn('Testing') + logger.debug('Even more') + logger.error('And this triggers it') + logger.info('Aha') + logger.error('And this triggers it again!') + + assert len(mail_handler.mails) == 2 + mail = mail_handler.mails[0][2] + + pieces = mail.split('Log records that led up to this one:') + assert len(pieces) == 2 + body, rest = pieces + rest = rest.replace('\r', '') + + assert re.search('Message type:\s+ERROR', body) + assert re.search('Module:\s+%s' % __name__, body) + assert re.search('Function:\s+test_mail_handler_batching', body) + + related = rest.strip().split('\n\n') + assert len(related) == 2 + assert re.search('Message type:\s+WARNING', related[0]) + assert re.search('Message type:\s+DEBUG', related[1]) + + assert 'And this triggers it again' in mail_handler.mails[1][2] + + +def test_group_handler_mail_combo(activation_strategy, logger): + mail_handler = make_fake_mail_handler(level=logbook.DEBUG) + handler = logbook.GroupHandler(mail_handler) + with activation_strategy(handler): + logger.error('The other way round') + logger.warn('Testing') + logger.debug('Even more') + assert mail_handler.mails == [] + + assert len(mail_handler.mails) == 1 + mail = mail_handler.mails[0][2] + + pieces = mail.split('Other log records in the same group:') + assert len(pieces) == 2 + body, rest = pieces + rest = rest.replace('\r', '') + + assert re.search('Message type:\\s+ERROR', body) + assert re.search('Module:\s+' + __name__, body) + assert re.search('Function:\s+test_group_handler_mail_combo', body) + + related = rest.strip().split('\n\n') + assert len(related) == 2 + assert re.search('Message type:\s+WARNING', related[0]) + assert re.search('Message type:\s+DEBUG', related[1]) diff --git a/tests/test_more.py b/tests/test_more.py new file mode 100644 index 0000000..e762ab9 --- /dev/null +++ b/tests/test_more.py @@ -0,0 +1,148 @@ +import sys + +import logbook +from logbook.helpers import StringIO + +import pytest + +from .utils import capturing_stderr_context, missing, require_module + + +@require_module('jinja2') +def test_jinja_formatter(logger): + from logbook.more import JinjaFormatter + fmter = JinjaFormatter('{{ record.channel }}/{{ record.level_name }}') + handler = logbook.TestHandler() + handler.formatter = fmter + with handler: + logger.info('info') + assert 'testlogger/INFO' in handler.formatted_records + + +@missing('jinja2') +def test_missing_jinja2(): + from logbook.more import JinjaFormatter + # check the RuntimeError is raised + with pytest.raises(RuntimeError): + JinjaFormatter('dummy') + + +def test_colorizing_support(logger): + from logbook.more import ColorizedStderrHandler + + class TestColorizingHandler(ColorizedStderrHandler): + + def should_colorize(self, record): + return True + stream = StringIO() + with TestColorizingHandler(format_string='{record.message}') as handler: + logger.error('An error') + logger.warn('A warning') + logger.debug('A debug message') + lines = handler.stream.getvalue().rstrip('\n').splitlines() + assert lines == [ + '\x1b[31;01mAn error\x1b[39;49;00m', + '\x1b[33;01mA warning\x1b[39;49;00m', + '\x1b[37mA debug message\x1b[39;49;00m'] + + +def test_tagged(default_handler): + from logbook.more import TaggingLogger, TaggingHandler + stream = StringIO() + second_handler = logbook.StreamHandler(stream) + + logger = TaggingLogger('name', ['cmd']) + handler = TaggingHandler(dict( + info=default_handler, + cmd=second_handler, + both=[default_handler, second_handler], + )) + handler.bubble = False + + with handler: + with capturing_stderr_context() as captured: + logger.log('info', 'info message') + logger.log('both', 'all message') + logger.cmd('cmd message') + + stderr = captured.getvalue() + + assert 'info message' in stderr + assert 'all message' in stderr + assert 'cmd message' not in stderr + + stringio = stream.getvalue() + + assert 'info message' not in stringio + assert 'all message' in stringio + assert 'cmd message' in stringio + + +def test_tagging_logger(default_handler): + from logbook import StderrHandler + from logbook.more import TaggingLogger + stream = StringIO() + + logger = TaggingLogger('tagged', ['a', 'b']) + handler = StderrHandler(format_string="{record.msg}|{record.extra[tags]}") + + with handler: + with capturing_stderr_context() as captured: + logger.a("a") + logger.b("b") + + stderr = captured.getvalue() + + assert "a|['a']" in stderr + assert "a|['b']" not in stderr + assert "b|['b']" in stderr + assert "b|['a']" not in stderr + + +def test_external_application_handler(tmpdir, logger): + from logbook.more import ExternalApplicationHandler as Handler + fn = tmpdir.join('tempfile') + handler = Handler([sys.executable, '-c', r'''if 1: + f = open(%(tempfile)s, 'w') + try: + f.write('{record.message}\n') + finally: + f.close() + ''' % {'tempfile': repr(str(fn))}]) + with handler: + logger.error('this is a really bad idea') + with fn.open() as rf: + contents = rf.read().strip() + assert contents == 'this is a really bad idea' + + +def test_exception_handler(logger): + from logbook.more import ExceptionHandler + + with ExceptionHandler(ValueError): + with pytest.raises(ValueError) as caught: + logger.info('here i am') + assert 'INFO: testlogger: here i am' in caught.value.args[0] + + +def test_exception_handler_specific_level(logger): + from logbook.more import ExceptionHandler + with logbook.TestHandler() as test_handler: + with pytest.raises(ValueError) as caught: + with ExceptionHandler(ValueError, level='WARNING'): + logger.info('this is irrelevant') + logger.warn('here i am') + assert 'WARNING: testlogger: here i am' in caught.value.args[0] + assert 'this is irrelevant' in test_handler.records[0].message + + +def test_dedup_handler(logger): + from logbook.more import DedupHandler + with logbook.TestHandler() as test_handler: + with DedupHandler(): + logger.info('foo') + logger.info('bar') + logger.info('foo') + assert 2 == len(test_handler.records) + assert 'message repeated 2 times: foo' in test_handler.records[0].message + assert 'message repeated 1 times: bar' in test_handler.records[1].message diff --git a/tests/test_null_handler.py b/tests/test_null_handler.py new file mode 100644 index 0000000..c84dc7d --- /dev/null +++ b/tests/test_null_handler.py @@ -0,0 +1,50 @@ +import logbook + +from .utils import capturing_stderr_context + + +def test_null_handler(activation_strategy, logger): + with capturing_stderr_context() as captured: + with activation_strategy(logbook.NullHandler()): + with activation_strategy(logbook.TestHandler(level='ERROR')) as handler: + logger.error('An error') + logger.warn('A warning') + assert captured.getvalue() == '' + assert (not handler.has_warning('A warning')) + assert handler.has_error('An error') + + +def test_blackhole_setting(activation_strategy): + null_handler = logbook.NullHandler() + heavy_init = logbook.LogRecord.heavy_init + with activation_strategy(null_handler): + def new_heavy_init(self): + raise RuntimeError('should not be triggered') + logbook.LogRecord.heavy_init = new_heavy_init + try: + with activation_strategy(null_handler): + logbook.warn('Awesome') + finally: + logbook.LogRecord.heavy_init = heavy_init + + null_handler.bubble = True + with capturing_stderr_context() as captured: + logbook.warning('Not a blockhole') + assert captured.getvalue() != '' + + +def test_null_handler_filtering(activation_strategy): + logger1 = logbook.Logger("1") + logger2 = logbook.Logger("2") + outer = logbook.TestHandler() + inner = logbook.NullHandler() + + inner.filter = lambda record, handler: record.dispatcher is logger1 + + with activation_strategy(outer): + with activation_strategy(inner): + logger1.warn("1") + logger2.warn("2") + + assert outer.has_warning('2', channel='2') + assert (not outer.has_warning('1', channel='1')) diff --git a/tests/test_processors.py b/tests/test_processors.py new file mode 100644 index 0000000..a58b421 --- /dev/null +++ b/tests/test_processors.py @@ -0,0 +1,97 @@ +import logbook + +from .utils import make_fake_mail_handler + + +def test_handler_filter_after_processor(activation_strategy, logger): + handler = make_fake_mail_handler(format_string='''\ +Subject: Application Error for {record.extra[path]} [{record.extra[method]}] + +Message type: {record.level_name} +Location: {record.filename}:{record.lineno} +Module: {record.module} +Function: {record.func_name} +Time: {record.time:%Y-%m-%d %H:%M:%S} +Remote IP: {record.extra[ip]} +Request: {record.extra[path]} [{record.extra[method]}] + +Message: + +{record.message} +''', + filter=lambda r, h: 'ip' in r.extra, + bubble=False) + + class Request(object): + remote_addr = '127.0.0.1' + method = 'GET' + path = '/index.html' + + def handle_request(request): + def inject_extra(record): + record.extra['ip'] = request.remote_addr + record.extra['method'] = request.method + record.extra['path'] = request.path + + processor = logbook.Processor(inject_extra) + with activation_strategy(processor): + handler.push_thread() + try: + try: + 1 / 0 + except Exception: + logger.exception('Exception happened during request') + finally: + handler.pop_thread() + + handle_request(Request()) + assert len(handler.mails) == 1 + mail = handler.mails[0][2] + assert 'Subject: Application Error for /index.html [GET]' in mail + assert '1 / 0' in mail + + +def test_handler_processors(activation_strategy, logger): + handler = make_fake_mail_handler(format_string='''\ +Subject: Application Error for {record.extra[path]} [{record.extra[method]}] + +Message type: {record.level_name} +Location: {record.filename}:{record.lineno} +Module: {record.module} +Function: {record.func_name} +Time: {record.time:%Y-%m-%d %H:%M:%S} +Remote IP: {record.extra[ip]} +Request: {record.extra[path]} [{record.extra[method]}] + +Message: + +{record.message} +''') + + class Request(object): + remote_addr = '127.0.0.1' + method = 'GET' + path = '/index.html' + + def handle_request(request): + def inject_extra(record): + record.extra['ip'] = request.remote_addr + record.extra['method'] = request.method + record.extra['path'] = request.path + + processor = logbook.Processor(inject_extra) + with activation_strategy(processor): + handler.push_thread() + try: + try: + 1 / 0 + except Exception: + logger.exception('Exception happened during request') + finally: + handler.pop_thread() + + handle_request(Request()) + assert len(handler.mails) == 1 + mail = handler.mails[0][2] + assert 'Subject: Application Error for /index.html [GET]' in mail + assert '1 / 0' in mail diff --git a/tests/test_queues.py b/tests/test_queues.py new file mode 100644 index 0000000..7550c9c --- /dev/null +++ b/tests/test_queues.py @@ -0,0 +1,309 @@ +# -*- coding: utf-8 -*- +import time +import socket + +from .utils import require_module, missing, LETTERS + +import logbook +from logbook.helpers import u + +import pytest + + +@require_module('zmq') +def test_zeromq_handler(logger, handlers, subscriber): + tests = [ + u('Logging something'), + u('Something with umlauts äöü'), + u('Something else for good measure'), + ] + for test in tests: + for handler in handlers: + with handler: + logger.warn(test) + record = subscriber.recv() + assert record.message == test + assert record.channel == logger.name + + +@require_module('zmq') +def test_zeromq_background_thread(logger, handlers, subscriber): + test_handler = logbook.TestHandler() + controller = subscriber.dispatch_in_background(test_handler) + + for handler in handlers: + with handler: + logger.warn('This is a warning') + logger.error('This is an error') + + # stop the controller. This will also stop the loop and join the + # background process. Before that we give it a fraction of a second + # to get all results + time.sleep(0.5) + controller.stop() + + assert test_handler.has_warning('This is a warning') + assert test_handler.has_error('This is an error') + + +@missing('zmq') +def test_missing_zeromq(): + from logbook.queues import ZeroMQHandler, ZeroMQSubscriber + with pytest.raises(RuntimeError): + ZeroMQHandler('tcp://127.0.0.1:42000') + with pytest.raises(RuntimeError): + ZeroMQSubscriber('tcp://127.0.0.1:42000') + + +class MultiProcessingHandlerSendBack(object): + def __init__(self, queue): + self.queue = queue + + def __call__(self): + from logbook.queues import MultiProcessingHandler + handler = MultiProcessingHandler(self.queue) + handler.push_thread() + try: + logbook.warn('Hello World') + finally: + handler.pop_thread() + + +@require_module('multiprocessing') +def test_multi_processing_handler(): + from multiprocessing import Process, Queue + from logbook.queues import MultiProcessingSubscriber + queue = Queue(-1) + test_handler = logbook.TestHandler() + subscriber = MultiProcessingSubscriber(queue) + + p = Process(target=MultiProcessingHandlerSendBack(queue)) + p.start() + p.join() + + with test_handler: + subscriber.dispatch_once() + assert test_handler.has_warning('Hello World') + + +def test_threaded_wrapper_handler(logger): + from logbook.queues import ThreadedWrapperHandler + test_handler = logbook.TestHandler() + with ThreadedWrapperHandler(test_handler) as handler: + logger.warn('Just testing') + logger.error('More testing') + + # give it some time to sync up + handler.close() + + assert (not handler.controller.running) + assert test_handler.has_warning('Just testing') + assert test_handler.has_error('More testing') + + +@require_module('execnet') +def test_execnet_handler(): + def run_on_remote(channel): + import logbook + from logbook.queues import ExecnetChannelHandler + handler = ExecnetChannelHandler(channel) + log = logbook.Logger('Execnet') + handler.push_application() + log.info('Execnet works') + + import execnet + gw = execnet.makegateway() + channel = gw.remote_exec(run_on_remote) + from logbook.queues import ExecnetChannelSubscriber + subscriber = ExecnetChannelSubscriber(channel) + record = subscriber.recv() + assert record.msg == 'Execnet works' + gw.exit() + + +class SubscriberGroupSendBack(object): + def __init__(self, message, queue): + self.message = message + self.queue = queue + + def __call__(self): + from logbook.queues import MultiProcessingHandler + with MultiProcessingHandler(self.queue): + logbook.warn(self.message) + + +@require_module('multiprocessing') +def test_subscriber_group(): + from multiprocessing import Process, Queue + from logbook.queues import MultiProcessingSubscriber, SubscriberGroup + a_queue = Queue(-1) + b_queue = Queue(-1) + subscriber = SubscriberGroup([ + MultiProcessingSubscriber(a_queue), + MultiProcessingSubscriber(b_queue) + ]) + + for _ in range(10): + p1 = Process(target=SubscriberGroupSendBack('foo', a_queue)) + p2 = Process(target=SubscriberGroupSendBack('bar', b_queue)) + p1.start() + p2.start() + p1.join() + p2.join() + messages = [subscriber.recv().message for i in (1, 2)] + assert sorted(messages) == ['bar', 'foo'] + + +@require_module('redis') +def test_redis_handler(): + import redis + from logbook.queues import RedisHandler + + KEY = 'redis' + FIELDS = ['message', 'host'] + r = redis.Redis(decode_responses=True) + redis_handler = RedisHandler(level=logbook.INFO, bubble=True) + # We don't want output for the tests, so we can wrap everything in a NullHandler + null_handler = logbook.NullHandler() + + # Check default values + with null_handler.applicationbound(): + with redis_handler: + logbook.info(LETTERS) + + key, message = r.blpop(KEY) + # Are all the fields in the record? + for field in FIELDS: + assert message.find(field) + assert key == KEY + assert message.find(LETTERS) + + # Change the key of the handler and check on redis + KEY = 'test_another_key' + redis_handler.key = KEY + + with null_handler.applicationbound(): + with redis_handler: + logbook.info(LETTERS) + + key, message = r.blpop(KEY) + assert key == KEY + + # Check that extra fields are added if specified when creating the handler + FIELDS.append('type') + extra_fields = {'type': 'test'} + del(redis_handler) + redis_handler = RedisHandler(key=KEY, level=logbook.INFO, + extra_fields=extra_fields, bubble=True) + + with null_handler.applicationbound(): + with redis_handler: + logbook.info(LETTERS) + + key, message = r.blpop(KEY) + for field in FIELDS: + assert message.find(field) + assert message.find('test') + + # And finally, check that fields are correctly added if appended to the + # log message + FIELDS.append('more_info') + with null_handler.applicationbound(): + with redis_handler: + logbook.info(LETTERS, more_info='This works') + + key, message = r.blpop(KEY) + for field in FIELDS: + assert message.find(field) + assert message.find('This works') + + +@require_module('redis') +def test_redis_handler_lpush(): + """ + Test if lpush stores messages in the right order + new items should be first on list + """ + import redis + from logbook.queues import RedisHandler + null_handler = logbook.NullHandler() + + redis_handler = RedisHandler(key='lpushed', push_method='lpush', + level=logbook.INFO, bubble=True) + + with null_handler.applicationbound(): + with redis_handler: + logbook.info("old item") + logbook.info("new item") + + time.sleep(1.5) + + r = redis.Redis(decode_responses=True) + logs = r.lrange('lpushed', 0, -1) + assert logs + assert "new item" in logs[0] + r.delete('lpushed') + + +@require_module('redis') +def test_redis_handler_rpush(): + """ + Test if rpush stores messages in the right order + old items should be first on list + """ + import redis + from logbook.queues import RedisHandler + null_handler = logbook.NullHandler() + + redis_handler = RedisHandler(key='rpushed', push_method='rpush', + level=logbook.INFO, bubble=True) + + with null_handler.applicationbound(): + with redis_handler: + logbook.info("old item") + logbook.info("new item") + + time.sleep(1.5) + + r = redis.Redis(decode_responses=True) + logs = r.lrange('rpushed', 0, -1) + assert logs + assert "old item" in logs[0] + r.delete('rpushed') + + +@pytest.fixture +def handlers(handlers_subscriber): + return handlers_subscriber[0] + + +@pytest.fixture +def subscriber(handlers_subscriber): + return handlers_subscriber[1] + + +@pytest.fixture +def handlers_subscriber(multi): + from logbook.queues import ZeroMQHandler, ZeroMQSubscriber + + # Get an unused port + tempsock = socket.socket(socket.AF_INET, socket.SOCK_STREAM) + tempsock.bind(('127.0.0.1', 0)) + host, unused_port = tempsock.getsockname() + tempsock.close() + + # Retrieve the ZeroMQ handler and subscriber + uri = 'tcp://%s:%d' % (host, unused_port) + if multi: + handlers = [ZeroMQHandler(uri, multi=True) for _ in range(3)] + else: + handlers = [ZeroMQHandler(uri)] + subscriber = ZeroMQSubscriber(uri, multi=multi) + # Enough time to start + time.sleep(0.1) + return handlers, subscriber + + +@pytest.fixture(params=[True, False]) +def multi(request): + return request.param diff --git a/tests/test_syslog_handler.py b/tests/test_syslog_handler.py new file mode 100644 index 0000000..8bd89ed --- /dev/null +++ b/tests/test_syslog_handler.py @@ -0,0 +1,41 @@ +import os +import socket +from contextlib import closing + +import logbook +from logbook.helpers import u + +import pytest + + +def test_syslog_handler(logger, activation_strategy, unix_sock_path): + to_test = [ + (socket.AF_INET, ('127.0.0.1', 0)), + ] + if hasattr(socket, 'AF_UNIX'): + to_test.append((socket.AF_UNIX, unix_sock_path)) + for sock_family, address in to_test: + with closing(socket.socket(sock_family, socket.SOCK_DGRAM)) as inc: + inc.bind(address) + inc.settimeout(1) + for app_name in [None, 'Testing']: + handler = logbook.SyslogHandler(app_name, inc.getsockname()) + with activation_strategy(handler): + logger.warn('Syslog is weird') + try: + rv = inc.recvfrom(1024)[0] + except socket.error: + assert False, 'got timeout on socket' + assert rv == (u('<12>%stestlogger: Syslog is weird\x00') % + ((app_name and (app_name + u(':'))) or u(''))).encode('utf-8') + + +@pytest.fixture +def unix_sock_path(request): + returned = "/tmp/__unixsock_logbook.test" + + @request.addfinalizer + def cleanup(): + if os.path.exists(returned): + os.unlink(returned) + return returned diff --git a/tests/test_test_handler.py b/tests/test_test_handler.py new file mode 100644 index 0000000..781b35a --- /dev/null +++ b/tests/test_test_handler.py @@ -0,0 +1,19 @@ +import re + + +def test_regex_matching(active_handler, logger): + logger.warn('Hello World!') + assert active_handler.has_warning(re.compile('^Hello')) + assert (not active_handler.has_warning(re.compile('world$'))) + assert (not active_handler.has_warning('^Hello World')) + + +def test_test_handler_cache(active_handler, logger): + logger.warn('First line') + assert len(active_handler.formatted_records) == 1 + cache = active_handler.formatted_records # store cache, to make sure it is identifiable + assert len(active_handler.formatted_records) == 1 + assert cache is active_handler.formatted_records + logger.warn('Second line invalidates cache') + assert len(active_handler.formatted_records) == 2 + assert (cache is not active_handler.formatted_records) diff --git a/tests/test_ticketing.py b/tests/test_ticketing.py new file mode 100644 index 0000000..efdb4e5 --- /dev/null +++ b/tests/test_ticketing.py @@ -0,0 +1,59 @@ +import os +try: + from thread import get_ident +except ImportError: + from _thread import get_ident + +import logbook +from logbook.helpers import xrange + +from .utils import require_module + +__file_without_pyc__ = __file__ +if __file_without_pyc__.endswith(".pyc"): + __file_without_pyc__ = __file_without_pyc__[:-1] + + +@require_module('sqlalchemy') +def test_basic_ticketing(logger): + from logbook.ticketing import TicketingHandler + with TicketingHandler('sqlite:///') as handler: + for x in xrange(5): + logger.warn('A warning') + logger.info('An error') + if x < 2: + try: + 1 / 0 + except Exception: + logger.exception() + + assert handler.db.count_tickets() == 3 + tickets = handler.db.get_tickets() + assert len(tickets) == 3 + assert tickets[0].level == logbook.INFO + assert tickets[1].level == logbook.WARNING + assert tickets[2].level == logbook.ERROR + assert tickets[0].occurrence_count == 5 + assert tickets[1].occurrence_count == 5 + assert tickets[2].occurrence_count == 2 + assert tickets[0].last_occurrence.level == logbook.INFO + + tickets[0].solve() + assert tickets[0].solved + tickets[0].delete() + + ticket = handler.db.get_ticket(tickets[1].ticket_id) + assert ticket == tickets[1] + + occurrences = handler.db.get_occurrences(tickets[2].ticket_id, + order_by='time') + assert len(occurrences) == 2 + record = occurrences[0] + assert __file_without_pyc__ in record.filename + # avoid 2to3 destroying our assertion + assert getattr(record, 'func_name') == 'test_basic_ticketing' + assert record.level == logbook.ERROR + assert record.thread == get_ident() + assert record.process == os.getpid() + assert record.channel == 'testlogger' + assert '1 / 0' in record.formatted_exception diff --git a/tests/test_unicode.py b/tests/test_unicode.py new file mode 100644 index 0000000..2b74eba --- /dev/null +++ b/tests/test_unicode.py @@ -0,0 +1,62 @@ +# -*- coding: utf-8 -*- +from .utils import require_py3, capturing_stderr_context + +import logbook + + +@require_py3 +def test_default_format_unicode(logger): + with capturing_stderr_context() as stream: + logger.warn('\u2603') + assert 'WARNING: testlogger: \u2603' in stream.getvalue() + + +@require_py3 +def test_default_format_encoded(logger): + with capturing_stderr_context() as stream: + # it's a string but it's in the right encoding so don't barf + logger.warn('\u2603') + assert 'WARNING: testlogger: \u2603' in stream.getvalue() + + +@require_py3 +def test_default_format_bad_encoding(logger): + with capturing_stderr_context() as stream: + # it's a string, is wrong, but just dump it in the logger, + # don't try to decode/encode it + logger.warn('Русский'.encode('koi8-r')) + assert "WARNING: testlogger: b'\\xf2\\xd5\\xd3\\xd3\\xcb\\xc9\\xca'" in stream.getvalue() + + +@require_py3 +def test_custom_unicode_format_unicode(logger): + format_string = ('[{record.level_name}] ' + '{record.channel}: {record.message}') + with capturing_stderr_context() as stream: + with logbook.StderrHandler(format_string=format_string): + logger.warn("\u2603") + assert '[WARNING] testlogger: \u2603' in stream.getvalue() + + +@require_py3 +def test_custom_string_format_unicode(logger): + format_string = ('[{record.level_name}] ' + '{record.channel}: {record.message}') + with capturing_stderr_context() as stream: + with logbook.StderrHandler(format_string=format_string): + logger.warn('\u2603') + assert '[WARNING] testlogger: \u2603' in stream.getvalue() + + +@require_py3 +def test_unicode_message_encoded_params(logger): + with capturing_stderr_context() as stream: + logger.warn("\u2603 {0}", "\u2603".encode('utf8')) + assert "WARNING: testlogger: \u2603 b'\\xe2\\x98\\x83'" in stream.getvalue() + + +@require_py3 +def test_encoded_message_unicode_params(logger): + with capturing_stderr_context() as stream: + logger.warn('\u2603 {0}'.encode('utf8'), '\u2603') + assert 'WARNING: testlogger: \u2603 \u2603' in stream.getvalue() diff --git a/tests/utils.py b/tests/utils.py index ebd54fd..d545806 100644 --- a/tests/utils.py +++ b/tests/utils.py @@ -6,19 +6,19 @@ :copyright: (c) 2010 by Armin Ronacher, Georg Brandl. :license: BSD, see LICENSE for more details. """ +import platform +import functools +import sys from contextlib import contextmanager -import platform -import sys -if platform.python_version() < "2.7": - import unittest2 as unittest -else: - import unittest import logbook from logbook.helpers import StringIO +import pytest + _missing = object() +LETTERS = "abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ" def get_total_delta_seconds(delta): """ @@ -27,23 +27,15 @@ return (delta.microseconds + (delta.seconds + delta.days * 24 * 3600) * 10**6) / 10**6 -require_py3 = unittest.skipUnless(sys.version_info[0] == 3, "Requires Python 3") +require_py3 = pytest.mark.skipif(sys.version_info[0] < 3, reason="Requires Python 3") def require_module(module_name): + found = True try: __import__(module_name) except ImportError: - return unittest.skip("Requires the %r module" % (module_name,)) - return lambda func: func + found = False -class LogbookTestSuite(unittest.TestSuite): - pass - -class LogbookTestCase(unittest.TestCase): - def setUp(self): - self.log = logbook.Logger('testlogger') - -# silence deprecation warning displayed on Py 3.2 -LogbookTestCase.assert_ = LogbookTestCase.assertTrue + return pytest.mark.skipif(not found, reason='Module {0} is required'.format(module_name)) def make_fake_mail_handler(**kwargs): class FakeMailHandler(logbook.MailHandler): @@ -64,6 +56,7 @@ def missing(name): def decorate(f): + @functools.wraps(f) def wrapper(*args, **kwargs): old = sys.modules.get(name, _missing) sys.modules[name] = None diff --git a/tox.ini b/tox.ini index d66c330..2151aa8 100644 --- a/tox.ini +++ b/tox.ini @@ -1,18 +1,28 @@ [tox] envlist=py26,py27,py32,py33,py34,pypy,docs +skipsdist=True [testenv] +whitelist_externals= + rm +deps= + pytest + Cython +changedir={toxinidir} commands= + {envbindir}/cython logbook/_speedups.pyx + {envpython} {toxinidir}/setup.py develop {envpython} {toxinidir}/scripts/test_setup.py - nosetests -w tests + py.test {toxinidir}/tests + rm -f {toxinidir}/logbook/_speedups.\{so,c\} + +[testenv:pypy] deps= - nose -changedir={toxinidir} - -[testenv:25] -deps= - ssl - nose + pytest +commands= + {envpython} {toxinidir}/setup.py develop + {envpython} {toxinidir}/scripts/test_setup.py + py.test {toxinidir}/tests [testenv:docs] deps=