532 lines
17 KiB
Python
532 lines
17 KiB
Python
|
###############################################################################
|
||
|
|
#
|
||
|
|
# The MIT License (MIT)
|
||
|
|
#
|
||
|
|
# Copyright (c) typedef int GmbH
|
||
|
|
#
|
||
|
|
# Permission is hereby granted, free of charge, to any person obtaining a copy
|
||
|
|
# of this software and associated documentation files (the "Software"), to deal
|
||
|
|
# in the Software without restriction, including without limitation the rights
|
||
|
|
# to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
|
||
|
|
# copies of the Software, and to permit persons to whom the Software is
|
||
|
|
# furnished to do so, subject to the following conditions:
|
||
|
|
#
|
||
|
|
# The above copyright notice and this permission notice shall be included in
|
||
|
|
# all copies or substantial portions of the Software.
|
||
|
|
#
|
||
|
|
# THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
|
||
|
|
# IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
|
||
|
|
# FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
|
||
|
|
# AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
|
||
|
|
# LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
|
||
|
|
# OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
|
||
|
|
# THE SOFTWARE.
|
||
|
|
#
|
||
|
|
###############################################################################
|
||
|
|
|
||
|
|
import io
|
||
|
|
import os
|
||
|
|
import sys
|
||
|
|
import weakref
|
||
|
|
import inspect
|
||
|
|
|
||
|
|
from functools import partial
|
||
|
|
|
||
|
|
from twisted.python.failure import Failure
|
||
|
|
from twisted.internet.defer import maybeDeferred, Deferred, DeferredList
|
||
|
|
from twisted.internet.defer import succeed, fail
|
||
|
|
from twisted.internet.interfaces import IReactorTime
|
||
|
|
|
||
|
|
from zope.interface import provider
|
||
|
|
|
||
|
|
from txaio.interfaces import IFailedFuture, ILogger, log_levels
|
||
|
|
from txaio._iotype import guess_stream_needs_encoding
|
||
|
|
from txaio import _Config
|
||
|
|
from txaio._common import _BatchedTimer
|
||
|
|
from txaio import _util
|
||
|
|
from twisted.logger import Logger as _Logger, formatEvent, ILogObserver
|
||
|
|
from twisted.logger import globalLogBeginner, formatTime, LogLevel
|
||
|
|
|
||
|
|
from twisted.internet.defer import ensureDeferred
|
||
|
|
from asyncio import iscoroutinefunction
|
||
|
|
|
||
|
|
using_twisted = True
|
||
|
|
using_asyncio = False
|
||
|
|
|
||
|
|
config = _Config()
|
||
|
|
_stderr, _stdout = sys.stderr, sys.stdout
|
||
|
|
|
||
|
|
# some book-keeping variables here. _observer is used as a global by
|
||
|
|
# the "backwards compatible" (Twisted < 15) loggers. The _loggers object
|
||
|
|
# is a weak-ref set; we add Logger instances to this *until* such
|
||
|
|
# time as start_logging is called (with the desired log-level) and
|
||
|
|
# then we call _set_log_level on each instance. After that,
|
||
|
|
# Logger's ctor uses _log_level directly.
|
||
|
|
_observer = None # for Twisted legacy logging support; see below
|
||
|
|
_loggers = weakref.WeakSet() # weak-references of each logger we've created
|
||
|
|
_log_level = 'info' # global log level; possibly changed in start_logging()
|
||
|
|
_started_logging = False
|
||
|
|
|
||
|
|
_categories = {}
|
||
|
|
|
||
|
|
IFailedFuture.register(Failure)
|
||
|
|
ILogger.register(_Logger)
|
||
|
|
|
||
|
|
|
||
|
|
def _no_op(*args, **kwargs):
|
||
|
|
pass
|
||
|
|
|
||
|
|
|
||
|
|
def add_log_categories(categories):
|
||
|
|
_categories.update(categories)
|
||
|
|
|
||
|
|
|
||
|
|
def with_config(loop=None):
|
||
|
|
global config
|
||
|
|
if loop is not None:
|
||
|
|
if config.loop is not None and config.loop is not loop:
|
||
|
|
raise RuntimeError(
|
||
|
|
"Twisted has only a single, global reactor. You passed in "
|
||
|
|
"a reactor different from the one already configured "
|
||
|
|
"in txaio.config.loop"
|
||
|
|
)
|
||
|
|
return _TxApi(config)
|
||
|
|
|
||
|
|
|
||
|
|
# NOTE: beware that twisted.logger._logger.Logger copies itself via an
|
||
|
|
# overriden __get__ method when used as recommended as a class
|
||
|
|
# descriptor. So, we override __get__ to just return ``self`` which
|
||
|
|
# means ``log_source`` will be wrong, but we don't document that as a
|
||
|
|
# key that you can depend on anyway :/
|
||
|
|
class Logger(object):
|
||
|
|
|
||
|
|
def __init__(self, level=None, logger=None, namespace=None, observer=None):
|
||
|
|
|
||
|
|
assert logger, "Should not be instantiated directly."
|
||
|
|
|
||
|
|
self._logger = logger(observer=observer, namespace=namespace)
|
||
|
|
self._log_level_set_explicitly = False
|
||
|
|
|
||
|
|
if level:
|
||
|
|
self.set_log_level(level)
|
||
|
|
else:
|
||
|
|
self._set_log_level(_log_level)
|
||
|
|
|
||
|
|
_loggers.add(self)
|
||
|
|
|
||
|
|
def __get__(self, oself, type=None):
|
||
|
|
# this causes the Logger to lie about the "source=", but
|
||
|
|
# otherwise we create a new Logger instance every time we do
|
||
|
|
# "self.log.info()" if we use it like:
|
||
|
|
# class Foo:
|
||
|
|
# log = make_logger
|
||
|
|
return self
|
||
|
|
|
||
|
|
def _log(self, level, *args, **kwargs):
|
||
|
|
|
||
|
|
# Look for a log_category, switch it in if we have it
|
||
|
|
if "log_category" in kwargs and kwargs["log_category"] in _categories:
|
||
|
|
args = tuple()
|
||
|
|
kwargs["format"] = _categories.get(kwargs["log_category"])
|
||
|
|
|
||
|
|
self._logger.emit(level, *args, **kwargs)
|
||
|
|
|
||
|
|
def emit(self, level, *args, **kwargs):
|
||
|
|
|
||
|
|
if log_levels.index(self._log_level) < log_levels.index(level):
|
||
|
|
return
|
||
|
|
|
||
|
|
if level == "trace":
|
||
|
|
return self._trace(*args, **kwargs)
|
||
|
|
|
||
|
|
level = LogLevel.lookupByName(level)
|
||
|
|
return self._log(level, *args, **kwargs)
|
||
|
|
|
||
|
|
def set_log_level(self, level, keep=True):
|
||
|
|
"""
|
||
|
|
Set the log level. If keep is True, then it will not change along with
|
||
|
|
global log changes.
|
||
|
|
"""
|
||
|
|
self._set_log_level(level)
|
||
|
|
self._log_level_set_explicitly = keep
|
||
|
|
|
||
|
|
def _set_log_level(self, level):
|
||
|
|
# up to the desired level, we don't do anything, as we're a
|
||
|
|
# "real" Twisted new-logger; for methods *after* the desired
|
||
|
|
# level, we bind to the no_op method
|
||
|
|
desired_index = log_levels.index(level)
|
||
|
|
|
||
|
|
for (idx, name) in enumerate(log_levels):
|
||
|
|
if name == 'none':
|
||
|
|
continue
|
||
|
|
|
||
|
|
if idx > desired_index:
|
||
|
|
current = getattr(self, name, None)
|
||
|
|
if not current == _no_op or current is None:
|
||
|
|
setattr(self, name, _no_op)
|
||
|
|
if name == 'error':
|
||
|
|
setattr(self, 'failure', _no_op)
|
||
|
|
|
||
|
|
else:
|
||
|
|
if getattr(self, name, None) in (_no_op, None):
|
||
|
|
|
||
|
|
if name == 'trace':
|
||
|
|
setattr(self, "trace", self._trace)
|
||
|
|
else:
|
||
|
|
setattr(self, name,
|
||
|
|
partial(self._log, LogLevel.lookupByName(name)))
|
||
|
|
|
||
|
|
if name == 'error':
|
||
|
|
setattr(self, "failure", self._failure)
|
||
|
|
|
||
|
|
self._log_level = level
|
||
|
|
|
||
|
|
def _failure(self, format=None, *args, **kw):
|
||
|
|
return self._logger.failure(format, *args, **kw)
|
||
|
|
|
||
|
|
def _trace(self, *args, **kw):
|
||
|
|
# there is no "trace" level in Twisted -- but this whole
|
||
|
|
# method will be no-op'd unless we are at the 'trace' level.
|
||
|
|
self.debug(*args, txaio_trace=True, **kw)
|
||
|
|
|
||
|
|
|
||
|
|
def make_logger(level=None, logger=_Logger, observer=None):
|
||
|
|
# we want the namespace to be the calling context of "make_logger"
|
||
|
|
# -- so we *have* to pass namespace kwarg to Logger (or else it
|
||
|
|
# will always say the context is "make_logger")
|
||
|
|
cf = inspect.currentframe().f_back
|
||
|
|
if "self" in cf.f_locals:
|
||
|
|
# We're probably in a class init or method
|
||
|
|
cls = cf.f_locals["self"].__class__
|
||
|
|
namespace = '{0}.{1}'.format(cls.__module__, cls.__name__)
|
||
|
|
else:
|
||
|
|
namespace = cf.f_globals["__name__"]
|
||
|
|
if cf.f_code.co_name != "<module>":
|
||
|
|
# If it's not the module, and not in a class instance, add the code
|
||
|
|
# object's name.
|
||
|
|
namespace = namespace + "." + cf.f_code.co_name
|
||
|
|
logger = Logger(level=level, namespace=namespace, logger=logger,
|
||
|
|
observer=observer)
|
||
|
|
return logger
|
||
|
|
|
||
|
|
|
||
|
|
@provider(ILogObserver)
|
||
|
|
class _LogObserver(object):
|
||
|
|
"""
|
||
|
|
Internal helper.
|
||
|
|
|
||
|
|
An observer which formats events to a given file.
|
||
|
|
"""
|
||
|
|
to_tx = {
|
||
|
|
'critical': LogLevel.critical,
|
||
|
|
'error': LogLevel.error,
|
||
|
|
'warn': LogLevel.warn,
|
||
|
|
'info': LogLevel.info,
|
||
|
|
'debug': LogLevel.debug,
|
||
|
|
'trace': LogLevel.debug,
|
||
|
|
}
|
||
|
|
|
||
|
|
def __init__(self, out):
|
||
|
|
self._file = out
|
||
|
|
self._encode = guess_stream_needs_encoding(out)
|
||
|
|
|
||
|
|
self._levels = None
|
||
|
|
|
||
|
|
def _acceptable_level(self, level):
|
||
|
|
if self._levels is None:
|
||
|
|
target_level = log_levels.index(_log_level)
|
||
|
|
self._levels = [
|
||
|
|
self.to_tx[lvl]
|
||
|
|
for lvl in log_levels
|
||
|
|
if log_levels.index(lvl) <= target_level and lvl != "none"
|
||
|
|
]
|
||
|
|
return level in self._levels
|
||
|
|
|
||
|
|
def __call__(self, event):
|
||
|
|
# it seems if a twisted.logger.Logger() has .failure() called
|
||
|
|
# on it, the log_format will be None for the traceback after
|
||
|
|
# "Unhandled error in Deferred" -- perhaps this is a Twisted
|
||
|
|
# bug?
|
||
|
|
if event['log_format'] is None:
|
||
|
|
msg = '{0} {1}{2}'.format(
|
||
|
|
formatTime(event["log_time"]),
|
||
|
|
failure_format_traceback(event['log_failure']),
|
||
|
|
os.linesep,
|
||
|
|
)
|
||
|
|
if self._encode:
|
||
|
|
msg = msg.encode('utf8')
|
||
|
|
self._file.write(msg)
|
||
|
|
else:
|
||
|
|
# although Logger will already have filtered out unwanted
|
||
|
|
# levels, bare Logger instances from Twisted code won't have.
|
||
|
|
if 'log_level' in event and self._acceptable_level(event['log_level']):
|
||
|
|
msg = '{0} {1}{2}'.format(
|
||
|
|
formatTime(event["log_time"]),
|
||
|
|
formatEvent(event),
|
||
|
|
os.linesep,
|
||
|
|
)
|
||
|
|
if self._encode:
|
||
|
|
msg = msg.encode('utf8')
|
||
|
|
|
||
|
|
self._file.write(msg)
|
||
|
|
|
||
|
|
|
||
|
|
def start_logging(out=_stdout, level='info'):
|
||
|
|
"""
|
||
|
|
Start logging to the file-like object in ``out``. By default, this
|
||
|
|
is stdout.
|
||
|
|
"""
|
||
|
|
global _loggers, _observer, _log_level, _started_logging
|
||
|
|
|
||
|
|
if level not in log_levels:
|
||
|
|
raise RuntimeError(
|
||
|
|
"Invalid log level '{0}'; valid are: {1}".format(
|
||
|
|
level, ', '.join(log_levels)
|
||
|
|
)
|
||
|
|
)
|
||
|
|
|
||
|
|
if _started_logging:
|
||
|
|
return
|
||
|
|
|
||
|
|
_started_logging = True
|
||
|
|
|
||
|
|
_log_level = level
|
||
|
|
set_global_log_level(_log_level)
|
||
|
|
|
||
|
|
if out:
|
||
|
|
_observer = _LogObserver(out)
|
||
|
|
|
||
|
|
_observers = []
|
||
|
|
if _observer:
|
||
|
|
_observers.append(_observer)
|
||
|
|
globalLogBeginner.beginLoggingTo(_observers)
|
||
|
|
|
||
|
|
|
||
|
|
_unspecified = object()
|
||
|
|
|
||
|
|
|
||
|
|
class _TxApi(object):
|
||
|
|
|
||
|
|
def __init__(self, config):
|
||
|
|
self._config = config
|
||
|
|
|
||
|
|
def failure_message(self, fail):
|
||
|
|
"""
|
||
|
|
:param fail: must be an IFailedFuture
|
||
|
|
returns a unicode error-message
|
||
|
|
"""
|
||
|
|
try:
|
||
|
|
return '{0}: {1}'.format(
|
||
|
|
fail.value.__class__.__name__,
|
||
|
|
fail.getErrorMessage(),
|
||
|
|
)
|
||
|
|
except Exception:
|
||
|
|
return 'Failed to produce failure message for "{0}"'.format(fail)
|
||
|
|
|
||
|
|
def failure_traceback(self, fail):
|
||
|
|
"""
|
||
|
|
:param fail: must be an IFailedFuture
|
||
|
|
returns a traceback instance
|
||
|
|
"""
|
||
|
|
return fail.tb
|
||
|
|
|
||
|
|
def failure_format_traceback(self, fail):
|
||
|
|
"""
|
||
|
|
:param fail: must be an IFailedFuture
|
||
|
|
returns a string
|
||
|
|
"""
|
||
|
|
try:
|
||
|
|
f = io.StringIO()
|
||
|
|
fail.printTraceback(file=f)
|
||
|
|
return f.getvalue()
|
||
|
|
except Exception:
|
||
|
|
return "Failed to format failure traceback for '{0}'".format(fail)
|
||
|
|
|
||
|
|
def create_future(self, result=_unspecified, error=_unspecified, canceller=None):
|
||
|
|
if result is not _unspecified and error is not _unspecified:
|
||
|
|
raise ValueError("Cannot have both result and error.")
|
||
|
|
|
||
|
|
f = Deferred(canceller=canceller)
|
||
|
|
if result is not _unspecified:
|
||
|
|
resolve(f, result)
|
||
|
|
elif error is not _unspecified:
|
||
|
|
reject(f, error)
|
||
|
|
return f
|
||
|
|
|
||
|
|
def create_future_success(self, result):
|
||
|
|
return succeed(result)
|
||
|
|
|
||
|
|
def create_future_error(self, error=None):
|
||
|
|
return fail(create_failure(error))
|
||
|
|
|
||
|
|
def as_future(self, fun, *args, **kwargs):
|
||
|
|
# Twisted doesn't automagically deal with coroutines on Py3
|
||
|
|
if iscoroutinefunction(fun):
|
||
|
|
try:
|
||
|
|
return ensureDeferred(fun(*args, **kwargs))
|
||
|
|
except TypeError as e:
|
||
|
|
return create_future_error(e)
|
||
|
|
return maybeDeferred(fun, *args, **kwargs)
|
||
|
|
|
||
|
|
def is_future(self, obj):
|
||
|
|
return isinstance(obj, Deferred)
|
||
|
|
|
||
|
|
def call_later(self, delay, fun, *args, **kwargs):
|
||
|
|
return IReactorTime(self._get_loop()).callLater(delay, fun, *args, **kwargs)
|
||
|
|
|
||
|
|
def make_batched_timer(self, bucket_seconds, chunk_size=100):
|
||
|
|
"""
|
||
|
|
Creates and returns an object implementing
|
||
|
|
:class:`txaio.IBatchedTimer`.
|
||
|
|
|
||
|
|
:param bucket_seconds: the number of seconds in each bucket. That
|
||
|
|
is, a value of 5 means that any timeout within a 5 second
|
||
|
|
window will be in the same bucket, and get notified at the
|
||
|
|
same time. This is only accurate to "milliseconds".
|
||
|
|
|
||
|
|
:param chunk_size: when "doing" the callbacks in a particular
|
||
|
|
bucket, this controls how many we do at once before yielding to
|
||
|
|
the reactor.
|
||
|
|
"""
|
||
|
|
|
||
|
|
def get_seconds():
|
||
|
|
return self._get_loop().seconds()
|
||
|
|
|
||
|
|
def create_delayed_call(delay, fun, *args, **kwargs):
|
||
|
|
return self._get_loop().callLater(delay, fun, *args, **kwargs)
|
||
|
|
|
||
|
|
return _BatchedTimer(
|
||
|
|
bucket_seconds * 1000.0, chunk_size,
|
||
|
|
seconds_provider=get_seconds,
|
||
|
|
delayed_call_creator=create_delayed_call,
|
||
|
|
)
|
||
|
|
|
||
|
|
def is_called(self, future):
|
||
|
|
return future.called
|
||
|
|
|
||
|
|
def resolve(self, future, result=None):
|
||
|
|
future.callback(result)
|
||
|
|
|
||
|
|
def reject(self, future, error=None):
|
||
|
|
if error is None:
|
||
|
|
error = create_failure()
|
||
|
|
elif isinstance(error, Exception):
|
||
|
|
error = Failure(error)
|
||
|
|
else:
|
||
|
|
if not isinstance(error, Failure):
|
||
|
|
raise RuntimeError("reject requires a Failure or Exception")
|
||
|
|
future.errback(error)
|
||
|
|
|
||
|
|
def cancel(self, future, msg=None):
|
||
|
|
future.cancel()
|
||
|
|
|
||
|
|
def create_failure(self, exception=None):
|
||
|
|
"""
|
||
|
|
Create a Failure instance.
|
||
|
|
|
||
|
|
if ``exception`` is None (the default), we MUST be inside an
|
||
|
|
"except" block. This encapsulates the exception into an object
|
||
|
|
that implements IFailedFuture
|
||
|
|
"""
|
||
|
|
if exception:
|
||
|
|
return Failure(exception)
|
||
|
|
return Failure()
|
||
|
|
|
||
|
|
def add_callbacks(self, future, callback, errback):
|
||
|
|
"""
|
||
|
|
callback or errback may be None, but at least one must be
|
||
|
|
non-None.
|
||
|
|
"""
|
||
|
|
assert future is not None
|
||
|
|
if callback is None:
|
||
|
|
assert errback is not None
|
||
|
|
future.addErrback(errback)
|
||
|
|
else:
|
||
|
|
# Twisted allows errback to be None here
|
||
|
|
future.addCallbacks(callback, errback)
|
||
|
|
return future
|
||
|
|
|
||
|
|
def gather(self, futures, consume_exceptions=True):
|
||
|
|
def completed(res):
|
||
|
|
rtn = []
|
||
|
|
for (ok, value) in res:
|
||
|
|
rtn.append(value)
|
||
|
|
if not ok and not consume_exceptions:
|
||
|
|
value.raiseException()
|
||
|
|
return rtn
|
||
|
|
|
||
|
|
# XXX if consume_exceptions is False in asyncio.gather(), it will
|
||
|
|
# abort on the first raised exception -- should we set
|
||
|
|
# fireOnOneErrback=True (if consume_exceptions=False?) -- but then
|
||
|
|
# we'll have to wrap the errback() to extract the "real" failure
|
||
|
|
# from the FirstError that gets thrown if you set that ...
|
||
|
|
|
||
|
|
dl = DeferredList(list(futures), consumeErrors=consume_exceptions)
|
||
|
|
# we unpack the (ok, value) tuples into just a list of values, so
|
||
|
|
# that the callback() gets the same value in asyncio and Twisted.
|
||
|
|
add_callbacks(dl, completed, None)
|
||
|
|
return dl
|
||
|
|
|
||
|
|
def sleep(self, delay):
|
||
|
|
"""
|
||
|
|
Inline sleep for use in co-routines.
|
||
|
|
|
||
|
|
:param delay: Time to sleep in seconds.
|
||
|
|
:type delay: float
|
||
|
|
"""
|
||
|
|
d = Deferred()
|
||
|
|
self._get_loop().callLater(delay, d.callback, None)
|
||
|
|
return d
|
||
|
|
|
||
|
|
def _get_loop(self):
|
||
|
|
"""
|
||
|
|
internal helper
|
||
|
|
"""
|
||
|
|
# we import and assign the default here (and not, e.g., when
|
||
|
|
# making Config) so as to delay importing reactor as long as
|
||
|
|
# possible in case someone is installing a custom one.
|
||
|
|
if self._config.loop is None:
|
||
|
|
from twisted.internet import reactor
|
||
|
|
self._config.loop = reactor
|
||
|
|
return self._config.loop
|
||
|
|
|
||
|
|
|
||
|
|
def set_global_log_level(level):
|
||
|
|
"""
|
||
|
|
Set the global log level on all loggers instantiated by txaio.
|
||
|
|
"""
|
||
|
|
for item in _loggers:
|
||
|
|
if not item._log_level_set_explicitly:
|
||
|
|
item._set_log_level(level)
|
||
|
|
global _log_level
|
||
|
|
_log_level = level
|
||
|
|
|
||
|
|
|
||
|
|
def get_global_log_level():
|
||
|
|
return _log_level
|
||
|
|
|
||
|
|
|
||
|
|
_default_api = _TxApi(config)
|
||
|
|
|
||
|
|
|
||
|
|
failure_message = _default_api.failure_message
|
||
|
|
failure_traceback = _default_api.failure_traceback
|
||
|
|
failure_format_traceback = _default_api.failure_format_traceback
|
||
|
|
create_future = _default_api.create_future
|
||
|
|
create_future_success = _default_api.create_future_success
|
||
|
|
create_future_error = _default_api.create_future_error
|
||
|
|
as_future = _default_api.as_future
|
||
|
|
is_future = _default_api.is_future
|
||
|
|
call_later = _default_api.call_later
|
||
|
|
make_batched_timer = _default_api.make_batched_timer
|
||
|
|
is_called = _default_api.is_called
|
||
|
|
resolve = _default_api.resolve
|
||
|
|
reject = _default_api.reject
|
||
|
|
cancel = _default_api.cancel
|
||
|
|
create_failure = _default_api.create_failure
|
||
|
|
add_callbacks = _default_api.add_callbacks
|
||
|
|
gather = _default_api.gather
|
||
|
|
sleep = _default_api.sleep
|
||
|
|
time_ns = _util.time_ns
|
||
|
|
perf_counter_ns = _util.perf_counter_ns
|