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 new file mode 100644 index 00000000..80b963cc --- /dev/null +++ b/afkak/_logronomicon.py @@ -0,0 +1,314 @@ +# -*- 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 Logger, LogLevel, eventAsText, globalLogPublisher + +_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) + + +# Stub to satisfy linters +def _relay_for(logger): + pass + + +# Stub to satisfy linters +class _LogMagic: + pass + + +# 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']] + 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(_LogMagic): + """ + A logger with Afkak-specific augmentations. + + There is no public constructor. To create an :class:`Log` use one + of the backend implementations: + + - :class:`StdlibLogBackend.with_namespace()` + - :class:`TwistedLogBackend.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[:-1].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. + + 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 + """ + 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, + ) + + +class TwistedLogBackend(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 StdlibLogBackend(object): + """ + Send Afkak's logs to :mod:`logging` + """ + def with_namespace(self, namespace): + return Log( + observer=_relay_for(logging.getLogger(namespace)), + namespace=namespace, + ) 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 diff --git a/afkak/test/test_logronomicon.py b/afkak/test/test_logronomicon.py new file mode 100644 index 00000000..80adb3ab --- /dev/null +++ b/afkak/test/test_logronomicon.py @@ -0,0 +1,168 @@ +# -*- 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 .. import StdlibLogBackend, TwistedLogBackend +from .logtools import capture_logging + + +class TwistedLogBackendTests(TestCase): + """ + 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:`StdlibLogBackendTests`. + + :ivar log: + :class:`afkak.Log` instance under test. + + :ivar events: Events emitted by the logger. + """ + namespace = 'test' + + def setUp(self): + self.events = [] + self.backend = TwistedLogBackend(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 StdlibLogBackendTests(TestCase): + """ + 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`. + + :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 = StdlibLogBackend() + 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) + + 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) 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