123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514515516517518519520521522523524525526527528529530531532533534535536537538539540541542543544545546547548549550551552553554555556557558559560561562563564565566567568569570571572573574575576577578579580581582583584585586587588589590591592593594595596597598599600601602603604605606607608609610611612613614615616617618619620621622623624625626627628629630631632633634635636637638639640641642643644645646647648649650651652653654655656657658659660661662663664665666667668669670671672673674675676677678679680681682683684685686687688689690691692693694695696697698699700701702703704705706707708709710711712713714715716717718719720721722723724725726727728729730731732733734 |
- # -*- test-case-name: twisted.test.test_log -*-
- # Copyright (c) Twisted Matrix Laboratories.
- # See LICENSE for details.
-
- """
- Logging and metrics infrastructure.
- """
-
-
- import sys
- import time
- import warnings
- from abc import ABC, abstractmethod
- from datetime import datetime
- from typing import Any, BinaryIO, Dict, Optional, cast
-
- from zope.interface import Interface
-
- from twisted.logger import (
- LegacyLogObserverWrapper,
- Logger as NewLogger,
- LoggingFile,
- LogLevel as NewLogLevel,
- LogPublisher as NewPublisher,
- STDLibLogObserver as NewSTDLibLogObserver,
- globalLogBeginner as newGlobalLogBeginner,
- globalLogPublisher as newGlobalLogPublisher,
- )
- from twisted.logger._global import LogBeginner
- from twisted.logger._legacy import publishToNewObserver as _publishNew
- from twisted.python import context, failure, reflect, util
- from twisted.python.threadable import synchronize
-
- EventDict = Dict[str, Any]
-
-
- class ILogContext:
- """
- Actually, this interface is just a synonym for the dictionary interface,
- but it serves as a key for the default information in a log.
-
- I do not inherit from C{Interface} because the world is a cruel place.
- """
-
-
- class ILogObserver(Interface):
- """
- An observer which can do something with log events.
-
- Given that most log observers are actually bound methods, it's okay to not
- explicitly declare provision of this interface.
- """
-
- def __call__(eventDict: EventDict) -> None:
- """
- Log an event.
-
- @param eventDict: A dictionary with arbitrary keys. However, these
- keys are often available:
- - C{message}: A C{tuple} of C{str} containing messages to be
- logged.
- - C{system}: A C{str} which indicates the "system" which is
- generating this event.
- - C{isError}: A C{bool} indicating whether this event represents
- an error.
- - C{failure}: A L{failure.Failure} instance
- - C{why}: Used as header of the traceback in case of errors.
- - C{format}: A string format used in place of C{message} to
- customize the event. The intent is for the observer to format
- a message by doing something like C{format % eventDict}.
- """
-
-
- context.setDefault(ILogContext, {"system": "-"})
-
-
- def callWithContext(ctx, func, *args, **kw):
- newCtx = context.get(ILogContext).copy()
- newCtx.update(ctx)
- return context.call({ILogContext: newCtx}, func, *args, **kw)
-
-
- def callWithLogger(logger, func, *args, **kw):
- """
- Utility method which wraps a function in a try:/except:, logs a failure if
- one occurs, and uses the system's logPrefix.
- """
- try:
- lp = logger.logPrefix()
- except KeyboardInterrupt:
- raise
- except BaseException:
- lp = "(buggy logPrefix method)"
- err(system=lp)
- try:
- return callWithContext({"system": lp}, func, *args, **kw)
- except KeyboardInterrupt:
- raise
- except BaseException:
- err(system=lp)
-
-
- def err(_stuff=None, _why=None, **kw):
- """
- Write a failure to the log.
-
- The C{_stuff} and C{_why} parameters use an underscore prefix to lessen
- the chance of colliding with a keyword argument the application wishes
- to pass. It is intended that they be supplied with arguments passed
- positionally, not by keyword.
-
- @param _stuff: The failure to log. If C{_stuff} is L{None} a new
- L{Failure} will be created from the current exception state. If
- C{_stuff} is an C{Exception} instance it will be wrapped in a
- L{Failure}.
- @type _stuff: L{None}, C{Exception}, or L{Failure}.
-
- @param _why: The source of this failure. This will be logged along with
- C{_stuff} and should describe the context in which the failure
- occurred.
- @type _why: C{str}
- """
- if _stuff is None:
- _stuff = failure.Failure()
- if isinstance(_stuff, failure.Failure):
- msg(failure=_stuff, why=_why, isError=1, **kw)
- elif isinstance(_stuff, Exception):
- msg(failure=failure.Failure(_stuff), why=_why, isError=1, **kw)
- else:
- msg(repr(_stuff), why=_why, isError=1, **kw)
-
-
- deferr = err
-
-
- class Logger:
- """
- This represents a class which may 'own' a log. Used by subclassing.
- """
-
- def logPrefix(self):
- """
- Override this method to insert custom logging behavior. Its
- return value will be inserted in front of every line. It may
- be called more times than the number of output lines.
- """
- return "-"
-
-
- class LogPublisher:
- """
- Class for singleton log message publishing.
- """
-
- synchronized = ["msg"]
-
- def __init__(
- self,
- observerPublisher=None,
- publishPublisher=None,
- logBeginner=None,
- warningsModule=warnings,
- ):
- if publishPublisher is None:
- publishPublisher = NewPublisher()
- if observerPublisher is None:
- observerPublisher = publishPublisher
- if observerPublisher is None:
- observerPublisher = NewPublisher()
- self._observerPublisher = observerPublisher
- self._publishPublisher = publishPublisher
- self._legacyObservers = []
- if logBeginner is None:
- # This default behavior is really only used for testing.
- beginnerPublisher = NewPublisher()
- beginnerPublisher.addObserver(observerPublisher)
- logBeginner = LogBeginner(
- beginnerPublisher, cast(BinaryIO, NullFile()), sys, warnings
- )
- self._logBeginner = logBeginner
- self._warningsModule = warningsModule
- self._oldshowwarning = warningsModule.showwarning
- self.showwarning = self._logBeginner.showwarning
-
- @property
- def observers(self):
- """
- Property returning all observers registered on this L{LogPublisher}.
-
- @return: observers previously added with L{LogPublisher.addObserver}
- @rtype: L{list} of L{callable}
- """
- return [x.legacyObserver for x in self._legacyObservers]
-
- def _startLogging(self, other, setStdout):
- """
- Begin logging to the L{LogBeginner} associated with this
- L{LogPublisher}.
-
- @param other: the observer to log to.
- @type other: L{LogBeginner}
-
- @param setStdout: if true, send standard I/O to the observer as well.
- @type setStdout: L{bool}
- """
- wrapped = LegacyLogObserverWrapper(other)
- self._legacyObservers.append(wrapped)
- self._logBeginner.beginLoggingTo([wrapped], True, setStdout)
-
- def _stopLogging(self):
- """
- Clean-up hook for fixing potentially global state. Only for testing of
- this module itself. If you want less global state, use the new
- warnings system in L{twisted.logger}.
- """
- if self._warningsModule.showwarning == self.showwarning:
- self._warningsModule.showwarning = self._oldshowwarning
-
- def addObserver(self, other):
- """
- Add a new observer.
-
- @type other: Provider of L{ILogObserver}
- @param other: A callable object that will be called with each new log
- message (a dict).
- """
- wrapped = LegacyLogObserverWrapper(other)
- self._legacyObservers.append(wrapped)
- self._observerPublisher.addObserver(wrapped)
-
- def removeObserver(self, other):
- """
- Remove an observer.
- """
- for observer in self._legacyObservers:
- if observer.legacyObserver == other:
- self._legacyObservers.remove(observer)
- self._observerPublisher.removeObserver(observer)
- break
-
- def msg(self, *message, **kw):
- """
- Log a new message.
-
- The message should be a native string, i.e. bytes on Python 2 and
- Unicode on Python 3. For compatibility with both use the native string
- syntax, for example::
-
- >>> log.msg('Hello, world.')
-
- You MUST avoid passing in Unicode on Python 2, and the form::
-
- >>> log.msg('Hello ', 'world.')
-
- This form only works (sometimes) by accident.
-
- Keyword arguments will be converted into items in the event
- dict that is passed to L{ILogObserver} implementations.
- Each implementation, in turn, can define keys that are used
- by it specifically, in addition to common keys listed at
- L{ILogObserver.__call__}.
-
- For example, to set the C{system} parameter while logging
- a message::
-
- >>> log.msg('Started', system='Foo')
-
- """
- actualEventDict = cast(EventDict, (context.get(ILogContext) or {}).copy())
- actualEventDict.update(kw)
- actualEventDict["message"] = message
- actualEventDict["time"] = time.time()
- if "isError" not in actualEventDict:
- actualEventDict["isError"] = 0
-
- _publishNew(self._publishPublisher, actualEventDict, textFromEventDict)
-
-
- synchronize(LogPublisher)
-
-
- if "theLogPublisher" not in globals():
-
- def _actually(something):
- """
- A decorator that returns its argument rather than the thing it is
- decorating.
-
- This allows the documentation generator to see an alias for a method or
- constant as an object with a docstring and thereby document it and
- allow references to it statically.
-
- @param something: An object to create an alias for.
- @type something: L{object}
-
- @return: a 1-argument callable that returns C{something}
- @rtype: L{object}
- """
-
- def decorate(thingWithADocstring):
- return something
-
- return decorate
-
- theLogPublisher = LogPublisher(
- observerPublisher=newGlobalLogPublisher,
- publishPublisher=newGlobalLogPublisher,
- logBeginner=newGlobalLogBeginner,
- )
-
- @_actually(theLogPublisher.addObserver)
- def addObserver(observer):
- """
- Add a log observer to the global publisher.
-
- @see: L{LogPublisher.addObserver}
-
- @param observer: a log observer
- @type observer: L{callable}
- """
-
- @_actually(theLogPublisher.removeObserver)
- def removeObserver(observer):
- """
- Remove a log observer from the global publisher.
-
- @see: L{LogPublisher.removeObserver}
-
- @param observer: a log observer previously added with L{addObserver}
- @type observer: L{callable}
- """
-
- @_actually(theLogPublisher.msg)
- def msg(*message, **event):
- """
- Publish a message to the global log publisher.
-
- @see: L{LogPublisher.msg}
-
- @param message: the log message
- @type message: C{tuple} of L{str} (native string)
-
- @param event: fields for the log event
- @type event: L{dict} mapping L{str} (native string) to L{object}
- """
-
- @_actually(theLogPublisher.showwarning)
- def showwarning():
- """
- Publish a Python warning through the global log publisher.
-
- @see: L{LogPublisher.showwarning}
- """
-
-
- def _safeFormat(fmtString: str, fmtDict: Dict[str, Any]) -> str:
- """
- Try to format a string, swallowing all errors to always return a string.
-
- @note: For backward-compatibility reasons, this function ensures that it
- returns a native string, meaning L{bytes} in Python 2 and L{str} in
- Python 3.
-
- @param fmtString: a C{%}-format string
- @param fmtDict: string formatting arguments for C{fmtString}
-
- @return: A native string, formatted from C{fmtString} and C{fmtDict}.
- """
- # There's a way we could make this if not safer at least more
- # informative: perhaps some sort of str/repr wrapper objects
- # could be wrapped around the things inside of C{fmtDict}. That way
- # if the event dict contains an object with a bad __repr__, we
- # can only cry about that individual object instead of the
- # entire event dict.
- try:
- text = fmtString % fmtDict
- except KeyboardInterrupt:
- raise
- except BaseException:
- try:
- text = (
- "Invalid format string or unformattable object in "
- "log message: %r, %s" % (fmtString, fmtDict)
- )
- except BaseException:
- try:
- text = (
- "UNFORMATTABLE OBJECT WRITTEN TO LOG with fmt %r, "
- "MESSAGE LOST" % (fmtString,)
- )
- except BaseException:
- text = (
- "PATHOLOGICAL ERROR IN BOTH FORMAT STRING AND "
- "MESSAGE DETAILS, MESSAGE LOST"
- )
-
- return text
-
-
- def textFromEventDict(eventDict: EventDict) -> Optional[str]:
- """
- Extract text from an event dict passed to a log observer. If it cannot
- handle the dict, it returns None.
-
- The possible keys of eventDict are:
- - C{message}: by default, it holds the final text. It's required, but can
- be empty if either C{isError} or C{format} is provided (the first
- having the priority).
- - C{isError}: boolean indicating the nature of the event.
- - C{failure}: L{failure.Failure} instance, required if the event is an
- error.
- - C{why}: if defined, used as header of the traceback in case of errors.
- - C{format}: string format used in place of C{message} to customize
- the event. It uses all keys present in C{eventDict} to format
- the text.
- Other keys will be used when applying the C{format}, or ignored.
- """
- edm = eventDict["message"]
- if not edm:
- if eventDict["isError"] and "failure" in eventDict:
- why = cast(str, eventDict.get("why"))
- if why:
- why = reflect.safe_str(why)
- else:
- why = "Unhandled Error"
- try:
- traceback = cast(failure.Failure, eventDict["failure"]).getTraceback()
- except Exception as e:
- traceback = "(unable to obtain traceback): " + str(e)
- text = why + "\n" + traceback
- elif "format" in eventDict:
- text = _safeFormat(eventDict["format"], eventDict)
- else:
- # We don't know how to log this
- return None
- else:
- text = " ".join(map(reflect.safe_str, edm))
- return text
-
-
- class _GlobalStartStopObserver(ABC):
- """
- Mix-in for global log observers that can start and stop.
- """
-
- @abstractmethod
- def emit(self, eventDict: EventDict) -> None:
- """
- Emit the given log event.
-
- @param eventDict: a log event
- """
-
- def start(self) -> None:
- """
- Start observing log events.
- """
- addObserver(self.emit)
-
- def stop(self) -> None:
- """
- Stop observing log events.
- """
- removeObserver(self.emit)
-
-
- class FileLogObserver(_GlobalStartStopObserver):
- """
- Log observer that writes to a file-like object.
-
- @type timeFormat: C{str} or L{None}
- @ivar timeFormat: If not L{None}, the format string passed to strftime().
- """
-
- timeFormat: Optional[str] = None
-
- def __init__(self, f):
- # Compatibility
- self.write = f.write
- self.flush = f.flush
-
- def getTimezoneOffset(self, when):
- """
- Return the current local timezone offset from UTC.
-
- @type when: C{int}
- @param when: POSIX (ie, UTC) timestamp for which to find the offset.
-
- @rtype: C{int}
- @return: The number of seconds offset from UTC. West is positive,
- east is negative.
- """
- offset = datetime.utcfromtimestamp(when) - datetime.fromtimestamp(when)
- return offset.days * (60 * 60 * 24) + offset.seconds
-
- def formatTime(self, when):
- """
- Format the given UTC value as a string representing that time in the
- local timezone.
-
- By default it's formatted as an ISO8601-like string (ISO8601 date and
- ISO8601 time separated by a space). It can be customized using the
- C{timeFormat} attribute, which will be used as input for the underlying
- L{datetime.datetime.strftime} call.
-
- @type when: C{int}
- @param when: POSIX (ie, UTC) timestamp for which to find the offset.
-
- @rtype: C{str}
- """
- if self.timeFormat is not None:
- return datetime.fromtimestamp(when).strftime(self.timeFormat)
-
- tzOffset = -self.getTimezoneOffset(when)
- when = datetime.utcfromtimestamp(when + tzOffset)
- tzHour = abs(int(tzOffset / 60 / 60))
- tzMin = abs(int(tzOffset / 60 % 60))
- if tzOffset < 0:
- tzSign = "-"
- else:
- tzSign = "+"
- return "%d-%02d-%02d %02d:%02d:%02d%s%02d%02d" % (
- when.year,
- when.month,
- when.day,
- when.hour,
- when.minute,
- when.second,
- tzSign,
- tzHour,
- tzMin,
- )
-
- def emit(self, eventDict: EventDict) -> None:
- """
- Format the given log event as text and write it to the output file.
-
- @param eventDict: a log event
- """
- text = textFromEventDict(eventDict)
- if text is None:
- return
-
- timeStr = self.formatTime(eventDict["time"])
- fmtDict = {"system": eventDict["system"], "text": text.replace("\n", "\n\t")}
- msgStr = _safeFormat("[%(system)s] %(text)s\n", fmtDict)
-
- util.untilConcludes(self.write, timeStr + " " + msgStr)
- util.untilConcludes(self.flush) # Hoorj!
-
-
- class PythonLoggingObserver(_GlobalStartStopObserver):
- """
- Output twisted messages to Python standard library L{logging} module.
-
- WARNING: specific logging configurations (example: network) can lead to
- a blocking system. Nothing is done here to prevent that, so be sure to not
- use this: code within Twisted, such as twisted.web, assumes that logging
- does not block.
- """
-
- def __init__(self, loggerName="twisted"):
- """
- @param loggerName: identifier used for getting logger.
- @type loggerName: C{str}
- """
- self._newObserver = NewSTDLibLogObserver(loggerName)
-
- def emit(self, eventDict: EventDict) -> None:
- """
- Receive a twisted log entry, format it and bridge it to python.
-
- By default the logging level used is info; log.err produces error
- level, and you can customize the level by using the C{logLevel} key::
-
- >>> log.msg('debugging', logLevel=logging.DEBUG)
- """
- if "log_format" in eventDict:
- _publishNew(self._newObserver, eventDict, textFromEventDict)
-
-
- class StdioOnnaStick:
- """
- Class that pretends to be stdout/err, and turns writes into log messages.
-
- @ivar isError: boolean indicating whether this is stderr, in which cases
- log messages will be logged as errors.
-
- @ivar encoding: unicode encoding used to encode any unicode strings
- written to this object.
- """
-
- closed = 0
- softspace = 0
- mode = "wb"
- name = "<stdio (log)>"
-
- def __init__(self, isError=0, encoding=None):
- self.isError = isError
- if encoding is None:
- encoding = sys.getdefaultencoding()
- self.encoding = encoding
- self.buf = ""
-
- def close(self):
- pass
-
- def fileno(self):
- return -1
-
- def flush(self):
- pass
-
- def read(self):
- raise OSError("can't read from the log!")
-
- readline = read
- readlines = read
- seek = read
- tell = read
-
- def write(self, data):
- d = (self.buf + data).split("\n")
- self.buf = d[-1]
- messages = d[0:-1]
- for message in messages:
- msg(message, printed=1, isError=self.isError)
-
- def writelines(self, lines):
- for line in lines:
- msg(line, printed=1, isError=self.isError)
-
-
- def startLogging(file, *a, **kw):
- """
- Initialize logging to a specified file.
-
- @return: A L{FileLogObserver} if a new observer is added, None otherwise.
- """
- if isinstance(file, LoggingFile):
- return
- flo = FileLogObserver(file)
- startLoggingWithObserver(flo.emit, *a, **kw)
- return flo
-
-
- def startLoggingWithObserver(observer, setStdout=1):
- """
- Initialize logging to a specified observer. If setStdout is true
- (defaults to yes), also redirect sys.stdout and sys.stderr
- to the specified file.
- """
- theLogPublisher._startLogging(observer, setStdout)
- msg("Log opened.")
-
-
- class NullFile:
- """
- A file-like object that discards everything.
- """
-
- softspace = 0
-
- def read(self):
- """
- Do nothing.
- """
-
- def write(self, bytes):
- """
- Do nothing.
-
- @param bytes: data
- @type bytes: L{bytes}
- """
-
- def flush(self):
- """
- Do nothing.
- """
-
- def close(self):
- """
- Do nothing.
- """
-
-
- def discardLogs():
- """
- Discard messages logged via the global C{logfile} object.
- """
- global logfile
- logfile = NullFile()
-
-
- # Prevent logfile from being erased on reload. This only works in cpython.
- if "logfile" not in globals():
- logfile = LoggingFile(
- logger=NewLogger(),
- level=NewLogLevel.info,
- encoding=getattr(sys.stdout, "encoding", None),
- )
- logerr = LoggingFile(
- logger=NewLogger(),
- level=NewLogLevel.error,
- encoding=getattr(sys.stderr, "encoding", None),
- )
-
-
- class DefaultObserver(_GlobalStartStopObserver):
- """
- Default observer.
-
- Will ignore all non-error messages and send error messages to sys.stderr.
- Will be removed when startLogging() is called for the first time.
- """
-
- stderr = sys.stderr
-
- def emit(self, eventDict: EventDict) -> None:
- """
- Emit an event dict.
-
- @param eventDict: an event dict
- """
- if eventDict["isError"]:
- text = textFromEventDict(eventDict)
- if text is not None:
- self.stderr.write(text)
- self.stderr.flush()
-
-
- if "defaultObserver" not in globals():
- defaultObserver = DefaultObserver()
|