This commit is contained in:
2024-12-17 14:36:15 -08:00
parent b2dbf46d28
commit 06d106de53
17731 changed files with 3037186 additions and 144 deletions

View File

@@ -0,0 +1,7 @@
# -*- test-case-name: twisted.logger.test -*-
# Copyright (c) Twisted Matrix Laboratories.
# See LICENSE for details.
"""
Unit tests for L{twisted.logger}.
"""

View File

@@ -0,0 +1,62 @@
# Copyright (c) Twisted Matrix Laboratories.
# See LICENSE for details.
"""
Test cases for L{twisted.logger._buffer}.
"""
from typing import List, cast
from zope.interface.exceptions import BrokenMethodImplementation
from zope.interface.verify import verifyObject
from twisted.trial import unittest
from .._buffer import LimitedHistoryLogObserver
from .._interfaces import ILogObserver, LogEvent
class LimitedHistoryLogObserverTests(unittest.TestCase):
"""
Tests for L{LimitedHistoryLogObserver}.
"""
def test_interface(self) -> None:
"""
L{LimitedHistoryLogObserver} provides L{ILogObserver}.
"""
observer = LimitedHistoryLogObserver(0)
try:
verifyObject(ILogObserver, observer)
except BrokenMethodImplementation as e:
self.fail(e)
def test_order(self) -> None:
"""
L{LimitedHistoryLogObserver} saves history in the order it is received.
"""
size = 4
events = [dict(n=n) for n in range(size // 2)]
observer = LimitedHistoryLogObserver(size)
for event in events:
observer(event)
outEvents: List[LogEvent] = []
observer.replayTo(cast(ILogObserver, outEvents.append))
self.assertEqual(events, outEvents)
def test_limit(self) -> None:
"""
When more events than a L{LimitedHistoryLogObserver}'s maximum size are
buffered, older events will be dropped.
"""
size = 4
events = [dict(n=n) for n in range(size * 2)]
observer = LimitedHistoryLogObserver(size)
for event in events:
observer(event)
outEvents: List[LogEvent] = []
observer.replayTo(cast(ILogObserver, outEvents.append))
self.assertEqual(events[-size:], outEvents)

View File

@@ -0,0 +1,36 @@
# Copyright (c) Twisted Matrix Laboratories.
# See LICENSE for details.
"""
Test cases for L{twisted.logger._capture}.
"""
from twisted.logger import Logger, LogLevel
from twisted.trial.unittest import TestCase
from .._capture import capturedLogs
class LogCaptureTests(TestCase):
"""
Tests for L{LogCaptureTests}.
"""
log = Logger()
def test_capture(self) -> None:
"""
Events logged within context are captured.
"""
foo = object()
with capturedLogs() as captured:
self.log.debug("Capture this, please", foo=foo)
self.log.info("Capture this too, please", foo=foo)
self.assertTrue(len(captured) == 2)
self.assertEqual(captured[0]["log_format"], "Capture this, please")
self.assertEqual(captured[0]["log_level"], LogLevel.debug)
self.assertEqual(captured[0]["foo"], foo)
self.assertEqual(captured[1]["log_format"], "Capture this too, please")
self.assertEqual(captured[1]["log_level"], LogLevel.info)
self.assertEqual(captured[1]["foo"], foo)

View File

@@ -0,0 +1,184 @@
# Copyright (c) Twisted Matrix Laboratories.
# See LICENSE for details.
"""
Test cases for L{twisted.logger._file}.
"""
from io import StringIO
from types import TracebackType
from typing import IO, Any, AnyStr, Optional, Type, cast
from zope.interface.exceptions import BrokenMethodImplementation
from zope.interface.verify import verifyObject
from twisted.python.failure import Failure
from twisted.trial.unittest import TestCase
from .._file import FileLogObserver, textFileLogObserver
from .._interfaces import ILogObserver
class FileLogObserverTests(TestCase):
"""
Tests for L{FileLogObserver}.
"""
def test_interface(self) -> None:
"""
L{FileLogObserver} is an L{ILogObserver}.
"""
with StringIO() as fileHandle:
observer = FileLogObserver(fileHandle, lambda e: str(e))
try:
verifyObject(ILogObserver, observer)
except BrokenMethodImplementation as e:
self.fail(e)
def test_observeWrites(self) -> None:
"""
L{FileLogObserver} writes to the given file when it observes events.
"""
with StringIO() as fileHandle:
observer = FileLogObserver(fileHandle, lambda e: str(e))
event = dict(x=1)
observer(event)
self.assertEqual(fileHandle.getvalue(), str(event))
def _test_observeWrites(self, what: Optional[str], count: int) -> None:
"""
Verify that observer performs an expected number of writes when the
formatter returns a given value.
@param what: the value for the formatter to return.
@param count: the expected number of writes.
"""
with DummyFile() as fileHandle:
observer = FileLogObserver(cast(IO[Any], fileHandle), lambda e: what)
event = dict(x=1)
observer(event)
self.assertEqual(fileHandle.writes, count)
def test_observeWritesNone(self) -> None:
"""
L{FileLogObserver} does not write to the given file when it observes
events and C{formatEvent} returns L{None}.
"""
self._test_observeWrites(None, 0)
def test_observeWritesEmpty(self) -> None:
"""
L{FileLogObserver} does not write to the given file when it observes
events and C{formatEvent} returns C{""}.
"""
self._test_observeWrites("", 0)
def test_observeFlushes(self) -> None:
"""
L{FileLogObserver} calles C{flush()} on the output file when it
observes an event.
"""
with DummyFile() as fileHandle:
observer = FileLogObserver(cast(IO[Any], fileHandle), lambda e: str(e))
event = dict(x=1)
observer(event)
self.assertEqual(fileHandle.flushes, 1)
class TextFileLogObserverTests(TestCase):
"""
Tests for L{textFileLogObserver}.
"""
def test_returnsFileLogObserver(self) -> None:
"""
L{textFileLogObserver} returns a L{FileLogObserver}.
"""
with StringIO() as fileHandle:
observer = textFileLogObserver(fileHandle)
self.assertIsInstance(observer, FileLogObserver)
def test_outFile(self) -> None:
"""
Returned L{FileLogObserver} has the correct outFile.
"""
with StringIO() as fileHandle:
observer = textFileLogObserver(fileHandle)
self.assertIs(observer._outFile, fileHandle)
def test_timeFormat(self) -> None:
"""
Returned L{FileLogObserver} has the correct outFile.
"""
with StringIO() as fileHandle:
observer = textFileLogObserver(fileHandle, timeFormat="%f")
observer(dict(log_format="XYZZY", log_time=112345.6))
self.assertEqual(fileHandle.getvalue(), "600000 [-#-] XYZZY\n")
def test_observeFailure(self) -> None:
"""
If the C{"log_failure"} key exists in an event, the observer appends
the failure's traceback to the output.
"""
with StringIO() as fileHandle:
observer = textFileLogObserver(fileHandle)
try:
1 / 0
except ZeroDivisionError:
failure = Failure()
event = dict(log_failure=failure)
observer(event)
output = fileHandle.getvalue()
self.assertTrue(
output.split("\n")[1].startswith("\tTraceback "), msg=repr(output)
)
def test_observeFailureThatRaisesInGetTraceback(self) -> None:
"""
If the C{"log_failure"} key exists in an event, and contains an object
that raises when you call its C{getTraceback()}, then the observer
appends a message noting the problem, instead of raising.
"""
with StringIO() as fileHandle:
observer = textFileLogObserver(fileHandle)
event = dict(log_failure=object()) # object has no getTraceback()
observer(event)
output = fileHandle.getvalue()
expected = "(UNABLE TO OBTAIN TRACEBACK FROM EVENT)"
self.assertIn(expected, output)
class DummyFile:
"""
File that counts writes and flushes.
"""
def __init__(self) -> None:
self.writes = 0
self.flushes = 0
def write(self, data: AnyStr) -> None:
"""
Write data.
@param data: data
"""
self.writes += 1
def flush(self) -> None:
"""
Flush buffers.
"""
self.flushes += 1
def __enter__(self) -> "DummyFile":
return self
def __exit__(
self,
exc_type: Optional[Type[BaseException]],
exc_value: Optional[BaseException],
traceback: Optional[TracebackType],
) -> Optional[bool]:
pass

View File

@@ -0,0 +1,393 @@
# Copyright (c) Twisted Matrix Laboratories.
# See LICENSE for details.
"""
Test cases for L{twisted.logger._filter}.
"""
from typing import Iterable, List, Tuple, Union, cast
from zope.interface import implementer
from zope.interface.exceptions import BrokenMethodImplementation
from zope.interface.verify import verifyObject
from constantly import NamedConstant
from twisted.trial import unittest
from .._filter import (
FilteringLogObserver,
ILogFilterPredicate,
LogLevelFilterPredicate,
PredicateResult,
)
from .._interfaces import ILogObserver, LogEvent
from .._levels import InvalidLogLevelError, LogLevel
from .._observer import LogPublisher, bitbucketLogObserver
class FilteringLogObserverTests(unittest.TestCase):
"""
Tests for L{FilteringLogObserver}.
"""
def test_interface(self) -> None:
"""
L{FilteringLogObserver} is an L{ILogObserver}.
"""
observer = FilteringLogObserver(cast(ILogObserver, lambda e: None), ())
try:
verifyObject(ILogObserver, observer)
except BrokenMethodImplementation as e:
self.fail(e)
def filterWith(
self, filters: Iterable[str], other: bool = False
) -> Union[List[int], Tuple[List[int], List[int]]]:
"""
Apply a set of pre-defined filters on a known set of events and return
the filtered list of event numbers.
The pre-defined events are four events with a C{count} attribute set to
C{0}, C{1}, C{2}, and C{3}.
@param filters: names of the filters to apply.
Options are:
- C{"twoMinus"} (count <=2),
- C{"twoPlus"} (count >= 2),
- C{"notTwo"} (count != 2),
- C{"no"} (False).
@param other: Whether to return a list of filtered events as well.
@return: event numbers or 2-tuple of lists of event numbers.
"""
events: List[LogEvent] = [
dict(count=0),
dict(count=1),
dict(count=2),
dict(count=3),
]
class Filters:
@staticmethod
def twoMinus(event: LogEvent) -> NamedConstant:
"""
count <= 2
@param event: an event
@return: L{PredicateResult.yes} if C{event["count"] <= 2},
otherwise L{PredicateResult.maybe}.
"""
if event["count"] <= 2:
return PredicateResult.yes
return PredicateResult.maybe
@staticmethod
def twoPlus(event: LogEvent) -> NamedConstant:
"""
count >= 2
@param event: an event
@return: L{PredicateResult.yes} if C{event["count"] >= 2},
otherwise L{PredicateResult.maybe}.
"""
if event["count"] >= 2:
return PredicateResult.yes
return PredicateResult.maybe
@staticmethod
def notTwo(event: LogEvent) -> NamedConstant:
"""
count != 2
@param event: an event
@return: L{PredicateResult.yes} if C{event["count"] != 2},
otherwise L{PredicateResult.maybe}.
"""
if event["count"] == 2:
return PredicateResult.no
return PredicateResult.maybe
@staticmethod
def no(event: LogEvent) -> NamedConstant:
"""
No way, man.
@param event: an event
@return: L{PredicateResult.no}
"""
return PredicateResult.no
@staticmethod
def bogus(event: LogEvent) -> NamedConstant:
"""
Bogus result.
@param event: an event
@return: something other than a valid predicate result.
"""
return None
predicates = (getattr(Filters, f) for f in filters)
eventsSeen: List[LogEvent] = []
eventsNotSeen: List[LogEvent] = []
trackingObserver = cast(ILogObserver, eventsSeen.append)
if other:
negativeObserver = cast(ILogObserver, eventsNotSeen.append)
else:
negativeObserver = bitbucketLogObserver
filteringObserver = FilteringLogObserver(
trackingObserver, predicates, negativeObserver
)
for e in events:
filteringObserver(e)
if other:
return (
[cast(int, e["count"]) for e in eventsSeen],
[cast(int, e["count"]) for e in eventsNotSeen],
)
else:
return [cast(int, e["count"]) for e in eventsSeen]
def test_shouldLogEventNoFilters(self) -> None:
"""
No filters: all events come through.
"""
self.assertEqual(self.filterWith([]), [0, 1, 2, 3])
def test_shouldLogEventNoFilter(self) -> None:
"""
Filter with negative predicate result.
"""
self.assertEqual(self.filterWith(["notTwo"]), [0, 1, 3])
def test_shouldLogEventOtherObserver(self) -> None:
"""
Filtered results get sent to the other observer, if passed.
"""
self.assertEqual(self.filterWith(["notTwo"], True), ([0, 1, 3], [2]))
def test_shouldLogEventYesFilter(self) -> None:
"""
Filter with positive predicate result.
"""
self.assertEqual(self.filterWith(["twoPlus"]), [0, 1, 2, 3])
def test_shouldLogEventYesNoFilter(self) -> None:
"""
Series of filters with positive and negative predicate results.
"""
self.assertEqual(self.filterWith(["twoPlus", "no"]), [2, 3])
def test_shouldLogEventYesYesNoFilter(self) -> None:
"""
Series of filters with positive, positive and negative predicate
results.
"""
self.assertEqual(self.filterWith(["twoPlus", "twoMinus", "no"]), [0, 1, 2, 3])
def test_shouldLogEventBadPredicateResult(self) -> None:
"""
Filter with invalid predicate result.
"""
self.assertRaises(TypeError, self.filterWith, ["bogus"])
def test_call(self) -> None:
"""
Test filtering results from each predicate type.
"""
e: LogEvent = dict(obj=object())
def callWithPredicateResult(result: NamedConstant) -> List[LogEvent]:
seen: List[LogEvent] = []
observer = FilteringLogObserver(
cast(ILogObserver, lambda e: seen.append(e)),
(cast(ILogFilterPredicate, lambda e: result),),
)
observer(e)
return seen
self.assertIn(e, callWithPredicateResult(PredicateResult.yes))
self.assertIn(e, callWithPredicateResult(PredicateResult.maybe))
self.assertNotIn(e, callWithPredicateResult(PredicateResult.no))
def test_trace(self) -> None:
"""
Tracing keeps track of forwarding through the filtering observer.
"""
event: LogEvent = dict(log_trace=[])
oYes = cast(ILogObserver, lambda e: None)
oNo = cast(ILogObserver, lambda e: None)
@implementer(ILogObserver)
def testObserver(e: LogEvent) -> None:
self.assertIs(e, event)
self.assertEqual(
event["log_trace"],
[
(publisher, yesFilter),
(yesFilter, oYes),
(publisher, noFilter),
# ... noFilter doesn't call oNo
(publisher, oTest),
],
)
oTest = testObserver
yesFilter = FilteringLogObserver(
oYes, (cast(ILogFilterPredicate, lambda e: PredicateResult.yes),)
)
noFilter = FilteringLogObserver(
oNo, (cast(ILogFilterPredicate, lambda e: PredicateResult.no),)
)
publisher = LogPublisher(yesFilter, noFilter, testObserver)
publisher(event)
class LogLevelFilterPredicateTests(unittest.TestCase):
"""
Tests for L{LogLevelFilterPredicate}.
"""
def test_defaultLogLevel(self) -> None:
"""
Default log level is used.
"""
predicate = LogLevelFilterPredicate()
# Test using both "" and None as default namespace, because None was the
# documented default value in the past.
for default in ("", cast(str, None)):
self.assertEqual(
predicate.logLevelForNamespace(default), predicate.defaultLogLevel
)
self.assertEqual(
predicate.logLevelForNamespace("rocker.cool.namespace"),
predicate.defaultLogLevel,
)
def test_setLogLevel(self) -> None:
"""
Setting and retrieving log levels.
"""
predicate = LogLevelFilterPredicate()
# Test using both "" and None as default namespace, because None was the
# documented default value in the past.
for default in ("", cast(str, None)):
predicate.setLogLevelForNamespace(default, LogLevel.error)
predicate.setLogLevelForNamespace("twext.web2", LogLevel.debug)
predicate.setLogLevelForNamespace("twext.web2.dav", LogLevel.warn)
self.assertEqual(predicate.logLevelForNamespace(""), LogLevel.error)
self.assertEqual(
predicate.logLevelForNamespace(cast(str, None)), LogLevel.error
)
self.assertEqual(predicate.logLevelForNamespace("twisted"), LogLevel.error)
self.assertEqual(
predicate.logLevelForNamespace("twext.web2"), LogLevel.debug
)
self.assertEqual(
predicate.logLevelForNamespace("twext.web2.dav"), LogLevel.warn
)
self.assertEqual(
predicate.logLevelForNamespace("twext.web2.dav.test"), LogLevel.warn
)
self.assertEqual(
predicate.logLevelForNamespace("twext.web2.dav.test1.test2"),
LogLevel.warn,
)
def test_setInvalidLogLevel(self) -> None:
"""
Can't pass invalid log levels to C{setLogLevelForNamespace()}.
"""
predicate = LogLevelFilterPredicate()
self.assertRaises(
InvalidLogLevelError,
predicate.setLogLevelForNamespace,
"twext.web2",
object(),
)
# Level must be a constant, not the name of a constant
self.assertRaises(
InvalidLogLevelError,
predicate.setLogLevelForNamespace,
"twext.web2",
"debug",
)
def test_clearLogLevels(self) -> None:
"""
Clearing log levels.
"""
predicate = LogLevelFilterPredicate()
predicate.setLogLevelForNamespace("twext.web2", LogLevel.debug)
predicate.setLogLevelForNamespace("twext.web2.dav", LogLevel.error)
predicate.clearLogLevels()
self.assertEqual(
predicate.logLevelForNamespace("twisted"), predicate.defaultLogLevel
)
self.assertEqual(
predicate.logLevelForNamespace("twext.web2"), predicate.defaultLogLevel
)
self.assertEqual(
predicate.logLevelForNamespace("twext.web2.dav"), predicate.defaultLogLevel
)
self.assertEqual(
predicate.logLevelForNamespace("twext.web2.dav.test"),
predicate.defaultLogLevel,
)
self.assertEqual(
predicate.logLevelForNamespace("twext.web2.dav.test1.test2"),
predicate.defaultLogLevel,
)
def test_filtering(self) -> None:
"""
Events are filtered based on log level/namespace.
"""
predicate = LogLevelFilterPredicate()
predicate.setLogLevelForNamespace("", LogLevel.error)
predicate.setLogLevelForNamespace("twext.web2", LogLevel.debug)
predicate.setLogLevelForNamespace("twext.web2.dav", LogLevel.warn)
def checkPredicate(
namespace: str, level: NamedConstant, expectedResult: NamedConstant
) -> None:
event: LogEvent = dict(log_namespace=namespace, log_level=level)
self.assertEqual(expectedResult, predicate(event))
checkPredicate("", LogLevel.debug, PredicateResult.no)
checkPredicate(cast(str, None), LogLevel.debug, PredicateResult.no)
checkPredicate("", LogLevel.error, PredicateResult.no)
checkPredicate(cast(str, None), LogLevel.error, PredicateResult.no)
checkPredicate("twext.web2", LogLevel.debug, PredicateResult.maybe)
checkPredicate("twext.web2", LogLevel.error, PredicateResult.maybe)
checkPredicate("twext.web2.dav", LogLevel.debug, PredicateResult.no)
checkPredicate("twext.web2.dav", LogLevel.error, PredicateResult.maybe)
checkPredicate("", LogLevel.critical, PredicateResult.no)
checkPredicate(cast(str, None), LogLevel.critical, PredicateResult.no)
checkPredicate("twext.web2", None, PredicateResult.no)

View File

@@ -0,0 +1,326 @@
# Copyright (c) Twisted Matrix Laboratories.
# See LICENSE for details.
"""
Test cases for L{twisted.logger._format}.
"""
import json
from itertools import count
from typing import Any, Callable, Optional
try:
from time import tzset
except ImportError:
tzset = None # type: ignore[assignment]
from twisted.trial import unittest
from .._flatten import KeyFlattener, aFormatter, extractField, flattenEvent
from .._format import formatEvent
from .._interfaces import LogEvent
class FlatFormattingTests(unittest.TestCase):
"""
Tests for flattened event formatting functions.
"""
def test_formatFlatEvent(self) -> None:
"""
L{flattenEvent} will "flatten" an event so that, if scrubbed of all but
serializable objects, it will preserve all necessary data to be
formatted once serialized. When presented with an event thusly
flattened, L{formatEvent} will produce the same output.
"""
counter = count()
class Ephemeral:
attribute = "value"
event1 = dict(
log_format=(
"callable: {callme()} "
"attribute: {object.attribute} "
"numrepr: {number!r} "
"numstr: {number!s} "
"strrepr: {string!r} "
"unistr: {unistr!s}"
),
callme=lambda: next(counter),
object=Ephemeral(),
number=7,
string="hello",
unistr="ö",
)
flattenEvent(event1)
event2 = dict(event1)
del event2["callme"]
del event2["object"]
event3 = json.loads(json.dumps(event2))
self.assertEqual(
formatEvent(event3),
(
"callable: 0 "
"attribute: value "
"numrepr: 7 "
"numstr: 7 "
"strrepr: 'hello' "
"unistr: ö"
),
)
def test_formatFlatEventBadFormat(self) -> None:
"""
If the format string is invalid, an error is produced.
"""
event1 = dict(
log_format=("strrepr: {string!X}"),
string="hello",
)
flattenEvent(event1)
event2 = json.loads(json.dumps(event1))
self.assertTrue(formatEvent(event2).startswith("Unable to format event"))
def test_formatFlatEventWithMutatedFields(self) -> None:
"""
L{formatEvent} will prefer the stored C{str()} or C{repr()} value for
an object, in case the other version.
"""
class Unpersistable:
"""
Unpersitable object.
"""
destructed = False
def selfDestruct(self) -> None:
"""
Self destruct.
"""
self.destructed = True
def __repr__(self) -> str:
if self.destructed:
return "post-serialization garbage"
else:
return "un-persistable"
up = Unpersistable()
event1 = dict(log_format="unpersistable: {unpersistable}", unpersistable=up)
flattenEvent(event1)
up.selfDestruct()
self.assertEqual(formatEvent(event1), "unpersistable: un-persistable")
def test_keyFlattening(self) -> None:
"""
Test that L{KeyFlattener.flatKey} returns the expected keys for format
fields.
"""
def keyFromFormat(format: str) -> str:
for (
literalText,
fieldName,
formatSpec,
conversion,
) in aFormatter.parse(format):
assert fieldName is not None
return KeyFlattener().flatKey(fieldName, formatSpec, conversion)
assert False, "Unable to derive key from format: {format}"
# No name
try:
self.assertEqual(keyFromFormat("{}"), "!:")
except ValueError:
# In python 2.6, an empty field name causes Formatter.parse to
# raise ValueError.
# In Python 2.7, it's allowed, so this exception is unexpected.
raise
# Just a name
self.assertEqual(keyFromFormat("{foo}"), "foo!:")
# Add conversion
self.assertEqual(keyFromFormat("{foo!s}"), "foo!s:")
self.assertEqual(keyFromFormat("{foo!r}"), "foo!r:")
# Add format spec
self.assertEqual(keyFromFormat("{foo:%s}"), "foo!:%s")
self.assertEqual(keyFromFormat("{foo:!}"), "foo!:!")
self.assertEqual(keyFromFormat("{foo::}"), "foo!::")
# Both
self.assertEqual(keyFromFormat("{foo!s:%s}"), "foo!s:%s")
self.assertEqual(keyFromFormat("{foo!s:!}"), "foo!s:!")
self.assertEqual(keyFromFormat("{foo!s::}"), "foo!s::")
sameFlattener = KeyFlattener()
(
(
literalText,
fieldName,
formatSpec,
conversion,
),
) = aFormatter.parse("{x}")
assert fieldName is not None
self.assertEqual(
sameFlattener.flatKey(fieldName, formatSpec, conversion), "x!:"
)
self.assertEqual(
sameFlattener.flatKey(fieldName, formatSpec, conversion), "x!:/2"
)
def _test_formatFlatEvent_fieldNamesSame(
self, event: Optional[LogEvent] = None
) -> LogEvent:
"""
The same format field used twice in one event is rendered twice.
@param event: An event to flatten. If L{None}, create a new event.
@return: C{event} or the event created.
"""
if event is None:
counter = count()
class CountStr:
"""
Hack
"""
def __str__(self) -> str:
return str(next(counter))
event = dict(
log_format="{x} {x}",
x=CountStr(),
)
flattenEvent(event)
self.assertEqual(formatEvent(event), "0 1")
return event
def test_formatFlatEventFieldNamesSame(self) -> None:
"""
The same format field used twice in one event is rendered twice.
"""
self._test_formatFlatEvent_fieldNamesSame()
def test_formatFlatEventFieldNamesSameAgain(self) -> None:
"""
The same event flattened twice gives the same (already rendered)
result.
"""
event = self._test_formatFlatEvent_fieldNamesSame()
self._test_formatFlatEvent_fieldNamesSame(event)
def test_formatEventFlatTrailingText(self) -> None:
"""
L{formatEvent} will handle a flattened event with tailing text after
a replacement field.
"""
event = dict(
log_format="test {x} trailing",
x="value",
)
flattenEvent(event)
result = formatEvent(event)
self.assertEqual(result, "test value trailing")
def test_extractField(
self, flattenFirst: Callable[[LogEvent], LogEvent] = lambda x: x
) -> None:
"""
L{extractField} will extract a field used in the format string.
@param flattenFirst: callable to flatten an event
"""
class ObjectWithRepr:
def __repr__(self) -> str:
return "repr"
class Something:
def __init__(self) -> None:
self.number = 7
self.object = ObjectWithRepr()
def __getstate__(self) -> None:
raise NotImplementedError("Just in case.")
event = dict(
log_format="{something.number} {something.object}",
something=Something(),
)
flattened = flattenFirst(event)
def extract(field: str) -> Any:
return extractField(field, flattened)
self.assertEqual(extract("something.number"), 7)
self.assertEqual(extract("something.number!s"), "7")
self.assertEqual(extract("something.object!s"), "repr")
def test_extractFieldFlattenFirst(self) -> None:
"""
L{extractField} behaves identically if the event is explicitly
flattened first.
"""
def flattened(event: LogEvent) -> LogEvent:
flattenEvent(event)
return event
self.test_extractField(flattened)
def test_flattenEventWithoutFormat(self) -> None:
"""
L{flattenEvent} will do nothing to an event with no format string.
"""
inputEvent = {"a": "b", "c": 1}
flattenEvent(inputEvent)
self.assertEqual(inputEvent, {"a": "b", "c": 1})
def test_flattenEventWithInertFormat(self) -> None:
"""
L{flattenEvent} will do nothing to an event with a format string that
contains no format fields.
"""
inputEvent = {"a": "b", "c": 1, "log_format": "simple message"}
flattenEvent(inputEvent)
self.assertEqual(
inputEvent,
{
"a": "b",
"c": 1,
"log_format": "simple message",
},
)
def test_flattenEventWithNoneFormat(self) -> None:
"""
L{flattenEvent} will do nothing to an event with log_format set to
None.
"""
inputEvent = {"a": "b", "c": 1, "log_format": None}
flattenEvent(inputEvent)
self.assertEqual(
inputEvent,
{
"a": "b",
"c": 1,
"log_format": None,
},
)

View File

@@ -0,0 +1,732 @@
# Copyright (c) Twisted Matrix Laboratories.
# See LICENSE for details.
"""
Test cases for L{twisted.logger._format}.
"""
from typing import Any, AnyStr, Dict, Optional, cast
try:
from time import tzset
# We should upgrade to a version of pyflakes that does not require this.
tzset
except ImportError:
tzset = None # type: ignore[assignment]
from twisted.python.failure import Failure
from twisted.python.test.test_tzhelper import addTZCleanup, mktime, setTZ
from twisted.trial import unittest
from twisted.trial.unittest import SkipTest
from .._format import (
eventAsText,
formatEvent,
formatEventAsClassicLogText,
formatTime,
formatUnformattableEvent,
formatWithCall,
)
from .._interfaces import LogEvent
from .._levels import LogLevel
class FormattingTests(unittest.TestCase):
"""
Tests for basic event formatting functions.
"""
def format(self, logFormat: AnyStr, **event: object) -> str:
"""
Create a Twisted log event dictionary from C{event} with the given
C{logFormat} format string, format it with L{formatEvent}, ensure that
its type is L{str}, and return its result.
"""
event["log_format"] = logFormat
result = formatEvent(event)
self.assertIs(type(result), str)
return result
def test_formatEvent(self) -> None:
"""
L{formatEvent} will format an event according to several rules:
- A string with no formatting instructions will be passed straight
through.
- PEP 3101 strings will be formatted using the keys and values of
the event as named fields.
- PEP 3101 keys ending with C{()} will be treated as instructions
to call that key (which ought to be a callable) before
formatting.
L{formatEvent} will always return L{str}, and if given bytes, will
always treat its format string as UTF-8 encoded.
"""
self.assertEqual("", self.format(b""))
self.assertEqual("", self.format(""))
self.assertEqual("abc", self.format("{x}", x="abc"))
self.assertEqual(
"no, yes.",
self.format(
"{not_called}, {called()}.", not_called="no", called=lambda: "yes"
),
)
self.assertEqual("S\xe1nchez", self.format(b"S\xc3\xa1nchez"))
self.assertIn("Unable to format event", self.format(b"S\xe1nchez"))
maybeResult = self.format(b"S{a!s}nchez", a=b"\xe1")
self.assertIn("Sb'\\xe1'nchez", maybeResult)
xe1 = str(repr(b"\xe1"))
self.assertIn("S" + xe1 + "nchez", self.format(b"S{a!r}nchez", a=b"\xe1"))
def test_formatMethod(self) -> None:
"""
L{formatEvent} will format PEP 3101 keys containing C{.}s ending with
C{()} as methods.
"""
class World:
def where(self) -> str:
return "world"
self.assertEqual(
"hello world", self.format("hello {what.where()}", what=World())
)
def test_formatAttributeSubscript(self) -> None:
"""
L{formatEvent} will format subscripts of attributes per PEP 3101.
"""
class Example(object):
config: Dict[str, str] = dict(foo="bar", baz="qux")
self.assertEqual(
"bar qux",
self.format(
"{example.config[foo]} {example.config[baz]}",
example=Example(),
),
)
def test_formatEventNoFormat(self) -> None:
"""
Formatting an event with no format.
"""
event = dict(foo=1, bar=2)
result = formatEvent(event)
self.assertEqual("", result)
def test_formatEventWeirdFormat(self) -> None:
"""
Formatting an event with a bogus format.
"""
event = dict(log_format=object(), foo=1, bar=2)
result = formatEvent(event)
self.assertIn("Log format must be str", result)
self.assertIn(repr(event), result)
def test_formatUnformattableEvent(self) -> None:
"""
Formatting an event that's just plain out to get us.
"""
event = dict(log_format="{evil()}", evil=lambda: 1 / 0)
result = formatEvent(event)
self.assertIn("Unable to format event", result)
self.assertIn(repr(event), result)
def test_formatUnformattableEventWithUnformattableKey(self) -> None:
"""
Formatting an unformattable event that has an unformattable key.
"""
event: LogEvent = {
"log_format": "{evil()}",
"evil": lambda: 1 / 0,
cast(str, Unformattable()): "gurk",
}
result = formatEvent(event)
self.assertIn("MESSAGE LOST: unformattable object logged:", result)
self.assertIn("Recoverable data:", result)
self.assertIn("Exception during formatting:", result)
def test_formatUnformattableEventWithUnformattableValue(self) -> None:
"""
Formatting an unformattable event that has an unformattable value.
"""
event = dict(
log_format="{evil()}",
evil=lambda: 1 / 0,
gurk=Unformattable(),
)
result = formatEvent(event)
self.assertIn("MESSAGE LOST: unformattable object logged:", result)
self.assertIn("Recoverable data:", result)
self.assertIn("Exception during formatting:", result)
def test_formatUnformattableEventWithUnformattableErrorOMGWillItStop(self) -> None:
"""
Formatting an unformattable event that has an unformattable value.
"""
event = dict(
log_format="{evil()}",
evil=lambda: 1 / 0,
recoverable="okay",
)
# Call formatUnformattableEvent() directly with a bogus exception.
result = formatUnformattableEvent(event, cast(BaseException, Unformattable()))
self.assertIn("MESSAGE LOST: unformattable object logged:", result)
self.assertIn(repr("recoverable") + " = " + repr("okay"), result)
class TimeFormattingTests(unittest.TestCase):
"""
Tests for time formatting functions.
"""
def setUp(self) -> None:
addTZCleanup(self)
def test_formatTimeWithDefaultFormat(self) -> None:
"""
Default time stamp format is RFC 3339 and offset respects the timezone
as set by the standard C{TZ} environment variable and L{tzset} API.
"""
if tzset is None:
raise SkipTest("Platform cannot change timezone; unable to verify offsets.")
def testForTimeZone(
name: str, expectedDST: Optional[str], expectedSTD: str
) -> None:
setTZ(name)
localSTD = mktime((2007, 1, 31, 0, 0, 0, 2, 31, 0))
self.assertEqual(formatTime(localSTD), expectedSTD)
if expectedDST:
localDST = mktime((2006, 6, 30, 0, 0, 0, 4, 181, 1))
self.assertEqual(formatTime(localDST), expectedDST)
# UTC
testForTimeZone(
"UTC+00",
None,
"2007-01-31T00:00:00+0000",
)
# West of UTC
testForTimeZone(
"EST+05EDT,M4.1.0,M10.5.0",
"2006-06-30T00:00:00-0400",
"2007-01-31T00:00:00-0500",
)
# East of UTC
testForTimeZone(
"CEST-01CEDT,M4.1.0,M10.5.0",
"2006-06-30T00:00:00+0200",
"2007-01-31T00:00:00+0100",
)
# No DST
testForTimeZone(
"CST+06",
None,
"2007-01-31T00:00:00-0600",
)
def test_formatTimeWithNoTime(self) -> None:
"""
If C{when} argument is L{None}, we get the default output.
"""
self.assertEqual(formatTime(None), "-")
self.assertEqual(formatTime(None, default="!"), "!")
def test_formatTimeWithNoFormat(self) -> None:
"""
If C{timeFormat} argument is L{None}, we get the default output.
"""
t = mktime((2013, 9, 24, 11, 40, 47, 1, 267, -1))
self.assertEqual(formatTime(t, timeFormat=None), "-")
self.assertEqual(formatTime(t, timeFormat=None, default="!"), "!")
def test_formatTimeWithAlternateTimeFormat(self) -> None:
"""
Alternate time format in output.
"""
t = mktime((2013, 9, 24, 11, 40, 47, 1, 267, -1))
self.assertEqual(formatTime(t, timeFormat="%Y/%W"), "2013/38")
def test_formatTimePercentF(self) -> None:
"""
"%f" supported in time format.
"""
self.assertEqual(formatTime(1000000.23456, timeFormat="%f"), "234560")
class ClassicLogFormattingTests(unittest.TestCase):
"""
Tests for classic text log event formatting functions.
"""
def test_formatTimeDefault(self) -> None:
"""
Time is first field. Default time stamp format is RFC 3339 and offset
respects the timezone as set by the standard C{TZ} environment variable
and L{tzset} API.
"""
if tzset is None:
raise SkipTest("Platform cannot change timezone; unable to verify offsets.")
addTZCleanup(self)
setTZ("UTC+00")
t = mktime((2013, 9, 24, 11, 40, 47, 1, 267, -1))
event = dict(log_format="XYZZY", log_time=t)
self.assertEqual(
formatEventAsClassicLogText(event),
"2013-09-24T11:40:47+0000 [-\x23-] XYZZY\n",
)
def test_formatTimeCustom(self) -> None:
"""
Time is first field. Custom formatting function is an optional
argument.
"""
def formatTime(t: Optional[float]) -> str:
return f"__{t}__"
event = dict(log_format="XYZZY", log_time=12345)
self.assertEqual(
formatEventAsClassicLogText(event, formatTime=formatTime),
"__12345__ [-\x23-] XYZZY\n",
)
def test_formatNamespace(self) -> None:
"""
Namespace is first part of second field.
"""
event = dict(log_format="XYZZY", log_namespace="my.namespace")
self.assertEqual(
formatEventAsClassicLogText(event),
"- [my.namespace\x23-] XYZZY\n",
)
def test_formatLevel(self) -> None:
"""
Level is second part of second field.
"""
event = dict(log_format="XYZZY", log_level=LogLevel.warn)
self.assertEqual(
formatEventAsClassicLogText(event),
"- [-\x23warn] XYZZY\n",
)
def test_formatSystem(self) -> None:
"""
System is second field.
"""
event = dict(log_format="XYZZY", log_system="S.Y.S.T.E.M.")
self.assertEqual(
formatEventAsClassicLogText(event),
"- [S.Y.S.T.E.M.] XYZZY\n",
)
def test_formatSystemRulz(self) -> None:
"""
System is not supplanted by namespace and level.
"""
event = dict(
log_format="XYZZY",
log_namespace="my.namespace",
log_level=LogLevel.warn,
log_system="S.Y.S.T.E.M.",
)
self.assertEqual(
formatEventAsClassicLogText(event),
"- [S.Y.S.T.E.M.] XYZZY\n",
)
def test_formatSystemUnformattable(self) -> None:
"""
System is not supplanted by namespace and level.
"""
event = dict(log_format="XYZZY", log_system=Unformattable())
self.assertEqual(
formatEventAsClassicLogText(event),
"- [UNFORMATTABLE] XYZZY\n",
)
def test_formatFormat(self) -> None:
"""
Formatted event is last field.
"""
event = dict(log_format="id:{id}", id="123")
self.assertEqual(
formatEventAsClassicLogText(event),
"- [-\x23-] id:123\n",
)
def test_formatNoFormat(self) -> None:
"""
No format string.
"""
event = dict(id="123")
self.assertIs(formatEventAsClassicLogText(event), None)
def test_formatEmptyFormat(self) -> None:
"""
Empty format string.
"""
event = dict(log_format="", id="123")
self.assertIs(formatEventAsClassicLogText(event), None)
def test_formatFormatMultiLine(self) -> None:
"""
If the formatted event has newlines, indent additional lines.
"""
event = dict(log_format='XYZZY\nA hollow voice says:\n"Plugh"')
self.assertEqual(
formatEventAsClassicLogText(event),
'- [-\x23-] XYZZY\n\tA hollow voice says:\n\t"Plugh"\n',
)
class FormatFieldTests(unittest.TestCase):
"""
Tests for format field functions.
"""
def test_formatWithCall(self) -> None:
"""
L{formatWithCall} is an extended version of L{str.format} that
will interpret a set of parentheses "C{()}" at the end of a format key
to mean that the format key ought to be I{called} rather than
stringified.
"""
self.assertEqual(
formatWithCall(
"Hello, {world}. {callme()}.",
dict(world="earth", callme=lambda: "maybe"),
),
"Hello, earth. maybe.",
)
self.assertEqual(
formatWithCall("Hello, {repr()!r}.", dict(repr=lambda: "repr")),
"Hello, 'repr'.",
)
class Unformattable:
"""
An object that raises an exception from C{__repr__}.
"""
def __repr__(self) -> str:
return str(1 / 0)
class CapturedError(Exception):
"""
A captured error for use in format tests.
"""
class EventAsTextTests(unittest.TestCase):
"""
Tests for L{eventAsText}, all of which ensure that the
returned type is UTF-8 decoded text.
"""
def test_eventWithTraceback(self) -> None:
"""
An event with a C{log_failure} key will have a traceback appended.
"""
try:
raise CapturedError("This is a fake error")
except CapturedError:
f = Failure()
event: LogEvent = {"log_format": "This is a test log message"}
event["log_failure"] = f
eventText = eventAsText(event, includeTimestamp=True, includeSystem=False)
self.assertIn(str(f.getTraceback()), eventText)
self.assertIn("This is a test log message", eventText)
def test_formatEmptyEventWithTraceback(self) -> None:
"""
An event with an empty C{log_format} key appends a traceback from
the accompanying failure.
"""
try:
raise CapturedError("This is a fake error")
except CapturedError:
f = Failure()
event: LogEvent = {"log_format": ""}
event["log_failure"] = f
eventText = eventAsText(event, includeTimestamp=True, includeSystem=False)
self.assertIn(str(f.getTraceback()), eventText)
self.assertIn("This is a fake error", eventText)
def test_formatUnformattableWithTraceback(self) -> None:
"""
An event with an unformattable value in the C{log_format} key still
has a traceback appended.
"""
try:
raise CapturedError("This is a fake error")
except CapturedError:
f = Failure()
event = {
"log_format": "{evil()}",
"evil": lambda: 1 / 0,
}
event["log_failure"] = f
eventText = eventAsText(event, includeTimestamp=True, includeSystem=False)
self.assertIsInstance(eventText, str)
self.assertIn(str(f.getTraceback()), eventText)
self.assertIn("This is a fake error", eventText)
def test_formatUnformattableErrorWithTraceback(self) -> None:
"""
An event with an unformattable value in the C{log_format} key, that
throws an exception when __repr__ is invoked still has a traceback
appended.
"""
try:
raise CapturedError("This is a fake error")
except CapturedError:
f = Failure()
event: LogEvent = {
"log_format": "{evil()}",
"evil": lambda: 1 / 0,
cast(str, Unformattable()): "gurk",
}
event["log_failure"] = f
eventText = eventAsText(event, includeTimestamp=True, includeSystem=False)
self.assertIsInstance(eventText, str)
self.assertIn("MESSAGE LOST", eventText)
self.assertIn(str(f.getTraceback()), eventText)
self.assertIn("This is a fake error", eventText)
def test_formatEventUnformattableTraceback(self) -> None:
"""
If a traceback cannot be appended, a message indicating this is true
is appended.
"""
event: LogEvent = {"log_format": ""}
event["log_failure"] = object()
eventText = eventAsText(event, includeTimestamp=True, includeSystem=False)
self.assertIsInstance(eventText, str)
self.assertIn("(UNABLE TO OBTAIN TRACEBACK FROM EVENT)", eventText)
def test_formatEventNonCritical(self) -> None:
"""
An event with no C{log_failure} key will not have a traceback appended.
"""
event: LogEvent = {"log_format": "This is a test log message"}
eventText = eventAsText(event, includeTimestamp=True, includeSystem=False)
self.assertIsInstance(eventText, str)
self.assertIn("This is a test log message", eventText)
def test_formatTracebackMultibyte(self) -> None:
"""
An exception message with multibyte characters is properly handled.
"""
try:
raise CapturedError("")
except CapturedError:
f = Failure()
event: LogEvent = {"log_format": "This is a test log message"}
event["log_failure"] = f
eventText = eventAsText(event, includeTimestamp=True, includeSystem=False)
self.assertIn("", eventText)
self.assertIn("Traceback", eventText)
def test_formatTracebackHandlesUTF8DecodeFailure(self) -> None:
"""
An error raised attempting to decode the UTF still produces a
valid log message.
"""
try:
# 'test' in utf-16
raise CapturedError(b"\xff\xfet\x00e\x00s\x00t\x00")
except CapturedError:
f = Failure()
event: LogEvent = {"log_format": "This is a test log message"}
event["log_failure"] = f
eventText = eventAsText(event, includeTimestamp=True, includeSystem=False)
self.assertIn("Traceback", eventText)
self.assertIn(r'CapturedError(b"\xff\xfet\x00e\x00s\x00t\x00")', eventText)
def test_eventAsTextSystemOnly(self) -> None:
"""
If includeSystem is specified as the only option no timestamp or
traceback are printed.
"""
try:
raise CapturedError("This is a fake error")
except CapturedError:
f = Failure()
t = mktime((2013, 9, 24, 11, 40, 47, 1, 267, -1))
event: LogEvent = {
"log_format": "ABCD",
"log_system": "fake_system",
"log_time": t,
}
event["log_failure"] = f
eventText = eventAsText(
event,
includeTimestamp=False,
includeTraceback=False,
includeSystem=True,
)
self.assertEqual(
eventText,
"[fake_system] ABCD",
)
def test_eventAsTextTimestampOnly(self) -> None:
"""
If includeTimestamp is specified as the only option no system or
traceback are printed.
"""
if tzset is None:
raise SkipTest("Platform cannot change timezone; unable to verify offsets.")
addTZCleanup(self)
setTZ("UTC+00")
try:
raise CapturedError("This is a fake error")
except CapturedError:
f = Failure()
t = mktime((2013, 9, 24, 11, 40, 47, 1, 267, -1))
event: LogEvent = {
"log_format": "ABCD",
"log_system": "fake_system",
"log_time": t,
}
event["log_failure"] = f
eventText = eventAsText(
event,
includeTimestamp=True,
includeTraceback=False,
includeSystem=False,
)
self.assertEqual(
eventText,
"2013-09-24T11:40:47+0000 ABCD",
)
def test_eventAsTextSystemMissing(self) -> None:
"""
If includeSystem is specified with a missing system [-#-]
is used.
"""
try:
raise CapturedError("This is a fake error")
except CapturedError:
f = Failure()
t = mktime((2013, 9, 24, 11, 40, 47, 1, 267, -1))
event: LogEvent = {
"log_format": "ABCD",
"log_time": t,
}
event["log_failure"] = f
eventText = eventAsText(
event,
includeTimestamp=False,
includeTraceback=False,
includeSystem=True,
)
self.assertEqual(
eventText,
"[-\x23-] ABCD",
)
def test_eventAsTextSystemMissingNamespaceAndLevel(self) -> None:
"""
If includeSystem is specified with a missing system but
namespace and level are present they are used.
"""
try:
raise CapturedError("This is a fake error")
except CapturedError:
f = Failure()
t = mktime((2013, 9, 24, 11, 40, 47, 1, 267, -1))
event: LogEvent = {
"log_format": "ABCD",
"log_time": t,
"log_level": LogLevel.info,
"log_namespace": "test",
}
event["log_failure"] = f
eventText = eventAsText(
event,
includeTimestamp=False,
includeTraceback=False,
includeSystem=True,
)
self.assertEqual(
eventText,
"[test\x23info] ABCD",
)
def test_eventAsTextSystemMissingLevelOnly(self) -> None:
"""
If includeSystem is specified with a missing system but
level is present, level is included.
"""
try:
raise CapturedError("This is a fake error")
except CapturedError:
f = Failure()
t = mktime((2013, 9, 24, 11, 40, 47, 1, 267, -1))
event: LogEvent = {
"log_format": "ABCD",
"log_time": t,
"log_level": LogLevel.info,
}
event["log_failure"] = f
eventText = eventAsText(
event,
includeTimestamp=False,
includeTraceback=False,
includeSystem=True,
)
self.assertEqual(
eventText,
"[-\x23info] ABCD",
)
def test_eventAsTextTypeAsInput(self) -> None:
"""
C{eventAsText} can handle formats that have classes or types as input.
"""
def getText(logFormat: str, **event: Any) -> str:
return eventAsText(
{"log_format": logFormat, **event},
includeTimestamp=False,
includeTraceback=False,
includeSystem=False,
)
self.assertEqual(str(int), getText("{c}", c=int))
self.assertEqual(str(RuntimeError), getText("{c}", c=RuntimeError))
self.assertEqual("str", getText("{c.__name__}", c=str))

View File

@@ -0,0 +1,352 @@
# Copyright (c) Twisted Matrix Laboratories.
# See LICENSE for details.
"""
Test cases for L{twisted.logger._global}.
"""
import io
from typing import IO, Any, List, Optional, TextIO, Tuple, Type, cast
from twisted.python.failure import Failure
from twisted.trial import unittest
from .._file import textFileLogObserver
from .._global import MORE_THAN_ONCE_WARNING, LogBeginner
from .._interfaces import ILogObserver, LogEvent
from .._levels import LogLevel
from .._logger import Logger
from .._observer import LogPublisher
from ..test.test_stdlib import nextLine
def compareEvents(
test: unittest.TestCase,
actualEvents: List[LogEvent],
expectedEvents: List[LogEvent],
) -> None:
"""
Compare two sequences of log events, examining only the the keys which are
present in both.
@param test: a test case doing the comparison
@param actualEvents: A list of log events that were emitted by a logger.
@param expectedEvents: A list of log events that were expected by a test.
"""
if len(actualEvents) != len(expectedEvents):
test.assertEqual(actualEvents, expectedEvents)
allMergedKeys = set()
for event in expectedEvents:
allMergedKeys |= set(event.keys())
def simplify(event: LogEvent) -> LogEvent:
copy = event.copy()
for key in event.keys():
if key not in allMergedKeys:
copy.pop(key)
return copy
simplifiedActual = [simplify(event) for event in actualEvents]
test.assertEqual(simplifiedActual, expectedEvents)
class LogBeginnerTests(unittest.TestCase):
"""
Tests for L{LogBeginner}.
"""
def setUp(self) -> None:
self.publisher = LogPublisher()
self.errorStream = io.StringIO()
class NotSys:
stdout = object()
stderr = object()
class NotWarnings:
def __init__(self) -> None:
self.warnings: List[
Tuple[
str, Type[Warning], str, int, Optional[IO[Any]], Optional[int]
]
] = []
def showwarning(
self,
message: str,
category: Type[Warning],
filename: str,
lineno: int,
file: Optional[IO[Any]] = None,
line: Optional[int] = None,
) -> None:
"""
Emulate warnings.showwarning.
@param message: A warning message to emit.
@param category: A warning category to associate with
C{message}.
@param filename: A file name for the source code file issuing
the warning.
@param lineno: A line number in the source file where the
warning was issued.
@param file: A file to write the warning message to. If
L{None}, write to L{sys.stderr}.
@param line: A line of source code to include with the warning
message. If L{None}, attempt to read the line from
C{filename} and C{lineno}.
"""
self.warnings.append((message, category, filename, lineno, file, line))
self.sysModule = NotSys()
self.warningsModule = NotWarnings()
self.beginner = LogBeginner(
self.publisher, self.errorStream, self.sysModule, self.warningsModule
)
def test_beginLoggingToAddObservers(self) -> None:
"""
Test that C{beginLoggingTo()} adds observers.
"""
event = dict(foo=1, bar=2)
events1: List[LogEvent] = []
events2: List[LogEvent] = []
o1 = cast(ILogObserver, lambda e: events1.append(e))
o2 = cast(ILogObserver, lambda e: events2.append(e))
self.beginner.beginLoggingTo((o1, o2))
self.publisher(event)
self.assertEqual([event], events1)
self.assertEqual([event], events2)
def test_beginLoggingToBufferedEvents(self) -> None:
"""
Test that events are buffered until C{beginLoggingTo()} is
called.
"""
event = dict(foo=1, bar=2)
events1: List[LogEvent] = []
events2: List[LogEvent] = []
o1 = cast(ILogObserver, lambda e: events1.append(e))
o2 = cast(ILogObserver, lambda e: events2.append(e))
self.publisher(event) # Before beginLoggingTo; this is buffered
self.beginner.beginLoggingTo((o1, o2))
self.assertEqual([event], events1)
self.assertEqual([event], events2)
def _bufferLimitTest(self, limit: int, beginner: LogBeginner) -> None:
"""
Verify that when more than C{limit} events are logged to L{LogBeginner},
only the last C{limit} are replayed by L{LogBeginner.beginLoggingTo}.
@param limit: The maximum number of events the log beginner should
buffer.
@param beginner: The L{LogBeginner} against which to verify.
@raise: C{self.failureException} if the wrong events are replayed by
C{beginner}.
"""
for count in range(limit + 1):
self.publisher(dict(count=count))
events: List[LogEvent] = []
beginner.beginLoggingTo([cast(ILogObserver, events.append)])
self.assertEqual(
list(range(1, limit + 1)),
list(event["count"] for event in events),
)
def test_defaultBufferLimit(self) -> None:
"""
Up to C{LogBeginner._DEFAULT_BUFFER_SIZE} log events are buffered for
replay by L{LogBeginner.beginLoggingTo}.
"""
limit = LogBeginner._DEFAULT_BUFFER_SIZE
self._bufferLimitTest(limit, self.beginner)
def test_overrideBufferLimit(self) -> None:
"""
The size of the L{LogBeginner} event buffer can be overridden with the
C{initialBufferSize} initilizer argument.
"""
limit = 3
beginner = LogBeginner(
self.publisher,
self.errorStream,
self.sysModule,
self.warningsModule,
initialBufferSize=limit,
)
self._bufferLimitTest(limit, beginner)
def test_beginLoggingToTwice(self) -> None:
"""
When invoked twice, L{LogBeginner.beginLoggingTo} will emit a log
message warning the user that they previously began logging, and add
the new log observers.
"""
events1: List[LogEvent] = []
events2: List[LogEvent] = []
fileHandle = io.StringIO()
textObserver = textFileLogObserver(fileHandle)
self.publisher(dict(event="prebuffer"))
firstFilename, firstLine = nextLine()
self.beginner.beginLoggingTo([cast(ILogObserver, events1.append), textObserver])
self.publisher(dict(event="postbuffer"))
secondFilename, secondLine = nextLine()
self.beginner.beginLoggingTo([cast(ILogObserver, events2.append), textObserver])
self.publisher(dict(event="postwarn"))
warning = dict(
log_format=MORE_THAN_ONCE_WARNING,
log_level=LogLevel.warn,
fileNow=secondFilename,
lineNow=secondLine,
fileThen=firstFilename,
lineThen=firstLine,
)
self.maxDiff = None
compareEvents(
self,
events1,
[
dict(event="prebuffer"),
dict(event="postbuffer"),
warning,
dict(event="postwarn"),
],
)
compareEvents(self, events2, [warning, dict(event="postwarn")])
output = fileHandle.getvalue()
self.assertIn(f"<{firstFilename}:{firstLine}>", output)
self.assertIn(f"<{secondFilename}:{secondLine}>", output)
def test_criticalLogging(self) -> None:
"""
Critical messages will be written as text to the error stream.
"""
log = Logger(observer=self.publisher)
log.info("ignore this")
log.critical("a critical {message}", message="message")
self.assertEqual(self.errorStream.getvalue(), "a critical message\n")
def test_criticalLoggingStops(self) -> None:
"""
Once logging has begun with C{beginLoggingTo}, critical messages are no
longer written to the output stream.
"""
log = Logger(observer=self.publisher)
self.beginner.beginLoggingTo(())
log.critical("another critical message")
self.assertEqual(self.errorStream.getvalue(), "")
def test_beginLoggingToRedirectStandardIO(self) -> None:
"""
L{LogBeginner.beginLoggingTo} will re-direct the standard output and
error streams by setting the C{stdio} and C{stderr} attributes on its
sys module object.
"""
events: List[LogEvent] = []
self.beginner.beginLoggingTo([cast(ILogObserver, events.append)])
print("Hello, world.", file=cast(TextIO, self.sysModule.stdout))
compareEvents(
self, events, [dict(log_namespace="stdout", log_io="Hello, world.")]
)
del events[:]
print("Error, world.", file=cast(TextIO, self.sysModule.stderr))
compareEvents(
self, events, [dict(log_namespace="stderr", log_io="Error, world.")]
)
def test_beginLoggingToDontRedirect(self) -> None:
"""
L{LogBeginner.beginLoggingTo} will leave the existing stdout/stderr in
place if it has been told not to replace them.
"""
oldOut = self.sysModule.stdout
oldErr = self.sysModule.stderr
self.beginner.beginLoggingTo((), redirectStandardIO=False)
self.assertIs(self.sysModule.stdout, oldOut)
self.assertIs(self.sysModule.stderr, oldErr)
def test_beginLoggingToPreservesEncoding(self) -> None:
"""
When L{LogBeginner.beginLoggingTo} redirects stdout/stderr streams, the
replacement streams will preserve the encoding of the replaced streams,
to minimally disrupt any application relying on a specific encoding.
"""
weird = io.TextIOWrapper(io.BytesIO(), "shift-JIS")
weirderr = io.TextIOWrapper(io.BytesIO(), "big5")
self.sysModule.stdout = weird
self.sysModule.stderr = weirderr
events: List[LogEvent] = []
self.beginner.beginLoggingTo([cast(ILogObserver, events.append)])
stdout = cast(TextIO, self.sysModule.stdout)
stderr = cast(TextIO, self.sysModule.stderr)
self.assertEqual(stdout.encoding, "shift-JIS")
self.assertEqual(stderr.encoding, "big5")
stdout.write(b"\x97\x9B\n") # type: ignore[call-overload]
stderr.write(b"\xBC\xFC\n") # type: ignore[call-overload]
compareEvents(self, events, [dict(log_io="\u674e"), dict(log_io="\u7469")])
def test_warningsModule(self) -> None:
"""
L{LogBeginner.beginLoggingTo} will redirect the warnings of its
warnings module into the logging system.
"""
self.warningsModule.showwarning("a message", DeprecationWarning, __file__, 1)
events: List[LogEvent] = []
self.beginner.beginLoggingTo([cast(ILogObserver, events.append)])
self.warningsModule.showwarning(
"another message", DeprecationWarning, __file__, 2
)
f = io.StringIO()
self.warningsModule.showwarning(
"yet another", DeprecationWarning, __file__, 3, file=f
)
self.assertEqual(
self.warningsModule.warnings,
[
("a message", DeprecationWarning, __file__, 1, None, None),
("yet another", DeprecationWarning, __file__, 3, f, None),
],
)
compareEvents(
self,
events,
[
dict(
warning="another message",
category=(
DeprecationWarning.__module__
+ "."
+ DeprecationWarning.__name__
),
filename=__file__,
lineno=2,
)
],
)
def test_failuresAppendTracebacks(self) -> None:
"""
The string resulting from a logged failure contains a traceback.
"""
f = Failure(Exception("this is not the behavior you are looking for"))
log = Logger(observer=self.publisher)
log.failure("a failure", failure=f)
msg = self.errorStream.getvalue()
self.assertIn("a failure", msg)
self.assertIn("this is not the behavior you are looking for", msg)
self.assertIn("Traceback", msg)

View File

@@ -0,0 +1,289 @@
# Copyright (c) Twisted Matrix Laboratories.
# See LICENSE for details.
"""
Test cases for L{twisted.logger._io}.
"""
import sys
from typing import List, Optional
from zope.interface import implementer
from constantly import NamedConstant
from twisted.trial import unittest
from .._interfaces import ILogObserver, LogEvent
from .._io import LoggingFile
from .._levels import LogLevel
from .._logger import Logger
from .._observer import LogPublisher
@implementer(ILogObserver)
class TestLoggingFile(LoggingFile):
"""
L{LoggingFile} that is also an observer which captures events and messages.
"""
def __init__(
self,
logger: Logger,
level: NamedConstant = LogLevel.info,
encoding: Optional[str] = None,
) -> None:
super().__init__(logger=logger, level=level, encoding=encoding)
self.events: List[LogEvent] = []
self.messages: List[str] = []
def __call__(self, event: LogEvent) -> None:
self.events.append(event)
if "log_io" in event:
self.messages.append(event["log_io"])
class LoggingFileTests(unittest.TestCase):
"""
Tests for L{LoggingFile}.
"""
def setUp(self) -> None:
"""
Create a logger for test L{LoggingFile} instances to use.
"""
self.publisher = LogPublisher()
self.logger = Logger(observer=self.publisher)
def test_softspace(self) -> None:
"""
L{LoggingFile.softspace} is 0.
"""
self.assertEqual(LoggingFile(self.logger).softspace, 0)
warningsShown = self.flushWarnings([self.test_softspace])
self.assertEqual(len(warningsShown), 1)
self.assertEqual(warningsShown[0]["category"], DeprecationWarning)
deprecatedClass = "twisted.logger._io.LoggingFile.softspace"
self.assertEqual(
warningsShown[0]["message"],
"%s was deprecated in Twisted 21.2.0" % (deprecatedClass),
)
def test_readOnlyAttributes(self) -> None:
"""
Some L{LoggingFile} attributes are read-only.
"""
f = LoggingFile(self.logger)
self.assertRaises(AttributeError, setattr, f, "closed", True)
self.assertRaises(AttributeError, setattr, f, "encoding", "utf-8")
self.assertRaises(AttributeError, setattr, f, "mode", "r")
self.assertRaises(AttributeError, setattr, f, "newlines", ["\n"])
self.assertRaises(AttributeError, setattr, f, "name", "foo")
def test_unsupportedMethods(self) -> None:
"""
Some L{LoggingFile} methods are unsupported.
"""
f = LoggingFile(self.logger)
self.assertRaises(IOError, f.read)
self.assertRaises(IOError, f.next)
self.assertRaises(IOError, f.readline)
self.assertRaises(IOError, f.readlines)
self.assertRaises(IOError, f.xreadlines)
self.assertRaises(IOError, f.seek)
self.assertRaises(IOError, f.tell)
self.assertRaises(IOError, f.truncate)
def test_level(self) -> None:
"""
Default level is L{LogLevel.info} if not set.
"""
f = LoggingFile(self.logger)
self.assertEqual(f.level, LogLevel.info)
f = LoggingFile(self.logger, level=LogLevel.error)
self.assertEqual(f.level, LogLevel.error)
def test_encoding(self) -> None:
"""
Default encoding is C{sys.getdefaultencoding()} if not set.
"""
f = LoggingFile(self.logger)
self.assertEqual(f.encoding, sys.getdefaultencoding())
f = LoggingFile(self.logger, encoding="utf-8")
self.assertEqual(f.encoding, "utf-8")
def test_mode(self) -> None:
"""
Reported mode is C{"w"}.
"""
f = LoggingFile(self.logger)
self.assertEqual(f.mode, "w")
def test_newlines(self) -> None:
"""
The C{newlines} attribute is L{None}.
"""
f = LoggingFile(self.logger)
self.assertIsNone(f.newlines)
def test_name(self) -> None:
"""
The C{name} attribute is fixed.
"""
f = LoggingFile(self.logger)
self.assertEqual(f.name, "<LoggingFile twisted.logger.test.test_io#info>")
def test_close(self) -> None:
"""
L{LoggingFile.close} closes the file.
"""
f = LoggingFile(self.logger)
f.close()
self.assertTrue(f.closed)
self.assertRaises(ValueError, f.write, "Hello")
def test_flush(self) -> None:
"""
L{LoggingFile.flush} does nothing.
"""
f = LoggingFile(self.logger)
f.flush()
def test_fileno(self) -> None:
"""
L{LoggingFile.fileno} returns C{-1}.
"""
f = LoggingFile(self.logger)
self.assertEqual(f.fileno(), -1)
def test_isatty(self) -> None:
"""
L{LoggingFile.isatty} returns C{False}.
"""
f = LoggingFile(self.logger)
self.assertFalse(f.isatty())
def test_writeBuffering(self) -> None:
"""
Writing buffers correctly.
"""
f = self.observedFile()
f.write("Hello")
self.assertEqual(f.messages, [])
f.write(", world!\n")
self.assertEqual(f.messages, ["Hello, world!"])
f.write("It's nice to meet you.\n\nIndeed.")
self.assertEqual(
f.messages,
[
"Hello, world!",
"It's nice to meet you.",
"",
],
)
def test_writeBytesDecoded(self) -> None:
"""
Bytes are decoded to text.
"""
f = self.observedFile(encoding="utf-8")
f.write(b"Hello, Mr. S\xc3\xa1nchez\n")
self.assertEqual(f.messages, ["Hello, Mr. S\xe1nchez"])
def test_writeUnicode(self) -> None:
"""
Unicode is unmodified.
"""
f = self.observedFile(encoding="utf-8")
f.write("Hello, Mr. S\xe1nchez\n")
self.assertEqual(f.messages, ["Hello, Mr. S\xe1nchez"])
def test_writeLevel(self) -> None:
"""
Log level is emitted properly.
"""
f = self.observedFile()
f.write("Hello\n")
self.assertEqual(len(f.events), 1)
self.assertEqual(f.events[0]["log_level"], LogLevel.info)
f = self.observedFile(level=LogLevel.error)
f.write("Hello\n")
self.assertEqual(len(f.events), 1)
self.assertEqual(f.events[0]["log_level"], LogLevel.error)
def test_writeFormat(self) -> None:
"""
Log format is C{"{message}"}.
"""
f = self.observedFile()
f.write("Hello\n")
self.assertEqual(len(f.events), 1)
self.assertEqual(f.events[0]["log_format"], "{log_io}")
def test_writelinesBuffering(self) -> None:
"""
C{writelines} does not add newlines.
"""
# Note this is different behavior than t.p.log.StdioOnnaStick.
f = self.observedFile()
f.writelines(("Hello", ", ", ""))
self.assertEqual(f.messages, [])
f.writelines(("world!\n",))
self.assertEqual(f.messages, ["Hello, world!"])
f.writelines(("It's nice to meet you.\n\n", "Indeed."))
self.assertEqual(
f.messages,
[
"Hello, world!",
"It's nice to meet you.",
"",
],
)
def test_print(self) -> None:
"""
L{LoggingFile} can replace L{sys.stdout}.
"""
f = self.observedFile()
self.patch(sys, "stdout", f)
print("Hello,", end=" ")
print("world.")
self.assertEqual(f.messages, ["Hello, world."])
def observedFile(
self,
level: NamedConstant = LogLevel.info,
encoding: Optional[str] = None,
) -> TestLoggingFile:
"""
Construct a L{LoggingFile} with a built-in observer.
@param level: C{level} argument to L{LoggingFile}
@param encoding: C{encoding} argument to L{LoggingFile}
@return: a L{TestLoggingFile} with an observer that appends received
events into the file's C{events} attribute (a L{list}) and
event messages into the file's C{messages} attribute (a L{list}).
"""
# Logger takes an observer argument, for which we want to use the
# TestLoggingFile we will create, but that takes the Logger as an
# argument, so we'll use an array to indirectly reference the
# TestLoggingFile.
loggingFiles: List[TestLoggingFile] = []
@implementer(ILogObserver)
def observer(event: LogEvent) -> None:
loggingFiles[0](event)
log = Logger(observer=observer)
loggingFiles.append(TestLoggingFile(logger=log, level=level, encoding=encoding))
return loggingFiles[0]

View File

@@ -0,0 +1,485 @@
# Copyright (c) Twisted Matrix Laboratories.
# See LICENSE for details.
"""
Tests for L{twisted.logger._json}.
"""
from io import BytesIO, StringIO
from typing import IO, Any, List, Optional, Sequence, cast
from zope.interface import implementer
from zope.interface.exceptions import BrokenMethodImplementation
from zope.interface.verify import verifyObject
from twisted.python.failure import Failure
from twisted.trial.unittest import TestCase
from .._flatten import extractField
from .._format import formatEvent
from .._global import globalLogPublisher
from .._interfaces import ILogObserver, LogEvent
from .._json import (
eventAsJSON,
eventFromJSON,
eventsFromJSONLogFile,
jsonFileLogObserver,
log as jsonLog,
)
from .._levels import LogLevel
from .._logger import Logger
from .._observer import LogPublisher
def savedJSONInvariants(testCase: TestCase, savedJSON: str) -> str:
"""
Assert a few things about the result of L{eventAsJSON}, then return it.
@param testCase: The L{TestCase} with which to perform the assertions.
@param savedJSON: The result of L{eventAsJSON}.
@return: C{savedJSON}
@raise AssertionError: If any of the preconditions fail.
"""
testCase.assertIsInstance(savedJSON, str)
testCase.assertEqual(savedJSON.count("\n"), 0)
return savedJSON
class SaveLoadTests(TestCase):
"""
Tests for loading and saving log events.
"""
def savedEventJSON(self, event: LogEvent) -> str:
"""
Serialize some an events, assert some things about it, and return the
JSON.
@param event: An event.
@return: JSON.
"""
return savedJSONInvariants(self, eventAsJSON(event))
def test_simpleSaveLoad(self) -> None:
"""
Saving and loading an empty dictionary results in an empty dictionary.
"""
self.assertEqual(eventFromJSON(self.savedEventJSON({})), {})
def test_saveLoad(self) -> None:
"""
Saving and loading a dictionary with some simple values in it results
in those same simple values in the output; according to JSON's rules,
though, all dictionary keys must be L{str} and any non-L{str}
keys will be converted.
"""
self.assertEqual(
eventFromJSON(self.savedEventJSON({1: 2, "3": "4"})), # type: ignore[dict-item]
{"1": 2, "3": "4"},
)
def test_saveUnPersistable(self) -> None:
"""
Saving and loading an object which cannot be represented in JSON will
result in a placeholder.
"""
self.assertEqual(
eventFromJSON(self.savedEventJSON({"1": 2, "3": object()})),
{"1": 2, "3": {"unpersistable": True}},
)
def test_saveNonASCII(self) -> None:
"""
Non-ASCII keys and values can be saved and loaded.
"""
self.assertEqual(
eventFromJSON(self.savedEventJSON({"\u1234": "\u4321", "3": object()})),
{"\u1234": "\u4321", "3": {"unpersistable": True}},
)
def test_saveBytes(self) -> None:
"""
Any L{bytes} objects will be saved as if they are latin-1 so they can
be faithfully re-loaded.
"""
inputEvent = {"hello": bytes(range(255))}
# On Python 3, bytes keys will be skipped by the JSON encoder. Not
# much we can do about that. Let's make sure that we don't get an
# error, though.
inputEvent.update({b"skipped": "okay"}) # type: ignore[dict-item]
self.assertEqual(
eventFromJSON(self.savedEventJSON(inputEvent)),
{"hello": bytes(range(255)).decode("charmap")},
)
def test_saveUnPersistableThenFormat(self) -> None:
"""
Saving and loading an object which cannot be represented in JSON, but
has a string representation which I{can} be saved as JSON, will result
in the same string formatting; any extractable fields will retain their
data types.
"""
class Reprable:
def __init__(self, value: object) -> None:
self.value = value
def __repr__(self) -> str:
return "reprable"
inputEvent = {"log_format": "{object} {object.value}", "object": Reprable(7)}
outputEvent = eventFromJSON(self.savedEventJSON(inputEvent))
self.assertEqual(formatEvent(outputEvent), "reprable 7")
def test_extractingFieldsPostLoad(self) -> None:
"""
L{extractField} can extract fields from an object that's been saved and
loaded from JSON.
"""
class Obj:
def __init__(self) -> None:
self.value = 345
inputEvent = dict(log_format="{object.value}", object=Obj())
loadedEvent = eventFromJSON(self.savedEventJSON(inputEvent))
self.assertEqual(extractField("object.value", loadedEvent), 345)
# The behavior of extractField is consistent between pre-persistence
# and post-persistence events, although looking up the key directly
# won't be:
self.assertRaises(KeyError, extractField, "object", loadedEvent)
self.assertRaises(KeyError, extractField, "object", inputEvent)
def test_failureStructurePreserved(self) -> None:
"""
Round-tripping a failure through L{eventAsJSON} preserves its class and
structure.
"""
events: List[LogEvent] = []
log = Logger(observer=cast(ILogObserver, events.append))
try:
1 / 0
except ZeroDivisionError:
f = Failure()
log.failure("a message about failure", f)
self.assertEqual(len(events), 1)
loaded = eventFromJSON(self.savedEventJSON(events[0]))["log_failure"]
self.assertIsInstance(loaded, Failure)
self.assertTrue(loaded.check(ZeroDivisionError))
self.assertIsInstance(loaded.getTraceback(), str)
def test_saveLoadLevel(self) -> None:
"""
It's important that the C{log_level} key remain a
L{constantly.NamedConstant} object.
"""
inputEvent = dict(log_level=LogLevel.warn)
loadedEvent = eventFromJSON(self.savedEventJSON(inputEvent))
self.assertIs(loadedEvent["log_level"], LogLevel.warn)
def test_saveLoadUnknownLevel(self) -> None:
"""
If a saved bit of JSON (let's say, from a future version of Twisted)
were to persist a different log_level, it will resolve as None.
"""
loadedEvent = eventFromJSON(
'{"log_level": {"name": "other", '
'"__class_uuid__": "02E59486-F24D-46AD-8224-3ACDF2A5732A"}}'
)
self.assertEqual(loadedEvent, dict(log_level=None))
class FileLogObserverTests(TestCase):
"""
Tests for L{jsonFileLogObserver}.
"""
def test_interface(self) -> None:
"""
A L{FileLogObserver} returned by L{jsonFileLogObserver} is an
L{ILogObserver}.
"""
with StringIO() as fileHandle:
observer = jsonFileLogObserver(fileHandle)
try:
verifyObject(ILogObserver, observer)
except BrokenMethodImplementation as e:
self.fail(e)
def assertObserverWritesJSON(self, recordSeparator: str = "\x1e") -> None:
"""
Asserts that an observer created by L{jsonFileLogObserver} with the
given arguments writes events serialized as JSON text, using the given
record separator.
@param recordSeparator: C{recordSeparator} argument to
L{jsonFileLogObserver}
"""
with StringIO() as fileHandle:
observer = jsonFileLogObserver(fileHandle, recordSeparator)
event = dict(x=1)
observer(event)
self.assertEqual(fileHandle.getvalue(), f'{recordSeparator}{{"x": 1}}\n')
def test_observeWritesDefaultRecordSeparator(self) -> None:
"""
A L{FileLogObserver} created by L{jsonFileLogObserver} writes events
serialzed as JSON text to a file when it observes events.
By default, the record separator is C{"\\x1e"}.
"""
self.assertObserverWritesJSON()
def test_observeWritesEmptyRecordSeparator(self) -> None:
"""
A L{FileLogObserver} created by L{jsonFileLogObserver} writes events
serialzed as JSON text to a file when it observes events.
This test sets the record separator to C{""}.
"""
self.assertObserverWritesJSON(recordSeparator="")
def test_failureFormatting(self) -> None:
"""
A L{FileLogObserver} created by L{jsonFileLogObserver} writes failures
serialized as JSON text to a file when it observes events.
"""
io = StringIO()
publisher = LogPublisher()
logged: List[LogEvent] = []
publisher.addObserver(cast(ILogObserver, logged.append))
publisher.addObserver(jsonFileLogObserver(io))
logger = Logger(observer=publisher)
try:
1 / 0
except BaseException:
logger.failure("failed as expected")
reader = StringIO(io.getvalue())
deserialized = list(eventsFromJSONLogFile(reader))
def checkEvents(logEvents: Sequence[LogEvent]) -> None:
self.assertEqual(len(logEvents), 1)
[failureEvent] = logEvents
self.assertIn("log_failure", failureEvent)
failureObject = failureEvent["log_failure"]
self.assertIsInstance(failureObject, Failure)
tracebackObject = failureObject.getTracebackObject()
self.assertEqual(
tracebackObject.tb_frame.f_code.co_filename.rstrip("co"),
__file__.rstrip("co"),
)
checkEvents(logged)
checkEvents(deserialized)
class LogFileReaderTests(TestCase):
"""
Tests for L{eventsFromJSONLogFile}.
"""
def setUp(self) -> None:
self.errorEvents: List[LogEvent] = []
@implementer(ILogObserver)
def observer(event: LogEvent) -> None:
if event["log_namespace"] == jsonLog.namespace and "record" in event:
self.errorEvents.append(event)
self.logObserver = observer
globalLogPublisher.addObserver(observer)
def tearDown(self) -> None:
globalLogPublisher.removeObserver(self.logObserver)
def _readEvents(
self,
inFile: IO[Any],
recordSeparator: Optional[str] = None,
bufferSize: int = 4096,
) -> None:
"""
Test that L{eventsFromJSONLogFile} reads two pre-defined events from a
file: C{{"x": 1}} and C{{"y": 2}}.
@param inFile: C{inFile} argument to L{eventsFromJSONLogFile}
@param recordSeparator: C{recordSeparator} argument to
L{eventsFromJSONLogFile}
@param bufferSize: C{bufferSize} argument to L{eventsFromJSONLogFile}
"""
events = iter(eventsFromJSONLogFile(inFile, recordSeparator, bufferSize))
self.assertEqual(next(events), {"x": 1})
self.assertEqual(next(events), {"y": 2})
self.assertRaises(StopIteration, next, events) # No more events
def test_readEventsAutoWithRecordSeparator(self) -> None:
"""
L{eventsFromJSONLogFile} reads events from a file and automatically
detects use of C{"\\x1e"} as the record separator.
"""
with StringIO('\x1e{"x": 1}\n' '\x1e{"y": 2}\n') as fileHandle:
self._readEvents(fileHandle)
self.assertEqual(len(self.errorEvents), 0)
def test_readEventsAutoEmptyRecordSeparator(self) -> None:
"""
L{eventsFromJSONLogFile} reads events from a file and automatically
detects use of C{""} as the record separator.
"""
with StringIO('{"x": 1}\n' '{"y": 2}\n') as fileHandle:
self._readEvents(fileHandle)
self.assertEqual(len(self.errorEvents), 0)
def test_readEventsExplicitRecordSeparator(self) -> None:
"""
L{eventsFromJSONLogFile} reads events from a file and is told to use
a specific record separator.
"""
# Use "\x08" (backspace)... because that seems weird enough.
with StringIO('\x08{"x": 1}\n' '\x08{"y": 2}\n') as fileHandle:
self._readEvents(fileHandle, recordSeparator="\x08")
self.assertEqual(len(self.errorEvents), 0)
def test_readEventsPartialBuffer(self) -> None:
"""
L{eventsFromJSONLogFile} handles buffering a partial event.
"""
with StringIO('\x1e{"x": 1}\n' '\x1e{"y": 2}\n') as fileHandle:
# Use a buffer size smaller than the event text.
self._readEvents(fileHandle, bufferSize=1)
self.assertEqual(len(self.errorEvents), 0)
def test_readTruncated(self) -> None:
"""
If the JSON text for a record is truncated, skip it.
"""
with StringIO('\x1e{"x": 1' '\x1e{"y": 2}\n') as fileHandle:
events = iter(eventsFromJSONLogFile(fileHandle))
self.assertEqual(next(events), {"y": 2})
self.assertRaises(StopIteration, next, events) # No more events
# We should have logged the lost record
self.assertEqual(len(self.errorEvents), 1)
self.assertEqual(
self.errorEvents[0]["log_format"],
"Unable to read truncated JSON record: {record!r}",
)
self.assertEqual(self.errorEvents[0]["record"], b'{"x": 1')
def test_readUnicode(self) -> None:
"""
If the file being read from vends L{str}, strings decode from JSON
as-is.
"""
# The Euro currency sign is "\u20ac"
with StringIO('\x1e{"currency": "\u20ac"}\n') as fileHandle:
events = iter(eventsFromJSONLogFile(fileHandle))
self.assertEqual(next(events), {"currency": "\u20ac"})
self.assertRaises(StopIteration, next, events) # No more events
self.assertEqual(len(self.errorEvents), 0)
def test_readUTF8Bytes(self) -> None:
"""
If the file being read from vends L{bytes}, strings decode from JSON as
UTF-8.
"""
# The Euro currency sign is b"\xe2\x82\xac" in UTF-8
with BytesIO(b'\x1e{"currency": "\xe2\x82\xac"}\n') as fileHandle:
events = iter(eventsFromJSONLogFile(fileHandle))
# The Euro currency sign is "\u20ac"
self.assertEqual(next(events), {"currency": "\u20ac"})
self.assertRaises(StopIteration, next, events) # No more events
self.assertEqual(len(self.errorEvents), 0)
def test_readTruncatedUTF8Bytes(self) -> None:
"""
If the JSON text for a record is truncated in the middle of a two-byte
Unicode codepoint, we don't want to see a codec exception and the
stream is read properly when the additional data arrives.
"""
# The Euro currency sign is "\u20ac" and encodes in UTF-8 as three
# bytes: b"\xe2\x82\xac".
with BytesIO(b'\x1e{"x": "\xe2\x82\xac"}\n') as fileHandle:
events = iter(eventsFromJSONLogFile(fileHandle, bufferSize=8))
self.assertEqual(next(events), {"x": "\u20ac"}) # Got text
self.assertRaises(StopIteration, next, events) # No more events
self.assertEqual(len(self.errorEvents), 0)
def test_readInvalidUTF8Bytes(self) -> None:
"""
If the JSON text for a record contains invalid UTF-8 text, ignore that
record.
"""
# The string b"\xe2\xac" is bogus
with BytesIO(b'\x1e{"x": "\xe2\xac"}\n' b'\x1e{"y": 2}\n') as fileHandle:
events = iter(eventsFromJSONLogFile(fileHandle))
self.assertEqual(next(events), {"y": 2})
self.assertRaises(StopIteration, next, events) # No more events
# We should have logged the lost record
self.assertEqual(len(self.errorEvents), 1)
self.assertEqual(
self.errorEvents[0]["log_format"],
"Unable to decode UTF-8 for JSON record: {record!r}",
)
self.assertEqual(self.errorEvents[0]["record"], b'{"x": "\xe2\xac"}\n')
def test_readInvalidJSON(self) -> None:
"""
If the JSON text for a record is invalid, skip it.
"""
with StringIO('\x1e{"x": }\n' '\x1e{"y": 2}\n') as fileHandle:
events = iter(eventsFromJSONLogFile(fileHandle))
self.assertEqual(next(events), {"y": 2})
self.assertRaises(StopIteration, next, events) # No more events
# We should have logged the lost record
self.assertEqual(len(self.errorEvents), 1)
self.assertEqual(
self.errorEvents[0]["log_format"],
"Unable to read JSON record: {record!r}",
)
self.assertEqual(self.errorEvents[0]["record"], b'{"x": }\n')
def test_readUnseparated(self) -> None:
"""
Multiple events without a record separator are skipped.
"""
with StringIO('\x1e{"x": 1}\n' '{"y": 2}\n') as fileHandle:
events = eventsFromJSONLogFile(fileHandle)
self.assertRaises(StopIteration, next, events) # No more events
# We should have logged the lost record
self.assertEqual(len(self.errorEvents), 1)
self.assertEqual(
self.errorEvents[0]["log_format"],
"Unable to read JSON record: {record!r}",
)
self.assertEqual(self.errorEvents[0]["record"], b'{"x": 1}\n{"y": 2}\n')
def test_roundTrip(self) -> None:
"""
Data written by a L{FileLogObserver} returned by L{jsonFileLogObserver}
and read by L{eventsFromJSONLogFile} is reconstructed properly.
"""
event = dict(x=1)
with StringIO() as fileHandle:
observer = jsonFileLogObserver(fileHandle)
observer(event)
fileHandle.seek(0)
events = eventsFromJSONLogFile(fileHandle)
self.assertEqual(tuple(events), (event,))
self.assertEqual(len(self.errorEvents), 0)

View File

@@ -0,0 +1,413 @@
# Copyright (c) Twisted Matrix Laboratories.
# See LICENSE for details.
"""
Test cases for L{twisted.logger._legacy}.
"""
import logging as py_logging
from time import time
from typing import List, cast
from zope.interface import implementer
from zope.interface.exceptions import BrokenMethodImplementation
from zope.interface.verify import verifyObject
from twisted.python import context, log as legacyLog
from twisted.python.failure import Failure
from twisted.trial import unittest
from .._format import formatEvent
from .._interfaces import ILogObserver, LogEvent
from .._legacy import LegacyLogObserverWrapper, publishToNewObserver
from .._levels import LogLevel
class LegacyLogObserverWrapperTests(unittest.TestCase):
"""
Tests for L{LegacyLogObserverWrapper}.
"""
def test_interface(self) -> None:
"""
L{LegacyLogObserverWrapper} is an L{ILogObserver}.
"""
legacyObserver = cast(legacyLog.ILogObserver, lambda e: None)
observer = LegacyLogObserverWrapper(legacyObserver)
try:
verifyObject(ILogObserver, observer)
except BrokenMethodImplementation as e:
self.fail(e)
def test_repr(self) -> None:
"""
L{LegacyLogObserverWrapper} returns the expected string.
"""
@implementer(legacyLog.ILogObserver)
class LegacyObserver:
def __repr__(self) -> str:
return "<Legacy Observer>"
def __call__(self, eventDict: legacyLog.EventDict) -> None:
return
observer = LegacyLogObserverWrapper(LegacyObserver())
self.assertEqual(repr(observer), "LegacyLogObserverWrapper(<Legacy Observer>)")
def observe(self, event: LogEvent) -> LogEvent:
"""
Send an event to a wrapped legacy observer and capture the event as
seen by that observer.
@param event: an event
@return: the event as observed by the legacy wrapper
"""
events: List[LogEvent] = []
legacyObserver = cast(legacyLog.ILogObserver, lambda e: events.append(e))
observer = LegacyLogObserverWrapper(legacyObserver)
observer(event)
self.assertEqual(len(events), 1)
return events[0]
def forwardAndVerify(self, event: LogEvent) -> LogEvent:
"""
Send an event to a wrapped legacy observer and verify that its data is
preserved.
@param event: an event
@return: the event as observed by the legacy wrapper
"""
# Make sure keys that are expected by the logging system are present
event.setdefault("log_time", time())
event.setdefault("log_system", "-")
event.setdefault("log_level", LogLevel.info)
# Send a copy: don't mutate me, bro
observed = self.observe(dict(event))
# Don't expect modifications
for key, value in event.items():
self.assertIn(key, observed)
return observed
def test_forward(self) -> None:
"""
Basic forwarding: event keys as observed by a legacy observer are the
same.
"""
self.forwardAndVerify(dict(foo=1, bar=2))
def test_time(self) -> None:
"""
The new-style C{"log_time"} key is copied to the old-style C{"time"}
key.
"""
stamp = time()
event = self.forwardAndVerify(dict(log_time=stamp))
self.assertEqual(event["time"], stamp)
def test_timeAlreadySet(self) -> None:
"""
The new-style C{"log_time"} key does not step on a pre-existing
old-style C{"time"} key.
"""
stamp = time()
event = self.forwardAndVerify(dict(log_time=stamp + 1, time=stamp))
self.assertEqual(event["time"], stamp)
def test_system(self) -> None:
"""
The new-style C{"log_system"} key is copied to the old-style
C{"system"} key.
"""
event = self.forwardAndVerify(dict(log_system="foo"))
self.assertEqual(event["system"], "foo")
def test_systemAlreadySet(self) -> None:
"""
The new-style C{"log_system"} key does not step on a pre-existing
old-style C{"system"} key.
"""
event = self.forwardAndVerify(dict(log_system="foo", system="bar"))
self.assertEqual(event["system"], "bar")
def test_noSystem(self) -> None:
"""
If the new-style C{"log_system"} key is absent, the old-style
C{"system"} key is set to C{"-"}.
"""
# Don't use forwardAndVerify(), since that sets log_system.
event = dict(log_time=time(), log_level=LogLevel.info)
observed = self.observe(dict(event))
self.assertEqual(observed["system"], "-")
def test_levelNotChange(self) -> None:
"""
If explicitly set, the C{isError} key will be preserved when forwarding
from a new-style logging emitter to a legacy logging observer,
regardless of log level.
"""
self.forwardAndVerify(dict(log_level=LogLevel.info, isError=1))
self.forwardAndVerify(dict(log_level=LogLevel.warn, isError=1))
self.forwardAndVerify(dict(log_level=LogLevel.error, isError=0))
self.forwardAndVerify(dict(log_level=LogLevel.critical, isError=0))
def test_pythonLogLevelNotSet(self) -> None:
"""
The new-style C{"log_level"} key is not translated to the old-style
C{"logLevel"} key.
Events are forwarded from the old module from to new module and are
then seen by old-style observers.
We don't want to add unexpected keys to old-style events.
"""
event = self.forwardAndVerify(dict(log_level=LogLevel.info))
self.assertNotIn("logLevel", event)
def test_stringPythonLogLevel(self) -> None:
"""
If a stdlib log level was provided as a string (eg. C{"WARNING"}) in
the legacy "logLevel" key, it does not get converted to a number.
The documentation suggested that numerical values should be used but
this was not a requirement.
"""
event = self.forwardAndVerify(
dict(
logLevel="WARNING", # py_logging.WARNING is 30
)
)
self.assertEqual(event["logLevel"], "WARNING")
def test_message(self) -> None:
"""
The old-style C{"message"} key is added, even if no new-style
C{"log_format"} is given, as it is required, but may be empty.
"""
event = self.forwardAndVerify(dict())
self.assertEqual(event["message"], ()) # "message" is a tuple
def test_messageAlreadySet(self) -> None:
"""
The old-style C{"message"} key is not modified if it already exists.
"""
event = self.forwardAndVerify(dict(message=("foo", "bar")))
self.assertEqual(event["message"], ("foo", "bar"))
def test_format(self) -> None:
"""
Formatting is translated such that text is rendered correctly, even
though old-style logging doesn't use PEP 3101 formatting.
"""
event = self.forwardAndVerify(dict(log_format="Hello, {who}!", who="world"))
self.assertEqual(legacyLog.textFromEventDict(event), "Hello, world!")
def test_formatMessage(self) -> None:
"""
Using the message key, which is special in old-style, works for
new-style formatting.
"""
event = self.forwardAndVerify(
dict(log_format="Hello, {message}!", message="world")
)
self.assertEqual(legacyLog.textFromEventDict(event), "Hello, world!")
def test_formatAlreadySet(self) -> None:
"""
Formatting is not altered if the old-style C{"format"} key already
exists.
"""
event = self.forwardAndVerify(dict(log_format="Hello!", format="Howdy!"))
self.assertEqual(legacyLog.textFromEventDict(event), "Howdy!")
def eventWithFailure(self, **values: object) -> LogEvent:
"""
Create a new-style event with a captured failure.
@param values: Additional values to include in the event.
@return: the new event
"""
failure = Failure(RuntimeError("nyargh!"))
return self.forwardAndVerify(
dict(log_failure=failure, log_format="oopsie...", **values)
)
def test_failure(self) -> None:
"""
Captured failures in the new style set the old-style C{"failure"},
C{"isError"}, and C{"why"} keys.
"""
event = self.eventWithFailure()
self.assertIs(event["failure"], event["log_failure"])
self.assertTrue(event["isError"])
self.assertEqual(event["why"], "oopsie...")
def test_failureAlreadySet(self) -> None:
"""
Captured failures in the new style do not step on a pre-existing
old-style C{"failure"} key.
"""
failure = Failure(RuntimeError("Weak salsa!"))
event = self.eventWithFailure(failure=failure)
self.assertIs(event["failure"], failure)
def test_isErrorAlreadySet(self) -> None:
"""
Captured failures in the new style do not step on a pre-existing
old-style C{"isError"} key.
"""
event = self.eventWithFailure(isError=0)
self.assertEqual(event["isError"], 0)
def test_whyAlreadySet(self) -> None:
"""
Captured failures in the new style do not step on a pre-existing
old-style C{"failure"} key.
"""
event = self.eventWithFailure(why="blah")
self.assertEqual(event["why"], "blah")
class PublishToNewObserverTests(unittest.TestCase):
"""
Tests for L{publishToNewObserver}.
"""
def setUp(self) -> None:
self.events: List[LogEvent] = []
self.observer = cast(ILogObserver, self.events.append)
def legacyEvent(self, *message: str, **values: object) -> legacyLog.EventDict:
"""
Return a basic old-style event as would be created by L{legacyLog.msg}.
@param message: a message event value in the legacy event format
@param values: additional event values in the legacy event format
@return: a legacy event
"""
event = (context.get(legacyLog.ILogContext) or {}).copy()
event.update(values)
event["message"] = message
event["time"] = time()
if "isError" not in event:
event["isError"] = 0
return event
def test_observed(self) -> None:
"""
The observer is called exactly once.
"""
publishToNewObserver(
self.observer, self.legacyEvent(), legacyLog.textFromEventDict
)
self.assertEqual(len(self.events), 1)
def test_time(self) -> None:
"""
The old-style C{"time"} key is copied to the new-style C{"log_time"}
key.
"""
publishToNewObserver(
self.observer, self.legacyEvent(), legacyLog.textFromEventDict
)
self.assertEqual(self.events[0]["log_time"], self.events[0]["time"])
def test_message(self) -> None:
"""
A published old-style event should format as text in the same way as
the given C{textFromEventDict} callable would format it.
"""
def textFromEventDict(event: LogEvent) -> str:
return "".join(reversed(" ".join(event["message"])))
event = self.legacyEvent("Hello,", "world!")
text = textFromEventDict(event)
publishToNewObserver(self.observer, event, textFromEventDict)
self.assertEqual(formatEvent(self.events[0]), text)
def test_defaultLogLevel(self) -> None:
"""
Published event should have log level of L{LogLevel.info}.
"""
publishToNewObserver(
self.observer, self.legacyEvent(), legacyLog.textFromEventDict
)
self.assertEqual(self.events[0]["log_level"], LogLevel.info)
def test_isError(self) -> None:
"""
If C{"isError"} is set to C{1} (true) on the legacy event, the
C{"log_level"} key should get set to L{LogLevel.critical}.
"""
publishToNewObserver(
self.observer, self.legacyEvent(isError=1), legacyLog.textFromEventDict
)
self.assertEqual(self.events[0]["log_level"], LogLevel.critical)
def test_stdlibLogLevel(self) -> None:
"""
If the old-style C{"logLevel"} key is set to a standard library logging
level, using a predefined (L{int}) constant, the new-style
C{"log_level"} key should get set to the corresponding log level.
"""
publishToNewObserver(
self.observer,
self.legacyEvent(logLevel=py_logging.WARNING),
legacyLog.textFromEventDict,
)
self.assertEqual(self.events[0]["log_level"], LogLevel.warn)
def test_stdlibLogLevelWithString(self) -> None:
"""
If the old-style C{"logLevel"} key is set to a standard library logging
level, using a string value, the new-style C{"log_level"} key should
get set to the corresponding log level.
"""
publishToNewObserver(
self.observer,
self.legacyEvent(logLevel="WARNING"),
legacyLog.textFromEventDict,
)
self.assertEqual(self.events[0]["log_level"], LogLevel.warn)
def test_stdlibLogLevelWithGarbage(self) -> None:
"""
If the old-style C{"logLevel"} key is set to a standard library logging
level, using an unknown value, the new-style C{"log_level"} key should
not get set.
"""
publishToNewObserver(
self.observer,
self.legacyEvent(logLevel="Foo!!!!!"),
legacyLog.textFromEventDict,
)
self.assertNotIn("log_level", self.events[0])
def test_defaultNamespace(self) -> None:
"""
Published event should have a namespace of C{"log_legacy"} to indicate
that it was forwarded from legacy logging.
"""
publishToNewObserver(
self.observer, self.legacyEvent(), legacyLog.textFromEventDict
)
self.assertEqual(self.events[0]["log_namespace"], "log_legacy")
def test_system(self) -> None:
"""
The old-style C{"system"} key is copied to the new-style
C{"log_system"} key.
"""
publishToNewObserver(
self.observer, self.legacyEvent(), legacyLog.textFromEventDict
)
self.assertEqual(self.events[0]["log_system"], self.events[0]["system"])

View File

@@ -0,0 +1,34 @@
# Copyright (c) Twisted Matrix Laboratories.
# See LICENSE for details.
"""
Test cases for L{twisted.logger._levels}.
"""
from twisted.trial import unittest
from .._levels import InvalidLogLevelError, LogLevel
class LogLevelTests(unittest.TestCase):
"""
Tests for L{LogLevel}.
"""
def test_levelWithName(self) -> None:
"""
Look up log level by name.
"""
for level in LogLevel.iterconstants():
self.assertIs(LogLevel.levelWithName(level.name), level)
def test_levelWithInvalidName(self) -> None:
"""
You can't make up log level names.
"""
bogus = "*bogus*"
try:
LogLevel.levelWithName(bogus)
except InvalidLogLevelError as e:
self.assertIs(e.level, bogus)
else:
self.fail("Expected InvalidLogLevelError.")

View File

@@ -0,0 +1,354 @@
# Copyright (c) Twisted Matrix Laboratories.
# See LICENSE for details.
"""
Test cases for L{twisted.logger._logger}.
"""
from typing import List, Optional, Type, cast
from zope.interface import implementer
from constantly import NamedConstant
from twisted.python.failure import Failure
from twisted.trial import unittest
from .._format import formatEvent
from .._global import globalLogPublisher
from .._interfaces import ILogObserver, LogEvent
from .._levels import InvalidLogLevelError, LogLevel
from .._logger import Logger
class TestLogger(Logger):
"""
L{Logger} with an overridden C{emit} method that keeps track of received
events.
"""
def emit(
self, level: NamedConstant, format: Optional[str] = None, **kwargs: object
) -> None:
@implementer(ILogObserver)
def observer(event: LogEvent) -> None:
self.event = event
globalLogPublisher.addObserver(observer)
try:
Logger.emit(self, level, format, **kwargs)
finally:
globalLogPublisher.removeObserver(observer)
self.emitted = {
"level": level,
"format": format,
"kwargs": kwargs,
}
class LogComposedObject:
"""
A regular object, with a logger attached.
"""
log = TestLogger()
def __init__(self, state: Optional[str] = None) -> None:
self.state = state
def __str__(self) -> str:
return f"<LogComposedObject {self.state}>"
class LoggerTests(unittest.TestCase):
"""
Tests for L{Logger}.
"""
def test_repr(self) -> None:
"""
repr() on Logger
"""
namespace = "bleargh"
log = Logger(namespace)
self.assertEqual(repr(log), f"<Logger {repr(namespace)}>")
def test_namespaceDefault(self) -> None:
"""
Default namespace is module name.
"""
log = Logger()
self.assertEqual(log.namespace, __name__)
def test_namespaceOMGItsTooHard(self) -> None:
"""
Default namespace is C{"<unknown>"} when a logger is created from a
context in which is can't be determined automatically and no namespace
was specified.
"""
result: List[Logger] = []
exec(
"result.append(Logger())",
dict(Logger=Logger),
locals(),
)
self.assertEqual(result[0].namespace, "<unknown>")
def test_namespaceAttribute(self) -> None:
"""
Default namespace for classes using L{Logger} as a descriptor is the
class name they were retrieved from.
"""
obj = LogComposedObject()
expectedNamespace = "{}.{}".format(
obj.__module__,
obj.__class__.__name__,
)
self.assertEqual(cast(TestLogger, obj.log).namespace, expectedNamespace)
self.assertEqual(
cast(Type[TestLogger], LogComposedObject.log).namespace, expectedNamespace
)
self.assertIs(
cast(Type[TestLogger], LogComposedObject.log).source, LogComposedObject
)
self.assertIs(cast(TestLogger, obj.log).source, obj)
self.assertIsNone(Logger().source)
def test_descriptorObserver(self) -> None:
"""
When used as a descriptor, the observer is propagated.
"""
observed: List[LogEvent] = []
class MyObject:
log = Logger(observer=cast(ILogObserver, observed.append))
MyObject.log.info("hello")
self.assertEqual(len(observed), 1)
self.assertEqual(observed[0]["log_format"], "hello")
def test_sourceAvailableForFormatting(self) -> None:
"""
On instances that have a L{Logger} class attribute, the C{log_source}
key is available to format strings.
"""
obj = LogComposedObject("hello")
log = cast(TestLogger, obj.log)
log.error("Hello, {log_source}.")
self.assertIn("log_source", log.event)
self.assertEqual(log.event["log_source"], obj)
stuff = formatEvent(log.event)
self.assertIn("Hello, <LogComposedObject hello>.", stuff)
def test_basicLogger(self) -> None:
"""
Test that log levels and messages are emitted correctly for
Logger.
"""
log = TestLogger()
for level in LogLevel.iterconstants():
format = "This is a {level_name} message"
message = format.format(level_name=level.name)
logMethod = getattr(log, level.name)
logMethod(format, junk=message, level_name=level.name)
# Ensure that test_emit got called with expected arguments
self.assertEqual(log.emitted["level"], level)
self.assertEqual(log.emitted["format"], format)
self.assertEqual(log.emitted["kwargs"]["junk"], message)
self.assertTrue(hasattr(log, "event"), "No event observed.")
self.assertEqual(log.event["log_format"], format)
self.assertEqual(log.event["log_level"], level)
self.assertEqual(log.event["log_namespace"], __name__)
self.assertIsNone(log.event["log_source"])
self.assertEqual(log.event["junk"], message)
self.assertEqual(formatEvent(log.event), message)
def test_sourceOnClass(self) -> None:
"""
C{log_source} event key refers to the class.
"""
@implementer(ILogObserver)
def observer(event: LogEvent) -> None:
self.assertEqual(event["log_source"], Thingo)
class Thingo:
log = TestLogger(observer=observer)
cast(TestLogger, Thingo.log).info()
def test_sourceOnInstance(self) -> None:
"""
C{log_source} event key refers to the instance.
"""
@implementer(ILogObserver)
def observer(event: LogEvent) -> None:
self.assertEqual(event["log_source"], thingo)
class Thingo:
log = TestLogger(observer=observer)
thingo = Thingo()
cast(TestLogger, thingo.log).info()
def test_sourceUnbound(self) -> None:
"""
C{log_source} event key is L{None}.
"""
@implementer(ILogObserver)
def observer(event: LogEvent) -> None:
self.assertIsNone(event["log_source"])
log = TestLogger(observer=observer)
log.info()
def test_defaultFailure(self) -> None:
"""
Test that log.failure() emits the right data.
"""
log = TestLogger()
try:
raise RuntimeError("baloney!")
except RuntimeError:
log.failure("Whoops")
errors = self.flushLoggedErrors(RuntimeError)
self.assertEqual(len(errors), 1)
self.assertEqual(log.emitted["level"], LogLevel.critical)
self.assertEqual(log.emitted["format"], "Whoops")
def test_conflictingKwargs(self) -> None:
"""
Make sure that kwargs conflicting with args don't pass through.
"""
log = TestLogger()
log.warn(
"*",
log_format="#",
log_level=LogLevel.error,
log_namespace="*namespace*",
log_source="*source*",
)
self.assertEqual(log.event["log_format"], "*")
self.assertEqual(log.event["log_level"], LogLevel.warn)
self.assertEqual(log.event["log_namespace"], log.namespace)
self.assertIsNone(log.event["log_source"])
def test_logInvalidLogLevel(self) -> None:
"""
Test passing in a bogus log level to C{emit()}.
"""
log = TestLogger()
log.emit("*bogus*")
errors = self.flushLoggedErrors(InvalidLogLevelError)
self.assertEqual(len(errors), 1)
def test_trace(self) -> None:
"""
Tracing keeps track of forwarding to the publisher.
"""
@implementer(ILogObserver)
def publisher(event: LogEvent) -> None:
observer(event)
@implementer(ILogObserver)
def observer(event: LogEvent) -> None:
self.assertEqual(event["log_trace"], [(log, publisher)])
log = TestLogger(observer=publisher)
log.info("Hello.", log_trace=[])
def test_failuresHandled(self) -> None:
"""
The L{Logger.failuresHandled} context manager catches any
L{BaseException} and converts it into a logged L{Failure}.
"""
events = []
@implementer(ILogObserver)
def logged(event: LogEvent) -> None:
events.append(event)
log = TestLogger(observer=logged)
reprd = 0
class Reprable:
def __repr__(self) -> str:
nonlocal reprd
reprd += 1
return f"<repr {reprd}>"
with log.failuresHandled(
"while testing failure handling for {value}", value=Reprable()
) as operation:
1 / 0
self.assertEqual(operation.succeeded, False)
self.assertEqual(operation.failed, True)
self.assertEqual(len(events), 1)
[logged] = events
events[:] = []
f: Failure = logged["log_failure"]
self.assertEqual(reprd, 0)
self.assertEqual(
formatEvent(logged), "while testing failure handling for <repr 1>"
)
self.assertEqual(reprd, 1)
self.assertEqual(f.type, ZeroDivisionError)
with log.failuresHandled("succeeding for {value}", value=Reprable()) as op2:
self.assertEqual(op2.succeeded, False)
self.assertEqual(op2.failed, False)
self.assertEqual(reprd, 1)
self.assertEqual(op2.succeeded, True)
self.assertEqual(op2.failed, False)
def test_failureHandler(self) -> None:
"""
The L{Logger.failureHandler} context manager can safely be shared
amongst multiple invocations and converts L{BaseException} into logged
L{Failure}s.
"""
events = []
@implementer(ILogObserver)
def logged(event: LogEvent) -> None:
events.append(event)
log = TestLogger(observer=logged)
failureHandler = log.failureHandler("hello")
success = False
with failureHandler as fh:
success = True
self.assertIs(fh, None)
self.assertEqual(success, True)
self.assertEqual(events, [])
success = False
def raisebase() -> None:
raise KeyboardInterrupt()
with failureHandler as fh:
raisebase()
self.assertEqual(len(events), 1)
[logged] = events
f = logged["log_failure"]
self.assertEqual(f.type, KeyboardInterrupt)

View File

@@ -0,0 +1,192 @@
# Copyright (c) Twisted Matrix Laboratories.
# See LICENSE for details.
"""
Test cases for L{twisted.logger._observer}.
"""
from typing import Dict, List, Tuple, cast
from zope.interface import implementer
from zope.interface.exceptions import BrokenMethodImplementation
from zope.interface.verify import verifyObject
from twisted.trial import unittest
from .._interfaces import ILogObserver, LogEvent
from .._logger import Logger
from .._observer import LogPublisher
class LogPublisherTests(unittest.TestCase):
"""
Tests for L{LogPublisher}.
"""
def test_interface(self) -> None:
"""
L{LogPublisher} is an L{ILogObserver}.
"""
publisher = LogPublisher()
try:
verifyObject(ILogObserver, publisher)
except BrokenMethodImplementation as e:
self.fail(e)
def test_observers(self) -> None:
"""
L{LogPublisher.observers} returns the observers.
"""
o1 = cast(ILogObserver, lambda e: None)
o2 = cast(ILogObserver, lambda e: None)
publisher = LogPublisher(o1, o2)
self.assertEqual({o1, o2}, set(publisher._observers))
def test_addObserver(self) -> None:
"""
L{LogPublisher.addObserver} adds an observer.
"""
o1 = cast(ILogObserver, lambda e: None)
o2 = cast(ILogObserver, lambda e: None)
o3 = cast(ILogObserver, lambda e: None)
publisher = LogPublisher(o1, o2)
publisher.addObserver(o3)
self.assertEqual({o1, o2, o3}, set(publisher._observers))
def test_addObserverNotCallable(self) -> None:
"""
L{LogPublisher.addObserver} refuses to add an observer that's
not callable.
"""
publisher = LogPublisher()
self.assertRaises(TypeError, publisher.addObserver, object())
def test_removeObserver(self) -> None:
"""
L{LogPublisher.removeObserver} removes an observer.
"""
o1 = cast(ILogObserver, lambda e: None)
o2 = cast(ILogObserver, lambda e: None)
o3 = cast(ILogObserver, lambda e: None)
publisher = LogPublisher(o1, o2, o3)
publisher.removeObserver(o2)
self.assertEqual({o1, o3}, set(publisher._observers))
def test_removeObserverNotRegistered(self) -> None:
"""
L{LogPublisher.removeObserver} removes an observer that is not
registered.
"""
o1 = cast(ILogObserver, lambda e: None)
o2 = cast(ILogObserver, lambda e: None)
o3 = cast(ILogObserver, lambda e: None)
publisher = LogPublisher(o1, o2)
publisher.removeObserver(o3)
self.assertEqual({o1, o2}, set(publisher._observers))
def test_fanOut(self) -> None:
"""
L{LogPublisher} calls its observers.
"""
event = dict(foo=1, bar=2)
events1: List[LogEvent] = []
events2: List[LogEvent] = []
events3: List[LogEvent] = []
o1 = cast(ILogObserver, events1.append)
o2 = cast(ILogObserver, events2.append)
o3 = cast(ILogObserver, events3.append)
publisher = LogPublisher(o1, o2, o3)
publisher(event)
self.assertIn(event, events1)
self.assertIn(event, events2)
self.assertIn(event, events3)
def test_observerRaises(self) -> None:
"""
Observer raises an exception during fan out: a failure is logged, but
not re-raised. Life goes on.
"""
event = dict(foo=1, bar=2)
exception = RuntimeError("ARGH! EVIL DEATH!")
events: List[LogEvent] = []
@implementer(ILogObserver)
def observer(event: LogEvent) -> None:
shouldRaise = not events
events.append(event)
if shouldRaise:
raise exception
collector: List[LogEvent] = []
publisher = LogPublisher(observer, cast(ILogObserver, collector.append))
publisher(event)
# Verify that the observer saw my event
self.assertIn(event, events)
# Verify that the observer raised my exception
errors = [e["log_failure"] for e in collector if "log_failure" in e]
self.assertEqual(len(errors), 1)
self.assertIs(errors[0].value, exception)
# Make sure the exceptional observer does not receive its own error.
self.assertEqual(len(events), 1)
def test_observerRaisesAndLoggerHatesMe(self) -> None:
"""
Observer raises an exception during fan out and the publisher's Logger
pukes when the failure is reported. The exception does not propagate
back to the caller.
"""
event = dict(foo=1, bar=2)
exception = RuntimeError("ARGH! EVIL DEATH!")
@implementer(ILogObserver)
def observer(event: LogEvent) -> None:
raise RuntimeError("Sad panda")
class GurkLogger(Logger):
def failure(self, *args: object, **kwargs: object) -> None:
raise exception
publisher = LogPublisher(observer)
publisher.log = GurkLogger()
publisher(event)
# Here, the lack of an exception thus far is a success, of sorts
def test_trace(self) -> None:
"""
Tracing keeps track of forwarding to observers.
"""
event = dict(foo=1, bar=2, log_trace=[])
traces: Dict[int, Tuple[Tuple[Logger, ILogObserver]]] = {}
# Copy trace to a tuple; otherwise, both observers will store the same
# mutable list, and we won't be able to see o1's view distinctly.
@implementer(ILogObserver)
def o1(e: LogEvent) -> None:
traces.setdefault(
1, cast(Tuple[Tuple[Logger, ILogObserver]], tuple(e["log_trace"]))
)
@implementer(ILogObserver)
def o2(e: LogEvent) -> None:
traces.setdefault(
2, cast(Tuple[Tuple[Logger, ILogObserver]], tuple(e["log_trace"]))
)
publisher = LogPublisher(o1, o2)
publisher(event)
self.assertEqual(traces[1], ((publisher, o1),))
self.assertEqual(traces[2], ((publisher, o1), (publisher, o2)))

View File

@@ -0,0 +1,293 @@
# Copyright (c) Twisted Matrix Laboratories.
# See LICENSE for details.
"""
Test cases for L{twisted.logger._format}.
"""
from __future__ import annotations
import logging as py_logging
import sys
from inspect import getsourcefile
from io import BytesIO, TextIOWrapper
from logging import Formatter, LogRecord, StreamHandler, getLogger
from typing import List, Optional, Tuple
from zope.interface.exceptions import BrokenMethodImplementation
from zope.interface.verify import verifyObject
from twisted.python.compat import currentframe
from twisted.python.failure import Failure
from twisted.trial import unittest
from .._interfaces import ILogObserver, LogEvent
from .._levels import LogLevel
from .._stdlib import STDLibLogObserver
def nextLine() -> Tuple[Optional[str], int]:
"""
Retrive the file name and line number immediately after where this function
is called.
@return: the file name and line number
"""
caller = currentframe(1)
return (
getsourcefile(sys.modules[caller.f_globals["__name__"]]),
caller.f_lineno + 1,
)
class StdlibLoggingContainer:
"""
Continer for a test configuration of stdlib logging objects.
"""
def __init__(self) -> None:
self.rootLogger = getLogger("")
self.originalLevel = self.rootLogger.getEffectiveLevel()
self.rootLogger.setLevel(py_logging.DEBUG)
self.bufferedHandler = BufferedHandler()
self.rootLogger.addHandler(self.bufferedHandler)
self.streamHandler, self.output = handlerAndBytesIO()
self.rootLogger.addHandler(self.streamHandler)
def close(self) -> None:
"""
Close the logger.
"""
self.rootLogger.setLevel(self.originalLevel)
self.rootLogger.removeHandler(self.bufferedHandler)
self.rootLogger.removeHandler(self.streamHandler)
self.streamHandler.close()
self.output.close()
def outputAsText(self) -> str:
"""
Get the output to the underlying stream as text.
@return: the output text
"""
return self.output.getvalue().decode("utf-8")
class STDLibLogObserverTests(unittest.TestCase):
"""
Tests for L{STDLibLogObserver}.
"""
def test_interface(self) -> None:
"""
L{STDLibLogObserver} is an L{ILogObserver}.
"""
observer = STDLibLogObserver()
try:
verifyObject(ILogObserver, observer)
except BrokenMethodImplementation as e:
self.fail(e)
def py_logger(self) -> StdlibLoggingContainer:
"""
Create a logging object we can use to test with.
@return: a stdlib-style logger
"""
logger = StdlibLoggingContainer()
self.addCleanup(logger.close)
return logger
def logEvent(self, *events: LogEvent) -> Tuple[List[LogRecord], str]:
"""
Send one or more events to Python's logging module, and capture the
emitted L{LogRecord}s and output stream as a string.
@param events: events
@return: a tuple: (records, output)
"""
pl = self.py_logger()
observer = STDLibLogObserver(
# Add 1 to default stack depth to skip *this* frame, since
# tests will want to know about their own frames.
stackDepth=STDLibLogObserver.defaultStackDepth
+ 1
)
for event in events:
observer(event)
return pl.bufferedHandler.records, pl.outputAsText()
def test_name(self) -> None:
"""
Logger name.
"""
records, output = self.logEvent({})
self.assertEqual(len(records), 1)
self.assertEqual(records[0].name, "twisted")
def test_levels(self) -> None:
"""
Log levels.
"""
levelMapping = {
None: py_logging.INFO, # Default
LogLevel.debug: py_logging.DEBUG,
LogLevel.info: py_logging.INFO,
LogLevel.warn: py_logging.WARNING,
LogLevel.error: py_logging.ERROR,
LogLevel.critical: py_logging.CRITICAL,
}
# Build a set of events for each log level
events = []
for level, pyLevel in levelMapping.items():
event = {}
# Set the log level on the event, except for default
if level is not None:
event["log_level"] = level
# Remember the Python log level we expect to see for this
# event (as an int)
event["py_levelno"] = int(pyLevel)
events.append(event)
records, output = self.logEvent(*events)
self.assertEqual(len(records), len(levelMapping))
# Check that each event has the correct level
for i in range(len(records)):
self.assertEqual(records[i].levelno, events[i]["py_levelno"])
def test_callerInfo(self) -> None:
"""
C{pathname}, C{lineno}, C{exc_info}, C{func} is set properly on
records.
"""
filename, logLine = nextLine()
records, output = self.logEvent({})
self.assertEqual(len(records), 1)
self.assertEqual(records[0].pathname, filename)
self.assertEqual(records[0].lineno, logLine)
self.assertIsNone(records[0].exc_info)
# Attribute "func" is missing from record, which is weird because it's
# documented.
# self.assertEqual(records[0].func, "test_callerInfo")
def test_basicFormat(self) -> None:
"""
Basic formattable event passes the format along correctly.
"""
event = dict(log_format="Hello, {who}!", who="dude")
records, output = self.logEvent(event)
self.assertEqual(len(records), 1)
self.assertEqual(str(records[0].msg), "Hello, dude!")
self.assertEqual(records[0].args, ())
def test_basicFormatRendered(self) -> None:
"""
Basic formattable event renders correctly.
"""
event = dict(log_format="Hello, {who}!", who="dude")
records, output = self.logEvent(event)
self.assertEqual(len(records), 1)
self.assertTrue(output.endswith(":Hello, dude!\n"), repr(output))
def test_noFormat(self) -> None:
"""
Event with no format.
"""
records, output = self.logEvent({})
self.assertEqual(len(records), 1)
self.assertEqual(str(records[0].msg), "")
def test_failure(self) -> None:
"""
An event with a failure logs the failure details as well.
"""
def failing_func() -> None:
1 / 0
try:
failing_func()
except ZeroDivisionError:
failure = Failure()
event = dict(log_format="Hi mom", who="me", log_failure=failure)
records, output = self.logEvent(event)
self.assertEqual(len(records), 1)
self.assertIn("Hi mom", output)
self.assertIn("in failing_func", output)
self.assertIn("ZeroDivisionError", output)
def test_cleanedFailure(self) -> None:
"""
A cleaned Failure object has a fake traceback object; make sure that
logging such a failure still results in the exception details being
logged.
"""
def failing_func() -> None:
1 / 0
try:
failing_func()
except ZeroDivisionError:
failure = Failure()
failure.cleanFailure()
event = dict(log_format="Hi mom", who="me", log_failure=failure)
records, output = self.logEvent(event)
self.assertEqual(len(records), 1)
self.assertIn("Hi mom", output)
self.assertIn("in failing_func", output)
self.assertIn("ZeroDivisionError", output)
def handlerAndBytesIO() -> tuple[StreamHandler[TextIOWrapper], BytesIO]:
"""
Construct a 2-tuple of C{(StreamHandler, BytesIO)} for testing interaction
with the 'logging' module.
@return: handler and io object
"""
output = BytesIO()
template = py_logging.BASIC_FORMAT
stream = TextIOWrapper(output, encoding="utf-8", newline="\n")
formatter = Formatter(template)
handler = StreamHandler(stream)
handler.setFormatter(formatter)
return handler, output
class BufferedHandler(py_logging.Handler):
"""
A L{py_logging.Handler} that remembers all logged records in a list.
"""
def __init__(self) -> None:
"""
Initialize this L{BufferedHandler}.
"""
py_logging.Handler.__init__(self)
self.records: List[LogRecord] = []
def emit(self, record: LogRecord) -> None:
"""
Remember the record.
"""
self.records.append(record)

View File

@@ -0,0 +1,139 @@
# Copyright (c) Twisted Matrix Laboratories.
# See LICENSE for details.
"""
Test cases for L{twisted.logger._util}.
"""
from zope.interface import implementer
from twisted.trial import unittest
from .._interfaces import ILogObserver, LogEvent
from .._observer import LogPublisher
from .._util import formatTrace
class UtilTests(unittest.TestCase):
"""
Utility tests.
"""
def test_trace(self) -> None:
"""
Tracing keeps track of forwarding done by the publisher.
"""
publisher = LogPublisher()
event: LogEvent = dict(log_trace=[])
@implementer(ILogObserver)
def o1(e: LogEvent) -> None:
pass
@implementer(ILogObserver)
def o2(e: LogEvent) -> None:
self.assertIs(e, event)
self.assertEqual(
e["log_trace"],
[
(publisher, o1),
(publisher, o2),
# Event hasn't been sent to o3 yet
],
)
@implementer(ILogObserver)
def o3(e: LogEvent) -> None:
self.assertIs(e, event)
self.assertEqual(
e["log_trace"],
[
(publisher, o1),
(publisher, o2),
(publisher, o3),
],
)
publisher.addObserver(o1)
publisher.addObserver(o2)
publisher.addObserver(o3)
publisher(event)
def test_formatTrace(self) -> None:
"""
Format trace as string.
"""
event: LogEvent = dict(log_trace=[])
@implementer(ILogObserver)
def o1(e: LogEvent) -> None:
pass
@implementer(ILogObserver)
def o2(e: LogEvent) -> None:
pass
@implementer(ILogObserver)
def o3(e: LogEvent) -> None:
pass
@implementer(ILogObserver)
def o4(e: LogEvent) -> None:
pass
@implementer(ILogObserver)
def o5(e: LogEvent) -> None:
pass
o1.name = "root/o1"
o2.name = "root/p1/o2"
o3.name = "root/p1/o3"
o4.name = "root/p1/p2/o4"
o5.name = "root/o5"
expectedTrace: str # populated below
@implementer(ILogObserver)
def testObserver(e: LogEvent) -> None:
self.assertIs(e, event)
trace = formatTrace(e["log_trace"])
self.assertEqual(trace, expectedTrace)
oTest = testObserver
p2 = LogPublisher(o4)
p1 = LogPublisher(o2, o3, p2)
p2.name = "root/p1/p2/" # type: ignore[attr-defined]
p1.name = "root/p1/" # type: ignore[attr-defined]
root = LogPublisher(o1, p1, o5, oTest)
root.name = "root/" # type: ignore[attr-defined]
expectedTraceTemplate = (
"{root} ({root.name})\n"
" -> {o1} ({o1.name})\n"
" -> {p1} ({p1.name})\n"
" -> {o2} ({o2.name})\n"
" -> {o3} ({o3.name})\n"
" -> {p2} ({p2.name})\n"
" -> {o4} ({o4.name})\n"
" -> {o5} ({o5.name})\n"
" -> {oTest}\n"
)
# Mypy rightly complains that we're pulling some Shenanigans with all
# these 'name' attributes above (LogPublisher does not have any such
# attribute, neither does FunctionType) so we split up the 'format'
# call so it can't see the attributes being formatted.
expectedTrace = expectedTraceTemplate.format(
root=root,
o1=o1,
o2=o2,
o3=o3,
o4=o4,
o5=o5,
p1=p1,
p2=p2,
oTest=oTest,
)
root(event)