From 4155cb92084358c0e7245dfde3bf3a9223e3351a Mon Sep 17 00:00:00 2001 From: Tom Most Date: Wed, 15 May 2019 13:26:50 -0700 Subject: [PATCH 1/4] Remove unused afkak.kafkacodec logger --- afkak/kafkacodec.py | 4 ---- 1 file changed, 4 deletions(-) diff --git a/afkak/kafkacodec.py b/afkak/kafkacodec.py index 274a9606..1d243eeb 100644 --- a/afkak/kafkacodec.py +++ b/afkak/kafkacodec.py @@ -4,7 +4,6 @@ from __future__ import absolute_import -import logging import struct import zlib from binascii import hexlify @@ -26,9 +25,6 @@ UnsupportedCodecError, ) -log = logging.getLogger(__name__) -log.addHandler(logging.NullHandler()) - _SUPPORTED_CODECS = (CODEC_GZIP, CODEC_NONE, CODEC_SNAPPY) ATTRIBUTE_CODEC_MASK = 0x03 MAX_BROKERS = 1024 From 3636491e96e174290f7d5ee011974316985c6018 Mon Sep 17 00:00:00 2001 From: Tom Most Date: Fri, 17 May 2019 22:21:14 -0700 Subject: [PATCH 2/4] Add logging facade --- afkak/_logronomicon.py | 302 ++++++++++++++++++++++++++++++++ afkak/test/test_logronomicon.py | 148 ++++++++++++++++ docs/logging.rst | 26 +++ setup.py | 2 +- 4 files changed, 477 insertions(+), 1 deletion(-) create mode 100644 afkak/_logronomicon.py create mode 100644 afkak/test/test_logronomicon.py create mode 100644 docs/logging.rst diff --git a/afkak/_logronomicon.py b/afkak/_logronomicon.py new file mode 100644 index 00000000..e9f9cf04 --- /dev/null +++ b/afkak/_logronomicon.py @@ -0,0 +1,302 @@ +# -*- coding: utf-8 -*- +# Copyright 2019 Ciena Corporation +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +""" +Afkak logging infrastructure + +This is a facade that can back into :mod:`logging` or :mod:`twisted.logger`. + +Features: + +- Uses the Twisted model internally, so logs are represented as structured + event dicts. +- Extends the Twisted model to include *context* data that is automatically + include in every event. +- Can add a prefix to each message based on the context. +- Doesn't mangle the :class:`logging.LogRecord` *filename*, *funcName*, or + *lineno* attributes (this is where we must petition elder evils). +""" + +import logging + +import attr +from twisted.logger import ( + ILogObserver, Logger, LogLevel, eventAsText, globalLogPublisher, +) +from zope.interface import implementer + +_logLevelToLoggingLevel = { + LogLevel.debug: logging.DEBUG, + LogLevel.info: logging.INFO, + LogLevel.warn: logging.WARNING, + LogLevel.error: logging.ERROR, + LogLevel.critical: logging.CRITICAL, +} + + +@attr.s(slots=True, str=False) +class _LazyMsg(object): + """ + A lazily-formatted message for the :mod:`logging` package. + + This is passed to the logging library like:: + + logging.debug(_LazyMsg(event)) + + It ends up as the :attr:`logging.LogRecord.msg` attribute. If the record's + :meth:`~logging.LogRecord.getMessage()` method is called (i.e., when + a handler actually wants to emit the message) the `__str__` method returns + a formatted message. + + :param dict event: + :mod:`twisted.logger` style event dict. + """ + _event = attr.ib() + + def __str__(self): + return eventAsText(self._event, False, False, False) + + +@implementer(ILogObserver) +@attr.s +class _StdlibRelay(object): + """ + Translate :mod:`twisted.logger` events into `logging.LogRecord` instances. + """ + _logger = attr.ib() + + def __call__(self, event): + if "log_failure" in event: + f = event['log_failure'] + exc_info = (f.type, f.value, f.getTracebackObject()) + else: + exc_info = None + + level = _logLevelToLoggingLevel[event['log_level']] + self._logger.log(level, _LazyMsg(event), exc_info=exc_info) + + +class Log(object): + """ + A logger with Afkak-specific augmentations. + + There is no public constructor. To create an :class:`Log` use one + of the backend implementations: + + - :class:`StdlibLogging.with_namespace()` + - :class:`TwistedLogging.with_namespace()` + + Add context information and prefixes using the :class:`Log` methods: + + - :meth:`with_context()` + - :meth:`with_prefix()` + + + """ + def __init__(self, observer, namespace, context=None, prefix=None): + """ + This constructor is private. + + :param str namespace: + Name of the Python module (i.e., ``__name__``). This is used as the + ``log_namespace`` of the event and should match the Python + :class:`logging.Logger` that the message is sent to. + + :param observer: :class:`twisted.logger.ILogObserver` + + :param dict context: + Keys to add to every event dict emitted by this logger. + + :param str prefix: + A format string (a-la :meth:`str.format()`) that may only reference + keys in *context*. + + """ + self._observer = observer + self._namespace = namespace + self._context = context or {} + self._prefix = prefix + ' ' if prefix else None + # FIXME: This should use twisted.logger's extended formatter + assert prefix is None or prefix.format(**context) is not None # Doesn't throw. + + # To avoid putting twisted.logger in the call stack (which would + # confuse logging.Logger.findCaller()) we generate events by invoking + # _logger which appends them to the _events. This is a gross hack. + # + # It would also be possible to reimplement what Logger does, but the + # "log_logger" key[1] in events is a problem: what if an observer expects + # that to be an instance of twisted.logger.Logger? We use the real + # thing out of an abundance of caution. + # + # [1]: https://twistedmatrix.com/documents/current/core/howto/logger.html#event-keys-added-by-the-system + self._events = [] + self._logger = Logger( + namespace=namespace, + observer=self._events.append, + ) + + def __repr__(self): + bits = ['<', self.__class__.__name__, ' ', self._namespace] + if self._prefix: + bits.append(' ') + # FIXME: This should use twisted.logger's extended formatter + bits.append(self._prefix.format(**self._context)) + bits.append('>') + return ''.join(bits) + + def with_context(self, **context): + """ + Construct a `Log` with additional context. + + :param dict context: + Additional keys to add to every event emitted by the logger. + + :returns: :class:`afkak.Log` instance + """ + new_context = self._context.copy() + new_context.update(context) + + return self.__class__( + namespace=self._namespace, + observer=self._observer, + context=new_context, + prefix=self._prefix, + ) + + def with_prefix(self, prefix): + """ + Construct a `Log` with an additional prefix. + + :param str prefix: + An additional prefix to add to each event's format string. This + prefix will appear *after* any prefix already present. + + :returns: :class:`afkak.Log` instance + """ + if self._prefix and prefix: + new_prefix = self._prefix + prefix + elif self._prefix: + new_prefix = self._prefix + else: + new_prefix = prefix + + return self.__class__( + namespace=self._namespace, + observer=self._observer, + context=self._context, + prefix=new_prefix, + ) + + def _emit(self, level, format, kwargs): + kwargs.update(self._context) + if self._prefix: + format = self._prefix + format + self._logger.emit(level, format, **kwargs) + event = self._events.pop() + assert not self._events + self._observer(event) + + def debug(self, format, **kwargs): + """ + Emit a log event at debug level + + :param format: Format string `per twisted.logger + `_ + :type format: str + + :param kwargs: Key/value pairs to include in the event. + """ + self._emit(LogLevel.debug, format, kwargs) + + def info(self, format, **kwargs): + """ + See :meth:`.debug()` + """ + self._emit(LogLevel.info, format, kwargs) + + def warn(self, format, **kwargs): + """ + See :meth:`.debug()` + """ + self._emit(LogLevel.warn, format, kwargs) + + def error(self, format, **kwargs): + """ + See :meth:`.debug()` + """ + self._emit(LogLevel.error, format, kwargs) + + def critical(self, format, **kwargs): + """ + See :meth:`.debug()` + """ + self._emit(LogLevel.critical, format, kwargs) + + def oops(self, failure, format, level=LogLevel.critical, **kwargs): + """ + Log an unexpected deferred failure + + Use this as a last-gasp errback:: + + d = defer.Deferred() + # ... + d.addErrback(log.oops, "BUG! {foo}", foo='1') + + The resulting message will include the failure's traceback. + + :param failure: An error + :type failure: :class:`twisted.python.failure.Failure` + + :param format: Format string `per twisted.logger + `_ + :type format: str + + :param level: + Level of the message. By default, :data:`LogLevel.critical` as + appropriate for a bug. + :type level: `twisted.logger.LogLevel` + + :returns: `None` to handle the error + """ + kwargs['log_failure'] = failure + self._emit(level, format, kwargs) + + +class TwistedLogging(object): + """ + Send Afkak's logs to :mod:`twisted.logger` + + :param observer: + The log observer to use. By default, the global one. + """ + def __init__(self, observer=globalLogPublisher): + self._observer = observer + + def with_namespace(self, namespace): + return Log( + observer=self._observer, + namespace=namespace, + ) + + +class StdlibLogging(object): + """ + Send Afkak's logs to :mod:`logging` + """ + def with_namespace(self, namespace): + return Log( + observer=_StdlibRelay(logging.getLogger(namespace)), + namespace=namespace, + ) diff --git a/afkak/test/test_logronomicon.py b/afkak/test/test_logronomicon.py new file mode 100644 index 00000000..4d5b7a18 --- /dev/null +++ b/afkak/test/test_logronomicon.py @@ -0,0 +1,148 @@ +# -*- coding: utf-8 -*- +# Copyright 2019 Ciena Corporation +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +import logging +from unittest import TestCase + +from twisted.logger import LogLevel, eventAsText +from twisted.python.failure import Failure + +from .._logronomicon import StdlibLogging, TwistedLogging +from .logtools import capture_logging + + +class TwistedLoggingTests(TestCase): + """ + Test `afkak.TwistedLogging`, the :mod:`twisted.logger` backend. + + These tests are pretty simple as they only need to test the plumbing. + Coverage of rendering is handled by :class:`StdlibLoggingTests`. + + :ivar log: + :class:`afkak.Log` instance under test. + + :ivar events: Events emitted by the logger. + """ + namespace = 'test' + + def setUp(self): + self.events = [] + self.backend = TwistedLogging(self.events.append) + self.log = self.backend.with_namespace(self.namespace) + + def test_prefix(self): + """ + The prefixes are prepended to the `log_format` field. + """ + self.log.debug('foo') + self.log.with_prefix('foo').debug('bar') + self.log.with_prefix('foo').with_prefix('bar').debug('biz') + + self.assertEqual([ + 'foo', + 'foo bar', + 'foo bar biz', + ], [e['log_format'] for e in self.events]) + + def test_context(self): + """ + Context is added to the messages emitted. + """ + self.log.with_context(foo='bar', bar='baz').info('{foo}{bar}', biz='biff') + + [e] = self.events + self.assertEqual(e['foo'], 'bar') + self.assertEqual(e['bar'], 'baz') + self.assertEqual(e['biz'], 'biff') + self.assertEqual('barbaz', eventAsText(e, False, False, False)) + + +class StdlibLoggingTests(TestCase): + """ + Test `afkak.StdlibLogging`, the :mod:`logging` library backend. + + These tests use the variable *log* for instances of :class:`afkak.Log`, + and *logger* for instances of `logging.Logger`. + + :ivar logger: + :class:`logging.Logger` to use in tests. It is configured not to + propagate messages upward. + + :ivar log: + :class:`afkak.Log` attached to *logger* + """ + namespace = __name__ + logger = logging.getLogger(namespace) + logger.propagate = False + + def setUp(self): + self.backend = StdlibLogging() + self.log = self.backend.with_namespace(self.namespace) + + def test_format(self): + """ + The facade produces `logging.LogRecord` instances that render + Twisted-style format strings. + """ + with capture_logging(self.logger) as records: + self.log.debug('{lvl} {f()}', lvl='debug', f=lambda: 10) + self.log.info('{lvl} {s!r}', lvl='info', s='20') + self.log.warn('{lvl} {d[k]}', lvl='warn', d={'k': '30'}) + self.log.error('{lvl} {lst[0]}', lvl='error', lst=[40]) + self.log.with_context(context=50).critical('{lvl} {context}', lvl='critical') + + self.assertEqual( + ['debug 10', "info '20'", 'warn 30', 'error 40', 'critical 50'], + [r.getMessage() for r in records], + ) + + def test_prefix(self): + """ + Each additional prefix is appended to the space-separated prefix list. + """ + log_with_context = self.log.with_context(prefix1='a', prefix2='b') + log_with_prefix = log_with_context.with_prefix('[{prefix1}]') + log_with_second_prefix = log_with_prefix.with_prefix('<{prefix2}>') + + with capture_logging(self.logger) as records: + self.log.info('hello {who}', who='world') + log_with_prefix.info('what {noun}', noun='now') + log_with_second_prefix.info('why?') + + [r1, r2, r3] = records + self.assertEqual('hello world', r1.getMessage()) + self.assertEqual('[a] what now', r2.getMessage()) + self.assertEqual('[a] why?', r3.getMessage()) + + def test_oops(self): + """ + The failure passed to `oops()` is converted to *exc_info* on the + `logging.LogRecord`. + """ + try: + raise IndentationError('...') + except Exception: + f = Failure() + exc_info = (f.type, f.value, f.getTracebackObject()) + + with capture_logging(self.logger) as records: + self.log.oops(f, 'Frobbed the {frizz}', frizz='froob') + self.log.oops(f, 'Failed at debug', level=LogLevel.debug) + + [r1, r2] = records + self.assertEqual('Frobbed the froob', r1.getMessage()) + self.assertEqual('Failed at debug', r2.getMessage()) + self.assertEqual(exc_info, r1.exc_info) + self.assertEqual(exc_info, r2.exc_info) diff --git a/docs/logging.rst b/docs/logging.rst new file mode 100644 index 00000000..f2375b5e --- /dev/null +++ b/docs/logging.rst @@ -0,0 +1,26 @@ +.. _logging: + +Logging in Afkak +================ + +.. default-role:: any + + + +Log objects +----------- + +.. autoclass:: afkak.Log + :members: + +StdlibLogging objects +--------------------- + +.. autoclass:: afkak.StdlibLogging + :members: + +TwistedLogging objects +---------------------- + +.. autoclass:: afkak.TwistedLogging + :members: diff --git a/setup.py b/setup.py index b890fb5d..b965ab59 100644 --- a/setup.py +++ b/setup.py @@ -20,7 +20,7 @@ version=version, install_requires=[ 'six', - 'Twisted>=18.7.0', # First release with @inlineCallbacks cancellation + 'Twisted>=18.9.0', # First release with twisted.logger.eventAsText ], # Afkak requires both b'' and u'' syntax, so it isn't compatible with early # Python 3 releases. Additionally, Python 3.3 is not supported because From 088d75be36d66342e0a5fd277bdc840247e3a77b Mon Sep 17 00:00:00 2001 From: Tom Most Date: Fri, 17 May 2019 22:25:39 -0700 Subject: [PATCH 3/4] Reexport at top level --- afkak/__init__.py | 2 ++ afkak/_logronomicon.py | 8 ++++---- afkak/test/test_logronomicon.py | 16 ++++++++-------- 3 files changed, 14 insertions(+), 12 deletions(-) diff --git a/afkak/__init__.py b/afkak/__init__.py index 3fbaa5dd..c9ee21d2 100644 --- a/afkak/__init__.py +++ b/afkak/__init__.py @@ -4,6 +4,7 @@ from __future__ import absolute_import +from ._logronomicon import Log, StdlibLogBackend, TwistedLogBackend from .client import KafkaClient from .common import ( CODEC_GZIP, CODEC_LZ4, CODEC_NONE, CODEC_SNAPPY, OFFSET_COMMITTED, @@ -23,6 +24,7 @@ __all__ = [ 'KafkaClient', 'Producer', 'Consumer', 'RoundRobinPartitioner', 'HashedPartitioner', + 'Log', 'StdlibLogBackend', 'TwistedLogBackend', 'create_message', 'create_message_set', 'CODEC_NONE', 'CODEC_GZIP', 'CODEC_LZ4', 'CODEC_SNAPPY', 'OFFSET_EARLIEST', 'OFFSET_LATEST', 'OFFSET_COMMITTED', diff --git a/afkak/_logronomicon.py b/afkak/_logronomicon.py index e9f9cf04..96fe8ca4 100644 --- a/afkak/_logronomicon.py +++ b/afkak/_logronomicon.py @@ -95,8 +95,8 @@ class Log(object): There is no public constructor. To create an :class:`Log` use one of the backend implementations: - - :class:`StdlibLogging.with_namespace()` - - :class:`TwistedLogging.with_namespace()` + - :class:`StdlibLogBackend.with_namespace()` + - :class:`TwistedLogBackend.with_namespace()` Add context information and prefixes using the :class:`Log` methods: @@ -274,7 +274,7 @@ def oops(self, failure, format, level=LogLevel.critical, **kwargs): self._emit(level, format, kwargs) -class TwistedLogging(object): +class TwistedLogBackend(object): """ Send Afkak's logs to :mod:`twisted.logger` @@ -291,7 +291,7 @@ def with_namespace(self, namespace): ) -class StdlibLogging(object): +class StdlibLogBackend(object): """ Send Afkak's logs to :mod:`logging` """ diff --git a/afkak/test/test_logronomicon.py b/afkak/test/test_logronomicon.py index 4d5b7a18..6381873f 100644 --- a/afkak/test/test_logronomicon.py +++ b/afkak/test/test_logronomicon.py @@ -19,16 +19,16 @@ from twisted.logger import LogLevel, eventAsText from twisted.python.failure import Failure -from .._logronomicon import StdlibLogging, TwistedLogging +from .. import StdlibLogBackend, TwistedLogBackend from .logtools import capture_logging -class TwistedLoggingTests(TestCase): +class TwistedLogBackendTests(TestCase): """ - Test `afkak.TwistedLogging`, the :mod:`twisted.logger` backend. + Test `afkak.TwistedLogBackend`, the :mod:`twisted.logger` backend. These tests are pretty simple as they only need to test the plumbing. - Coverage of rendering is handled by :class:`StdlibLoggingTests`. + Coverage of rendering is handled by :class:`StdlibLogBackendTests`. :ivar log: :class:`afkak.Log` instance under test. @@ -39,7 +39,7 @@ class TwistedLoggingTests(TestCase): def setUp(self): self.events = [] - self.backend = TwistedLogging(self.events.append) + self.backend = TwistedLogBackend(self.events.append) self.log = self.backend.with_namespace(self.namespace) def test_prefix(self): @@ -69,9 +69,9 @@ def test_context(self): self.assertEqual('barbaz', eventAsText(e, False, False, False)) -class StdlibLoggingTests(TestCase): +class StdlibLogBackendTests(TestCase): """ - Test `afkak.StdlibLogging`, the :mod:`logging` library backend. + Test `afkak.StdlibLogBackend`, the :mod:`logging` library backend. These tests use the variable *log* for instances of :class:`afkak.Log`, and *logger* for instances of `logging.Logger`. @@ -88,7 +88,7 @@ class StdlibLoggingTests(TestCase): logger.propagate = False def setUp(self): - self.backend = StdlibLogging() + self.backend = StdlibLogBackend() self.log = self.backend.with_namespace(self.namespace) def test_format(self): From b209cbea94d9262a74a4a1245ca5031e8b008610 Mon Sep 17 00:00:00 2001 From: Tom Most Date: Fri, 17 May 2019 23:15:50 -0700 Subject: [PATCH 4/4] ph'nglui mglw'nafh Cthulhu R'lyeh wgah'nagl fhtagn --- afkak/_logronomicon.py | 200 +++++++++++++++++--------------- afkak/test/test_logronomicon.py | 20 ++++ 2 files changed, 126 insertions(+), 94 deletions(-) diff --git a/afkak/_logronomicon.py b/afkak/_logronomicon.py index 96fe8ca4..80b963cc 100644 --- a/afkak/_logronomicon.py +++ b/afkak/_logronomicon.py @@ -32,10 +32,7 @@ import logging import attr -from twisted.logger import ( - ILogObserver, Logger, LogLevel, eventAsText, globalLogPublisher, -) -from zope.interface import implementer +from twisted.logger import Logger, LogLevel, eventAsText, globalLogPublisher _logLevelToLoggingLevel = { LogLevel.debug: logging.DEBUG, @@ -69,26 +66,112 @@ def __str__(self): return eventAsText(self._event, False, False, False) -@implementer(ILogObserver) -@attr.s -class _StdlibRelay(object): - """ - Translate :mod:`twisted.logger` events into `logging.LogRecord` instances. - """ - _logger = attr.ib() +# Stub to satisfy linters +def _relay_for(logger): + pass + + +# Stub to satisfy linters +class _LogMagic: + pass + - def __call__(self, event): - if "log_failure" in event: +# These methods must be compiled to look like they came from logging.__file__ +# because when the logging library walks up the stack to find the call location +# it reports the first call that isn't in the logging/__init__.py source file. +exec(compile(r''' +def _relay_for(logger): + def relay(event): + if 'log_failure' in event: f = event['log_failure'] exc_info = (f.type, f.value, f.getTracebackObject()) else: exc_info = None level = _logLevelToLoggingLevel[event['log_level']] - self._logger.log(level, _LazyMsg(event), exc_info=exc_info) + logger.log(level, _LazyMsg(event), exc_info=exc_info) + + return relay + + +class _LogMagic(object): + def _emit(self, level, format, kwargs): + kwargs.update(self._context) + if self._prefix: + format = self._prefix + format + self._logger.emit(level, format, **kwargs) + event = self._events.pop() + assert not self._events + self._observer(event) + + def debug(self, format, **kwargs): + """ + Emit a log event at debug level + + :param format: Format string `per twisted.logger + `_ + :type format: str + + :param kwargs: Key/value pairs to include in the event. + """ + self._emit(LogLevel.debug, format, kwargs) + + def info(self, format, **kwargs): + """ + See :meth:`.debug()` + """ + self._emit(LogLevel.info, format, kwargs) + + def warn(self, format, **kwargs): + """ + See :meth:`.debug()` + """ + self._emit(LogLevel.warn, format, kwargs) + + def error(self, format, **kwargs): + """ + See :meth:`.debug()` + """ + self._emit(LogLevel.error, format, kwargs) + + def critical(self, format, **kwargs): + """ + See :meth:`.debug()` + """ + self._emit(LogLevel.critical, format, kwargs) + + def oops(self, failure, format, level=LogLevel.critical, **kwargs): + """ + Log an unexpected deferred failure + + Use this as a last-gasp errback:: + + d = defer.Deferred() + # ... + d.addErrback(log.oops, "BUG! {foo}", foo='1') + + The resulting message will include the failure's traceback. + + :param failure: An error + :type failure: :class:`twisted.python.failure.Failure` + + :param format: Format string `per twisted.logger + `_ + :type format: str + + :param level: + Level of the message. By default, :data:`LogLevel.critical` as + appropriate for a bug. + :type level: `twisted.logger.LogLevel` + + :returns: `None` to handle the error + """ + kwargs['log_failure'] = failure + self._emit(level, format, kwargs) +''', logging._srcfile, 'exec')) -class Log(object): +class Log(_LogMagic): """ A logger with Afkak-specific augmentations. @@ -152,7 +235,7 @@ def __repr__(self): if self._prefix: bits.append(' ') # FIXME: This should use twisted.logger's extended formatter - bits.append(self._prefix.format(**self._context)) + bits.append(self._prefix[:-1].format(**self._context)) bits.append('>') return ''.join(bits) @@ -179,9 +262,12 @@ def with_prefix(self, prefix): """ Construct a `Log` with an additional prefix. - :param str prefix: - An additional prefix to add to each event's format string. This - prefix will appear *after* any prefix already present. + The new instance has the same namespace and context as this instance. + The new prefix will be added *after* any current prefix, joined by + a space. + + :param str prefix: Format string `per twisted.logger + `_ :returns: :class:`afkak.Log` instance """ @@ -199,80 +285,6 @@ def with_prefix(self, prefix): prefix=new_prefix, ) - def _emit(self, level, format, kwargs): - kwargs.update(self._context) - if self._prefix: - format = self._prefix + format - self._logger.emit(level, format, **kwargs) - event = self._events.pop() - assert not self._events - self._observer(event) - - def debug(self, format, **kwargs): - """ - Emit a log event at debug level - - :param format: Format string `per twisted.logger - `_ - :type format: str - - :param kwargs: Key/value pairs to include in the event. - """ - self._emit(LogLevel.debug, format, kwargs) - - def info(self, format, **kwargs): - """ - See :meth:`.debug()` - """ - self._emit(LogLevel.info, format, kwargs) - - def warn(self, format, **kwargs): - """ - See :meth:`.debug()` - """ - self._emit(LogLevel.warn, format, kwargs) - - def error(self, format, **kwargs): - """ - See :meth:`.debug()` - """ - self._emit(LogLevel.error, format, kwargs) - - def critical(self, format, **kwargs): - """ - See :meth:`.debug()` - """ - self._emit(LogLevel.critical, format, kwargs) - - def oops(self, failure, format, level=LogLevel.critical, **kwargs): - """ - Log an unexpected deferred failure - - Use this as a last-gasp errback:: - - d = defer.Deferred() - # ... - d.addErrback(log.oops, "BUG! {foo}", foo='1') - - The resulting message will include the failure's traceback. - - :param failure: An error - :type failure: :class:`twisted.python.failure.Failure` - - :param format: Format string `per twisted.logger - `_ - :type format: str - - :param level: - Level of the message. By default, :data:`LogLevel.critical` as - appropriate for a bug. - :type level: `twisted.logger.LogLevel` - - :returns: `None` to handle the error - """ - kwargs['log_failure'] = failure - self._emit(level, format, kwargs) - class TwistedLogBackend(object): """ @@ -297,6 +309,6 @@ class StdlibLogBackend(object): """ def with_namespace(self, namespace): return Log( - observer=_StdlibRelay(logging.getLogger(namespace)), + observer=_relay_for(logging.getLogger(namespace)), namespace=namespace, ) diff --git a/afkak/test/test_logronomicon.py b/afkak/test/test_logronomicon.py index 6381873f..80adb3ab 100644 --- a/afkak/test/test_logronomicon.py +++ b/afkak/test/test_logronomicon.py @@ -146,3 +146,23 @@ def test_oops(self): self.assertEqual('Failed at debug', r2.getMessage()) self.assertEqual(exc_info, r1.exc_info) self.assertEqual(exc_info, r2.exc_info) + + def test_caller(self): + """ + The caller location information on the `logging.LogRecord` points at + the actual caller, rather than the facade. + """ + with capture_logging(self.logger) as records: + self.log.debug('CALLER LOG MESSAGE') + + # Find the line number of the above line. + with open(__file__.rstrip('co'), 'rb') as f: + for i, line in enumerate(f): + if b"'CALLER LOG MESSAGE'" in line: + lineno = i + 1 + break + + [r] = records + self.assertEqual(r.funcName, 'test_caller') + self.assertTrue(r.filename.startswith('test_logronomicon.py')) + self.assertEqual(r.lineno, lineno)