PKG][eliot/_version.py # This file was generated by 'versioneer.py' (0.14) from # revision-control system data, or from the parent directory name of an # unpacked source archive. Distribution tarballs contain a pre-generated copy # of this file. version_version = '0.11.0' version_full = '9d61e6a93c07bbe20e777d51b028b432b3399a89' def get_versions(default={}, verbose=False): return {'version': version_version, 'full': version_full} PK⡁Gw!gzzeliot/_parse.py""" Parse a stream of serialized messages into a forest of ``WrittenAction`` and ``WrittenMessage`` objects. """ from __future__ import unicode_literals from six import text_type as unicode from pyrsistent import PClass, pmap_field, pset_field, discard from ._message import WrittenMessage, TASK_UUID_FIELD from ._action import ( TaskLevel, WrittenAction, ACTION_STATUS_FIELD, STARTED_STATUS, ACTION_TYPE_FIELD, ) class Task(PClass): """ A tree of actions with the same task UUID. """ _nodes = pmap_field(TaskLevel, (WrittenAction, WrittenMessage)) _completed = pset_field(TaskLevel) _root_level = TaskLevel(level=[]) def root(self): """ @return: The root L{WrittenAction}. """ return self._nodes[self._root_level] def is_complete(self): """ @return bool: True only if all messages in the task tree have been added to it. """ return self._root_level in self._completed def _insert_action(self, node): """ Add a L{WrittenAction} to the tree. Parent actions will be created as necessary. @param child: A L{WrittenAction} to add to the tree. @return: Updated L{Task}. """ task = self if (node.end_message and node.start_message and (len(node.children) == node.end_message.task_level.level[-1] - 2)): # Possibly this action is complete, make sure all sub-actions # are complete: completed = True for child in node.children: if (isinstance(child, WrittenAction) and child.task_level not in self._completed): completed = False break if completed: task = task.transform(["_completed"], lambda s: s.add(node.task_level)) task = task.transform(["_nodes", node.task_level], node) return task._ensure_node_parents(node) def _ensure_node_parents(self, child): """ Ensure the node (WrittenAction/WrittenMessage) is referenced by parent nodes. Parent actions will be created as necessary. @param child: A L{WrittenMessage} or L{WrittenAction} which is being added to the tree. @return: Updated L{Task}. """ task_level = child.task_level if task_level.parent() is None: return self parent = self._nodes.get(task_level.parent()) if parent is None: parent = WrittenAction(task_level=task_level.parent(), task_uuid=child.task_uuid) parent = parent._add_child(child) return self._insert_action(parent) def add(self, message_dict): """ Update the L{Task} with a dictionary containing a serialized Eliot message. @param message_dict: Dictionary whose task UUID matches this one. @return: Updated L{Task}. """ is_action = message_dict.get(ACTION_TYPE_FIELD) is not None written_message = WrittenMessage.from_dict(message_dict) if is_action: action_level = written_message.task_level.parent() action = self._nodes.get(action_level) if action is None: action = WrittenAction(task_level=action_level, task_uuid=message_dict[TASK_UUID_FIELD]) if message_dict[ACTION_STATUS_FIELD] == STARTED_STATUS: # Either newly created MissingAction, or one created by # previously added descendant of the action. action = action._start(written_message) else: action = action._end(written_message) return self._insert_action(action) else: # Special case where there is no action: if written_message.task_level.level == [1]: return self.transform( ["_nodes", self._root_level], written_message, ["_completed"], lambda s: s.add(self._root_level)) else: return self._ensure_node_parents(written_message) class Parser(PClass): """ Parse serialized Eliot messages into L{Task} instances. @ivar _tasks: Map from UUID to corresponding L{Task}. """ _tasks = pmap_field(unicode, Task) def add(self, message_dict): """ Update the L{Parser} with a dictionary containing a serialized Eliot message. @param message_dict: Dictionary of serialized Eliot message. @return: Tuple of (list of completed L{Task} instances, updated L{Parser}). """ uuid = message_dict[TASK_UUID_FIELD] if uuid in self._tasks: task = self._tasks[uuid] else: task = Task() task = task.add(message_dict) if task.is_complete(): parser = self.transform(["_tasks", uuid], discard) return [task], parser else: parser = self.transform(["_tasks", uuid], task) return [], parser def incomplete_tasks(self): """ @return: List of L{Task} that are not yet complete. """ return list(self._tasks.values()) @classmethod def parse_stream(cls, iterable): """ Parse a stream of messages into a stream of L{Task} instances. :param iterable: An iterable of serialized Eliot message dictionaries. :return: An iterable of parsed L{Task} instances. Remaining incomplete L{Task} will be returned when the input stream is exhausted. """ parser = Parser() for message_dict in iterable: completed, parser = parser.add(message_dict) for task in completed: yield task for task in parser.incomplete_tasks(): yield task PKGzyܺeliot/prettyprint.py""" API and command-line support for human-readable Eliot messages. """ from __future__ import unicode_literals import pprint from datetime import datetime from sys import stdin, stdout, argv from ._bytesjson import loads from ._message import ( TIMESTAMP_FIELD, TASK_UUID_FIELD, TASK_LEVEL_FIELD, MESSAGE_TYPE_FIELD, ) from ._action import ACTION_TYPE_FIELD, ACTION_STATUS_FIELD from ._util import load_module from six import text_type as unicode, PY2, PY3 if PY3: # Ensure binary stdin, since we expect specifically UTF-8 encoded # messages, not platform-encoding messages. stdin = stdin.buffer # On Python 2 pprint formats unicode with u'' prefix, which is inconsistent # with Python 3 and not very nice to read. So we modify a copy to omit the u''. if PY2: def _nicer_unicode_repr(o, original_repr=repr): if isinstance(o, unicode): return original_repr(o.encode("utf-8")) else: return original_repr(o) pprint = load_module(b"unicode_pprint", pprint) pprint.repr = _nicer_unicode_repr # Fields that all Eliot messages are expected to have: REQUIRED_FIELDS = {TASK_LEVEL_FIELD, TASK_UUID_FIELD, TIMESTAMP_FIELD} def pretty_format(message): """ Convert a message dictionary into a human-readable string. @param message: Message to parse, as dictionary. @return: Unicode string. """ skip = {TIMESTAMP_FIELD, TASK_UUID_FIELD, TASK_LEVEL_FIELD, MESSAGE_TYPE_FIELD, ACTION_TYPE_FIELD, ACTION_STATUS_FIELD} def add_field(previous, key, value): value = unicode(pprint.pformat(value, width=40)).replace( "\\n", "\n ").replace("\\t", "\t") # Reindent second line and later to match up with first line's # indentation: lines = value.split("\n") # indent lines are " | " indent = "{}| ".format(" " * (2 + len(key))) value = "\n".join([lines[0]] + [indent + l for l in lines[1:]]) return " %s: %s\n" % (key, value) remaining = "" for field in [ACTION_TYPE_FIELD, MESSAGE_TYPE_FIELD, ACTION_STATUS_FIELD]: if field in message: remaining += add_field(remaining, field, message[field]) for (key, value) in sorted(message.items()): if key not in skip: remaining += add_field(remaining, key, value) level = "/" + "/".join(map(unicode, message[TASK_LEVEL_FIELD])) return "%s -> %s\n%sZ\n%s" % ( message[TASK_UUID_FIELD], level, # If we were returning or storing the datetime we'd want to use an # explicit timezone instead of a naive datetime, but since we're # just using it for formatting we needn't bother. datetime.utcfromtimestamp(message[TIMESTAMP_FIELD]).isoformat( sep=str(" ")), remaining, ) _CLI_HELP = """\ Usage: cat messages | eliot-prettyprint Convert Eliot messages into more readable format. Reads JSON lines from stdin, write out pretty-printed results on stdout. """ def _main(): """ Command-line program that reads in JSON from stdin and writes out pretty-printed messages to stdout. """ if argv[1:]: stdout.write(_CLI_HELP) raise SystemExit() for line in stdin: try: message = loads(line) except ValueError: stdout.write("Not JSON: {}\n\n".format(line.rstrip(b"\n"))) continue if REQUIRED_FIELDS - set(message.keys()): stdout.write("Not an Eliot message: {}\n\n".format( line.rstrip(b"\n"))) continue result = pretty_format(message) + "\n" if PY2: result = result.encode("utf-8") stdout.write(result) __all__ = ["pretty_format"] PKæG&SJ##eliot/twisted.py""" APIs for using Eliot from Twisted. """ from __future__ import absolute_import, unicode_literals import json import os import sys from twisted.python import log from twisted.python.failure import Failure from ._action import currentAction from . import addDestination __all__ = ["AlreadyFinished", "DeferredContext", "redirectLogsForTrial"] def _passthrough(result): return result class AlreadyFinished(Exception): """ L{DeferredContext.addCallbacks} or similar method was called after L{DeferredContext.addActionFinish}. This indicates a programming bug, e.g. forgetting to unwrap the underlying L{Deferred} when passing on to some other piece of code that doesn't care about the action context. """ class DeferredContext(object): """ A L{Deferred} equivalent of L{eliot.Action.context} and L{eliot.action.finish}. Makes a L{Deferred}'s callbacks run in a L{eliot.Action}'s context, and allows indicating which callbacks to wait for before the action is finished. The action to use will be taken from the call context. @ivar result: The wrapped L{Deferred}. """ def __init__(self, deferred): """ @param deferred: L{twisted.internet.defer.Deferred} to wrap. """ self.result = deferred self._action = currentAction() self._finishAdded = False if self._action is None: raise RuntimeError( "DeferredContext() should only be created in the context of an " "eliot.Action.") def addCallbacks(self, callback, errback, callbackArgs=None, callbackKeywords=None, errbackArgs=None, errbackKeywords=None): """ Add a pair of callbacks that will be run in the context of an eliot action. @return: C{self} @rtype: L{DeferredContext} @raises AlreadyFinished: L{DeferredContext.addActionFinish} has been called. This indicates a programmer error. """ if self._finishAdded: raise AlreadyFinished() def callbackWithContext(*args, **kwargs): return self._action.run(callback, *args, **kwargs) def errbackWithContext(*args, **kwargs): return self._action.run(errback, *args, **kwargs) self.result.addCallbacks(callbackWithContext, errbackWithContext, callbackArgs, callbackKeywords, errbackArgs, errbackKeywords) return self def addCallback(self, callback, *args, **kw): """ Add a success callback that will be run in the context of an eliot action. @return: C{self} @rtype: L{DeferredContext} @raises AlreadyFinished: L{DeferredContext.addActionFinish} has been called. This indicates a programmer error. """ return self.addCallbacks(callback, _passthrough, callbackArgs=args, callbackKeywords=kw) def addErrback(self, errback, *args, **kw): """ Add a failure callback that will be run in the context of an eliot action. @return: C{self} @rtype: L{DeferredContext} @raises AlreadyFinished: L{DeferredContext.addActionFinish} has been called. This indicates a programmer error. """ return self.addCallbacks(_passthrough, errback, errbackArgs=args, errbackKeywords=kw) def addBoth(self, callback, *args, **kw): """ Add a single callback as both success and failure callbacks. @return: C{self} @rtype: L{DeferredContext} @raises AlreadyFinished: L{DeferredContext.addActionFinish} has been called. This indicates a programmer error. """ return self.addCallbacks(callback, callback, args, kw, args, kw) def addActionFinish(self): """ Indicates all callbacks that should run within the action's context have been added, and that the action should therefore finish once those callbacks have fired. @return: The wrapped L{Deferred}. @raises AlreadyFinished: L{DeferredContext.addActionFinish} has been called previously. This indicates a programmer error. """ if self._finishAdded: raise AlreadyFinished() self._finishAdded = True def done(result): if isinstance(result, Failure): exception = result.value else: exception = None self._action.finish(exception) return result self.result.addBoth(done) return self.result class _RedirectLogsForTrial(object): """ When called inside a I{trial} process redirect Eliot log messages to Twisted's logging system, otherwise do nothing. This allows reading Eliot logs output by running unit tests with I{trial} in its normal log location: C{_trial_temp/test.log}. This function can usually be safely called in all programs since it will have no side-effects if used outside of trial. The only exception is you are redirecting Twisted logs to Eliot; you should make sure not call this function in that case so as to prevent infinite loops. In addition, calling the function multiple times has the same effect as calling it once. (This is not thread-safe at the moment, so in theory multiple threads calling this might result in multiple destinatios being added - see https://github.com/clusterhq/eliot/issues/78). Currently this works by checking if C{sys.argv[0]} is called C{trial}; the ideal mechanism would require https://twistedmatrix.com/trac/ticket/6939 to be fixed, but probably there are better solutions even without that - https://github.com/clusterhq/eliot/issues/76 covers those. @ivar _sys: An object similar to, and typically identical to, Python's L{sys} module. @ivar _log: An object similar to, and typically identical to, L{twisted.python.log}. @ivar _redirected: L{True} if trial logs have been redirected once already. """ def __init__(self, sys, log): self._sys = sys self._log = log self._redirected = False def _logEliotMessage(self, message): """ Log an Eliot message to Twisted's log. @param message: A rendered Eliot message. @type message: L{dict} """ self._log.msg("ELIOT: " + json.dumps(message)) if message.get("message_type") == "eliot:traceback": self._log.msg("ELIOT Extracted Traceback:\n" + message["traceback"]) def __call__(self): """ Do the redirect if necessary. @return: The destination added to Eliot if any, otherwise L{None}. """ if (os.path.basename(self._sys.argv[0]) == 'trial' and not self._redirected): self._redirected = True addDestination(self._logEliotMessage) return self._logEliotMessage redirectLogsForTrial = _RedirectLogsForTrial(sys, log) PKYuAGL&veliot/_bytesjson.py""" Python 2/3 JSON encoding/decoding, emulating Python 2's json module. Python 3 json module doesn't support decoding bytes or encoding. Rather than adding isinstance checks in main code path which would slow down Python 2, instead we write our encoder that can support those. """ import json as pyjson from six import PY2 class JSONEncoder(pyjson.JSONEncoder): """ JSON encoder that supports L{bytes}. """ def default(self, o): if isinstance(o, bytes): return o.decode("utf-8") return pyjson.JSONEncoder.default(self, o) _encoder = JSONEncoder() def _loads(s): if isinstance(s, bytes): s = s.decode("utf-8") return pyjson.loads(s) def _dumps(obj): return _encoder.encode(obj).encode("utf-8") if PY2: # No need for the above on Python 2 loads, dumps = pyjson.loads, pyjson.dumps else: loads, dumps = _loads, _dumps __all__ = ["loads", "dumps"] PKGֆ{eliot/__init__.py""" Eliot: Logging for Complex & Distributed Systems. """ # Expose the public API: from ._message import Message from ._action import startAction, startTask, Action, preserve_context from ._output import ( ILogger, Logger, MemoryLogger, to_file, FileDestination, ) from ._validation import Field, fields, MessageType, ActionType from ._traceback import writeTraceback, writeFailure from ._errors import register_exception_extractor addDestination = Logger._destinations.add removeDestination = Logger._destinations.remove addGlobalFields = Logger._destinations.addGlobalFields # PEP 8 variants: start_action = startAction start_task = startTask write_traceback = writeTraceback write_failure = writeFailure add_destination = addDestination remove_destination = removeDestination add_global_fields = addGlobalFields __all__ = ["Message", "writeTraceback", "writeFailure", "startAction", "startTask", "Action", "preserve_context", "Field", "fields", "MessageType", "ActionType", "ILogger", "Logger", "MemoryLogger", "addDestination", "removeDestination", "addGlobalFields", "FileDestination", "register_exception_extractor", # PEP 8 variants: "write_traceback", "write_failure", "start_action", "start_task", "add_destination", "remove_destination", "add_global_fields", "to_file", "__version__", ] from ._version import get_versions __version__ = get_versions()['version'] del get_versions PKPxE돷AAeliot/tai64n.py""" TAI64N encoding and decoding. TAI64N encodes nanosecond-accuracy timestamps and is supported by logstash. @see: U{http://cr.yp.to/libtai/tai64.html}. """ from __future__ import unicode_literals import struct from binascii import b2a_hex, a2b_hex _STRUCTURE = b">QI" _OFFSET = (2 ** 62) + 10 # last 10 are leap seconds def encode(timestamp): """ Convert seconds since epoch to TAI64N string. @param timestamp: Seconds since UTC Unix epoch as C{float}. @return: TAI64N-encoded time, as C{unicode}. """ seconds = int(timestamp) nanoseconds = int((timestamp - seconds) * 1000000000) seconds = seconds + _OFFSET encoded = b2a_hex(struct.pack(_STRUCTURE, seconds, nanoseconds)) return "@" + encoded.decode("ascii") def decode(tai64n): """ Convert TAI64N string to seconds since epoch. Note that dates before 2013 may not decode accurately due to leap second issues. If you need correct decoding for earlier dates you can try the tai64n package available from PyPI (U{https://pypi.python.org/pypi/tai64n}). @param tai64n: TAI64N-encoded time, as C{unicode}. @return: Seconds since UTC Unix epoch as C{float}. """ seconds, nanoseconds = struct.unpack(_STRUCTURE, a2b_hex(tai64n[1:])) seconds -= _OFFSET return seconds + (nanoseconds / 1000000000.0) PKGd#nc//eliot/_output.py""" Implementation of hooks and APIs for outputting log messages. """ from __future__ import unicode_literals, absolute_import import sys import json as pyjson from six import text_type as unicode, PY3 from pyrsistent import PClass, field from . import _bytesjson as slow_json if PY3: fast_json = slow_json else: try: # ujson has some issues, in particular it is far too lenient on bad # inputs... but on the other hand it's much faster than built-in # json module on CPython. So we use it until we come up with some # better. We import built-in module for use by the validation code # path, since we want to validate messages encode in all JSON # encoders. import ujson as fast_json except ImportError: import json as fast_json from zope.interface import Interface, implementer from ._traceback import writeTraceback, TRACEBACK_MESSAGE from ._message import ( Message, EXCEPTION_FIELD, MESSAGE_TYPE_FIELD, REASON_FIELD, ) from ._util import saferepr, safeunicode class _DestinationsSendError(Exception): """ An error occured sending to one or more destinations. @ivar errors: A list of tuples output from C{sys.exc_info()}. """ def __init__(self, errors): self.errors = errors Exception.__init__(self) class Destinations(object): """ Manage a list of destinations for message dictionaries. The global instance of this class is where L{Logger} instances will send written messages. """ def __init__(self): self._destinations = [] self._globalFields = {} def addGlobalFields(self, **fields): """ Add fields that will be included in all messages sent through this destination. @param fields: Keyword arguments mapping field names to values. """ self._globalFields.update(fields) def send(self, message): """ Deliver a message to all destinations. The passed in message might be mutated. @param message: A message dictionary that can be serialized to JSON. @type message: L{dict} """ message.update(self._globalFields) errors = [] for dest in self._destinations: try: dest(message) except: errors.append(sys.exc_info()) if errors: raise _DestinationsSendError(errors) def add(self, destination): """ Add a new destination. A destination should never ever throw an exception. Seriously. A destination should not mutate the dictionary it is given. @param destination: A callable that takes message dictionaries, """ self._destinations.append(destination) def remove(self, destination): """ Remove an existing destination. @param destination: A destination previously added with C{self.add}. @raises ValueError: If the destination is unknown. """ self._destinations.remove(destination) class ILogger(Interface): """ Write out message dictionaries to some destination. """ def write(dictionary, serializer=None): """ Write a dictionary to the appropriate destination. @param serializer: Either C{None}, or a L{eliot._validation._MessageSerializer} which can be used to validate this message. @param dictionary: The message to write out. The given dictionary will not be mutated. @type dictionary: C{dict} """ @implementer(ILogger) class Logger(object): """ Write out messages to the globally configured destination(s). You will typically want to create one of these for every chunk of code whose messages you want to unit test in isolation, e.g. a class. The tests can then replace a specific L{Logger} with a L{MemoryLogger}. """ _destinations = Destinations() def _safeUnicodeDictionary(self, dictionary): """ Serialize a dictionary to a unicode string no matter what it contains. The resulting dictionary will loosely follow Python syntax but it is not expected to actually be a lossless encoding in all cases. @param dictionary: A L{dict} to serialize. @return: A L{unicode} string representing the input dictionary as faithfully as can be done without putting in too much effort. """ try: return unicode( dict((saferepr(key), saferepr(value)) for (key, value) in dictionary.items())) except: return saferepr(dictionary) def write(self, dictionary, serializer=None): """ Serialize the dictionary, and write it to C{self._destinations}. """ dictionary = dictionary.copy() try: if serializer is not None: serializer.serialize(dictionary) except: writeTraceback(self) msg = Message({MESSAGE_TYPE_FIELD: "eliot:serialization_failure", "message": self._safeUnicodeDictionary(dictionary)}) msg.write(self) return try: self._destinations.send(dictionary) except _DestinationsSendError as e: for (exc_type, exception, exc_traceback) in e.errors: try: # Can't use same code path as serialization errors because # if destination continues to error out we will get # infinite recursion. So instead we have to manually # construct a message. msg = Message({ MESSAGE_TYPE_FIELD: "eliot:destination_failure", REASON_FIELD: safeunicode(exception), EXCEPTION_FIELD: exc_type.__module__ + "." + exc_type.__name__, "message": self._safeUnicodeDictionary(dictionary)}) self._destinations.send(dict(msg._freeze())) except: # Nothing we can do here, raising exception to caller will # break business logic, better to have that continue to # work even if logging isn't. pass class UnflushedTracebacks(Exception): """ The L{MemoryLogger} had some tracebacks logged which were not flushed. This means either your code has a bug and logged an unexpected traceback. If you expected the traceback then you will need to flush it using L{MemoryLogger.flushTracebacks}. """ @implementer(ILogger) class MemoryLogger(object): """ Store written messages in memory. When unit testing you don't want to create this directly but rather use the L{eliot.testing.validateLogging} decorator on a test method, which will provide additional testing integration. @ivar messages: A C{list} of the dictionaries passed to L{MemoryLogger.write}. Do not mutate this list. @ivar serializers: A C{list} of the serializers passed to L{MemoryLogger.write}, each corresponding to a message L{MemoryLogger.messages}. Do not mutate this list. @ivar tracebackMessages: A C{list} of messages written to this logger for tracebacks using L{eliot.writeTraceback} or L{eliot.writeFailure}. Do not mutate this list. """ def __init__(self): self.reset() def flushTracebacks(self, exceptionType): """ Flush all logged tracebacks whose exception is of the given type. This means they are expected tracebacks and should not cause the test to fail. @param exceptionType: A subclass of L{Exception}. @return: C{list} of flushed messages. """ result = [] remaining = [] for message in self.tracebackMessages: if isinstance(message[REASON_FIELD], exceptionType): result.append(message) else: remaining.append(message) self.tracebackMessages = remaining return result # PEP 8 variant: flush_tracebacks = flushTracebacks def write(self, dictionary, serializer=None): """ Add the dictionary to list of messages. """ self.messages.append(dictionary) self.serializers.append(serializer) if serializer is TRACEBACK_MESSAGE._serializer: self.tracebackMessages.append(dictionary) def validate(self): """ Validate all written messages. Does minimal validation of types, and for messages with corresponding serializers use those to do additional validation. @raises TypeError: If a field name is not unicode. @raises eliot.ValidationError: If serializer was given and validation failed. """ for dictionary, serializer in zip(self.messages, self.serializers): if serializer is not None: serializer.validate(dictionary) for key in dictionary: if not isinstance(key, unicode): if isinstance(key, bytes): key.decode("utf-8") else: raise TypeError(dictionary, "%r is not unicode" % (key,)) if serializer is not None: serializer.serialize(dictionary) # Make sure we can be encoded with different JSON encoder, since # ujson has different behavior in some cases: fast_json.dumps(dictionary) slow_json.dumps(dictionary) def serialize(self): """ Serialize all written messages. This is the Field-based serialization, not JSON. @return: A C{list} of C{dict}, the serialized messages. """ result = [] for dictionary, serializer in zip(self.messages, self.serializers): dictionary = dictionary.copy() serializer.serialize(dictionary) result.append(dictionary) return result def reset(self): """ Clear all logged messages. Any logged tracebacks will also be cleared, and will therefore not cause a test failure. This is useful to ensure a logger is in a known state before testing logging of a specific code path. """ self.messages = [] self.serializers = [] self.tracebackMessages = [] class FileDestination(PClass): """ Callable that writes JSON messages to a file. On Python 3 the file may support either C{bytes} or C{unicode}. On Python 2 only C{bytes} are supported since that is what all files expect in practice. @ivar file: The file to which messages will be written. @ivar _dumps: Function that serializes an object to JSON. @ivar _linebreak: C{"\n"} as either bytes or unicode. """ file = field(mandatory=True) _dumps = field(mandatory=True) _linebreak = field(mandatory=True) def __new__(cls, file): unicodeFile = False if PY3: try: file.write(b"") except TypeError: unicodeFile = True if unicodeFile: # On Python 3 native json module outputs unicode: _dumps = pyjson.dumps _linebreak = u"\n" else: _dumps = fast_json.dumps _linebreak = b"\n" return PClass.__new__( cls, file=file, _dumps=_dumps, _linebreak=_linebreak) def __call__(self, message): """ @param message: A message dictionary. """ self.file.write(self._dumps(message) + self._linebreak) self.file.flush() def to_file(output_file): """ Add a destination that writes a JSON message per line to the given file. @param output_file: A file-like object. """ Logger._destinations.add(FileDestination(file=output_file)) # The default Logger, used when none is specified: _DEFAULT_LOGGER = Logger() PK⡁G;ZFfeliot/_message.py""" Log messages and related utilities. """ from __future__ import unicode_literals import time from uuid import uuid4 from six import text_type as unicode from pyrsistent import PClass, thaw, pmap_field, pmap MESSAGE_TYPE_FIELD = 'message_type' TASK_UUID_FIELD = 'task_uuid' TASK_LEVEL_FIELD = 'task_level' TIMESTAMP_FIELD = 'timestamp' EXCEPTION_FIELD = 'exception' REASON_FIELD = 'reason' class Message(object): """ A log message. Messages are basically dictionaries, mapping "fields" to "values". Field names should not start with C{'_'}, as those are reserved for system use (e.g. C{"_id"} is used by Elasticsearch for unique message identifiers and may be auto-populated by logstash). """ # Overrideable for testing purposes: _time = time.time @classmethod def new(_class, _serializer=None, **fields): """ Create a new L{Message}. The keyword arguments will become the initial contents of the L{Message}. @param _serializer: A positional argument, either C{None} or a L{eliot._validation._MessageSerializer} with which a L{eliot.ILogger} may choose to serialize the message. If you're using L{eliot.MessageType} this will be populated for you. @return: The new L{Message} """ return _class(fields, _serializer) @classmethod def log(_class, **fields): """ Write a new L{Message} to the default L{Logger}. The keyword arguments will become contents of the L{Message}. """ _class.new(**fields).write() def __init__(self, contents, serializer=None): """ You can also use L{Message.new} to create L{Message} objects. @param contents: The contents of this L{Message}, a C{dict} whose keys must be C{unicode}, or text that has been UTF-8 encoded to C{bytes}. @param serializer: Either C{None}, or L{eliot._validation._MessageSerializer} with which a L{eliot.Logger} may choose to serialize the message. If you're using L{eliot.MessageType} this will be populated for you. """ self._contents = pmap(contents) self._serializer = serializer def bind(self, **fields): """ Return a new L{Message} with this message's contents plus the additional given bindings. """ return Message(self._contents.update(fields), self._serializer) def contents(self): """ Return a copy of L{Message} contents. """ return dict(self._contents) def _timestamp(self): """ Return the current time. """ return self._time() def _freeze(self, action=None): """ Freeze this message for logging, registering it with C{action}. @param action: The L{Action} which is the context for this message. If C{None}, the L{Action} will be deduced from the current call stack. @return: A L{PMap} with added C{timestamp}, C{task_uuid}, and C{task_level} entries. """ if action is None: action = currentAction() if action is None: task_uuid = unicode(uuid4()) task_level = [1] else: task_uuid = action._identification[TASK_UUID_FIELD] task_level = thaw(action._nextTaskLevel().level) timestamp = self._timestamp() return self._contents.update({ TIMESTAMP_FIELD: timestamp, TASK_UUID_FIELD: task_uuid, TASK_LEVEL_FIELD: task_level, }) def write(self, logger=None, action=None): """ Write the message to the given logger. This will additionally include a timestamp, the action context if any, and any other fields. Byte field names will be converted to Unicode. @type logger: L{eliot.ILogger} or C{None} indicating the default one. @param action: The L{Action} which is the context for this message. If C{None}, the L{Action} will be deduced from the current call stack. """ if logger is None: logger = _output._DEFAULT_LOGGER logged_dict = self._freeze(action=action) logger.write(dict(logged_dict), self._serializer) class WrittenMessage(PClass): """ A L{Message} that has been logged. @ivar _logged_dict: The originally logged dictionary. """ _logged_dict = pmap_field((str, unicode), object) @property def timestamp(self): """ The Unix timestamp of when the message was logged. """ return self._logged_dict[TIMESTAMP_FIELD] @property def task_uuid(self): """ The UUID of the task in which the message was logged. """ return self._logged_dict[TASK_UUID_FIELD] @property def task_level(self): """ The L{TaskLevel} of this message appears within the task. """ return TaskLevel(level=self._logged_dict[TASK_LEVEL_FIELD]) @property def contents(self): """ A C{PMap}, the message contents without Eliot metadata. """ return self._logged_dict.discard( TIMESTAMP_FIELD).discard(TASK_UUID_FIELD).discard(TASK_LEVEL_FIELD) @classmethod def from_dict(cls, logged_dictionary): """ Reconstruct a L{WrittenMessage} from a logged dictionary. @param logged_dictionary: A C{PMap} representing a parsed log entry. @return: A L{WrittenMessage} for that dictionary. """ return cls(_logged_dict=logged_dictionary) def as_dict(self): """ Return the dictionary that was used to write this message. @return: A C{dict}, as might be logged by Eliot. """ return self._logged_dict # Import at end to deal with circular imports: from ._action import currentAction, TaskLevel from . import _output PKYuAGFeliot/logwriter.py""" A log destination for use by Twisted applications. Runs in a thread, so that we don't do blocking I/O in the event loop thread. """ from __future__ import unicode_literals, absolute_import import threading import select from warnings import warn from twisted.application.service import Service from twisted.internet.threads import deferToThreadPool if getattr(select, "poll", None): from twisted.internet.pollreactor import PollReactor as Reactor else: from twisted.internet.selectreactor import SelectReactor as Reactor from . import addDestination, removeDestination from ._output import FileDestination class ThreadedWriter(Service): """ An non-blocking Eliot log destination that wraps a blocking destination, writing log messages to the latter in a managed thread. Unfortunately Python's Queue is not reentrant (http://bugs.python.org/issue14976) and neither is RLock (http://bugs.python.org/issue13697). In order to queue items in a thread we therefore rely on the self-pipe trick, and the easiest way to do that is by running another reactor in the thread. @ivar _reactor: A private reactor running in a thread which will do the log writes. @ivar _thread: C{None}, or a L{threading.Thread} running the private reactor. """ name = u"Eliot Log Writer" def __init__(self, destination, reactor): """ @param destination: The underlying destination for log files. This will be called from a non-reactor thread. @param reactor: The main reactor. """ self._destination = destination self._reactor = Reactor() # Ick. See https://twistedmatrix.com/trac/ticket/6982 for real solution. self._reactor._registerAsIOThread = False self._mainReactor = reactor self._thread = None def startService(self): """ Start the writer thread. """ Service.startService(self) self._thread = threading.Thread(target=self._writer) self._thread.start() addDestination(self) def stopService(self): """ Stop the writer thread, wait for it to finish. """ Service.stopService(self) removeDestination(self) self._reactor.callFromThread(self._reactor.stop) return deferToThreadPool( self._mainReactor, self._mainReactor.getThreadPool(), self._thread.join) def __call__(self, data): """ Add the data to the queue, to be serialized to JSON and written by the writer thread with a newline added. @param data: C{bytes} to write to disk. """ self._reactor.callFromThread(self._destination, data) def _writer(self): """ The function run by the writer thread. """ self._reactor.run(installSignalHandlers=False) class ThreadedFileWriter(ThreadedWriter): """ ``ThreadedWriter`` that takes a log file and writes to it using a ``FileDestination``. This exists for backwards compatibility purpose. The recommended API is ``ThreadedWriter``. """ def __init__(self, logFile, reactor): """ @param logFile: A C{file}-like object that is at the end of its existing contents (e.g. opened with append mode) and accepts bytes. @type logFile: C{file}, or any file-like object with C{write}, C{flush} and C{close} methods e.g. a L{twisted.python.logfile.LogFile} if you want log rotation. @param reactor: The main reactor. """ warn( "ThreadedFileWriter is deprecated since 0.9.0. " "Use ThreadedWriter instead.", DeprecationWarning, stacklevel=2 ) self._logFile = logFile ThreadedWriter.__init__(self, FileDestination(file=logFile), reactor) def stopService(self): d = ThreadedWriter.stopService(self) d.addCallback(lambda _: self._logFile.close()) return d PKG+>+>eliot/_validation.py""" A log message serialization and validation system for Eliot. Validation is intended to be done by unit tests, not the production code path, although in theory it could be done then as well. """ from __future__ import unicode_literals import six unicode = six.text_type from pyrsistent import PClass, field as pyrsistent_field from ._message import ( Message, REASON_FIELD, MESSAGE_TYPE_FIELD, TASK_LEVEL_FIELD, TASK_UUID_FIELD, TIMESTAMP_FIELD, ) from ._action import ( startAction, startTask, ACTION_STATUS_FIELD, ACTION_TYPE_FIELD, STARTED_STATUS, SUCCEEDED_STATUS, FAILED_STATUS, ) class ValidationError(Exception): """ A field value failed validation. """ # Types that can be encoded to JSON: _JSON_TYPES = {type(None), int, float, unicode, list, dict, bytes, bool} _JSON_TYPES |= set(six.integer_types) RESERVED_FIELDS = (TASK_LEVEL_FIELD, TASK_UUID_FIELD, TIMESTAMP_FIELD) class Field(object): """ A named field that can accept rich types and serialize them to the logging system's basic types (currently, JSON types). An optional extra validation function can be used to validate inputs when unit testing. @ivar key: The name of the field, the key which refers to it, e.g. C{"path"}. @ivar description: A description of what this field contains. @type description: C{unicode} """ def __init__(self, key, serializer, description="", extraValidator=None): """ @param serializer: A function that takes a single rich input and returns a serialized value that can be written out as JSON. May raise L{ValidationError} to indicate bad inputs. @param extraValidator: Allow additional validation of the field value. A callable that takes a field value, and raises L{ValidationError} if the value is a incorrect one for this field. Alternatively can be set to C{None}, in which case no additional validation is done. """ self.key = key self.description = description self._serializer = serializer self._extraValidator = extraValidator def validate(self, input): """ Validate the given input value against this L{Field} definition. @param input: An input value supposedly serializable by this L{Field}. @raises ValidationError: If the value is not serializable or fails to be validated by the additional validator. """ # Make sure the input serializes: self._serializer(input) # Use extra validator, if given: if self._extraValidator is not None: self._extraValidator(input) def serialize(self, input): """ Convert the given input to a value that can actually be logged. @param input: An input value supposedly serializable by this L{Field}. @return: A serialized value. """ return self._serializer(input) @classmethod def forValue(klass, key, value, description): """ Create a L{Field} that can only have a single value. @param key: The name of the field, the key which refers to it, e.g. C{"path"}. @param value: The allowed value for the field. @param description: A description of what this field contains. @type description: C{unicode} @return: A L{Field}. """ def validate(checked): if checked != value: raise ValidationError(checked, "Field %r must be %r" % (key, value)) return klass(key, lambda _: value, description, validate) # PEP 8 variant: for_value = forValue @classmethod def forTypes(klass, key, classes, description, extraValidator=None): """ Create a L{Field} that must be an instance of a given set of types. @param key: The name of the field, the key which refers to it, e.g. C{"path"}. @ivar classes: A C{list} of allowed Python classes for this field's values. Supported classes are C{unicode}, C{int}, C{float}, C{bool}, C{long}, C{list} and C{dict} and C{None} (the latter isn't strictly a class, but will be converted appropriately). @param description: A description of what this field contains. @type description: C{unicode} @param extraValidator: See description in L{Field.__init__}. @return: A L{Field}. """ fixedClasses = [] for k in classes: if k is None: k = type(None) if k not in _JSON_TYPES: raise TypeError("%s is not JSON-encodeable" % (k,)) fixedClasses.append(k) fixedClasses = tuple(fixedClasses) def validate(value): if not isinstance(value, fixedClasses): raise ValidationError( value, "Field %r requires type to be one of %s" % (key, classes)) if extraValidator is not None: extraValidator(value) return klass(key, lambda v: v, description, extraValidator=validate) # PEP 8 variant: for_types = forTypes def fields(*fields, **keys): """ Factory for for L{MessageType} and L{ActionType} field definitions. @param *fields: A L{tuple} of L{Field} instances. @param **keys: A L{dict} mapping key names to the expected type of the field's values. @return: A L{list} of L{Field} instances. """ return list(fields) + [ Field.forTypes(key, [value], "") for key, value in keys.items()] REASON = Field.forTypes(REASON_FIELD, [unicode], "The reason for an event.") TRACEBACK = Field.forTypes("traceback", [unicode], "The traceback for an exception.") EXCEPTION = Field.forTypes("exception", [unicode], "The FQPN of an exception class.") class _MessageSerializer(object): """ A serializer and validator for messages. @ivar fields: A C{dict} mapping a C{unicode} field name to the respective L{Field}. @ivar allow_additional_fields: If true, additional fields don't cause validation failure. """ def __init__(self, fields, allow_additional_fields=False): keys = [] for field in fields: if not isinstance(field, Field): raise TypeError( 'Expected a Field instance but got', field) keys.append(field.key) if len(set(keys)) != len(keys): raise ValueError(keys, "Duplicate field name") if ACTION_TYPE_FIELD in keys: if MESSAGE_TYPE_FIELD in keys: raise ValueError(keys, "Messages must have either " "'action_type' or 'message_type', not both") elif MESSAGE_TYPE_FIELD not in keys: raise ValueError(keys, "Messages must have either 'action_type' ", "or 'message_type'") if any(key.startswith("_") for key in keys): raise ValueError(keys, "Field names must not start with '_'") for reserved in RESERVED_FIELDS: if reserved in keys: raise ValueError(keys, "The field name %r is reserved for use " "by the logging framework" % (reserved,)) self.fields = dict((field.key, field) for field in fields) self.allow_additional_fields = allow_additional_fields def serialize(self, message): """ Serialize the given message in-place, converting inputs to outputs. We do this in-place for performance reasons. There are more fields in a message than there are L{Field} objects because of the timestamp, task_level and task_uuid fields. By only iterating over our L{Fields} we therefore reduce the number of function calls in a critical code path. @param message: A C{dict}. """ for key, field in self.fields.items(): message[key] = field.serialize(message[key]) def validate(self, message): """ Validate the given message. @param message: A C{dict}. @raises ValidationError: If the message has the wrong fields or one of its field values fail validation. """ for key, field in self.fields.items(): if key not in message: raise ValidationError(message, "Field %r is missing" % (key,)) field.validate(message[key]) if self.allow_additional_fields: return # Otherwise, additional fields are not allowed: fieldSet = set(self.fields) | set(RESERVED_FIELDS) for key in message: if key not in fieldSet: raise ValidationError(message, "Unexpected field %r" % (key,)) class MessageType(object): """ A specific type of non-action message. Example usage: # Schema definition: KEY = Field("key", [int], u"The lookup key for things.") STATUS = Field("status", [int], u"The status of a thing.") LOG_STATUS = MessageType( "yourapp:subsystem:status", [KEY, STATUS], u"We just set the status of something.") # Actual code, with logging added: def setstatus(key, status): doactualset(key, status) LOG_STATUS(key=key, status=status).write() You do not need to use the L{MessageType} to create the L{eliot.Message}, however; you could build it up using a series of L{eliot.Message.bind} calls. Having a L{MessageType} is nonetheless still useful for validation and documentation. @ivar message_type: The name of the type, e.g. C{"yourapp:subsystem:yourtype"}. @ivar description: A description of what this message means. @type description: C{unicode} """ def __init__(self, message_type, fields, description=""): """ @ivar type: The name of the type, e.g. C{"yourapp:subsystem:yourtype"}. @ivar fields: A C{list} of L{Field} instances which can appear in this type. @param description: A description of what this message means. @type description: C{unicode} """ self.message_type = message_type self.description = description self._serializer = _MessageSerializer( fields + [Field.forValue(MESSAGE_TYPE_FIELD, message_type, "The message type.")]) def __call__(self, **fields): """ Create a new L{eliot.Message} of this type with the given fields. @param fields: Extra fields to add to the message. @rtype: L{eliot.Message} """ fields[MESSAGE_TYPE_FIELD] = self.message_type return Message(fields, self._serializer) class _ActionSerializers(PClass): """ Serializers for the three action messages: start, success and failure. """ start = pyrsistent_field(mandatory=True) success = pyrsistent_field(mandatory=True) failure = pyrsistent_field(mandatory=True) class ActionType(object): """ A specific type of action. Example usage: # Schema definition: KEY = Field("key", [int], u"The lookup key for things.") RESULT = Field("result", [str], u"The result of lookups.") LOG_DOSOMETHING = ActionType( "yourapp:subsystem:youraction", [KEY], [RESULT], u"Do something with a key, resulting in a value.") # Actual code, with logging added: def dosomething(key): with LOG_DOSOMETHING(logger, key=key) as action: _dostuff(key) _morestuff(key) result = _theresult() action.addSuccessFields(result=result) return result @ivar action_type: The name of the action, e.g. C{"yourapp:subsystem:youraction"}. @ivar startFields: A C{list} of L{Field} instances which can appear in this action's start message. @ivar successFields: A C{list} of L{Field} instances which can appear in this action's succesful finish message. @ivar failureFields: A C{list} of L{Field} instances which can appear in this action's failed finish message (in addition to the built-in C{"exception"} and C{"reason"} fields). @ivar description: A description of what this action's messages mean. @type description: C{unicode} """ # Overrideable hook for testing; need staticmethod() so functions don't # get turned into methods. _startAction = staticmethod(startAction) _startTask = staticmethod(startTask) def __init__(self, action_type, startFields, successFields, description=""): self.action_type = action_type self.description = description actionTypeField = Field.forValue(ACTION_TYPE_FIELD, action_type, "The action type") def makeActionStatusField(value): return Field.forValue(ACTION_STATUS_FIELD, value, "The action status") startFields = startFields + [ actionTypeField, makeActionStatusField(STARTED_STATUS)] successFields = successFields + [ actionTypeField, makeActionStatusField(SUCCEEDED_STATUS)] failureFields = [ actionTypeField, makeActionStatusField(FAILED_STATUS), REASON, EXCEPTION] self._serializers = _ActionSerializers( start=_MessageSerializer(startFields), success=_MessageSerializer(successFields), # Failed action messages can have extra fields from exception # extraction: failure=_MessageSerializer(failureFields, allow_additional_fields=True)) def __call__(self, logger=None, **fields): """ Start a new L{eliot.Action} of this type with the given start fields. You can use the result as a Python context manager, or use the L{eliot.Action.finish} API. LOG_DOSOMETHING = ActionType("yourapp:subsystem:dosomething", [Field.forTypes("entry", [int], "")], [Field.forTypes("result", [int], "")], [], "Do something with an entry.") with LOG_DOSOMETHING(entry=x) as action: do(x) result = something(x * 2) action.addSuccessFields(result=result) Or perhaps: action = LOG_DOSOMETHING(entry=x) action.run(doSomething) action.finish() @param logger: A L{eliot.ILogger} provider to which the action's messages will be written, or C{None} to use the default one. @param fields: Extra fields to add to the message. @rtype: L{eliot.Action} """ return self._startAction(logger, self.action_type, self._serializers, **fields) def asTask(self, logger, **fields): """ Start a new L{eliot.Action} of this type as a task (i.e. top-level action) with the given start fields. See L{ActionType.__call__} for example of usage. @param logger: A L{eliot.ILogger} provider to which the action's messages will be written. @param fields: Extra fields to add to the message. @rtype: L{eliot.Action} """ return self._startTask(logger, self.action_type, self._serializers, **fields) # PEP 8 variant: as_task = asTask __all__ = [] PKG>~33eliot/testing.py""" Utilities to aid unit testing L{eliot} and code that uses it. """ from __future__ import unicode_literals from unittest import SkipTest from functools import wraps from pyrsistent import PClass, field from ._action import ( ACTION_STATUS_FIELD, ACTION_TYPE_FIELD, STARTED_STATUS, FAILED_STATUS, SUCCEEDED_STATUS, ) from ._message import MESSAGE_TYPE_FIELD, TASK_LEVEL_FIELD, TASK_UUID_FIELD from ._output import MemoryLogger from . import _output COMPLETED_STATUSES = (FAILED_STATUS, SUCCEEDED_STATUS) def issuperset(a, b): """ Use L{assertContainsFields} instead. @type a: C{dict} @type b: C{dict} @return: Boolean indicating whether C{a} has all key/value pairs that C{b} does. """ aItems = a.items() return all(pair in aItems for pair in b.items()) def assertContainsFields(test, message, fields): """ Assert that the given message contains the given fields. @param test: L{unittest.TestCase} being run. @param message: C{dict}, the message we are checking. @param fields: C{dict}, the fields we expect the message to have. @raises AssertionError: If the message doesn't contain the fields. """ messageSubset = dict([(key, value) for key, value in message.items() if key in fields]) test.assertEqual(messageSubset, fields) class LoggedAction(PClass): """ An action whose start and finish messages have been logged. @ivar startMessage: A C{dict}, the start message contents. Also available as C{start_message}. @ivar endMessage: A C{dict}, the end message contents (in both success and failure cases). Also available as C{end_message}. @ivar children: A C{list} of direct child L{LoggedMessage} and L{LoggedAction} instances. """ startMessage = field(mandatory=True) endMessage = field(mandatory=True) children = field(mandatory=True) def __new__(cls, startMessage, endMessage, children): return PClass.__new__(cls, startMessage=startMessage, endMessage=endMessage, children=children) @property def start_message(self): return self.startMessage @property def end_message(self): return self.endMessage @classmethod def fromMessages(klass, uuid, level, messages): """ Given a task uuid and level (identifying an action) and a list of dictionaries, create a L{LoggedAction}. All child messages and actions will be added as L{LoggedAction} or L{LoggedMessage} children. Note that some descendant messages may be missing if you end up logging to two or more different ILogger providers. @param uuid: The uuid of the task (C{unicode}). @param level: The C{task_level} of the action's start message, e.g. C{"/1/2/1"}. @param messages: A list of message C{dict}s. @return: L{LoggedAction} constructed from start and finish messages for this specific action. @raises: L{ValueError} if one or both of the action's messages cannot be found. """ startMessage = None endMessage = None children = [] levelPrefix = level[:-1] for message in messages: if message[TASK_UUID_FIELD] != uuid: # Different task altogether: continue messageLevel = message[TASK_LEVEL_FIELD] if messageLevel[:-1] == levelPrefix: status = message.get(ACTION_STATUS_FIELD) if status == STARTED_STATUS: startMessage = message elif status in COMPLETED_STATUSES: endMessage = message else: # Presumably a message in this action: children.append(LoggedMessage(message)) elif (len(messageLevel) == len(levelPrefix) + 2 and messageLevel[:-2] == levelPrefix and messageLevel[-1] == 1): # If start message level is [1], [1, 2, 1] implies first # message of a direct child. child = klass.fromMessages( uuid, message[TASK_LEVEL_FIELD], messages) children.append(child) if startMessage is None or endMessage is None: raise ValueError(uuid, level) return klass(startMessage, endMessage, children) # PEP 8 variant: from_messages = fromMessages @classmethod def ofType(klass, messages, actionType): """ Find all L{LoggedAction} of the specified type. @param messages: A list of message C{dict}s. @param actionType: A L{eliot.ActionType}, the type of the actions to find. @return: A C{list} of L{LoggedAction}. """ result = [] for message in messages: if (message.get(ACTION_TYPE_FIELD) == actionType.action_type and message[ACTION_STATUS_FIELD] == STARTED_STATUS): result.append(klass.fromMessages(message[TASK_UUID_FIELD], message[TASK_LEVEL_FIELD], messages)) return result # PEP 8 variant: of_type = ofType def descendants(self): """ Find all descendant L{LoggedAction} or L{LoggedMessage} of this instance. @return: An iterable of L{LoggedAction} and L{LoggedMessage} instances. """ for child in self.children: yield child if isinstance(child, LoggedAction): for descendant in child.descendants(): yield descendant @property def succeeded(self): """ Indicate whether this action succeeded. @return: C{bool} indicating whether the action succeeded. """ return self.endMessage[ACTION_STATUS_FIELD] == SUCCEEDED_STATUS class LoggedMessage(PClass): """ A message that has been logged. @ivar message: A C{dict}, the message contents. """ message = field(mandatory=True) def __new__(cls, message): return PClass.__new__(cls, message=message) @classmethod def ofType(klass, messages, messageType): """ Find all L{LoggedMessage} of the specified type. @param messages: A list of message C{dict}s. @param messageType: A L{eliot.MessageType}, the type of the messages to find. @return: A C{list} of L{LoggedMessage}. """ result = [] for message in messages: if message.get(MESSAGE_TYPE_FIELD) == messageType.message_type: result.append(klass(message)) return result # PEP 8 variant: of_type = ofType class UnflushedTracebacks(Exception): """ The L{MemoryLogger} had some tracebacks logged which were not flushed. This means either your code has a bug and logged an unexpected traceback. If you expected the traceback then you will need to flush it using L{MemoryLogger.flushTracebacks}. """ def validateLogging(assertion, *assertionArgs, **assertionKwargs): """ Decorator factory for L{unittest.TestCase} methods to add logging validation. 1. The decorated test method gets a C{logger} keyword argument, a L{MemoryLogger}. 2. All messages logged to this logger will be validated at the end of the test. 3. Any unflushed logged tracebacks will cause the test to fail. For example: from unittest import TestCase from eliot.testing import assertContainsFields, validateLogging class MyTests(TestCase): def assertFooLogging(self, logger): assertContainsFields(self, logger.messages[0], {"key": 123}) @param assertion: A callable that will be called with the L{unittest.TestCase} instance, the logger and C{assertionArgs} and C{assertionKwargs} once the actual test has run, allowing for extra logging-related assertions on the effects of the test. Use L{None} if you want the cleanup assertions registered but no custom assertions. @param assertionArgs: Additional positional arguments to pass to C{assertion}. @param assertionKwargs: Additional keyword arguments to pass to C{assertion}. """ def decorator(function): @wraps(function) def wrapper(self, *args, **kwargs): skipped = False kwargs["logger"] = logger = MemoryLogger() self.addCleanup(logger.validate) def checkForUnflushed(): if not skipped and logger.tracebackMessages: raise UnflushedTracebacks(logger.tracebackMessages) self.addCleanup(checkForUnflushed) # TestCase runs cleanups in reverse order, and we want this to # run *before* tracebacks are checked: if assertion is not None: self.addCleanup(lambda: skipped or assertion( self, logger, *assertionArgs, **assertionKwargs)) try: return function(self, *args, **kwargs) except SkipTest: skipped = True raise return wrapper return decorator # PEP 8 variant: validate_logging = validateLogging def capture_logging(assertion, *assertionArgs, **assertionKwargs): """ Capture and validate all logging that doesn't specify a L{Logger}. See L{validate_logging} for details on the rest of its behavior. """ def decorator(function): @validate_logging(assertion, *assertionArgs, **assertionKwargs) @wraps(function) def wrapper(self, *args, **kwargs): logger = kwargs["logger"] current_logger = _output._DEFAULT_LOGGER _output._DEFAULT_LOGGER = logger def cleanup(): _output._DEFAULT_LOGGER = current_logger self.addCleanup(cleanup) return function(self, logger) return wrapper return decorator def assertHasMessage(testCase, logger, messageType, fields=None): """ Assert that the given logger has a message of the given type, and the first message found of this type has the given fields. This can be used as the assertion function passed to L{validateLogging} or as part of a unit test. @param testCase: L{unittest.TestCase} instance. @param logger: L{eliot.MemoryLogger} whose messages will be checked. @param messageType: L{eliot.MessageType} indicating which message we're looking for. @param fields: The first message of the given type found must have a superset of the given C{dict} as its fields. If C{None} then fields are not checked. @return: The first found L{LoggedMessage} of the given type, if field validation succeeded. @raises AssertionError: No message was found, or the fields were not superset of given fields. """ if fields is None: fields = {} messages = LoggedMessage.ofType(logger.messages, messageType) testCase.assertTrue(messages, "No messages of type %s" % (messageType,)) loggedMessage = messages[0] assertContainsFields(testCase, loggedMessage.message, fields) return loggedMessage def assertHasAction(testCase, logger, actionType, succeeded, startFields=None, endFields=None): """ Assert that the given logger has an action of the given type, and the first action found of this type has the given fields and success status. This can be used as the assertion function passed to L{validateLogging} or as part of a unit test. @param testCase: L{unittest.TestCase} instance. @param logger: L{eliot.MemoryLogger} whose messages will be checked. @param actionType: L{eliot.ActionType} indicating which message we're looking for. @param succeeded: Expected success status of the action, a C{bool}. @param startFields: The first action of the given type found must have a superset of the given C{dict} as its start fields. If C{None} then fields are not checked. @param endFields: The first action of the given type found must have a superset of the given C{dict} as its end fields. If C{None} then fields are not checked. @return: The first found L{LoggedAction} of the given type, if field validation succeeded. @raises AssertionError: No action was found, or the fields were not superset of given fields. """ if startFields is None: startFields = {} if endFields is None: endFields = {} actions = LoggedAction.ofType(logger.messages, actionType) testCase.assertTrue(actions, "No actions of type %s" % (actionType,)) action = actions[0] testCase.assertEqual(action.succeeded, succeeded) assertContainsFields(testCase, action.startMessage, startFields) assertContainsFields(testCase, action.endMessage, endFields) return action PKGe7 eliot/_traceback.py""" Logging of tracebacks and L{twisted.python.failure.Failure} instances, as well as common utilities for handling exception logging. """ from __future__ import unicode_literals import traceback import sys from warnings import warn from ._message import EXCEPTION_FIELD, REASON_FIELD from ._util import safeunicode, load_module from ._validation import MessageType, Field from ._errors import _error_extraction TRACEBACK_MESSAGE = MessageType( "eliot:traceback", [Field(REASON_FIELD, safeunicode, "The exception's value."), Field("traceback", safeunicode, "The traceback."), Field(EXCEPTION_FIELD, lambda typ: "%s.%s" % (typ.__module__, typ.__name__), "The exception type's FQPN.")], "An unexpected exception indicating a bug.") # The fields here are actually subset of what you might get in practice, # due to exception extraction, so we hackily modify the serializer: TRACEBACK_MESSAGE._serializer.allow_additional_fields = True def _writeTracebackMessage(logger, typ, exception, traceback): """ Write a traceback to the log. @param typ: The class of the exception. @param exception: The L{Exception} instance. @param traceback: The traceback, a C{str}. """ msg = TRACEBACK_MESSAGE(reason=exception, traceback=traceback, exception=typ) msg = msg.bind(**_error_extraction.get_fields_for_exception( logger, exception)) msg.write(logger) # The default Python standard library traceback.py formatting functions # involving reading source from disk. This is a potential performance hit # since disk I/O can block. We therefore format the tracebacks with in-memory # information only. # # Unfortunately, the easiest way to do this is... exciting. def _get_traceback_no_io(): """ Return a version of L{traceback} that doesn't do I/O. """ module = load_module(str("_traceback_no_io"), traceback) class FakeLineCache(object): def checkcache(self, *args, **kwargs): None def getline(self, *args, **kwargs): return "" def lazycache(self, *args, **kwargs): return None module.linecache = FakeLineCache() return module _traceback_no_io = _get_traceback_no_io() def writeTraceback(logger=None, system=None): """ Write the latest traceback to the log. This should be used inside an C{except} block. For example: try: dostuff() except: writeTraceback(logger) """ if system is not None: warn("The `system` argument to writeTraceback is no longer used.", DeprecationWarning, stacklevel=2) typ, exception, tb = sys.exc_info() traceback = "".join(_traceback_no_io.format_exception(typ, exception, tb)) _writeTracebackMessage(logger, typ, exception, traceback) def writeFailure(failure, logger=None, system=None): """ Write a L{twisted.python.failure.Failure} to the log. This is for situations where you got an unexpected exception and want to log a traceback. For example: d = dostuff() d.addCallback(process) # Final error handler. d.addErrback(writeFailure, logger, "myapp:subsystem") @param failure: L{Failure} to write to the log. @type logger: L{eliot.ILogger} @return: None """ if system is not None: warn("The `system` argument to writeFailure is no longer used.", DeprecationWarning, stacklevel=2) # Failure.getBriefTraceback does not include source code, so does not do # I/O. _writeTracebackMessage(logger, failure.value.__class__, failure.value, failure.getBriefTraceback()) PK⡁GyWWeliot/_errors.py""" Error-handling utility code. """ from __future__ import unicode_literals from inspect import getmro class ErrorExtraction(object): """ Extract fields from exceptions for failed-action messages. @ivar registry: Map exception class to function that extracts fields. """ def __init__(self): self.registry = {} def register_exception_extractor(self, exception_class, extractor): """ Register a function that converts exceptions to fields. @param exception_class: Class to register for. @param extractor: Single-argument callable that takes an exception of the given class (or a subclass) and returns a dictionary, fields to include in a failed action message. """ self.registry[exception_class] = extractor def get_fields_for_exception(self, logger, exception): """ Given an exception instance, return fields to add to the failed action message. @param logger: ``ILogger`` currently being used. @param exception: An exception instance. @return: Dictionary with fields to include. """ for klass in getmro(exception.__class__): if klass in self.registry: extractor = self.registry[klass] try: return extractor(exception) except: from ._traceback import writeTraceback writeTraceback(logger) return {} return {} _error_extraction = ErrorExtraction() register_exception_extractor = _error_extraction.register_exception_extractor get_fields_for_exception = _error_extraction.get_fields_for_exception # Default handler for OSError and IOError by registered EnvironmentError: register_exception_extractor(EnvironmentError, lambda e: {"errno": e.errno}) PKPxE4iieliot/serializers.py""" Standardized serialization code. """ from __future__ import unicode_literals from hashlib import md5 _TIME_FORMAT = "%Y-%m-%dT%H:%M:%S.%fZ" def timestamp(dt): """ Convert a UTC datetime to a string. @param dt: A C{datetime.datetime} in UTC timezone. @return: C{unicode} """ return dt.strftime(_TIME_FORMAT) def identity(value): """ Return the passed in object. """ return value def md5hex(data): """ Return hex MD5 of the input bytes. @param data: Some C{bytes}. @return: Hex-encoded MD5 of the data. """ return md5(data).hexdigest() PK⡁Gluip p eliot/journald.py""" journald support for Eliot. """ from cffi import FFI from os import strerror from sys import argv from os.path import basename from ._bytesjson import dumps from ._message import TASK_UUID_FIELD, MESSAGE_TYPE_FIELD from ._action import ACTION_TYPE_FIELD, ACTION_STATUS_FIELD, FAILED_STATUS _ffi = FFI() _ffi.cdef(""" int sd_journal_send(const char *format, ...); """) try: try: _journald = _ffi.dlopen("libsystemd.so.0") except OSError: # Older versions of systemd have separate library: _journald = _ffi.dlopen("libsystemd-journal.so.0") except OSError as e: raise ImportError("Failed to load journald: " + str(e)) def sd_journal_send(**kwargs): """ Send a message to the journald log. @param kwargs: Mapping between field names to values, both as bytes. @raise IOError: If the operation failed. """ # The function uses printf formatting, so we need to quote # percentages. fields = [_ffi.new("char[]", key.encode("ascii") + b'=' + value.replace(b"%", b"%%")) for key, value in kwargs.items()] fields.append(_ffi.NULL) result = _journald.sd_journal_send(*fields) if result != 0: raise IOError(-result, strerror(-result)) class JournaldDestination(object): """ A logging destination that writes to journald. The message will be logged as JSON, with an additional field C{ELIOT_TASK} storing the C{task_uuid} and C{ELIOT_TYPE} storing the C{message_type} or C{action_type}. Messages for failed actions will get priority 3 ("error"), and traceback messages will get priority 2 ("critical"). All other messages will get priority 1 ("info"). """ def __init__(self): self._identifier = basename(argv[0]).encode("utf-8") def __call__(self, message): """ Write the given message to journald. @param message: Dictionary passed from a C{Logger}. """ eliot_type = u"" priority = b"6" if ACTION_TYPE_FIELD in message: eliot_type = message[ACTION_TYPE_FIELD] if message[ACTION_STATUS_FIELD] == FAILED_STATUS: priority = b"3" elif MESSAGE_TYPE_FIELD in message: eliot_type = message[MESSAGE_TYPE_FIELD] if eliot_type == u"eliot:traceback": priority = b"2" sd_journal_send(MESSAGE=dumps(message), ELIOT_TASK=message[TASK_UUID_FIELD].encode("utf-8"), ELIOT_TYPE=eliot_type.encode("utf-8"), SYSLOG_IDENTIFIER=self._identifier, PRIORITY=priority) PKGV :lleliot/_action.py""" Support for actions and tasks. Actions have a beginning and an eventual end, and can be nested. Tasks are top-level actions. """ from __future__ import unicode_literals, absolute_import import threading from uuid import uuid4 from itertools import count from contextlib import contextmanager from warnings import warn from pyrsistent import ( field, PClass, optional, pmap_field, pvector_field, pvector, ) from six import text_type as unicode from ._message import ( Message, WrittenMessage, EXCEPTION_FIELD, REASON_FIELD, TASK_UUID_FIELD, ) from ._util import safeunicode from ._errors import _error_extraction ACTION_STATUS_FIELD = 'action_status' ACTION_TYPE_FIELD = 'action_type' STARTED_STATUS = 'started' SUCCEEDED_STATUS = 'succeeded' FAILED_STATUS = 'failed' VALID_STATUSES = (STARTED_STATUS, SUCCEEDED_STATUS, FAILED_STATUS) class _ExecutionContext(threading.local): """ Call stack-based context, storing the current L{Action}. Bit like L{twisted.python.context}, but: - Single purpose. - Allows support for Python context managers (this could easily be added to Twisted, though). - Does not require Twisted; Eliot should not require Twisted if possible. """ def __init__(self): self._stack = [] def push(self, action): """ Push the given L{Action} to the front of the stack. @param action: L{Action} that will be used for log messages and as parent of newly created L{Action} instances. """ self._stack.append(action) def pop(self): """ Pop the front L{Action} on the stack. """ self._stack.pop(-1) def current(self): """ @return: The current front L{Action}, or C{None} if there is no L{Action} set. """ if not self._stack: return None return self._stack[-1] _context = _ExecutionContext() currentAction = _context.current class TaskLevel(PClass): """ The location of a message within the tree of actions of a task. @ivar level: A pvector of integers. Each item indicates a child relationship, and the value indicates message count. E.g. C{[2, 3]} indicates this is the third message within an action which is the second item in the task. """ level = pvector_field(int) # PClass really ought to provide this ordering facility for us: # tobgu/pyrsistent#45. def __lt__(self, other): return self.level < other.level def __le__(self, other): return self.level <= other.level def __gt__(self, other): return self.level > other.level def __ge__(self, other): return self.level >= other.level @classmethod def fromString(cls, string): """ Convert a serialized Unicode string to a L{TaskLevel}. @param string: Output of L{TaskLevel.toString}. @return: L{TaskLevel} parsed from the string. """ return cls(level=[int(i) for i in string.split("/") if i]) def toString(self): """ Convert to a Unicode string, for serialization purposes. @return: L{unicode} representation of the L{TaskLevel}. """ return "/" + "/".join(map(unicode, self.level)) def next_sibling(self): """ Return the next L{TaskLevel}, that is a task at the same level as this one, but one after. @return: L{TaskLevel} which follows this one. """ return TaskLevel(level=self.level.set(-1, self.level[-1] + 1)) def child(self): """ Return a child of this L{TaskLevel}. @return: L{TaskLevel} which is the first child of this one. """ return TaskLevel(level=self.level.append(1)) def parent(self): """ Return the parent of this L{TaskLevel}, or C{None} if it doesn't have one. @return: L{TaskLevel} which is the parent of this one. """ if not self.level: return None return TaskLevel(level=self.level[:-1]) def is_sibling_of(self, task_level): """ Is this task a sibling of C{task_level}? """ return self.parent() == task_level.parent() # PEP 8 compatibility: from_string = fromString to_string = toString _TASK_ID_NOT_SUPPLIED = object() class Action(object): """ Part of a nested heirarchy of ongoing actions. An action has a start and an end; a message is logged for each. Actions should only be used from a single thread, by implication the thread where they were created. @ivar _identification: Fields identifying this action. @ivar _successFields: Fields to be included in successful finish message. @ivar _finished: L{True} if the L{Action} has finished, otherwise L{False}. """ def __init__(self, logger, task_uuid, task_level, action_type, serializers=None): """ Initialize the L{Action} and log the start message. You probably do not want to use this API directly: use L{startAction} or L{startTask} instead. @param logger: The L{eliot.ILogger} to which to write messages. @param task_uuid: The uuid of the top-level task, e.g. C{"123525"}. @param task_level: The action's level in the task. @type task_level: L{TaskLevel} @param action_type: The type of the action, e.g. C{"yourapp:subsystem:dosomething"}. @param serializers: Either a L{eliot._validation._ActionSerializers} instance or C{None}. In the latter case no validation or serialization will be done for messages generated by the L{Action}. """ self._numberOfMessages = iter(count()) self._successFields = {} self._logger = logger if isinstance(task_level, unicode): warn("Action should be initialized with a TaskLevel", DeprecationWarning, stacklevel=2) task_level = TaskLevel.fromString(task_level) self._task_level = task_level self._last_child = None self._identification = {TASK_UUID_FIELD: task_uuid, ACTION_TYPE_FIELD: action_type, } self._serializers = serializers self._finished = False def serializeTaskId(self): """ Create a unique identifier for the current location within the task. The format is C{b"@"}. @return: L{bytes} encoding the current location within the task. """ return "{}@{}".format(self._identification[TASK_UUID_FIELD], self._nextTaskLevel().toString()).encode("ascii") @classmethod def continueTask(cls, logger=None, task_id=_TASK_ID_NOT_SUPPLIED): """ Start a new action which is part of a serialized task. @param logger: The L{eliot.ILogger} to which to write messages, or C{None} if the default one should be used. @param task_id: A serialized task identifier, the output of L{Action.serialize_task_id}. Required. @return: The new L{Action} instance. """ if task_id is _TASK_ID_NOT_SUPPLIED: raise RuntimeError("You must supply a task_id keyword argument.") uuid, task_level = task_id.decode("ascii").split("@") action = cls(logger, uuid, TaskLevel.fromString(task_level), "eliot:remote_task") action._start({}) return action # PEP 8 variants: serialize_task_id = serializeTaskId continue_task = continueTask def _nextTaskLevel(self): """ Return the next C{task_level} for messages within this action. Called whenever a message is logged within the context of an action. @return: The message's C{task_level}. """ if not self._last_child: self._last_child = self._task_level.child() else: self._last_child = self._last_child.next_sibling() return self._last_child def _start(self, fields): """ Log the start message. The action identification fields, and any additional given fields, will be logged. In general you shouldn't call this yourself, instead using a C{with} block or L{Action.finish}. """ fields[ACTION_STATUS_FIELD] = STARTED_STATUS fields.update(self._identification) if self._serializers is None: serializer = None else: serializer = self._serializers.start Message(fields, serializer).write(self._logger, self) def finish(self, exception=None): """ Log the finish message. The action identification fields, and any additional given fields, will be logged. In general you shouldn't call this yourself, instead using a C{with} block or L{Action.finish}. @param exception: C{None}, in which case the fields added with L{Action.addSuccessFields} are used. Or an L{Exception}, in which case an C{"exception"} field is added with the given L{Exception} type and C{"reason"} with its contents. """ if self._finished: return self._finished = True serializer = None if exception is None: fields = self._successFields fields[ACTION_STATUS_FIELD] = SUCCEEDED_STATUS if self._serializers is not None: serializer = self._serializers.success else: fields = _error_extraction.get_fields_for_exception( self._logger, exception) fields[EXCEPTION_FIELD] = "%s.%s" % (exception.__class__.__module__, exception.__class__.__name__) fields[REASON_FIELD] = safeunicode(exception) fields[ACTION_STATUS_FIELD] = FAILED_STATUS if self._serializers is not None: serializer = self._serializers.failure fields.update(self._identification) Message(fields, serializer).write(self._logger, self) def child(self, logger, action_type, serializers=None): """ Create a child L{Action}. Rather than calling this directly, you can use L{startAction} to create child L{Action} using the execution context. @param logger: The L{eliot.ILogger} to which to write messages. @param action_type: The type of this action, e.g. C{"yourapp:subsystem:dosomething"}. @param serializers: Either a L{eliot._validation._ActionSerializers} instance or C{None}. In the latter case no validation or serialization will be done for messages generated by the L{Action}. """ newLevel = self._nextTaskLevel() return self.__class__(logger, self._identification[TASK_UUID_FIELD], newLevel, action_type, serializers) def run(self, f, *args, **kwargs): """ Run the given function with this L{Action} as its execution context. """ _context.push(self) try: return f(*args, **kwargs) finally: _context.pop() def addSuccessFields(self, **fields): """ Add fields to be included in the result message when the action finishes successfully. @param fields: Additional fields to add to the result message. """ self._successFields.update(fields) # PEP 8 variant: add_success_fields = addSuccessFields @contextmanager def context(self): """ Create a context manager that ensures code runs within action's context. The action does NOT finish when the context is exited. """ _context.push(self) try: yield finally: _context.pop() # Python context manager implementation: def __enter__(self): """ Push this action onto the execution context. """ _context.push(self) return self def __exit__(self, type, exception, traceback): """ Pop this action off the execution context, log finish message. """ _context.pop() self.finish(exception) class WrongTask(Exception): """ Tried to add a message to an action, but the message was from another task. """ def __init__(self, action, message): Exception.__init__( self, 'Tried to add {} to {}. Expected task_uuid = {}, got {}'.format( message, action, action.task_uuid, message.task_uuid)) class WrongTaskLevel(Exception): """ Tried to add a message to an action, but the task level of the message indicated that it was not a direct child. """ def __init__(self, action, message): Exception.__init__( self, 'Tried to add {} to {}, but {} is not a sibling of {}'.format( message, action, message.task_level, action.task_level)) class WrongActionType(Exception): """ Tried to end a message with a different action_type than the beginning. """ def __init__(self, action, message): error_msg = 'Tried to end {} with {}. Expected action_type = {}, got {}' Exception.__init__( self, error_msg.format( action, message, action.action_type, message.contents.get(ACTION_TYPE_FIELD, ''))) class InvalidStatus(Exception): """ Tried to end a message with an invalid status. """ def __init__(self, action, message): error_msg = 'Tried to end {} with {}. Expected status {} or {}, got {}' Exception.__init__( self, error_msg.format( action, message, SUCCEEDED_STATUS, FAILED_STATUS, message.contents.get(ACTION_STATUS_FIELD, ''))) class DuplicateChild(Exception): """ Tried to add a child to an action that already had a child at that task level. """ def __init__(self, action, message): Exception.__init__( self, 'Tried to add {} to {}, but already had child at {}'.format( message, action, message.task_level)) class InvalidStartMessage(Exception): """ Tried to start an action with an invalid message. """ def __init__(self, message, reason): Exception.__init__( self, 'Invalid start message {}: {}'.format(message, reason)) @classmethod def wrong_status(cls, message): return cls(message, 'must have status "STARTED"') @classmethod def wrong_task_level(cls, message): return cls(message, 'first message must have task level ending in 1') class WrittenAction(PClass): """ An Action that has been logged. This class is intended to provide a definition within Eliot of what an action actually is, and a means of constructing actions that are known to be valid. @ivar WrittenMessage start_message: A start message whose task UUID and level match this action, or C{None} if it is not yet set on the action. @ivar WrittenMessage end_message: An end message hose task UUID and level match this action. Can be C{None} if the action is unfinished. @ivar TaskLevel task_level: The action's task level, e.g. if start message has level C{[2, 3, 1]} it will be C{TaskLevel(level=[2, 3])}. @ivar UUID task_uuid: The UUID of the task to which this action belongs. @ivar _children: A L{pmap} from L{TaskLevel} to the L{WrittenAction} and L{WrittenMessage} objects that make up this action. """ start_message = field(type=optional(WrittenMessage), mandatory=True, initial=None) end_message = field(type=optional(WrittenMessage), mandatory=True, initial=None) task_level = field(type=TaskLevel, mandatory=True) task_uuid = field(type=unicode, mandatory=True, factory=unicode) # Pyrsistent doesn't support pmap_field with recursive types. _children = pmap_field(TaskLevel, object) @classmethod def from_messages(cls, start_message=None, children=pvector(), end_message=None): """ Create a C{WrittenAction} from C{WrittenMessage}s and other C{WrittenAction}s. @param WrittenMessage start_message: A message that has C{ACTION_STATUS_FIELD}, C{ACTION_TYPE_FIELD}, and a C{task_level} that ends in C{1}, or C{None} if unavailable. @param children: An iterable of C{WrittenMessage} and C{WrittenAction} @param WrittenMessage end_message: A message that has the same C{action_type} as this action. @raise WrongTask: If C{end_message} has a C{task_uuid} that differs from C{start_message.task_uuid}. @raise WrongTaskLevel: If any child message or C{end_message} has a C{task_level} that means it is not a direct child. @raise WrongActionType: If C{end_message} has an C{ACTION_TYPE_FIELD} that differs from the C{ACTION_TYPE_FIELD} of C{start_message}. @raise InvalidStatus: If C{end_message} doesn't have an C{action_status}, or has one that is not C{SUCCEEDED_STATUS} or C{FAILED_STATUS}. @raise InvalidStartMessage: If C{start_message} does not have a C{ACTION_STATUS_FIELD} of C{STARTED_STATUS}, or if it has a C{task_level} indicating that it is not the first message of an action. @return: A new C{WrittenAction}. """ actual_message = [message for message in [start_message, end_message] + list(children) if message][0] action = cls( task_level=actual_message.task_level.parent(), task_uuid=actual_message.task_uuid, ) if start_message: action = action._start(start_message) for child in children: if action._children.get(child.task_level, child) != child: raise DuplicateChild(action, child) action = action._add_child(child) if end_message: action = action._end(end_message) return action @property def action_type(self): """ The type of this action, e.g. C{"yourapp:subsystem:dosomething"}. """ if self.start_message: return self.start_message.contents[ACTION_TYPE_FIELD] elif self.end_message: return self.end_message.contents[ACTION_TYPE_FIELD] else: return None @property def status(self): """ One of C{STARTED_STATUS}, C{SUCCEEDED_STATUS}, C{FAILED_STATUS} or C{None}. """ message = self.end_message if self.end_message else self.start_message if message: return message.contents[ACTION_STATUS_FIELD] else: return None @property def start_time(self): """ The Unix timestamp of when the action started, or C{None} if there has been no start message added so far. """ if self.start_message: return self.start_message.timestamp @property def end_time(self): """ The Unix timestamp of when the action ended, or C{None} if there has been no end message. """ if self.end_message: return self.end_message.timestamp @property def exception(self): """ If the action failed, the name of the exception that was raised to cause it to fail. If the action succeeded, or hasn't finished yet, then C{None}. """ if self.end_message: return self.end_message.contents.get(EXCEPTION_FIELD, None) @property def reason(self): """ The reason the action failed. If the action succeeded, or hasn't finished yet, then C{None}. """ if self.end_message: return self.end_message.contents.get(REASON_FIELD, None) @property def children(self): """ The list of child messages and actions sorted by task level, excluding the start and end messages. """ return pvector(sorted(self._children.values(), key=lambda m: m.task_level)) def _validate_message(self, message): """ Is C{message} a valid direct child of this action? @param message: Either a C{WrittenAction} or a C{WrittenMessage}. @raise WrongTask: If C{message} has a C{task_uuid} that differs from the action's C{task_uuid}. @raise WrongTaskLevel: If C{message} has a C{task_level} that means it's not a direct child. """ if message.task_uuid != self.task_uuid: raise WrongTask(self, message) if not message.task_level.parent() == self.task_level: raise WrongTaskLevel(self, message) def _add_child(self, message): """ Return a new action with C{message} added as a child. Assumes C{message} is not an end message. @param message: Either a C{WrittenAction} or a C{WrittenMessage}. @raise WrongTask: If C{message} has a C{task_uuid} that differs from the action's C{task_uuid}. @raise WrongTaskLevel: If C{message} has a C{task_level} that means it's not a direct child. @return: A new C{WrittenAction}. """ self._validate_message(message) level = message.task_level return self.transform(('_children', level), message) def _start(self, start_message): """ Start this action given its start message. @param WrittenMessage start_message: A start message that has the same level as this action. @raise InvalidStartMessage: If C{start_message} does not have a C{ACTION_STATUS_FIELD} of C{STARTED_STATUS}, or if it has a C{task_level} indicating that it is not the first message of an action. """ if start_message.contents.get( ACTION_STATUS_FIELD, None) != STARTED_STATUS: raise InvalidStartMessage.wrong_status(start_message) if start_message.task_level.level[-1] != 1: raise InvalidStartMessage.wrong_task_level(start_message) return self.set(start_message=start_message) def _end(self, end_message): """ End this action with C{end_message}. Assumes that the action has not already been ended. @param WrittenMessage end_message: An end message that has the same level as this action. @raise WrongTask: If C{end_message} has a C{task_uuid} that differs from the action's C{task_uuid}. @raise WrongTaskLevel: If C{end_message} has a C{task_level} that means it's not a direct child. @raise InvalidStatus: If C{end_message} doesn't have an C{action_status}, or has one that is not C{SUCCEEDED_STATUS} or C{FAILED_STATUS}. @return: A new, completed C{WrittenAction}. """ action_type = end_message.contents.get(ACTION_TYPE_FIELD, None) if self.action_type not in (None, action_type): raise WrongActionType(self, end_message) self._validate_message(end_message) status = end_message.contents.get(ACTION_STATUS_FIELD, None) if status not in (FAILED_STATUS, SUCCEEDED_STATUS): raise InvalidStatus(self, end_message) return self.set(end_message=end_message) def startAction(logger=None, action_type="", _serializers=None, **fields): """ Create a child L{Action}, figuring out the parent L{Action} from execution context, and log the start message. You can use the result as a Python context manager, or use the L{Action.finish} API to explicitly finish it. with startAction(logger, "yourapp:subsystem:dosomething", entry=x) as action: do(x) result = something(x * 2) action.addSuccessFields(result=result) Or alternatively: action = startAction(logger, "yourapp:subsystem:dosomething", entry=x) with action.context(): do(x) result = something(x * 2) action.addSuccessFields(result=result) action.finish() @param logger: The L{eliot.ILogger} to which to write messages, or C{None} to use the default one. @param action_type: The type of this action, e.g. C{"yourapp:subsystem:dosomething"}. @param _serializers: Either a L{eliot._validation._ActionSerializers} instance or C{None}. In the latter case no validation or serialization will be done for messages generated by the L{Action}. @param fields: Additional fields to add to the start message. @return: A new L{Action}. """ parent = currentAction() if parent is None: return startTask(logger, action_type, _serializers, **fields) else: action = parent.child(logger, action_type, _serializers) action._start(fields) return action def startTask(logger=None, action_type=u"", _serializers=None, **fields): """ Like L{action}, but creates a new top-level L{Action} with no parent. @param logger: The L{eliot.ILogger} to which to write messages, or C{None} to use the default one. @param action_type: The type of this action, e.g. C{"yourapp:subsystem:dosomething"}. @param _serializers: Either a L{eliot._validation._ActionSerializers} instance or C{None}. In the latter case no validation or serialization will be done for messages generated by the L{Action}. @param fields: Additional fields to add to the start message. @return: A new L{Action}. """ action = Action(logger, unicode(uuid4()), TaskLevel(level=[]), action_type, _serializers) action._start(fields) return action class TooManyCalls(Exception): """ The callable was called more than once. This typically indicates a coding bug: the result of C{preserve_context} should only be called once, and C{preserve_context} should therefore be called each time you want to pass the callable to a thread. """ def preserve_context(f): """ Package up the given function with the current Eliot context, and then restore context and call given function when the resulting callable is run. This allows continuing the action context within a different thread. The result should only be used once, since it relies on L{Action.serialize_task_id} whose results should only be deserialized once. @param f: A callable. @return: One-time use callable that calls given function in context of a child of current Eliot action. """ action = currentAction() if action is None: return f task_id = action.serialize_task_id() called = threading.Lock() def restore_eliot_context(*args, **kwargs): # Make sure the function has not already been called: if not called.acquire(False): raise TooManyCalls(f) with Action.continue_task(task_id=task_id): return f(*args, **kwargs) return restore_eliot_context PKYuAGeP{ eliot/filter.py""" Command line program for filtering line-based Eliot logs. """ from __future__ import unicode_literals, absolute_import if __name__ == '__main__': import eliot.filter eliot.filter.main() import sys from datetime import datetime, timedelta from . import _bytesjson as json class _JSONEncoder(json.JSONEncoder): """ JSON encoder that supports L{datetime}. """ def default(self, o): if isinstance(o, datetime): return o.isoformat() return json.JSONEncoder.default(self, o) _encoder = _JSONEncoder() class EliotFilter(object): """ Filter Eliot log lines using a Python expression. @ivar code: A Python code object, the compiled filter expression. """ _SKIP = object() def __init__(self, expr, incoming, output): """ @param expr: A Python expression that will be called for each log message. @type expr: L{str} @param incoming: An iterable of L{bytes}, each of which is a serialized Eliot message. @param output: A file to which output should be written. @type output: L{file} or a file-like object. """ self.code = compile(expr, "", "eval") self.incoming = incoming self.output = output def run(self): """ For each incoming message, decode the JSON, evaluate expression, encode as JSON and write that to the output file. """ for line in self.incoming: message = json.loads(line) result = self._evaluate(message) if result is self._SKIP: continue self.output.write(_encoder.encode(result).encode("utf-8") + b"\n") def _evaluate(self, message): """ Evaluate the expression with the given Python object in its locals. @param message: A decoded JSON input. @return: The resulting object. """ return eval(self.code, globals(), {"J": message, "timedelta": timedelta, "datetime": datetime, "SKIP": self._SKIP}) USAGE = b"""\ Usage: cat eliot.log | python -m eliot.filter Read JSON-expression per line from stdin, and filter it using a Python expression . The expression will have a local `J` containing decoded JSON. `datetime` and `timedelta` from Python's `datetime` module are also available as locals, containing the corresponding classes. `SKIP` is also available, if it's the expression result that indicates nothing should be output. The output will be written to stdout using JSON serialization. `datetime` objects will be serialized to ISO format. Examples: - Pass through the messages unchanged: $ cat eliot.log | python -m eliot.filter J - Retrieve a specific field from a specific message type, dropping messages of other types: $ cat eliot.log | python -m eliot.filter \\ "J['field'] if J.get('message_type') == 'my:message' else SKIP" """ def main(sys=sys): """ Run the program. Accept arguments from L{sys.argv}, read from L{sys.stdin}, write to L{sys.stdout}. @param sys: An object with same interface and defaulting to the L{sys} module. """ if len(sys.argv) != 2: sys.stderr.write(USAGE) return 1 EliotFilter(sys.argv[1], sys.stdin, sys.stdout).run() return 0 PKG/eliot/_util.py""" Utilities that don't go anywhere else. """ from __future__ import unicode_literals from types import ModuleType from six import exec_, text_type as unicode def safeunicode(o): """ Like C{unicode()}, but catches and swallows any raised exceptions. @param o: An object of some sort. @return: C{unicode(o)}, or an error message if that failed. @rtype: C{unicode} """ try: return unicode(o) except: # Not much we can do about this... return "eliot: unknown, unicode() raised exception" def saferepr(o): """ Like C{unicode(repr())}, but catches and swallows any raised exceptions. @param o: An object of some sort. @return: C{unicode(repr(o))}, or an error message if that failed. @rtype: C{unicode} """ try: return unicode(repr(o)) except: # Not much we can do about this... return "eliot: unknown, unicode() raised exception" def load_module(name, original_module): """ Load a copy of a module, distinct from what you'd get if you imported it directly. @param str name: The name of the new module. @param original_module: The original module we're recreating. @return: A new, distinct module. """ module = ModuleType(name) path = original_module.__file__ if path.endswith(".pyc") or path.endswith(".pyo"): path = path[:-1] with open(path) as f: exec_(f.read(), module.__dict__, module.__dict__) return module PKæGxa eliot/tests/test_api.py""" Tests for the public API exposed by L{eliot}. """ from __future__ import unicode_literals from unittest import TestCase from .._output import Logger import eliot class PublicAPITests(TestCase): """ Tests for the public API. """ def test_addDestination(self): """ L{eliot.addDestination} adds destinations to the L{Destinations} attached to L{Logger}. """ self.assertEqual(eliot.addDestination, Logger._destinations.add) def test_removeDestination(self): """ L{eliot.addDestination} removes destinations from the L{Destinations} attached to L{Logger}. """ self.assertEqual(eliot.removeDestination, Logger._destinations.remove) def test_addGlobalFields(self): """ L{eliot.addGlobalFields} calls the corresponding method on the L{Destinations} attached to L{Logger}. """ self.assertEqual(eliot.addGlobalFields, Logger._destinations.addGlobalFields) class PEP8Tests(TestCase): """ Tests for the PEP 8 variant of the the public API. """ def test_add_destination(self): """ L{eliot.addDestionation} is the same as L{eliot.add_destination}. """ self.assertIs(eliot.add_destination, eliot.addDestination) def test_remove_destination(self): """ L{eliot.removeDestionation} is the same as L{eliot.remove_destination}. """ self.assertIs(eliot.remove_destination, eliot.removeDestination) def test_add_global_fields(self): """ L{eliot.add_global_fields} is the same as L{eliot.addGlobalFields}. """ self.assertIs(eliot.add_global_fields, eliot.addGlobalFields) def test_write_traceback(self): """ L{eliot.writeTraceback} is the same as L{eliot.write_traceback}. """ self.assertIs(eliot.write_traceback, eliot.writeTraceback) def test_write_failure(self): """ L{eliot.writeFailure} is the same as L{eliot.write_failure}. """ self.assertIs(eliot.write_failure, eliot.writeFailure) def test_start_task(self): """ L{eliot.startTask} is the same as L{eliot.start_task}. """ self.assertIs(eliot.start_task, eliot.startTask) def test_start_action(self): """ L{eliot.startAction} is the same as L{eliot.start_action}. """ self.assertIs(eliot.start_action, eliot.startAction) PK⡁G{==eliot/tests/strategies.py""" Hypothesis strategies for eliot. """ from __future__ import unicode_literals from functools import partial from six import text_type as unicode from hypothesis.strategies import ( builds, dictionaries, fixed_dictionaries, floats, integers, lists, just, none, one_of, recursive, text, uuids, ) from pyrsistent import pmap, pvector, ny, thaw from .._action import ( ACTION_STATUS_FIELD, ACTION_TYPE_FIELD, FAILED_STATUS, STARTED_STATUS, SUCCEEDED_STATUS, TaskLevel, WrittenAction) from .._message import ( EXCEPTION_FIELD, REASON_FIELD, TASK_LEVEL_FIELD, TASK_UUID_FIELD, WrittenMessage) task_level_indexes = integers(min_value=1) # Task levels can be arbitrarily deep, but in the wild rarely as much as 100. # Five seems a sensible average. task_level_lists = lists(task_level_indexes, min_size=1, average_size=5) task_levels = task_level_lists.map(lambda level: TaskLevel(level=level)) # Text generation is slow, and most of the things are short labels. We set # a restricted alphabet so they're easier to read, and in general large # amount of randomness in label generation doesn't enhance our testing in # any way, since we don't parse type names or user field values. labels = text(average_size=3, min_size=1, alphabet="CGAT") timestamps = floats(min_value=0) message_core_dicts = fixed_dictionaries( dict(task_level=task_level_lists.map(pvector), task_uuid=uuids().map(unicode), timestamp=timestamps)).map(pmap) # Text generation is slow. We can make it faster by not generating so # much. These are reasonable values. message_data_dicts = dictionaries( keys=labels, values=labels, # People don't normally put much more than twenty fields in their # messages, surely? average_size=10, ).map(pmap) def written_from_pmap(d): """ Convert a C{pmap} to a C{WrittenMessage}. """ return WrittenMessage.from_dict(thaw(d)) def union(*dicts): result = pmap().evolver() for d in dicts: # Work around bug in pyrsistent where it sometimes loses updates if # they contain some kv pairs that are identical to the ones in the # dict being updated. # # https://github.com/tobgu/pyrsistent/pull/54 for key, value in d.items(): if key in result and result[key] is value: continue result[key] = value return result.persistent() message_dicts = builds(union, message_data_dicts, message_core_dicts) written_messages = message_dicts.map(written_from_pmap) _start_action_fields = fixed_dictionaries( { ACTION_STATUS_FIELD: just(STARTED_STATUS), ACTION_TYPE_FIELD: labels, }) start_action_message_dicts = builds( union, message_dicts, _start_action_fields).map( lambda x: x.update({TASK_LEVEL_FIELD: x[TASK_LEVEL_FIELD].set(-1, 1)})) start_action_messages = start_action_message_dicts.map( written_from_pmap) def sibling_task_level(message, n): return message.task_level.parent().level.append(n) _end_action_fields = one_of( just({ACTION_STATUS_FIELD: SUCCEEDED_STATUS}), fixed_dictionaries({ ACTION_STATUS_FIELD: just(FAILED_STATUS), # Text generation is slow. We can make it faster by not generating so # much. Thqese are reasonable values. EXCEPTION_FIELD: labels, REASON_FIELD: labels, }), ) def _make_written_action(start_message, child_messages, end_message_dict): """ Helper for creating arbitrary L{WrittenAction}s. The child messages and end message (if provided) will be updated to have the same C{task_uuid} as C{start_message}. Likewise, their C{task_level}s will be such that they follow on from C{start_message}. @param WrittenMessage start_message: The message to start the action with. @param child_messages: A sequence of L{WrittenAction}s and L{WrittenMessage}s that make up the action. @param (PMap | None) end_message_dict: A dictionary that makes up an end message. If None, then the action is unfinished. @return: A L{WrittenAction} """ task_uuid = start_message.task_uuid children = [] for i, child in enumerate(child_messages, 2): task_level = TaskLevel(level=sibling_task_level(start_message, i)) children.append(reparent_action(task_uuid, task_level, child)) if end_message_dict: end_message = written_from_pmap( union(end_message_dict, { ACTION_TYPE_FIELD: start_message.contents[ACTION_TYPE_FIELD], TASK_UUID_FIELD: task_uuid, TASK_LEVEL_FIELD: sibling_task_level( start_message, 2 + len(children)), }) ) else: end_message = None return WrittenAction.from_messages(start_message, children, end_message) written_actions = recursive( written_messages, lambda children: builds( _make_written_action, start_message=start_action_messages, child_messages=lists(children, average_size=5), end_message_dict=builds( union, message_dicts, _end_action_fields) | none(), ), ) def _map_messages(f, written_action): """ Map C{f} across all of the messages that make up C{written_action}. This is a structure-preserving map operation. C{f} will be applied to all messages that make up C{written_action}: the start message, end message, and children. If any of the children are themselves L{WrittenAction}s, we recurse down into them. @param f: A function that takes a L{WrittenMessage} and returns a new L{WrittenMessage}. @param (WrittenAction | WrittenMessage) written_action: A written @return: A L{WrittenMessage} if C{written_action} is a C{WrittenMessage}, a L{WrittenAction} otherwise. """ if isinstance(written_action, WrittenMessage): return f(written_action) start_message = f(written_action.start_message) children = written_action.children.transform([ny], partial(_map_messages, f)) if written_action.end_message: end_message = f(written_action.end_message) else: end_message = None return WrittenAction.from_messages( start_message=start_message, children=pvector(children), end_message=end_message, ) def reparent_action(task_uuid, task_level, written_action): """ Return a version of C{written_action} that has the given C{task_uuid} and is rooted at the given C{task_level}. @param UUID task_uuid: The new task UUID. @param TaskLevel task_level: The new task level. @param (WrittenAction | WrittenMessage) written_action: The action or message to update. @return: A new version of C{written_action}. """ new_prefix = list(task_level.level) old_prefix_len = len(written_action.task_level.level) def fix_message(message): return ( message.transform( ['_logged_dict', TASK_LEVEL_FIELD], lambda level: new_prefix + level[old_prefix_len:]) .transform(['_logged_dict', TASK_UUID_FIELD], task_uuid)) return _map_messages(fix_message, written_action) PKæG2NNeliot/tests/test_twisted.py""" Tests for L{eliot.twisted}. """ from __future__ import absolute_import, unicode_literals, print_function import traceback import sys from functools import wraps import json try: from twisted.internet.defer import Deferred, succeed, fail from twisted.trial.unittest import TestCase from twisted.python.failure import Failure from twisted.python.log import LogPublisher, textFromEventDict from twisted.python import log as twlog except ImportError: # Make tests not run at all. TestCase = object else: # Make sure we always import this if Twisted is available, so broken # logwriter.py causes a failure: from ..twisted import ( DeferredContext, AlreadyFinished, _passthrough, redirectLogsForTrial, _RedirectLogsForTrial) from .._action import startAction, currentAction, Action, TaskLevel from .._output import MemoryLogger, Logger from .._message import Message from ..testing import assertContainsFields from .. import removeDestination, addDestination from .._traceback import writeTraceback from .common import FakeSys class PassthroughTests(TestCase): """ Tests for L{_passthrough}. """ def test_passthrough(self): """ L{_passthrough} returns the passed-in value. """ obj = object() self.assertIs(obj, _passthrough(obj)) def withActionContext(f): """ Decorator that calls a function with an action context. @param f: A function. """ logger = MemoryLogger() action = startAction(logger, "test") @wraps(f) def test(self): with action.context(): return f(self) return test class DeferredContextTests(TestCase): """ Tests for L{DeferredContext}. """ def test_requireContext(self): """ L{DeferredContext} raises a L{RuntimeError} if it is called without an action context. """ self.assertRaises(RuntimeError, DeferredContext, Deferred()) @withActionContext def test_result(self): """ The passed-in L{Deferred} is available as the L{DeferredContext}'s C{result} attribute. """ result = Deferred() context = DeferredContext(result) self.assertIs(context.result, result) @withActionContext def test_addCallbacksCallbackToDeferred(self): """ L{DeferredContext.addCallbacks} passes the given callback and its corresponding arguments to the wrapped L{Deferred}'s C{addCallbacks}. """ called = [] def f(value, x, y): called.append((value, x, y)) result = Deferred() context = DeferredContext(result) context.addCallbacks(f, lambda x: None, (1,), {"y": 2}) result.callback(0) self.assertEqual(called, [(0, 1, 2)]) @withActionContext def test_addCallbacksErrbackToDeferred(self): """ L{DeferredContext.addCallbacks} passes the given errback and its corresponding arguments to the wrapped L{Deferred}'s C{addCallbacks}. """ called = [] def f(value, x, y): value.trap(RuntimeError) called.append((x, y)) result = Deferred() context = DeferredContext(result) context.addCallbacks(lambda x: None, f, None, None, (1,), {"y": 2}) result.errback(RuntimeError()) self.assertEqual(called, [(1, 2)]) @withActionContext def test_addCallbacksReturnSelf(self): """ L{DeferredContext.addCallbacks} returns the L{DeferredContext}. """ result = Deferred() context = DeferredContext(result) self.assertIs(context, context.addCallbacks( lambda x: None, lambda x: None)) def test_addCallbacksCallbackContext(self): """ L{DeferedContext.addCallbacks} adds a callback that runs in context of action that the L{DeferredContext} was created with. """ logger = MemoryLogger() action1 = startAction(logger, "test") action2 = startAction(logger, "test") context = [] d = succeed(None) with action1.context(): d = DeferredContext(d) with action2.context(): d.addCallbacks(lambda x: context.append(currentAction()), lambda x: x) self.assertEqual(context, [action1]) def test_addCallbacksErrbackContext(self): """ L{DeferedContext.addCallbacks} adds an errback that runs in context of action that the L{DeferredContext} was created with. """ logger = MemoryLogger() action1 = startAction(logger, "test") action2 = startAction(logger, "test") context = [] d = fail(RuntimeError()) with action1.context(): d = DeferredContext(d) with action2.context(): d.addCallbacks(lambda x: x, lambda x: context.append(currentAction())) self.assertEqual(context, [action1]) @withActionContext def test_addCallbacksCallbackResult(self): """ A callback added with DeferredContext.addCallbacks has its result passed on to the next callback. """ d = succeed(0) d = DeferredContext(d) d.addCallbacks(lambda x: [x, 1], lambda x: x) self.assertEqual(self.successResultOf(d), [0, 1]) @withActionContext def test_addCallbacksErrbackResult(self): """ An errback added with DeferredContext.addCallbacks has its result passed on to the next callback. """ exception = ZeroDivisionError() d = fail(exception) d = DeferredContext(d) d.addCallbacks(lambda x: x, lambda x: [x.value, 1]) self.assertEqual(self.successResultOf(d), [exception, 1]) def test_addActionFinishNoImmediateLogging(self): """ L{DeferredContext.addActionFinish} does not log anything if the L{Deferred} hasn't fired yet. """ d = Deferred() logger = MemoryLogger() action = Action(logger, "uuid", TaskLevel(level=[1]), "sys:me") with action.context(): DeferredContext(d).addActionFinish() self.assertFalse(logger.messages) def test_addActionFinishSuccess(self): """ When the L{Deferred} referred to by L{DeferredContext.addActionFinish} fires successfully, a finish message is logged. """ d = Deferred() logger = MemoryLogger() action = Action(logger, "uuid", TaskLevel(level=[1]), "sys:me") with action.context(): DeferredContext(d).addActionFinish() d.callback("result") assertContainsFields(self, logger.messages[0], {"task_uuid": "uuid", "task_level": [1, 1], "action_type": "sys:me", "action_status": "succeeded"}) def test_addActionFinishSuccessPassThrough(self): """ L{DeferredContext.addActionFinish} passes through a successful result unchanged. """ d = Deferred() logger = MemoryLogger() action = Action(logger, "uuid", TaskLevel(level=[1]), "sys:me") with action.context(): DeferredContext(d).addActionFinish() d.callback("result") result = [] d.addCallback(result.append) self.assertEqual(result, ["result"]) def test_addActionFinishFailure(self): """ When the L{Deferred} referred to in L{DeferredContext.addActionFinish} fires with an exception, a finish message is logged. """ d = Deferred() logger = MemoryLogger() action = Action(logger, "uuid", TaskLevel(level=[1]), "sys:me") with action.context(): DeferredContext(d).addActionFinish() exception = RuntimeError("because") d.errback(exception) assertContainsFields(self, logger.messages[0], {"task_uuid": "uuid", "task_level": [1, 1], "action_type": "sys:me", "action_status": "failed", "reason": "because", "exception": "%s.RuntimeError" % (RuntimeError.__module__,)}) d.addErrback(lambda _: None) # don't let Failure go to Twisted logs def test_addActionFinishFailurePassThrough(self): """ L{DeferredContext.addActionFinish} passes through a failed result unchanged. """ d = Deferred() logger = MemoryLogger() action = Action(logger, "uuid", TaskLevel(level=[1]), "sys:me") with action.context(): DeferredContext(d).addActionFinish() failure = Failure(RuntimeError()) d.errback(failure) result = [] d.addErrback(result.append) self.assertEqual(result, [failure]) @withActionContext def test_addActionFinishRaisesAfterAddActionFinish(self): """ After L{DeferredContext.addActionFinish} is called, additional calls to L{DeferredContext.addActionFinish} result in a L{AlreadyFinished} exception. """ d = DeferredContext(Deferred()) d.addActionFinish() self.assertRaises(AlreadyFinished, d.addActionFinish) @withActionContext def test_addCallbacksRaisesAfterAddActionFinish(self): """ After L{DeferredContext.addActionFinish} is called, additional calls to L{DeferredContext.addCallbacks} result in a L{AlreadyFinished} exception. """ d = DeferredContext(Deferred()) d.addActionFinish() self.assertRaises(AlreadyFinished, d.addCallbacks, lambda x: x, lambda x: x) @withActionContext def test_addActionFinishResult(self): """ L{DeferredContext.addActionFinish} returns the L{Deferred}. """ d = Deferred() self.assertIs(d, DeferredContext(d).addActionFinish()) # Having made sure DeferredContext.addCallbacks does the right thing # regarding action contexts, for addCallback/addErrback/addBoth we only # need to ensure that they call DeferredContext.addCallbacks. @withActionContext def test_addCallbackCallsAddCallbacks(self): """ L{DeferredContext.addCallback} passes its arguments on to L{DeferredContext.addCallbacks}. """ result = Deferred() context = DeferredContext(result) called = [] def addCallbacks(callback, errback, callbackArgs=None, callbackKeywords=None, errbackArgs=None, errbackKeywords=None): called.append((callback, errback, callbackArgs, callbackKeywords, errbackArgs, errbackKeywords)) context.addCallbacks = addCallbacks f = lambda x, y, z: None context.addCallback(f, 2, z=3) self.assertEqual(called, [(f, _passthrough, (2,), {"z": 3}, None, None)]) @withActionContext def test_addCallbackReturnsSelf(self): """ L{DeferredContext.addCallback} returns the L{DeferredContext}. """ result = Deferred() context = DeferredContext(result) self.assertIs(context, context.addCallback(lambda x: None)) @withActionContext def test_addErrbackCallsAddCallbacks(self): """ L{DeferredContext.addErrback} passes its arguments on to L{DeferredContext.addCallbacks}. """ result = Deferred() context = DeferredContext(result) called = [] def addCallbacks(callback, errback, callbackArgs=None, callbackKeywords=None, errbackArgs=None, errbackKeywords=None): called.append((callback, errback, callbackArgs, callbackKeywords, errbackArgs, errbackKeywords)) context.addCallbacks = addCallbacks f = lambda x, y, z: None context.addErrback(f, 2, z=3) self.assertEqual(called, [(_passthrough, f, None, None, (2,), {"z": 3})]) @withActionContext def test_addErrbackReturnsSelf(self): """ L{DeferredContext.addErrback} returns the L{DeferredContext}. """ result = Deferred() context = DeferredContext(result) self.assertIs(context, context.addErrback(lambda x: None)) @withActionContext def test_addBothCallsAddCallbacks(self): """ L{DeferredContext.addBoth} passes its arguments on to L{DeferredContext.addCallbacks}. """ result = Deferred() context = DeferredContext(result) called = [] def addCallbacks(callback, errback, callbackArgs=None, callbackKeywords=None, errbackArgs=None, errbackKeywords=None): called.append((callback, errback, callbackArgs, callbackKeywords, errbackArgs, errbackKeywords)) context.addCallbacks = addCallbacks f = lambda x, y, z: None context.addBoth(f, 2, z=3) self.assertEqual(called, [(f, f, (2,), {"z": 3}, (2,), {"z": 3})]) @withActionContext def test_addBothReturnsSelf(self): """ L{DeferredContext.addBoth} returns the L{DeferredContext}. """ result = Deferred() context = DeferredContext(result) self.assertIs(context, context.addBoth(lambda x: None)) class RedirectLogsForTrialTests(TestCase): """ Tests for L{redirectLogsForTrial}. """ def assertDestinationAdded(self, programPath): """ Assert that when running under the given program a new destination is added by L{redirectLogsForTrial}. @param programPath: A path to a program. @type programPath: L{str} """ destination = _RedirectLogsForTrial(FakeSys([programPath], b""), LogPublisher())() # If this was not added as destination, removing it will raise an # exception: try: removeDestination(destination) except ValueError: self.fail("Destination was not added.") def test_withTrial(self): """ When C{sys.argv[0]} is C{"trial"} a new destination is added by L{redirectLogsForTrial}. """ self.assertDestinationAdded("trial") def test_withAbsoluteTrialPath(self): """ When C{sys.argv[0]} is an absolute path ending with C{"trial"} a new destination is added by L{redirectLogsForTrial}. """ self.assertDestinationAdded("/usr/bin/trial") def test_withRelativeTrialPath(self): """ When C{sys.argv[0]} is a relative path ending with C{"trial"} a new destination is added by L{redirectLogsForTrial}. """ self.assertDestinationAdded("./trial") def test_withoutTrialNoDestination(self): """ When C{sys.argv[0]} is not C{"trial"} no destination is added by L{redirectLogsForTrial}. """ originalDestinations = Logger._destinations._destinations[:] _RedirectLogsForTrial(FakeSys(["myprogram.py"], b""), LogPublisher())() self.assertEqual(Logger._destinations._destinations, originalDestinations) def test_trialAsPathNoDestination(self): """ When C{sys.argv[0]} has C{"trial"} as directory name but not program name no destination is added by L{redirectLogsForTrial}. """ originalDestinations = Logger._destinations._destinations[:] _RedirectLogsForTrial(FakeSys(["./trial/myprogram.py"], b""), LogPublisher())() self.assertEqual(Logger._destinations._destinations, originalDestinations) def test_withoutTrialResult(self): """ When not running under I{trial} L{None} is returned. """ self.assertIs( None, _RedirectLogsForTrial(FakeSys(["myprogram.py"], b""), LogPublisher())()) def test_noDuplicateAdds(self): """ If a destination has already been added, calling L{redirectLogsForTrial} a second time does not add another destination. """ redirect = _RedirectLogsForTrial(FakeSys(["trial"], b""), LogPublisher()) destination = redirect() self.addCleanup(removeDestination, destination) originalDestinations = Logger._destinations._destinations[:] redirect() self.assertEqual(Logger._destinations._destinations, originalDestinations) def test_noDuplicateAddsResult(self): """ If a destination has already been added, calling L{redirectLogsForTrial} a second time returns L{None}. """ redirect = _RedirectLogsForTrial(FakeSys(["trial"], b""), LogPublisher()) destination = redirect() self.addCleanup(removeDestination, destination) result = redirect() self.assertIs(result, None) def redirectToLogPublisher(self): """ Redirect Eliot logs to a Twisted log publisher. @return: L{list} of L{str} - the written, formatted Twisted log messages will eventually be added to it. """ written = [] publisher = LogPublisher() publisher.addObserver(lambda m: written.append(textFromEventDict(m))) destination = _RedirectLogsForTrial(FakeSys(["trial"], b""), publisher)() self.addCleanup(removeDestination, destination) return written def redirectToList(self): """ Redirect Eliot logs to a list. @return: L{list} that will have eventually have the written Eliot messages added to it. """ written = [] destination = written.append addDestination(destination) self.addCleanup(removeDestination, destination) return written def test_normalMessages(self): """ Regular eliot messages are pretty-printed to the given L{LogPublisher}. """ writtenToTwisted = self.redirectToLogPublisher() written = self.redirectToList() logger = Logger() Message.new(x=123, y=456).write(logger) self.assertEqual(writtenToTwisted, ["ELIOT: %s" % (json.dumps(written[0]),)]) def test_tracebackMessages(self): """ Traceback eliot messages are written to the given L{LogPublisher} with the traceback formatted for easier reading. """ writtenToTwisted = self.redirectToLogPublisher() written = self.redirectToList() logger = Logger() def raiser(): raise RuntimeError("because") try: raiser() except Exception: expectedTraceback = traceback.format_exc() writeTraceback(logger) lines = expectedTraceback.split("\n") # Remove source code lines: expectedTraceback = "\n".join( [l for l in lines if not l.startswith(" ")]) self.assertEqual(writtenToTwisted, ["ELIOT: %s" % (json.dumps(written[0]),), "ELIOT Extracted Traceback:\n%s" % (expectedTraceback,) ]) def test_publicAPI(self): """ L{redirectLogsForTrial} is an instance of L{_RedirectLogsForTrial}. """ self.assertIsInstance(redirectLogsForTrial, _RedirectLogsForTrial) def test_defaults(self): """ By default L{redirectLogsForTrial} looks at L{sys.argv} and L{twisted.python.log} for trial detection and log output. """ self.assertEqual((redirectLogsForTrial._sys, redirectLogsForTrial._log), (sys, twlog)) PKGB6eliot/tests/test_action.py""" Tests for L{eliot._action}. """ from __future__ import unicode_literals from unittest import TestCase from threading import Thread from warnings import catch_warnings, simplefilter from hypothesis import assume, given, Settings from hypothesis.strategies import ( integers, lists, just, text, ) from pyrsistent import pvector, v import testtools from testtools.matchers import MatchesStructure from .._action import ( Action, _ExecutionContext, currentAction, startTask, startAction, ACTION_STATUS_FIELD, ACTION_TYPE_FIELD, FAILED_STATUS, STARTED_STATUS, SUCCEEDED_STATUS, DuplicateChild, InvalidStartMessage, InvalidStatus, TaskLevel, WrittenAction, WrongActionType, WrongTask, WrongTaskLevel, TooManyCalls) from .._message import ( EXCEPTION_FIELD, REASON_FIELD, TASK_LEVEL_FIELD, TASK_UUID_FIELD, MESSAGE_TYPE_FIELD, Message, ) from .._output import MemoryLogger from .._validation import ActionType, Field, _ActionSerializers from ..testing import assertContainsFields, capture_logging from .._parse import Parser from .. import ( _action, add_destination, remove_destination, register_exception_extractor, preserve_context, ) from .strategies import ( message_dicts, start_action_message_dicts, start_action_messages, task_level_indexes, task_level_lists, written_actions, written_messages, reparent_action, sibling_task_level, union, written_from_pmap, ) class ExecutionContextTests(TestCase): """ Tests for L{_ExecutionContext}. """ def test_nothingPushed(self): """ If no action has been pushed, L{_ExecutionContext.current} returns C{None}. """ ctx = _ExecutionContext() self.assertIs(ctx.current(), None) def test_pushSingle(self): """ L{_ExecutionContext.current} returns the action passed to L{_ExecutionContext.push} (assuming no pops). """ ctx = _ExecutionContext() a = object() ctx.push(a) self.assertIs(ctx.current(), a) def test_pushMultiple(self): """ L{_ExecutionContext.current} returns the action passed to the last call to L{_ExecutionContext.push} (assuming no pops). """ ctx = _ExecutionContext() a = object() b = object() ctx.push(a) ctx.push(b) self.assertIs(ctx.current(), b) def test_multipleCurrent(self): """ Multiple calls to L{_ExecutionContext.current} return the same result. """ ctx = _ExecutionContext() a = object() ctx.push(a) ctx.current() self.assertIs(ctx.current(), a) def test_popSingle(self): """ L{_ExecutionContext.pop} cancels a L{_ExecutionContext.push}, leading to an empty context. """ ctx = _ExecutionContext() a = object() ctx.push(a) ctx.pop() self.assertIs(ctx.current(), None) def test_popMultiple(self): """ L{_ExecutionContext.pop} cancels the last L{_ExecutionContext.push}, resulting in current context being whatever was pushed before that. """ ctx = _ExecutionContext() a = object() b = object() ctx.push(a) ctx.push(b) ctx.pop() self.assertIs(ctx.current(), a) def test_threadStart(self): """ Each thread starts with an empty execution context. """ ctx = _ExecutionContext() first = object() ctx.push(first) valuesInThread = [] def inthread(): valuesInThread.append(ctx.current()) thread = Thread(target=inthread) thread.start() thread.join() self.assertEqual(valuesInThread, [None]) def test_threadSafety(self): """ Each thread gets its own execution context. """ ctx = _ExecutionContext() first = object() ctx.push(first) second = object() valuesInThread = [] def inthread(): ctx.push(second) valuesInThread.append(ctx.current()) thread = Thread(target=inthread) thread.start() thread.join() # Neither thread was affected by the other: self.assertEqual(valuesInThread, [second]) self.assertIs(ctx.current(), first) def test_globalInstance(self): """ A global L{_ExecutionContext} is exposed in the L{eliot._action} module. """ self.assertIsInstance(_action._context, _ExecutionContext) self.assertEqual(_action.currentAction, _action._context.current) class ActionTests(TestCase): """ Tests for L{Action}. """ def test_start(self): """ L{Action._start} logs an C{action_status="started"} message. """ logger = MemoryLogger() action = Action(logger, "unique", TaskLevel(level=[]), "sys:thename") action._start({"key": "value"}) assertContainsFields(self, logger.messages[0], {"task_uuid": "unique", "task_level": [1], "action_type": "sys:thename", "action_status": "started", "key": "value"}) def test_startMessageSerialization(self): """ The start message logged by L{Action._start} is created with the appropriate start message L{eliot._validation._MessageSerializer}. """ serializers = ActionType("sys:thename", [Field("key", lambda x: x, "")], [], "")._serializers class Logger(list): def write(self, msg, serializer): self.append(serializer) logger = Logger() action = Action(logger, "unique", TaskLevel(level=[]), "sys:thename", serializers) action._start({"key": "value"}) self.assertIs(logger[0], serializers.start) def test_child(self): """ L{Action.child} returns a new L{Action} with the given logger, system and name, and a task_uuid taken from the parent L{Action}. """ logger = MemoryLogger() action = Action(logger, "unique", TaskLevel(level=[]), "sys:thename") logger2 = MemoryLogger() child = action.child(logger2, "newsystem:newname") self.assertEqual([child._logger, child._identification, child._task_level], [logger2, {"task_uuid": "unique", "action_type": "newsystem:newname"}, TaskLevel(level=[1])]) def test_childLevel(self): """ Each call to L{Action.child} increments the new sub-level set on the child. """ logger = MemoryLogger() action = Action(logger, "unique", TaskLevel(level=[]), "sys:thename") child1 = action.child(logger, "newsystem:newname") child2 = action.child(logger, "newsystem:newname") child1_1 = child1.child(logger, "newsystem:other") self.assertEqual(child1._task_level, TaskLevel(level=[1])) self.assertEqual(child2._task_level, TaskLevel(level=[2])) self.assertEqual(child1_1._task_level, TaskLevel(level=[1, 1])) def test_childSerializers(self): """ L{Action.child} returns a new L{Action} with the serializers passed to it, rather than the parent's. """ logger = MemoryLogger() serializers = object() action = Action(logger, "unique", TaskLevel(level=[]), "sys:thename", serializers) childSerializers = object() child = action.child(logger, "newsystem:newname", childSerializers) self.assertIs(child._serializers, childSerializers) def test_run(self): """ L{Action.run} runs the given function with given arguments, returning its result. """ action = Action(None, "", TaskLevel(level=[]), "") def f(*args, **kwargs): return args, kwargs result = action.run(f, 1, 2, x=3) self.assertEqual(result, ((1, 2), {"x": 3})) def test_runContext(self): """ L{Action.run} runs the given function with the action set as the current action. """ result = [] action = Action(None, "", TaskLevel(level=[]), "") action.run(lambda: result.append(currentAction())) self.assertEqual(result, [action]) def test_runContextUnsetOnReturn(self): """ L{Action.run} unsets the action once the given function returns. """ action = Action(None, "", TaskLevel(level=[]), "") action.run(lambda: None) self.assertIs(currentAction(), None) def test_runContextUnsetOnRaise(self): """ L{Action.run} unsets the action once the given function raises an exception. """ action = Action(None, "", TaskLevel(level=[]), "") self.assertRaises(ZeroDivisionError, action.run, lambda: 1/0) self.assertIs(currentAction(), None) def test_withSetsContext(self): """ L{Action.__enter__} sets the action as the current action. """ action = Action(MemoryLogger(), "", TaskLevel(level=[]), "") with action: self.assertIs(currentAction(), action) def test_withUnsetOnReturn(self): """ L{Action.__exit__} unsets the action on successful block finish. """ action = Action(MemoryLogger(), "", TaskLevel(level=[]), "") with action: pass self.assertIs(currentAction(), None) def test_withUnsetOnRaise(self): """ L{Action.__exit__} unsets the action if the block raises an exception. """ action = Action(MemoryLogger(), "", TaskLevel(level=[]), "") try: with action: 1/0 except ZeroDivisionError: pass else: self.fail("no exception") self.assertIs(currentAction(), None) def test_withContextSetsContext(self): """ L{Action.context().__enter__} sets the action as the current action. """ action = Action(MemoryLogger(), "", TaskLevel(level=[]), "") with action.context(): self.assertIs(currentAction(), action) def test_withContextUnsetOnReturn(self): """ L{Action.context().__exit__} unsets the action on successful block finish. """ action = Action(MemoryLogger(), "", TaskLevel(level=[]), "") with action.context(): pass self.assertIs(currentAction(), None) def test_withContextNoLogging(self): """ L{Action.context().__exit__} does not log any messages. """ logger = MemoryLogger() action = Action(logger, "", TaskLevel(level=[]), "") with action.context(): pass self.assertFalse(logger.messages) def test_withContextUnsetOnRaise(self): """ L{Action.conext().__exit__} unsets the action if the block raises an exception. """ action = Action(MemoryLogger(), "", TaskLevel(level=[]), "") try: with action.context(): 1/0 except ZeroDivisionError: pass else: self.fail("no exception") self.assertIs(currentAction(), None) def test_finish(self): """ L{Action.finish} with no exception logs an C{action_status="succeeded"} message. """ logger = MemoryLogger() action = Action(logger, "unique", TaskLevel(level=[]), "sys:thename") action.finish() assertContainsFields(self, logger.messages[0], {"task_uuid": "unique", "task_level": [1], "action_type": "sys:thename", "action_status": "succeeded"}) def test_successfulFinishSerializer(self): """ L{Action.finish} with no exception passes the success L{eliot._validation._MessageSerializer} to the message it creates. """ serializers = ActionType("sys:thename", [], [Field("key", lambda x: x, "")], "")._serializers class Logger(list): def write(self, msg, serializer): self.append(serializer) logger = Logger() action = Action(logger, "unique", TaskLevel(level=[]), "sys:thename", serializers) action.finish() self.assertIs(logger[0], serializers.success) def test_failureFinishSerializer(self): """ L{Action.finish} with an exception passes the failure L{eliot._validation._MessageSerializer} to the message it creates. """ serializers = ActionType("sys:thename", [], [Field("key", lambda x: x, "")], "")._serializers class Logger(list): def write(self, msg, serializer): self.append(serializer) logger = Logger() action = Action(logger, "unique", TaskLevel(level=[]), "sys:thename", serializers) action.finish(Exception()) self.assertIs(logger[0], serializers.failure) def test_startFieldsNotInFinish(self): """ L{Action.finish} logs a message without the fields from L{Action._start}. """ logger = MemoryLogger() action = Action(logger, "unique", TaskLevel(level=[]), "sys:thename") action._start({"key": "value"}) action.finish() self.assertNotIn("key", logger.messages[1]) def test_finishWithBadException(self): """ L{Action.finish} still logs a message if the given exception raises another exception when called with C{unicode()}. """ logger = MemoryLogger() action = Action(logger, "unique", TaskLevel(level=[]), "sys:thename") class BadException(Exception): def __str__(self): raise TypeError() action.finish(BadException()) self.assertEqual(logger.messages[0]["reason"], "eliot: unknown, unicode() raised exception") def test_withLogsSuccessfulFinishMessage(self): """ L{Action.__exit__} logs an action finish message on a successful block finish. """ logger = MemoryLogger() action = Action(logger, "uuid", TaskLevel(level=[1]), "sys:me") with action: pass # Start message is only created if we use the action()/task() utility # functions, the intended public APIs. self.assertEqual(len(logger.messages), 1) assertContainsFields(self, logger.messages[0], {"task_uuid": "uuid", "task_level": [1, 1], "action_type": "sys:me", "action_status": "succeeded"}) def test_withLogsExceptionMessage(self): """ L{Action.__exit__} logs an action finish message on an exception raised from the block. """ logger = MemoryLogger() action = Action(logger, "uuid", TaskLevel(level=[1]), "sys:me") exception = RuntimeError("because") try: with action: raise exception except RuntimeError: pass else: self.fail("no exception") self.assertEqual(len(logger.messages), 1) assertContainsFields(self, logger.messages[0], {"task_uuid": "uuid", "task_level": [1, 1], "action_type": "sys:me", "action_status": "failed", "reason": "because", "exception": "%s.RuntimeError" % ( RuntimeError.__module__,)}) def test_withReturnValue(self): """ L{Action.__enter__} returns the action itself. """ logger = MemoryLogger() action = Action(logger, "uuid", TaskLevel(level=[1]), "sys:me") with action as act: self.assertIs(action, act) def test_addSuccessFields(self): """ On a successful finish, L{Action.__exit__} adds fields from L{Action.addSuccessFields} to the result message. """ logger = MemoryLogger() action = Action(logger, "uuid", TaskLevel(level=[1]), "sys:me") with action as act: act.addSuccessFields(x=1, y=2) act.addSuccessFields(z=3) assertContainsFields(self, logger.messages[0], {"x": 1, "y": 2, "z": 3}) def test_nextTaskLevel(self): """ Each call to L{Action._nextTaskLevel()} increments a counter. """ action = Action(MemoryLogger(), "uuid", TaskLevel(level=[1]), "sys:me") self.assertEqual([action._nextTaskLevel() for i in range(5)], [TaskLevel(level=level) for level in ([1, 1], [1, 2], [1, 3], [1, 4], [1, 5])]) def test_multipleFinishCalls(self): """ If L{Action.finish} is called, subsequent calls to L{Action.finish} have no effect. """ logger = MemoryLogger() action = Action(logger, "uuid", TaskLevel(level=[1]), "sys:me") with action as act: act.finish() act.finish(Exception()) act.finish() # Only initial finish message is logged: self.assertEqual(len(logger.messages), 1) def test_stringActionCompatibility(self): """ L{Action} can be initialized with a string version of a L{TaskLevel}, for backwards compatibility. """ logger = MemoryLogger() action = Action(logger, "uuid", "/1/2/", "sys:me") self.assertEqual(action._task_level, TaskLevel(level=[1, 2])) def test_stringActionCompatibilityWarning(self): """ Calling L{Action} with a string results in a L{DeprecationWarning} """ logger = MemoryLogger() with catch_warnings(record=True) as warnings: simplefilter("always") # Catch all warnings Action(logger, "uuid", "/1/2/", "sys:me") self.assertEqual(warnings[-1].category, DeprecationWarning) class StartActionAndTaskTests(TestCase): """ Tests for L{startAction} and L{startTask}. """ def test_startTaskNewAction(self): """ L{startTask} creates a new top-level L{Action}. """ logger = MemoryLogger() action = startTask(logger, "sys:do") self.assertIsInstance(action, Action) self.assertEqual(action._task_level, TaskLevel(level=[])) def test_startTaskSerializers(self): """ If serializers are passed to L{startTask} they are attached to the resulting L{Action}. """ logger = MemoryLogger() serializers = _ActionSerializers(start=None, success=None, failure=None) action = startTask(logger, "sys:do", serializers) self.assertIs(action._serializers, serializers) def test_startActionSerializers(self): """ If serializers are passed to L{startAction} they are attached to the resulting L{Action}. """ logger = MemoryLogger() serializers = _ActionSerializers(start=None, success=None, failure=None) action = startAction(logger, "sys:do", serializers) self.assertIs(action._serializers, serializers) def test_startTaskNewUUID(self): """ L{startTask} creates an L{Action} with its own C{task_uuid}. """ logger = MemoryLogger() action = startTask(logger, "sys:do") action2 = startTask(logger, "sys:do") self.assertNotEqual(action._identification["task_uuid"], action2._identification["task_uuid"]) def test_startTaskLogsStart(self): """ L{startTask} logs a start message for the newly created L{Action}. """ logger = MemoryLogger() action = startTask(logger, "sys:do", key="value") assertContainsFields(self, logger.messages[0], {"task_uuid": action._identification["task_uuid"], "task_level": [1], "action_type": "sys:do", "action_status": "started", "key": "value"}) def test_startActionNoParent(self): """ L{startAction} when C{currentAction()} is C{None} creates a top-level L{Action}. """ logger = MemoryLogger() action = startAction(logger, "sys:do") self.assertIsInstance(action, Action) self.assertEqual(action._task_level, TaskLevel(level=[])) def test_startActionNoParentLogStart(self): """ L{startAction} when C{currentAction()} is C{None} logs a start message. """ logger = MemoryLogger() action = startAction(logger, "sys:do", key="value") assertContainsFields(self, logger.messages[0], {"task_uuid": action._identification["task_uuid"], "task_level": [1], "action_type": "sys:do", "action_status": "started", "key": "value"}) def test_startActionWithParent(self): """ L{startAction} uses the C{currentAction()} as parent for a new L{Action}. """ logger = MemoryLogger() parent = Action(logger, "uuid", TaskLevel(level=[2]), "other:thing") with parent: action = startAction(logger, "sys:do") self.assertIsInstance(action, Action) self.assertEqual(action._identification["task_uuid"], "uuid") self.assertEqual(action._task_level, TaskLevel(level=[2, 1])) def test_startActionWithParentLogStart(self): """ L{startAction} when C{currentAction()} is an L{Action} logs a start message. """ logger = MemoryLogger() parent = Action(logger, "uuid", TaskLevel(level=[]), "other:thing") with parent: startAction(logger, "sys:do", key="value") assertContainsFields(self, logger.messages[0], {"task_uuid": "uuid", "task_level": [1, 1], "action_type": "sys:do", "action_status": "started", "key": "value"}) def test_startTaskNoLogger(self): """ When no logger is given L{startTask} logs to the default ``Logger``. """ messages = [] add_destination(messages.append) self.addCleanup(remove_destination, messages.append) action = startTask(action_type="sys:do", key="value") assertContainsFields(self, messages[0], {"task_uuid": action._identification["task_uuid"], "task_level": [1], "action_type": "sys:do", "action_status": "started", "key": "value"}) def test_startActionNoLogger(self): """ When no logger is given L{startAction} logs to the default ``Logger``. """ messages = [] add_destination(messages.append) self.addCleanup(remove_destination, messages.append) action = startAction(action_type="sys:do", key="value") assertContainsFields(self, messages[0], {"task_uuid": action._identification["task_uuid"], "task_level": [1], "action_type": "sys:do", "action_status": "started", "key": "value"}) class PEP8Tests(TestCase): """ Tests for PEP 8 method compatibility. """ def test_add_success_fields(self): """ L{Action.addSuccessFields} is the same as L{Action.add_success_fields}. """ self.assertEqual(Action.addSuccessFields, Action.add_success_fields) def test_serialize_task_id(self): """ L{Action.serialize_task_id} is the same as L{Action.serializeTaskId}. """ self.assertEqual(Action.serialize_task_id, Action.serializeTaskId) def test_continue_task(self): """ L{Action.continue_task} is the same as L{Action.continueTask}. """ self.assertEqual(Action.continue_task, Action.continueTask) class SerializationTests(TestCase): """ Tests for L{Action} serialization and deserialization. """ def test_serializeTaskId(self): """ L{Action.serializeTaskId} result is composed of the task UUID and an incremented task level. """ action = Action(None, "uniq123", TaskLevel(level=[1, 2]), "mytype") self.assertEqual([action._nextTaskLevel(), action.serializeTaskId(), action._nextTaskLevel()], [TaskLevel(level=[1, 2, 1]), b"uniq123@/1/2/2", TaskLevel(level=[1, 2, 3])]) def test_continueTaskReturnsAction(self): """ L{Action.continueTask} returns an L{Action} whose C{task_level} and C{task_uuid} are derived from those in the given serialized task identifier. """ originalAction = Action(None, "uniq456", TaskLevel(level=[3, 4]), "mytype") taskId = originalAction.serializeTaskId() newAction = Action.continueTask(MemoryLogger(), taskId) self.assertEqual([newAction.__class__, newAction._identification, newAction._task_level], [Action, {"task_uuid": "uniq456", "action_type": "eliot:remote_task"}, TaskLevel(level=[3, 4, 1])]) def test_continueTaskStartsAction(self): """ L{Action.continueTask} starts the L{Action} it creates. """ originalAction = Action(None, "uniq456", TaskLevel(level=[3, 4]), "mytype") taskId = originalAction.serializeTaskId() logger = MemoryLogger() Action.continueTask(logger, taskId) assertContainsFields(self, logger.messages[0], {"task_uuid": "uniq456", "task_level": [3, 4, 1, 1], "action_type": "eliot:remote_task", "action_status": "started"}) def test_continueTaskNoLogger(self): """ L{Action.continueTask} can be called without a logger. """ originalAction = Action(None, "uniq456", TaskLevel(level=[3, 4]), "mytype") taskId = originalAction.serializeTaskId() messages = [] add_destination(messages.append) self.addCleanup(remove_destination, messages.append) Action.continueTask(task_id=taskId) assertContainsFields(self, messages[0], {"task_uuid": "uniq456", "task_level": [3, 4, 1, 1], "action_type": "eliot:remote_task", "action_status": "started"}) def test_continueTaskRequiredTaskId(self): """ L{Action.continue_task} requires a C{task_id} to be passed in. """ self.assertRaises(RuntimeError, Action.continueTask) class TaskLevelTests(TestCase): """ Tests for L{TaskLevel}. """ def assert_fully_less_than(self, x, y): """ Assert that x < y according to all the comparison operators. """ self.assertTrue(all([ # lt x < y, not y < x, # le x <= y, not y <= x, # gt y > x, not x > y, # ge y >= x, not x >= y, # eq not x == y, not y == x, # ne x != y, y != x, ])) @given(lists(task_level_indexes)) def test_parent_of_child(self, base_task_level): """ L{TaskLevel.child} returns the first child of the task. """ base_task = TaskLevel(level=base_task_level) child_task = base_task.child() self.assertEqual(base_task, child_task.parent()) @given(task_level_lists) def test_child_greater_than_parent(self, task_level): """ L{TaskLevel.child} returns a child that is greater than its parent. """ task = TaskLevel(level=task_level) self.assert_fully_less_than(task, task.child()) @given(task_level_lists) def test_next_sibling_greater(self, task_level): """ L{TaskLevel.next_sibling} returns a greater task level. """ task = TaskLevel(level=task_level) self.assert_fully_less_than(task, task.next_sibling()) @given(task_level_lists) def test_next_sibling(self, task_level): """ L{TaskLevel.next_sibling} returns the next sibling of a task. """ task = TaskLevel(level=task_level) sibling = task.next_sibling() self.assertEqual( sibling, TaskLevel(level=task_level[:-1] + [task_level[-1] + 1])) def test_parent_of_root(self): """ L{TaskLevel.parent} of the root task level is C{None}. """ self.assertIs(TaskLevel(level=[]).parent(), None) def test_toString(self): """ L{TaskLevel.toString} serializes the object to a Unicode string. """ root = TaskLevel(level=[]) child2_1 = root.child().next_sibling().child() self.assertEqual([root.toString(), child2_1.toString()], ["/", "/2/1"]) def test_fromString(self): """ L{TaskLevel.fromString} deserializes the output of L{TaskLevel.toString}. """ self.assertEqual([TaskLevel.fromString("/"), TaskLevel.fromString("/2/1")], [TaskLevel(level=[]), TaskLevel(level=[2, 1])]) def test_from_string(self): """ L{TaskLevel.from_string} is the same as as L{TaskLevel.fromString}. """ self.assertEqual(TaskLevel.from_string, TaskLevel.fromString) def test_to_string(self): """ L{TaskLevel.to_string} is the same as as L{TaskLevel.toString}. """ self.assertEqual(TaskLevel.to_string, TaskLevel.toString) class WrittenActionTests(testtools.TestCase): """ Tests for L{WrittenAction}. """ @given(start_action_messages) def test_from_single_start_message(self, message): """ A L{WrittenAction} can be constructed from a single "start" message. Such an action inherits the C{action_type} of the start message, has no C{end_time}, and has a C{status} of C{STARTED_STATUS}. """ action = WrittenAction.from_messages(message) self.assertThat( action, MatchesStructure.byEquality( status=STARTED_STATUS, action_type=message.contents[ACTION_TYPE_FIELD], task_uuid=message.task_uuid, task_level=message.task_level.parent(), start_time=message.timestamp, children=pvector([]), end_time=None, reason=None, exception=None, )) @given(start_action_messages, message_dicts, integers(min_value=2)) def test_from_single_end_message(self, start_message, end_message_dict, n): """ A L{WrittenAction} can be constructed from a single "end" message. Such an action inherits the C{action_type} and C{task_level} of the end message, has no C{start_time}, and has a C{status} matching that of the end message. """ end_message = written_from_pmap( union(end_message_dict, { ACTION_STATUS_FIELD: SUCCEEDED_STATUS, ACTION_TYPE_FIELD: start_message.contents[ACTION_TYPE_FIELD], TASK_UUID_FIELD: start_message.task_uuid, TASK_LEVEL_FIELD: sibling_task_level(start_message, n), })) action = WrittenAction.from_messages(end_message=end_message) self.assertThat( action, MatchesStructure.byEquality( status=SUCCEEDED_STATUS, action_type=end_message.contents[ACTION_TYPE_FIELD], task_uuid=end_message.task_uuid, task_level=end_message.task_level.parent(), start_time=None, children=pvector([]), end_time=end_message.timestamp, reason=None, exception=None, )) @given(message_dicts) def test_from_single_child_message(self, message_dict): """ A L{WrittenAction} can be constructed from a single child message. Such an action inherits the C{task_level} of the message, has no C{start_time}, C{status}, C{task_type} or C{end_time}. """ message = written_from_pmap(message_dict) action = WrittenAction.from_messages(children=[message]) self.assertThat( action, MatchesStructure.byEquality( status=None, action_type=None, task_uuid=message.task_uuid, task_level=message.task_level.parent(), start_time=None, children=pvector([message]), end_time=None, reason=None, exception=None, )) @given(start_action_messages, message_dicts, integers(min_value=2)) def test_different_task_uuid(self, start_message, end_message_dict, n): """ By definition, an action is either a top-level task or takes place within such a task. If we try to assemble actions from messages with differing task UUIDs, we raise an error. """ assume(start_message.task_uuid != end_message_dict['task_uuid']) action_type = start_message.as_dict()[ACTION_TYPE_FIELD] end_message = written_from_pmap( union( end_message_dict.set(ACTION_TYPE_FIELD, action_type), { ACTION_STATUS_FIELD: SUCCEEDED_STATUS, TASK_LEVEL_FIELD: sibling_task_level(start_message, n), })) self.assertRaises( WrongTask, WrittenAction.from_messages, start_message, end_message=end_message) @given(message_dicts) def test_invalid_start_message_missing_status(self, message_dict): """ A start message must have an C{ACTION_STATUS_FIELD} with the value C{STARTED_STATUS}, otherwise it's not a start message. If we receive such a message, raise an error. This test handles the case where the status field is not present. """ assume(ACTION_STATUS_FIELD not in message_dict) message = written_from_pmap(message_dict) self.assertRaises( InvalidStartMessage, WrittenAction.from_messages, message) @given(message_dict=start_action_message_dicts, status=(just(FAILED_STATUS) | just(SUCCEEDED_STATUS) | text())) def test_invalid_start_message_wrong_status(self, message_dict, status): """ A start message must have an C{ACTION_STATUS_FIELD} with the value C{STARTED_STATUS}, otherwise it's not a start message. If we receive such a message, raise an error. This test handles the case where the status field is present, but is not C{STARTED_STATUS}. """ message = written_from_pmap( message_dict.update({ACTION_STATUS_FIELD: status})) self.assertRaises( InvalidStartMessage, WrittenAction.from_messages, message) @given(start_action_message_dicts, integers(min_value=2)) def test_invalid_task_level_in_start_message(self, start_message_dict, i): """ All messages in an action have a task level. The first message in an action must have a task level ending in C{1}, indicating that it's the first message. If we try to start an action with a message that has a task level that does not end in C{1}, raise an error. """ new_level = start_message_dict[TASK_LEVEL_FIELD].append(i) message_dict = start_message_dict.set(TASK_LEVEL_FIELD, new_level) message = written_from_pmap(message_dict) self.assertRaises( InvalidStartMessage, WrittenAction.from_messages, message) @given(start_action_messages, message_dicts, text(), integers(min_value=1)) def test_action_type_mismatch(self, start_message, end_message_dict, end_type, n): """ The end message of an action must have the same C{ACTION_TYPE_FIELD} as the start message of an action. If we try to end an action with a message that has a different type, we raise an error. """ assume(end_type != start_message.contents[ACTION_TYPE_FIELD]) end_message = written_from_pmap(union(end_message_dict, { ACTION_STATUS_FIELD: SUCCEEDED_STATUS, ACTION_TYPE_FIELD: end_type, TASK_UUID_FIELD: start_message.task_uuid, TASK_LEVEL_FIELD: sibling_task_level(start_message, n), })) self.assertRaises( WrongActionType, WrittenAction.from_messages, start_message, end_message=end_message) @given(start_action_messages, message_dicts, integers(min_value=2)) def test_successful_end(self, start_message, end_message_dict, n): """ A L{WrittenAction} can be constructed with just a start message and an end message: in this case, an end message that indicates the action was successful. Such an action inherits the C{end_time} from the end message, and has a C{status} of C{SUCCEEDED_STATUS}. """ end_message = written_from_pmap( union(end_message_dict, {ACTION_STATUS_FIELD: SUCCEEDED_STATUS, ACTION_TYPE_FIELD: start_message.contents[ACTION_TYPE_FIELD], TASK_UUID_FIELD: start_message.task_uuid, TASK_LEVEL_FIELD: sibling_task_level(start_message, n), } )) action = WrittenAction.from_messages( start_message, end_message=end_message) self.assertThat( action, MatchesStructure.byEquality( action_type=start_message.contents[ACTION_TYPE_FIELD], status=SUCCEEDED_STATUS, task_uuid=start_message.task_uuid, task_level=start_message.task_level.parent(), start_time=start_message.timestamp, children=pvector([]), end_time=end_message.timestamp, reason=None, exception=None, )) @given(start_action_messages, message_dicts, text(), text(), integers(min_value=2)) def test_failed_end(self, start_message, end_message_dict, exception, reason, n): """ A L{WrittenAction} can be constructed with just a start message and an end message: in this case, an end message that indicates that the action failed. Such an action inherits the C{end_time} from the end message, has a C{status} of C{FAILED_STATUS}, and an C{exception} and C{reason} that match the raised exception. """ end_message = written_from_pmap( union(end_message_dict, {ACTION_STATUS_FIELD: FAILED_STATUS, ACTION_TYPE_FIELD: start_message.contents[ACTION_TYPE_FIELD], TASK_UUID_FIELD: start_message.task_uuid, TASK_LEVEL_FIELD: sibling_task_level(start_message, n), EXCEPTION_FIELD: exception, REASON_FIELD: reason, } )) action = WrittenAction.from_messages( start_message, end_message=end_message) self.assertThat( action, MatchesStructure.byEquality( action_type=start_message.contents[ACTION_TYPE_FIELD], status=FAILED_STATUS, task_uuid=start_message.task_uuid, task_level=start_message.task_level.parent(), start_time=start_message.timestamp, children=pvector([]), end_time=end_message.timestamp, reason=reason, exception=exception, )) @given(start_action_messages, message_dicts, integers(min_value=2)) def test_end_has_no_status(self, start_message, end_message_dict, n): """ If we try to end a L{WrittenAction} with a message that lacks an C{ACTION_STATUS_FIELD}, we raise an error, because it's not a valid end message. """ assume(ACTION_STATUS_FIELD not in end_message_dict) end_message = written_from_pmap( union(end_message_dict, { ACTION_TYPE_FIELD: start_message.contents[ACTION_TYPE_FIELD], TASK_UUID_FIELD: start_message.task_uuid, TASK_LEVEL_FIELD: sibling_task_level(start_message, n), })) self.assertRaises( InvalidStatus, WrittenAction.from_messages, start_message, end_message=end_message) # This test is slow, and when run under coverage on pypy on Travis won't # make the default of 5 examples. 1 is enough. @given(start_action_messages, lists(written_messages | written_actions), settings=Settings(min_satisfying_examples=1)) def test_children(self, start_message, child_messages): """ We can construct a L{WrittenAction} with child messages. These messages can be either L{WrittenAction}s or L{WrittenMessage}s. They are available in the C{children} field. """ messages = [ reparent_action( start_message.task_uuid, TaskLevel(level=sibling_task_level(start_message, i)), message) for (i, message) in enumerate(child_messages, 2)] action = WrittenAction.from_messages(start_message, messages) task_level = lambda m: m.task_level self.assertEqual( sorted(messages, key=task_level), action.children) @given(start_action_messages, message_dicts) def test_wrong_task_uuid(self, start_message, child_message): """ All child messages of an action must have the same C{task_uuid} as the action. """ assume(child_message[TASK_UUID_FIELD] != start_message.task_uuid) message = written_from_pmap(child_message) self.assertRaises( WrongTask, WrittenAction.from_messages, start_message, v(message)) @given(start_action_messages, message_dicts) def test_wrong_task_level(self, start_message, child_message): """ All child messages of an action must have a task level that is a direct child of the action's task level. """ assume(not start_message.task_level.is_sibling_of( TaskLevel(level=child_message[TASK_LEVEL_FIELD]))) message = written_from_pmap( child_message.update({TASK_UUID_FIELD: start_message.task_uuid})) self.assertRaises( WrongTaskLevel, WrittenAction.from_messages, start_message, v(message)) @given(start_action_messages, message_dicts, message_dicts, integers(min_value=2)) def test_duplicate_task_level(self, start_message, child1, child2, index): """ If we try to add a child to an action that has a task level that's the same as the task level of an existing child, we raise an error. """ parent_level = start_message.task_level.parent().level messages = [ written_from_pmap( union(child_message, { TASK_UUID_FIELD: start_message.task_uuid, TASK_LEVEL_FIELD: parent_level.append(index), })) for child_message in [child1, child2]] assume(messages[0] != messages[1]) self.assertRaises( DuplicateChild, WrittenAction.from_messages, start_message, messages) def make_error_extraction_tests(get_messages): """ Create a test case class for testing extraction of fields from exceptions. @param get_messages: Callable that takes an exception instance, returns all message dictionaries generated by logging it. @return: ``TestCase`` subclass. """ class ErrorFieldExtraction(TestCase): """ Tests for extracting fields from exceptions in failed actions. """ def test_matching_class(self): """ If an exception fails an action and the exact type has registered extractor, extract errors using it. """ class MyException(Exception): pass register_exception_extractor(MyException, lambda e: {"key": e.args[0]}) exception = MyException("a value") [message] = get_messages(exception) assertContainsFields(self, message, {"key": "a value"}) def test_subclass_falls_back_to_parent(self): """ If an exception fails an action and the exact type has not been registered but the error is a subclass of a registered class, extract errors using it. """ class MyException(Exception): pass class SubException(MyException): pass register_exception_extractor(MyException, lambda e: {"key": e.args[0]}) [message] = get_messages(SubException("the value")) assertContainsFields(self, message, {"key": "the value"}) def test_subclass_matches_first(self): """ If both a superclass and base class have registered extractors, the more specific one is used. """ class MyException(Exception): pass class SubException(MyException): pass class SubSubException(SubException): pass register_exception_extractor(MyException, lambda e: {"parent": e.args[0]}) register_exception_extractor(SubException, lambda e: {"child": e.args[0]}) [message] = get_messages(SubSubException("the value")) assertContainsFields(self, message, {"child": "the value"}) def test_error_in_extracter(self): """ If an error occurs in extraction, log the message as usual just without the extra fields, and an additional traceback. """ class MyException(Exception): pass def extract(e): return e.nosuchattribute register_exception_extractor(MyException, extract) messages = get_failed_action_messages(MyException()) assertContainsFields(self, messages[1], {"action_type": "sys:me", "action_status": "failed"}) assertContainsFields(self, messages[0], {"message_type": "eliot:traceback"}) self.assertIn("nosuchattribute", str(messages[0]["reason"])) def test_environmenterror(self): """ ``EnvironmentError`` has a registered extractor that extracts the errno. """ [message] = get_messages(EnvironmentError(12, "oh noes")) assertContainsFields(self, message, {"errno": 12}) return ErrorFieldExtraction def get_failed_action_messages(exception): """ Fail an action using the given exception. :return: Logged dictionaries from the exception failing an action. """ action_type = ActionType("sys:me", [], []) logger = MemoryLogger() action = action_type.as_task(logger=logger) try: with action: raise exception except exception.__class__: pass logger.validate() return logger.messages[1:] class FailedActionExtractionTests(make_error_extraction_tests( get_failed_action_messages)): """ Tests for error extraction in failed actions. """ def test_regular_fields(self): """ The normal failed action fields are still present when error extraction is used. """ class MyException(Exception): pass register_exception_extractor(MyException, lambda e: {"key": e.args[0]}) exception = MyException("because") messages = get_failed_action_messages(exception) assertContainsFields(self, messages[0], {"task_level": [2], "action_type": "sys:me", "action_status": "failed", "reason": "because", "exception": "eliot.tests.test_action.MyException"}) class PreserveContextTests(TestCase): """ Tests for L{preserve_context}. """ def add(self, x, y): """ Add two inputs. """ Message.log(message_type="child") return x + y def test_no_context(self): """ If C{preserve_context} is run outside an action context it just returns the same function. """ wrapped = preserve_context(self.add) self.assertEqual(wrapped(2, 3), 5) def test_with_context_calls_underlying(self): """ If run inside an Eliot context, the result of C{preserve_context} is the result of calling the underlying function. """ with startAction(action_type="parent"): wrapped = preserve_context(self.add) self.assertEqual(wrapped(3, y=4), 7) @capture_logging(None) def test_with_context_preserves_context(self, logger): """ If run inside an Eliot context, the result of C{preserve_context} runs the wrapped function within a C{eliot:task} which is a child of the original action. """ with startAction(action_type="parent"): wrapped = preserve_context(lambda: self.add(3, 4)) thread = Thread(target=wrapped) thread.start() thread.join() [tree] = Parser.parse_stream(logger.messages) root = tree.root() self.assertEqual((root.action_type, root.children[0].action_type, root.children[0].children[0].contents[ MESSAGE_TYPE_FIELD]), ("parent", "eliot:remote_task", "child")) def test_callable_only_once(self): """ The result of C{preserve_context} can only be called once. """ with startAction(action_type="parent"): wrapped = preserve_context(self.add) wrapped(1, 2) self.assertRaises(TooManyCalls, wrapped, 3, 4) PKPxEd!%%eliot/tests/__init__.py""" Tests for the eliot package. """ PK; GY*#*#eliot/tests/test_message.py""" Tests for L{eliot._message}. """ from __future__ import unicode_literals from unittest import TestCase from uuid import UUID import time from pyrsistent import pmap try: from twisted.python.failure import Failure except ImportError: Failure = None from .._message import WrittenMessage, Message from .._output import MemoryLogger from .._action import Action, startAction, TaskLevel from .. import add_destination, remove_destination class MessageTests(TestCase): """ Test for L{Message}. """ def test_new(self): """ L{Message.new} returns a new L{Message} that is initialized with the given keyword arguments as its contents. """ msg = Message.new(key="value", another=2) self.assertEqual(msg.contents(), {"key": "value", "another": 2}) def test_contentsCopies(self): """ L{Message.contents} returns a copy of the L{Message} contents. """ msg = Message.new(key="value") del msg.contents()["key"] self.assertEqual(msg.contents(), {"key": "value"}) def test_bindOverwrites(self): """ L{Message.bind} returns a new L{Message} whose contents include the additional given fields. """ msg = Message.new(key="value", another=2) another = msg.bind(another=3, more=4) self.assertIsInstance(another, Message) self.assertEqual(another.contents(), {"key": "value", "another": 3, "more": 4}) def test_bindPreservesOriginal(self): """ L{Message.bind} does not mutate the instance it is called on. """ msg = Message.new(key=4) msg.bind(key=6) self.assertEqual(msg.contents(), {"key": 4}) def test_writeCallsLoggerWrite(self): """ L{Message.write} calls the given logger's C{write} method with a dictionary that is superset of the L{Message} contents. """ logger = MemoryLogger() msg = Message.new(key=4) msg.write(logger) self.assertEqual(len(logger.messages), 1) self.assertEqual(logger.messages[0]["key"], 4) def test_writeDefaultLogger(self): """ L{Message.write} writes to the default logger if none is given. """ messages = [] add_destination(messages.append) self.addCleanup(remove_destination, messages.append) Message.new(some_key=1234).write() self.assertEqual(messages[0][u"some_key"], 1234) def test_writeCreatesNewDictionary(self): """ L{Message.write} creates a new dictionary on each call. This is important because we mutate the dictionary in ``Logger.write``, so we want to make sure the ``Message`` is unchanged in that case. In general we want ``Message`` objects to be effectively immutable. """ class Logger(list): def write(self, d, serializer): self.append(d) logger = Logger() msg = Message.new(key=4) msg.write(logger) logger[0]["key"] = 5 msg.write(logger) self.assertEqual(logger[1]["key"], 4) def test_logCallsDefaultLoggerWrite(self): """ L{Message.log} calls the given logger's C{write} method with a dictionary that is superset of the L{Message} contents. """ messages = [] add_destination(messages.append) self.addCleanup(remove_destination, messages.append) Message.log(some_key=1234) self.assertEqual(messages[0][u"some_key"], 1234) def test_defaultTime(self): """ L{Message._time} returns L{time.time} by default. """ msg = Message({}) self.assertIs(msg._time, time.time) def test_writeAddsTimestamp(self): """ L{Message.write} adds a C{"timestamp"} field to the dictionary written to the logger, with the current time in seconds since the epoch. """ logger = MemoryLogger() msg = Message.new(key=4) timestamp = 1387299889.153187625 msg._time = lambda: timestamp msg.write(logger) self.assertEqual(logger.messages[0]["timestamp"], timestamp) def test_explicitAction(self): """ L{Message.write} adds the identification fields from the given L{Action} to the dictionary written to the logger. """ logger = MemoryLogger() action = Action(logger, "unique", TaskLevel(level=[]), "sys:thename") msg = Message.new(key=2) msg.write(logger, action) written = logger.messages[0] del written["timestamp"] self.assertEqual(written, {"task_uuid": "unique", "task_level": [1], "key": 2}) def test_implicitAction(self): """ If no L{Action} is specified, L{Message.write} adds the identification fields from the current execution context's L{Action} to the dictionary written to the logger. """ action = Action(MemoryLogger(), "unique", TaskLevel(level=[]), "sys:thename") logger = MemoryLogger() msg = Message.new(key=2) with action: msg.write(logger) written = logger.messages[0] del written["timestamp"] self.assertEqual(written, {"task_uuid": "unique", "task_level": [1], "key": 2}) def test_missingAction(self): """ If no L{Action} is specified, and the current execution context has no L{Action}, a new task_uuid is generated. This ensures all messages have a unique identity, as specified by task_uuid/task_level. """ logger = MemoryLogger() Message.new(key=2).write(logger) Message.new(key=3).write(logger) message1, message2 = logger.messages self.assertEqual( (UUID(message1["task_uuid"]) != UUID(message2["task_uuid"]), message1["task_level"], message2["task_level"]), (True, [1], [1])) def test_actionCounter(self): """ Each message written within the context of an L{Action} gets its C{task_level} field incremented. """ logger = MemoryLogger() msg = Message.new(key=2) with startAction(logger, "sys:thename"): for i in range(4): msg.write(logger) # We expect 6 messages: start action, 4 standalone messages, finish # action: self.assertEqual([m["task_level"] for m in logger.messages], [[1], [2], [3], [4], [5], [6]]) def test_writePassesSerializer(self): """ If a L{Message} is created with a serializer, it is passed as a second argument to the logger when C{write} is called. """ class ListLogger(list): def write(self, dictionary, serializer): self.append(serializer) logger = ListLogger() serializer = object() msg = Message({}, serializer) msg.write(logger) self.assertIs(logger[0], serializer) def test_serializerPassedInBind(self): """ The L{Message} returned by L{Message.bind} includes the serializer passed to the parent. """ serializer = object() msg = Message({}, serializer) msg2 = msg.bind(x=1) self.assertIs(msg2._serializer, serializer) def test_newWithSerializer(self): """ L{Message.new} can accept a serializer. """ serializer = object() msg = Message.new(serializer, x=1) self.assertIs(msg._serializer, serializer) class WrittenMessageTests(TestCase): """ Tests for L{WrittenMessage}. """ def test_as_dict(self): """ L{WrittenMessage.as_dict} returns the dictionary that will be serialized to the log. """ log_entry = pmap({ 'timestamp': 1, 'task_uuid': 'unique', 'task_level': [1], 'foo': 'bar', }) self.assertEqual(WrittenMessage.from_dict(log_entry).as_dict(), log_entry) def test_from_dict(self): """ L{WrittenMessage.from_dict} converts a dictionary that has been deserialized from a log into a L{WrittenMessage} object. """ log_entry = pmap({ 'timestamp': 1, 'task_uuid': 'unique', 'task_level': [1], 'foo': 'bar', }) parsed = WrittenMessage.from_dict(log_entry) self.assertEqual(parsed.timestamp, 1) self.assertEqual(parsed.task_uuid, 'unique') self.assertEqual(parsed.task_level, TaskLevel(level=[1])) self.assertEqual(parsed.contents, pmap({'foo': 'bar'})) PKGRw1RReliot/tests/test_prettyprint.py""" Tests for C{eliot.prettyprint}. """ from __future__ import unicode_literals from unittest import TestCase from subprocess import check_output, Popen, PIPE from pyrsistent import pmap from .._bytesjson import dumps from ..prettyprint import pretty_format, _CLI_HELP, REQUIRED_FIELDS SIMPLE_MESSAGE = { "timestamp": 1443193754, "task_uuid": "8c668cde-235b-4872-af4e-caea524bd1c0", "message_type": "messagey", "task_level": [1, 2], "keys": [123, 456]} UNTYPED_MESSAGE = { "timestamp": 1443193754, "task_uuid": "8c668cde-235b-4872-af4e-caea524bd1c0", "task_level": [1], "key": 1234, "abc": "def"} class FormattingTests(TestCase): """ Tests for L{pretty_format}. """ def test_message(self): """ A typed message is printed as expected. """ self.assertEqual( pretty_format(SIMPLE_MESSAGE), """\ 8c668cde-235b-4872-af4e-caea524bd1c0 -> /1/2 2015-09-25 15:09:14Z message_type: 'messagey' keys: [123, 456] """) def test_untyped_message(self): """ A message with no type is printed as expected. """ self.assertEqual( pretty_format(UNTYPED_MESSAGE), """\ 8c668cde-235b-4872-af4e-caea524bd1c0 -> /1 2015-09-25 15:09:14Z abc: 'def' key: 1234 """) def test_action(self): """ An action message is printed as expected. """ message = {"task_uuid": "8bc6ded2-446c-4b6d-abbc-4f21f1c9a7d8", "place": "Statue #1", "task_level": [2, 2, 2, 1], "action_type": "visited", "timestamp": 1443193958.0, "action_status": "started"} self.assertEqual( pretty_format(message), """\ 8bc6ded2-446c-4b6d-abbc-4f21f1c9a7d8 -> /2/2/2/1 2015-09-25 15:12:38Z action_type: 'visited' action_status: 'started' place: 'Statue #1' """) def test_multi_line(self): """ Multiple line values are indented nicely. """ message = {"timestamp": 1443193754, "task_uuid": "8c668cde-235b-4872-af4e-caea524bd1c0", "task_level": [1], "key": "hello\nthere\nmonkeys!\n", "more": "stuff"} self.assertEqual( pretty_format(message), """\ 8c668cde-235b-4872-af4e-caea524bd1c0 -> /1 2015-09-25 15:09:14Z key: 'hello | there | monkeys! | ' more: 'stuff' """) def test_tabs(self): """ Tabs are formatted as tabs, not quoted. """ message = {"timestamp": 1443193754, "task_uuid": "8c668cde-235b-4872-af4e-caea524bd1c0", "task_level": [1], "key": "hello\tmonkeys!"} self.assertEqual( pretty_format(message), """\ 8c668cde-235b-4872-af4e-caea524bd1c0 -> /1 2015-09-25 15:09:14Z key: 'hello monkeys!' """) def test_structured(self): """ Structured field values (e.g. a dictionary) are formatted in a helpful manner. """ message = {"timestamp": 1443193754, "task_uuid": "8c668cde-235b-4872-af4e-caea524bd1c0", "task_level": [1], "key": {"value": 123, "another": [1, 2, {"more": "data"}]}} self.assertEqual( pretty_format(message), """\ 8c668cde-235b-4872-af4e-caea524bd1c0 -> /1 2015-09-25 15:09:14Z key: {'another': [1, 2, {'more': 'data'}], | 'value': 123} """) class CommandLineTests(TestCase): """ Tests for the command-line tool. """ def test_help(self): """ C{--help} prints out the help text and exits. """ result = check_output(["eliot-prettyprint", "--help"]) self.assertEqual(result, _CLI_HELP.encode("utf-8")) def write_and_read(self, lines): """ Write the given lines to the command-line on stdin, return stdout. @param lines: Sequences of lines to write, as bytes, and lacking new lines. @return: Unicode-decoded result of subprocess stdout. """ process = Popen([b"eliot-prettyprint"], stdin=PIPE, stdout=PIPE) process.stdin.write(b"".join(line + b"\n" for line in lines)) process.stdin.close() result = process.stdout.read().decode("utf-8") process.stdout.close() return result def test_output(self): """ Lacking command-line arguments the process reads JSON lines from stdin and writes out a pretty-printed version. """ messages = [SIMPLE_MESSAGE, UNTYPED_MESSAGE, SIMPLE_MESSAGE] stdout = self.write_and_read(map(dumps, messages)) self.assertEqual( stdout, "".join(pretty_format(message) + "\n" for message in messages)) def test_not_json_message(self): """ Non-JSON lines are not formatted. """ not_json = b"NOT JSON!!" lines = [dumps(SIMPLE_MESSAGE), not_json, dumps(UNTYPED_MESSAGE)] stdout = self.write_and_read(lines) self.assertEqual( stdout, "{}\nNot JSON: {}\n\n{}\n".format( pretty_format(SIMPLE_MESSAGE), str(not_json), pretty_format(UNTYPED_MESSAGE))) def test_missing_required_field(self): """ Non-Eliot JSON messages are not formatted. """ base = pmap(SIMPLE_MESSAGE) messages = [dumps(dict(base.remove(field))) for field in REQUIRED_FIELDS] + [dumps(SIMPLE_MESSAGE)] stdout = self.write_and_read(messages) self.assertEqual( stdout, "{}{}\n".format( "".join("Not an Eliot message: {}\n\n".format(msg) for msg in messages[:-1]), pretty_format(SIMPLE_MESSAGE))) PKYuAG5((eliot/tests/test_logwriter.py""" Tests for L{eliot.logwriter}. """ from __future__ import unicode_literals import time import threading # Make sure to use StringIO that only accepts unicode: from io import BytesIO, StringIO from unittest import skipIf import json as pyjson from warnings import catch_warnings, simplefilter from six import PY2 try: from zope.interface.verify import verifyClass from twisted.internet import reactor from twisted.trial.unittest import TestCase from twisted.application.service import IService from twisted.python import threadable except ImportError: # Make tests not run at all. TestCase = object else: # Make sure we always import this if Twisted is available, so broken # logwriter.py causes a failure: from ..logwriter import ThreadedFileWriter, ThreadedWriter from .. import Logger, removeDestination, FileDestination class BlockingFile(object): """ A file-like whose writes can be blocked. Also, allow calling C{getvalue} after C{close}, unlike L{BytesIO}. """ def __init__(self): self.file = BytesIO() self.lock = threading.Lock() self.data = b"" def block(self): """ Prevent writes until L{unblock} is called. """ self.lock.acquire() def unblock(self): """ Allow writes if L{block} was previous called. """ self.lock.release() def getvalue(self): """ Get written bytes. @return: Written bytes. """ return self.data def write(self, data): with self.lock: self.file.write(data) def flush(self): self.data = self.file.getvalue() def close(self): self.file.close() class ThreadedWriterTests(TestCase): """ Tests for L{ThreadedWriter}. Many of these tests involve interactions across threads, so they arbitrarily wait for up to 5 seconds to reduce chances of slow thread switching causing the test to fail. """ def test_interface(self): """ L{ThreadedWriter} provides L{IService}. """ verifyClass(IService, ThreadedWriter) def test_name(self): """ L{ThreadedWriter} has a name. """ self.assertEqual(ThreadedWriter.name, u"Eliot Log Writer") def test_startServiceRunning(self): """ L{ThreadedWriter.startService} starts the service as required by the L{IService} interface. """ writer = ThreadedWriter(FileDestination(file=BytesIO()), reactor) self.assertFalse(writer.running) writer.startService() self.addCleanup(writer.stopService) self.assertTrue(writer.running) def test_stopServiceRunning(self): """ L{ThreadedWriter.stopService} stops the service as required by the L{IService} interface. """ writer = ThreadedWriter(FileDestination(file=BytesIO()), reactor) writer.startService() d = writer.stopService() d.addCallback(lambda _: self.assertFalse(writer.running)) return d def test_startServiceStartsThread(self): """ L{ThreadedWriter.startService} starts up a thread running L{ThreadedWriter._writer}. """ previousThreads = threading.enumerate() result = [] event = threading.Event() def _writer(): current = threading.currentThread() if current not in previousThreads: result.append(current) event.set() writer = ThreadedWriter(FileDestination(file=BytesIO()), reactor) writer._writer = _writer writer.startService() event.wait() self.assertTrue(result) # Make sure thread is dead so it doesn't die half way through another # test: result[0].join(5) def test_stopServiceStopsThread(self): """ L{ThreadedWriter.stopService} stops the writer thread. """ previousThreads = set(threading.enumerate()) writer = ThreadedWriter(FileDestination(file=BytesIO()), reactor) writer.startService() start = time.time() while set(threading.enumerate()) == previousThreads and ( time.time() - start < 5): time.sleep(0.0001) # If not true the next assertion might pass by mistake: self.assertNotEqual(set(threading.enumerate()), previousThreads) writer.stopService() while set(threading.enumerate()) != previousThreads and ( time.time() - start < 5): time.sleep(0.0001) self.assertEqual(set(threading.enumerate()), previousThreads) def test_stopServiceFinishesWriting(self): """ L{ThreadedWriter.stopService} stops the writer thread, but only after all queued writes are written out. """ f = BlockingFile() writer = ThreadedWriter(FileDestination(file=f), reactor) f.block() writer.startService() for i in range(100): writer({u"write": 123}) threads = threading.enumerate() writer.stopService() # Make sure writes didn't happen before the stopService, thus making the # test pointless: self.assertEqual(f.getvalue(), b"") f.unblock() start = time.time() while threading.enumerate() == threads and time.time() - start < 5: time.sleep(0.0001) self.assertEqual(f.getvalue(), b'{"write": 123}\n' * 100) def test_stopServiceResult(self): """ L{ThreadedWriter.stopService} returns a L{Deferred} that fires only after the thread has shut down. """ f = BlockingFile() writer = ThreadedWriter(FileDestination(file=f), reactor) f.block() writer.startService() writer({"hello": 123}) threads = threading.enumerate() d = writer.stopService() f.unblock() def done(_): self.assertEqual(f.getvalue(), b'{"hello": 123}\n') self.assertNotEqual(threading.enumerate(), threads) d.addCallback(done) return d def test_noChangeToIOThread(self): """ Running a L{ThreadedWriter} doesn't modify the Twisted registered IO thread. """ writer = ThreadedWriter(FileDestination(file=BytesIO()), reactor) writer.startService() d = writer.stopService() # Either the current thread (the one running the tests) is the the I/O # thread or the I/O thread was never set. Either may happen depending on # how and whether the reactor has been started by the unittesting # framework. d.addCallback(lambda _: self.assertIn( threadable.ioThread, (None, threading.currentThread().ident))) return d def test_startServiceRegistersDestination(self): """ L{ThreadedWriter.startService} registers itself as an Eliot log destination. """ f = BlockingFile() writer = ThreadedWriter(FileDestination(file=f), reactor) writer.startService() Logger().write({"x": "abc"}) d = writer.stopService() d.addCallback(lambda _: self.assertIn(b"abc", f.getvalue())) return d def test_stopServiceUnregistersDestination(self): """ L{ThreadedWriter.stopService} unregisters itself as an Eliot log destination. """ writer = ThreadedWriter(FileDestination(file=BytesIO()), reactor) writer.startService() d = writer.stopService() d.addCallback(lambda _: removeDestination(writer)) return self.assertFailure(d, ValueError) def test_call(self): """ The message passed to L{ThreadedWriter.__call__} is passed to the underlying destination in the writer thread. """ result = [] def destination(message): result.append((message, threading.currentThread().ident)) writer = ThreadedWriter(destination, reactor) writer.startService() thread_ident = writer._thread.ident msg = {"key": 123} writer(msg) d = writer.stopService() d.addCallback( lambda _: self.assertEqual(result, [(msg, thread_ident)])) return d class ThreadedFileWriterTests(TestCase): """ Tests for ``ThreadedFileWriter``. """ def test_deprecation_warning(self): """ Instantiating ``ThreadedFileWriter`` gives a ``DeprecationWarning``. """ with catch_warnings(record=True) as warnings: ThreadedFileWriter(BytesIO(), reactor) simplefilter("always") # Catch all warnings self.assertEqual(warnings[-1].category, DeprecationWarning) def test_write(self): """ Messages passed to L{ThreadedFileWriter.__call__} are then written by the writer thread with a newline added. """ f = BytesIO() writer = ThreadedFileWriter(f, reactor) writer.startService() self.addCleanup(writer.stopService) writer({"hello": 123}) start = time.time() while not f.getvalue() and time.time() - start < 5: time.sleep(0.0001) self.assertEqual(f.getvalue(), b'{"hello": 123}\n') @skipIf(PY2, "Python 2 files always accept bytes") def test_write_unicode(self): """ Messages passed to L{ThreadedFileWriter.__call__} are then written by the writer thread with a newline added to files that accept unicode. """ f = StringIO() writer = ThreadedFileWriter(f, reactor) writer.startService() self.addCleanup(writer.stopService) original = {"hello\u1234": 123} writer(original) start = time.time() while not f.getvalue() and time.time() - start < 5: time.sleep(0.0001) self.assertEqual(f.getvalue(), pyjson.dumps(original) + "\n") def test_stopServiceClosesFile(self): """ L{ThreadedWriter.stopService} closes the file. """ f = BytesIO() writer = ThreadedFileWriter(f, reactor) writer.startService() d = writer.stopService() def done(_): self.assertTrue(f.closed) d.addCallback(done) return d PKPxEd7heliot/tests/common.py""" Common testing infrastructure. """ from io import BytesIO class FakeSys(object): """ A fake L{sys} module. """ def __init__(self, argv, stdinBytes): """ @param argv: List of command-line arguments. @param stdinBytes: C{bytes} that are readable from stdin. """ self.argv = argv self.stdin = BytesIO(stdinBytes) self.stdout = BytesIO() self.stderr = BytesIO() PKYuAG`ŏeliot/tests/test_filter.py""" Tests for L{eliot.filter}. """ from __future__ import unicode_literals import sys from unittest import TestCase from datetime import datetime from io import BytesIO import inspect from .common import FakeSys from .. import _bytesjson as json from ..filter import EliotFilter, main, USAGE class EliotFilterTests(TestCase): """ Tests for L{EliotFilter}. """ def test_expression(self): """ For each item in the incoming sequence L{EliotFilter.run} calls L{EliotFilter._evaluate} with the item decoded from JSON, and writes the result to the output file as JSON. """ f = BytesIO() efilter = EliotFilter("J", [b'"abcd"', b"[1, 2]"], f) efilter._evaluate = lambda expr: {"x": len(expr), "orig": expr} self.assertEqual(f.getvalue(), b"") efilter.run() self.assertEqual(f.getvalue(), json.dumps({"x": 4, "orig": "abcd"}) + b"\n" + json.dumps({"x": 2, "orig": [1, 2]}) + b'\n') def evaluateExpression(self, expr, message): """ Render a single message with the given expression using L{EliotFilter._evaluate}. """ efilter = EliotFilter(expr, [], BytesIO()) return efilter._evaluate(message) def test_J(self): """ The expression has access to the decoded JSON message as C{J} in its locals. """ result = self.evaluateExpression("J['a']", {"a": 123}) self.assertEqual(result, 123) def test_otherLocals(self): """ The expression has access to L{datetime} and L{timedelta} in its built-ins. """ result = self.evaluateExpression( "isinstance(datetime.utcnow() - datetime.utcnow(), timedelta)", {}) self.assertEqual(result, True) def test_datetimeSerialization(self): """ Any L{datetime} in results will be serialized using L{datetime.isoformat}. """ dt = datetime(2012, 12, 31) f = BytesIO() EliotFilter("datetime(2012, 12, 31)", ["{}"], f).run() expected = json.dumps(dt.isoformat()) + b"\n" self.assertEqual(f.getvalue(), expected) def test_SKIP(self): """ A result of C{SKIP} indicates nothing should be output. """ f = BytesIO() EliotFilter("SKIP", [b'{"a": 123}'], f).run() self.assertEqual(f.getvalue(), b"") class MainTests(TestCase): """ Test cases for L{main}. """ def test_default(self): """ By default L{main} uses information from L{sys}. """ self.assertEqual(inspect.getargspec(main).defaults, (sys,)) def test_stdinOut(self): """ L{main} reads from the C{stdin} attribute of the given C{sys} equivalent, and writes rendered expressions to the C{stdout} attribute. """ sys = FakeSys(["eliotfilter", "J[0]"], b"[1, 2]\n[4, 5]\n") main(sys) self.assertEqual(sys.stdout.getvalue(), b"1\n4\n") def test_success(self): """ A successful run returns C{0}. """ sys = FakeSys(["eliotfilter", "J[0]"], b"[1, 2]\n[4, 5]\n") result = main(sys) self.assertEqual(result, 0) def test_noArguments(self): """ If given no arguments, usage documentation is printed to stderr and C{1} is returned. """ sys = FakeSys(["eliotfilter"], b"") result = main(sys) self.assertEqual(sys.stderr.getvalue(), USAGE) self.assertEqual(result, 1) PK⡁G~g:(:(eliot/tests/test_parse.py""" Tests for L{eliot._parse}. """ from __future__ import unicode_literals from unittest import TestCase from itertools import chain from six import text_type as unicode, assertCountEqual from six.moves import zip_longest from hypothesis import strategies as st, given, assume from pyrsistent import PClass, field, pvector_field from .. import start_action, Message from ..testing import MemoryLogger from .._parse import Task, Parser from .._message import ( WrittenMessage, MESSAGE_TYPE_FIELD, TASK_LEVEL_FIELD, TASK_UUID_FIELD, ) from .._action import FAILED_STATUS, ACTION_STATUS_FIELD, WrittenAction from .strategies import labels class ActionStructure(PClass): """ A tree structure used to generate/compare to Eliot trees. Individual messages are encoded as a unicode string; actions are encoded as a L{ActionStructure} instance. """ type = field(type=(unicode, None.__class__)) children = pvector_field(object) # XXX ("StubAction", unicode)) failed = field(type=bool) @classmethod def from_written(cls, written): """ Create an L{ActionStructure} or L{unicode} from a L{WrittenAction} or L{WrittenMessage}. """ if isinstance(written, WrittenMessage): return written.as_dict()[MESSAGE_TYPE_FIELD] else: # WrittenAction if not written.end_message: raise AssertionError("Missing end message.") return cls( type=written.action_type, failed=(written.end_message.contents[ACTION_STATUS_FIELD] == FAILED_STATUS), children=[cls.from_written(o) for o in written.children]) @classmethod def to_eliot(cls, structure_or_message, logger): """ Given a L{ActionStructure} or L{unicode}, generate appropriate structured Eliot log mesages to given L{MemoryLogger}. """ if isinstance(structure_or_message, cls): action = structure_or_message try: with start_action(logger, action_type=action.type): for child in action.children: cls.to_eliot(child, logger) if structure_or_message.failed: raise RuntimeError("Make the eliot action fail.") except RuntimeError: pass else: Message.new(message_type=structure_or_message).write(logger) return logger.messages @st.composite def action_structures(draw): """ A Hypothesis strategy that creates a tree of L{ActionStructure} and L{unicode}. """ tree = draw(st.recursive(labels, st.lists, max_leaves=50)) def to_structure(tree_or_message): if isinstance(tree_or_message, list): return ActionStructure( type=draw(labels), failed=draw(st.booleans()), children=[to_structure(o) for o in tree_or_message]) else: return tree_or_message return to_structure(tree) def _structure_and_messages(structure): messages = ActionStructure.to_eliot(structure, MemoryLogger()) return st.permutations(messages).map( lambda permuted: (structure, permuted)) # Hypothesis strategy that creates a tuple of ActionStructure/unicode and # corresponding serialized Eliot messages, randomly shuffled. STRUCTURES_WITH_MESSAGES = action_structures().flatmap(_structure_and_messages) def parse_to_task(messages): """ Feed a set of messages to a L{Task}. @param messages: Sequence of messages dictionaries to parse. @return: Resulting L{Task}. """ task = Task() for message in messages: task = task.add(message) return task class TaskTests(TestCase): """ Tests for L{Task}. """ @given(structure_and_messages=STRUCTURES_WITH_MESSAGES) def test_missing_action(self, structure_and_messages): """ If we parse messages (in shuffled order) but a start message is missing then the structure is still deduced correctly from the remaining messages. """ action_structure, messages = structure_and_messages assume(not isinstance(action_structure, unicode)) # Remove first start message we encounter; since messages are # shuffled the location removed will differ over Hypothesis test # iterations: messages = messages[:] for i, message in enumerate(messages): if message[TASK_LEVEL_FIELD][-1] == 1: # start message del messages[i] break task = parse_to_task(messages) parsed_structure = ActionStructure.from_written(task.root()) # We expect the action with missing start message to otherwise # be parsed correctly: self.assertEqual(parsed_structure, action_structure) @given(structure_and_messages=STRUCTURES_WITH_MESSAGES) def test_parse_from_random_order(self, structure_and_messages): """ If we shuffle messages and parse them the parser builds a tree of actions that is the same as the one used to generate the messages. Shuffled messages means we have to deal with (temporarily) missing information sufficiently well to be able to parse correctly once the missing information arrives. """ action_structure, messages = structure_and_messages task = Task() for message in messages: task = task.add(message) # Assert parsed structure matches input structure: parsed_structure = ActionStructure.from_written(task.root()) self.assertEqual(parsed_structure, action_structure) @given(structure_and_messages=STRUCTURES_WITH_MESSAGES) def test_is_complete(self, structure_and_messages): """ ``Task.is_complete()`` only returns true when all messages within the tree have been delivered. """ action_structure, messages = structure_and_messages task = Task() completed = [] for message in messages: task = task.add(message) completed.append(task.is_complete()) self.assertEqual(completed, [False for m in messages[:-1]] + [True]) def test_parse_contents(self): """ L{{Task.add}} parses the contents of the messages it receives. """ logger = MemoryLogger() with start_action(logger, action_type="xxx", y=123) as ctx: Message.new(message_type="zzz", z=4).write(logger) ctx.add_success_fields(foo=[1, 2]) messages = logger.messages expected = WrittenAction.from_messages( WrittenMessage.from_dict(messages[0]), [WrittenMessage.from_dict(messages[1])], WrittenMessage.from_dict(messages[2])) task = parse_to_task(messages) self.assertEqual(task.root(), expected) class ParserTests(TestCase): """ Tests for L{Parser}. """ @given(structure_and_messages1=STRUCTURES_WITH_MESSAGES, structure_and_messages2=STRUCTURES_WITH_MESSAGES, structure_and_messages3=STRUCTURES_WITH_MESSAGES) def test_parse_into_tasks(self, structure_and_messages1, structure_and_messages2, structure_and_messages3): """ Adding messages to a L{Parser} parses them into a L{Task} instances. """ _, messages1 = structure_and_messages1 _, messages2 = structure_and_messages2 _, messages3 = structure_and_messages3 all_messages = (messages1, messages2, messages3) # Need unique UUIDs per task: assume(len(set(m[0][TASK_UUID_FIELD] for m in all_messages)) == 3) parser = Parser() all_tasks = [] for message in chain(*zip_longest(*all_messages)): if message is not None: completed_tasks, parser = parser.add(message) all_tasks.extend(completed_tasks) assertCountEqual( self, all_tasks, [parse_to_task(msgs) for msgs in all_messages]) @given(structure_and_messages=STRUCTURES_WITH_MESSAGES) def test_incomplete_tasks(self, structure_and_messages): """ Until a L{Task} is fully parsed, it is returned in L{Parser.incomplete_tasks}. """ _, messages = structure_and_messages parser = Parser() task = Task() incomplete_matches = [] for message in messages[:-1]: _, parser = parser.add(message) task = task.add(message) incomplete_matches.append(parser.incomplete_tasks() == [task]) task = task.add(messages[-1]) _, parser = parser.add(messages[-1]) self.assertEqual( dict(incomplete_matches=incomplete_matches, final_incompleted=parser.incomplete_tasks()), dict(incomplete_matches=[True] * (len(messages) - 1), final_incompleted=[])) @given(structure_and_messages1=STRUCTURES_WITH_MESSAGES, structure_and_messages2=STRUCTURES_WITH_MESSAGES, structure_and_messages3=STRUCTURES_WITH_MESSAGES) def test_parse_stream(self, structure_and_messages1, structure_and_messages2, structure_and_messages3): """ L{Parser.parse_stream} returns an iterable of completed and then incompleted tasks. """ _, messages1 = structure_and_messages1 _, messages2 = structure_and_messages2 _, messages3 = structure_and_messages3 # Need at least one non-dropped message in partial tree: assume(len(messages3) > 1) # Need unique UUIDs per task: assume(len(set(m[0][TASK_UUID_FIELD] for m in (messages1, messages2, messages3))) == 3) # Two complete tasks, one incomplete task: all_messages = (messages1, messages2, messages3[:-1]) all_tasks = list(Parser.parse_stream( [m for m in chain(*zip_longest(*all_messages)) if m is not None])) assertCountEqual( self, all_tasks, [parse_to_task(msgs) for msgs in all_messages]) PKرGjAlrlreliot/tests/test_testing.py""" Tests for L{eliot.testing}. """ from __future__ import unicode_literals from unittest import SkipTest, TestResult, TestCase from ..testing import ( issuperset, assertContainsFields, LoggedAction, LoggedMessage, validateLogging, UnflushedTracebacks, assertHasMessage, assertHasAction, validate_logging, capture_logging, ) from .._output import MemoryLogger from .._action import startAction from .._message import Message from .._validation import ActionType, MessageType, ValidationError, Field from .._traceback import writeTraceback from .. import add_destination, remove_destination, _output class IsSuperSetTests(TestCase): """ Tests for L{issuperset}. """ def test_equal(self): """ Equal dictionaries are supersets of each other. """ a = {"a": 1} b = a.copy() self.assertTrue(issuperset(a, b)) def test_additionalIsSuperSet(self): """ If C{A} is C{B} plus some extra entries, C{A} is superset of C{B}. """ a = {"a": 1, "b": 2, "c": 3} b = {"a": 1, "c": 3} self.assertTrue(issuperset(a, b)) def test_missingIsNotSuperSet(self): """ If C{A} is C{B} minus some entries, C{A} is not a superset of C{B}. """ a = {"a": 1, "c": 3} b = {"a": 1, "b": 2, "c": 3} self.assertFalse(issuperset(a, b)) class LoggedActionTests(TestCase): """ Tests for L{LoggedAction}. """ def test_values(self): """ The values given to the L{LoggedAction} constructor are stored on it. """ d1 = {'x': 1} d2 = {'y': 2} root = LoggedAction(d1, d2, []) self.assertEqual((root.startMessage, root.endMessage), (d1, d2)) def fromMessagesIndex(self, messages, index): """ Call L{LoggedAction.fromMessages} using action specified by index in a list of message dictionaries. @param messages: A C{list} of message dictionaries. @param index: Index to the logger's messages. @return: Result of L{LoggedAction.fromMessages}. """ uuid = messages[index]["task_uuid"] level = messages[index]["task_level"] return LoggedAction.fromMessages(uuid, level, messages) def test_fromMessagesCreatesLoggedAction(self): """ L{LoggedAction.fromMessages} returns a L{LoggedAction}. """ logger = MemoryLogger() with startAction(logger, "test"): pass logged = self.fromMessagesIndex(logger.messages, 0) self.assertIsInstance(logged, LoggedAction) def test_fromMessagesStartAndSuccessfulFinish(self): """ L{LoggedAction.fromMessages} finds the start and successful finish messages of an action and stores them in the result. """ logger = MemoryLogger() Message.new(x=1).write(logger) with startAction(logger, "test"): Message.new(x=1).write(logger) # Now we should have x message, start action message, another x message # and finally finish message. logged = self.fromMessagesIndex(logger.messages, 1) self.assertEqual((logged.startMessage, logged.endMessage), (logger.messages[1], logger.messages[3])) def test_fromMessagesStartAndErrorFinish(self): """ L{LoggedAction.fromMessages} finds the start and successful finish messages of an action and stores them in the result. """ logger = MemoryLogger() try: with startAction(logger, "test"): raise KeyError() except KeyError: pass logged = self.fromMessagesIndex(logger.messages, 0) self.assertEqual((logged.startMessage, logged.endMessage), (logger.messages[0], logger.messages[1])) def test_fromMessagesStartNotFound(self): """ L{LoggedAction.fromMessages} raises a L{ValueError} if a start message is not found. """ logger = MemoryLogger() with startAction(logger, "test"): pass self.assertRaises(ValueError, self.fromMessagesIndex, logger.messages[1:], 0) def test_fromMessagesFinishNotFound(self): """ L{LoggedAction.fromMessages} raises a L{ValueError} if a finish message is not found. """ logger = MemoryLogger() with startAction(logger, "test"): pass self.assertRaises(ValueError, self.fromMessagesIndex, logger.messages[:1], 0) def test_fromMessagesAddsChildMessages(self): """ L{LoggedAction.fromMessages} adds direct child messages to the constructed L{LoggedAction}. """ logger = MemoryLogger() # index 0: Message.new(x=1).write(logger) # index 1 - start action with startAction(logger, "test"): # index 2 Message.new(x=2).write(logger) # index 3 Message.new(x=3).write(logger) # index 4 - end action # index 5 Message.new(x=4).write(logger) logged = self.fromMessagesIndex(logger.messages, 1) expectedChildren = [LoggedMessage(logger.messages[2]), LoggedMessage(logger.messages[3])] self.assertEqual(logged.children, expectedChildren) def test_fromMessagesAddsChildActions(self): """ L{LoggedAction.fromMessages} recursively adds direct child actions to the constructed L{LoggedAction}. """ logger = MemoryLogger() # index 0 with startAction(logger, "test"): # index 1: with startAction(logger, "test"): # index 2 Message.new(x=2).write(logger) # index 3 - end action # index 4 - end action logged = self.fromMessagesIndex(logger.messages, 0) self.assertEqual(logged.children[0], self.fromMessagesIndex(logger.messages, 1)) def test_ofType(self): """ L{LoggedAction.ofType} returns a list of L{LoggedAction} created by the specified L{ActionType}. """ ACTION = ActionType("myaction", [], [], "An action!") logger = MemoryLogger() # index 0 with startAction(logger, "test"): # index 1: with ACTION(logger): # index 2 Message.new(x=2).write(logger) # index 3 - end action # index 4 - end action # index 5 with ACTION(logger): pass # index 6 - end action logged = LoggedAction.ofType(logger.messages, ACTION) self.assertEqual(logged, [self.fromMessagesIndex(logger.messages, 1), self.fromMessagesIndex(logger.messages, 5)]) def test_ofTypeNotFound(self): """ L{LoggedAction.ofType} returns an empty list if actions of the given type cannot be found. """ ACTION = ActionType("myaction", [], [], "An action!") logger = MemoryLogger() self.assertEqual(LoggedAction.ofType(logger.messages, ACTION), []) def test_descendants(self): """ L{LoggedAction.descendants} returns all descendants of the L{LoggedAction}. """ ACTION = ActionType("myaction", [], [], "An action!") logger = MemoryLogger() # index 0 with ACTION(logger): # index 1: with startAction(logger, "test"): # index 2 Message.new(x=2).write(logger) # index 3 - end action # index 4 Message.new(x=2).write(logger) # index 5 - end action loggedAction = LoggedAction.ofType(logger.messages, ACTION)[0] self.assertEqual(list(loggedAction.descendants()), [self.fromMessagesIndex(logger.messages, 1), LoggedMessage(logger.messages[2]), LoggedMessage(logger.messages[4])]) def test_succeeded(self): """ If the action succeeded, L{LoggedAction.succeeded} will be true. """ logger = MemoryLogger() with startAction(logger, "test"): pass logged = self.fromMessagesIndex(logger.messages, 0) self.assertTrue(logged.succeeded) def test_notSucceeded(self): """ If the action failed, L{LoggedAction.succeeded} will be false. """ logger = MemoryLogger() try: with startAction(logger, "test"): raise KeyError() except KeyError: pass logged = self.fromMessagesIndex(logger.messages, 0) self.assertFalse(logged.succeeded) class LoggedMessageTest(TestCase): """ Tests for L{LoggedMessage}. """ def test_values(self): """ The values given to the L{LoggedMessage} constructor are stored on it. """ message = {'x': 1} logged = LoggedMessage(message) self.assertEqual(logged.message, message) def test_ofType(self): """ L{LoggedMessage.ofType} returns a list of L{LoggedMessage} created by the specified L{MessageType}. """ MESSAGE = MessageType("mymessage", [], "A message!") logger = MemoryLogger() # index 0 MESSAGE().write(logger) # index 1 Message.new(x=2).write(logger) # index 2 MESSAGE().write(logger) logged = LoggedMessage.ofType(logger.messages, MESSAGE) self.assertEqual(logged, [LoggedMessage(logger.messages[0]), LoggedMessage(logger.messages[2])]) def test_ofTypeNotFound(self): """ L{LoggedMessage.ofType} returns an empty list if messages of the given type cannot be found. """ MESSAGE = MessageType("mymessage", [], "A message!") logger = MemoryLogger() self.assertEqual(LoggedMessage.ofType(logger.messages, MESSAGE), []) class AssertContainsFields(TestCase): """ Tests for L{assertContainsFields}. """ class ContainsTest(TestCase): """ A test case that uses L{assertContainsFields}. """ def __init__(self, message, expectedFields): TestCase.__init__(self) self.message = message self.expectedFields = expectedFields def runTest(self): assertContainsFields(self, self.message, self.expectedFields) def test_equal(self): """ Equal dictionaries contain each other. """ message = {"a": 1} expected = message.copy() test = self.ContainsTest(message, expected) # No exception raised: test.debug() def test_additionalIsSuperSet(self): """ If C{A} is C{B} plus some extra entries, C{A} contains the fields in C{B}. """ message = {"a": 1, "b": 2, "c": 3} expected = {"a": 1, "c": 3} test = self.ContainsTest(message, expected) # No exception raised: test.debug() def test_missingFields(self): """ If C{A} is C{B} minus some entries, C{A} does not contain the fields in C{B}. """ message = {"a": 1, "c": 3} expected = {"a": 1, "b": 2, "c": 3} test = self.ContainsTest(message, expected) self.assertRaises(AssertionError, test.debug) def test_differentValues(self): """ If C{A} has a different value for a specific field than C{B}, C{A} does not contain the fields in C{B}. """ message = {"a": 1, "c": 3} expected = {"a": 1, "c": 2} test = self.ContainsTest(message, expected) self.assertRaises(AssertionError, test.debug) class ValidateLoggingTestsMixin(object): """ Tests for L{validateLogging} and L{capture_logging}. """ validate = None def test_decoratedFunctionCalledWithMemoryLogger(self): """ The underlying function decorated with L{validateLogging} is called with a L{MemoryLogger} instance in addition to any other arguments if the wrapper is called. """ result = [] class MyTest(TestCase): @self.validate(None) def test_foo(this, logger): result.append((this, logger.__class__)) theTest = MyTest("test_foo") theTest.run() self.assertEqual(result, [(theTest, MemoryLogger)]) def test_newMemoryLogger(self): """ The underlying function decorated with L{validateLogging} is called with a new L{MemoryLogger} every time the wrapper is called. """ result = [] class MyTest(TestCase): @self.validate(None) def test_foo(this, logger): result.append(logger) theTest = MyTest("test_foo") theTest.run() theTest.run() self.assertIsNot(result[0], result[1]) def test_returns(self): """ The result of the underlying function is returned by wrapper when called. """ class MyTest(TestCase): @self.validate(None) def test_foo(self, logger): return 123 self.assertEqual(MyTest("test_foo").test_foo(), 123) def test_raises(self): """ The exception raised by the underlying function is passed through by the wrapper when called. """ exc = Exception() class MyTest(TestCase): @self.validate(None) def test_foo(self, logger): raise exc raised = None try: MyTest("test_foo").debug() except Exception as e: raised = e self.assertIs(exc, raised) def test_name(self): """ The wrapper has the same name as the wrapped function. """ class MyTest(TestCase): @self.validate(None) def test_foo(self, logger): pass self.assertEqual(MyTest.test_foo.__name__, "test_foo") def test_addCleanupValidate(self): """ When a test method is decorated with L{validateLogging} it has L{MemoryLogger.validate} registered as a test cleanup. """ MESSAGE = MessageType("mymessage", [], "A message") class MyTest(TestCase): @self.validate(None) def runTest(self, logger): self.logger = logger logger.write({"message_type": "wrongmessage"}, MESSAGE._serializer) test = MyTest() self.assertRaises(ValidationError, test.debug) self.assertEqual(list(test.logger.messages[0].keys()), ["message_type"]) def test_addCleanupTracebacks(self): """ When a test method is decorated with L{validateLogging} it has has a check unflushed tracebacks in the L{MemoryLogger} registered as a test cleanup. """ class MyTest(TestCase): @self.validate(None) def runTest(self, logger): try: 1 / 0 except ZeroDivisionError: writeTraceback(logger) test = MyTest() self.assertRaises(UnflushedTracebacks, test.debug) def test_assertion(self): """ If a callable is passed to L{validateLogging}, it is called with the L{TestCase} instance and the L{MemoryLogger} passed to the test method. """ result = [] class MyTest(TestCase): def assertLogging(self, logger): result.append((self, logger)) @self.validate(assertLogging) def runTest(self, logger): self.logger = logger test = MyTest() test.run() self.assertEqual(result, [(test, test.logger)]) def test_assertionArguments(self): """ If a callable together with additional arguments and keyword arguments are passed to L{validateLogging}, the callable is called with the additional args and kwargs. """ result = [] class MyTest(TestCase): def assertLogging(self, logger, x, y): result.append((self, logger, x, y)) @self.validate(assertLogging, 1, y=2) def runTest(self, logger): self.logger = logger test = MyTest() test.run() self.assertEqual(result, [(test, test.logger, 1, 2)]) def test_assertionAfterTest(self): """ If a callable is passed to L{validateLogging}, it is called with the after the main test code has run, allowing it to make assertions about log messages from the test. """ class MyTest(TestCase): def assertLogging(self, logger): self.result.append(2) @self.validate(assertLogging) def runTest(self, logger): self.result = [1] test = MyTest() test.run() self.assertEqual(test.result, [1, 2]) def test_assertionBeforeTracebackCleanup(self): """ If a callable is passed to L{validateLogging}, it is called with the before the check for unflushed tracebacks, allowing it to flush traceback log messages. """ class MyTest(TestCase): def assertLogging(self, logger): logger.flushTracebacks(ZeroDivisionError) self.flushed = True @self.validate(assertLogging) def runTest(self, logger): self.flushed = False try: 1 / 0 except ZeroDivisionError: writeTraceback(logger) test = MyTest() test.run() self.assertTrue(test.flushed) class ValidateLoggingTests(ValidateLoggingTestsMixin, TestCase): """ Tests for L{validate_logging}. """ validate = staticmethod(validate_logging) class CaptureLoggingTests(ValidateLoggingTestsMixin, TestCase): """ Tests for L{capture_logging}. """ validate = staticmethod(capture_logging) def setUp(self): # Since we're not always calling the test method via the TestCase # infrastructure, sometimes cleanup methods are not called. This # means the original default logger is not restored. So we do so # manually. If the issue is a bug in capture_logging itself the # tests below will catch that. original_logger = _output._DEFAULT_LOGGER def cleanup(): _output._DEFAULT_LOGGER = original_logger self.addCleanup(cleanup) def test_default_logger(self): """ L{capture_logging} captures messages from logging that doesn't specify a L{Logger}. """ class MyTest(TestCase): @capture_logging(None) def runTest(self, logger): Message.log(some_key=1234) self.logger = logger test = MyTest() test.run() self.assertEqual(test.logger.messages[0][u"some_key"], 1234) def test_global_cleanup(self): """ After the function wrapped with L{capture_logging} finishes, logging that doesn't specify a logger is logged normally. """ class MyTest(TestCase): @capture_logging(None) def runTest(self, logger): pass test = MyTest() test.run() messages = [] add_destination(messages.append) self.addCleanup(remove_destination, messages.append) Message.log(some_key=1234) self.assertEqual(messages[0][u"some_key"], 1234) def test_global_cleanup_exception(self): """ If the function wrapped with L{capture_logging} throws an exception, logging that doesn't specify a logger is logged normally. """ class MyTest(TestCase): @capture_logging(None) def runTest(self, logger): raise RuntimeError() test = MyTest() test.run() messages = [] add_destination(messages.append) self.addCleanup(remove_destination, messages.append) Message.log(some_key=1234) self.assertEqual(messages[0][u"some_key"], 1234) def test_validationNotRunForSkip(self): """ If the decorated test raises L{SkipTest} then the logging validation is also skipped. """ class MyTest(TestCase): recorded = False def record(self, logger): self.recorded = True @validateLogging(record) def runTest(self, logger): raise SkipTest("Do not run this test.") test = MyTest() result = TestResult() test.run(result) # Verify that the validation function did not run and that the test was # nevertheless marked as a skip with the correct reason. self.assertEqual( (test.recorded, result.skipped, result.errors, result.failures), (False, [(test, "Do not run this test.")], [], []) ) def test_unflushedTracebacksDontFailForSkip(self): """ If the decorated test raises L{SkipTest} then the unflushed traceback checking normally implied by L{validateLogging} is also skipped. """ class MyTest(TestCase): @validateLogging(lambda self, logger: None) def runTest(self, logger): try: 1 / 0 except: writeTraceback(logger) raise SkipTest("Do not run this test.") test = MyTest() result = TestResult() test.run(result) # Verify that there was only a skip, no additional errors or failures # reported. self.assertEqual( (1, [], []), (len(result.skipped), result.errors, result.failures) ) MESSAGE1 = MessageType("message1", [Field.forTypes("x", [int], "A number")], "A message for testing.") MESSAGE2 = MessageType("message2", [], "A message for testing.") class AssertHasMessageTests(TestCase): """ Tests for L{assertHasMessage}. """ class UnitTest(TestCase): """ Test case that can be instantiated. """ def runTest(self): pass def test_failIfNoMessagesOfType(self): """ L{assertHasMessage} raises L{AssertionError} if the given L{MemoryLogger} has no messages of the given L{MessageType}. """ test = self.UnitTest() logger = MemoryLogger() MESSAGE1(x=123).write(logger) self.assertRaises(AssertionError, assertHasMessage, test, logger, MESSAGE2) def test_returnsIfMessagesOfType(self): """ L{assertHasMessage} returns the first message of the given L{MessageType}. """ test = self.UnitTest() logger = MemoryLogger() MESSAGE1(x=123).write(logger) self.assertEqual(assertHasMessage(test, logger, MESSAGE1), LoggedMessage.ofType(logger.messages, MESSAGE1)[0]) def test_failIfNotSubset(self): """ L{assertHasMessage} raises L{AssertionError} if the found message doesn't contain the given fields. """ test = self.UnitTest() logger = MemoryLogger() MESSAGE1(x=123).write(logger) self.assertRaises(AssertionError, assertHasMessage, test, logger, MESSAGE1, {"x": 24}) def test_returnsIfSubset(self): """ L{assertHasMessage} returns the first message of the given L{MessageType} if it contains the given fields. """ test = self.UnitTest() logger = MemoryLogger() MESSAGE1(x=123).write(logger) self.assertEqual(assertHasMessage(test, logger, MESSAGE1, {"x": 123}), LoggedMessage.ofType(logger.messages, MESSAGE1)[0]) ACTION1 = ActionType("action1", [Field.forTypes("x", [int], "A number")], [Field.forTypes("result", [int], "A number")], "A action for testing.") ACTION2 = ActionType("action2", [], [], "A action for testing.") class AssertHasActionTests(TestCase): """ Tests for L{assertHasAction}. """ class UnitTest(TestCase): """ Test case that can be instantiated. """ def runTest(self): pass def test_failIfNoActionsOfType(self): """ L{assertHasAction} raises L{AssertionError} if the given L{MemoryLogger} has no actions of the given L{ActionType}. """ test = self.UnitTest() logger = MemoryLogger() with ACTION1(logger, x=123): pass self.assertRaises(AssertionError, assertHasAction, test, logger, ACTION2, True) def test_failIfWrongSuccessStatus(self): """ L{assertHasAction} raises L{AssertionError} if the given success status does not match that of the found actions. """ test = self.UnitTest() logger = MemoryLogger() with ACTION1(logger, x=123): pass try: with ACTION2(logger): 1/0 except ZeroDivisionError: pass self.assertRaises(AssertionError, assertHasAction, test, logger, ACTION1, False) self.assertRaises(AssertionError, assertHasAction, test, logger, ACTION2, True) def test_returnsIfMessagesOfType(self): """ A successful L{assertHasAction} returns the first message of the given L{ActionType}. """ test = self.UnitTest() logger = MemoryLogger() with ACTION1(logger, x=123): pass self.assertEqual(assertHasAction(test, logger, ACTION1, True), LoggedAction.ofType(logger.messages, ACTION1)[0]) def test_failIfNotStartSubset(self): """ L{assertHasAction} raises L{AssertionError} if the found action doesn't contain the given start fields. """ test = self.UnitTest() logger = MemoryLogger() with ACTION1(logger, x=123): pass self.assertRaises(AssertionError, assertHasAction, test, logger, ACTION1, True, {"x": 24}) def test_failIfNotEndSubset(self): """ L{assertHasAction} raises L{AssertionError} if the found action doesn't contain the given end fields. """ test = self.UnitTest() logger = MemoryLogger() with ACTION1(logger, x=123) as act: act.addSuccessFields(result=5) self.assertRaises(AssertionError, assertHasAction, test, logger, ACTION1, True, startFields={"x": 123}, endFields={"result": 24}) def test_returns(self): """ A successful L{assertHasAction} returns the first message of the given L{ActionType} after doing all validation. """ test = self.UnitTest() logger = MemoryLogger() with ACTION1(logger, x=123) as act: act.addSuccessFields(result=5) self.assertEqual( assertHasAction(test, logger, ACTION1, True, {"x": 123}, {"result": 5}), LoggedAction.ofType(logger.messages, ACTION1)[0]) class PEP8Tests(TestCase): """ Tests for PEP 8 method compatibility. """ def test_LoggedAction_from_messages(self): """ L{LoggedAction.from_messages} is the same as L{LoggedAction.fromMessages}. """ self.assertEqual(LoggedAction.from_messages, LoggedAction.fromMessages) def test_LoggedAction_of_type(self): """ L{LoggedAction.of_type} is the same as L{LoggedAction.ofType}. """ self.assertEqual(LoggedAction.of_type, LoggedAction.ofType) def test_LoggedAction_end_message(self): """ L{LoggedAction.end_message} is the same as L{LoggedAction.endMessage}. """ action = LoggedAction({1: 2}, {3: 4}, []) self.assertEqual(action.end_message, action.endMessage) def test_LoggedAction_start_message(self): """ L{LoggedAction.start_message} is the same as L{LoggedAction.startMessage}. """ action = LoggedAction({1: 2}, {3: 4}, []) self.assertEqual(action.start_message, action.startMessage) def test_LoggedMessage_of_type(self): """ L{LoggedMessage.of_type} is the same as L{LoggedMessage.ofType}. """ self.assertEqual(LoggedMessage.of_type, LoggedMessage.ofType) def test_validate_logging(self): """ L{validate_logging} is the same as L{validateLogging}. """ self.assertEqual(validate_logging, validateLogging) PK⡁GƬeliot/tests/test_journald.py""" Tests for L{eliot.journald}. """ from os import getpid, strerror from unittest import skipUnless, TestCase from subprocess import check_output, CalledProcessError, STDOUT from errno import EINVAL from sys import argv from uuid import uuid4 from time import sleep from six import text_type as unicode from .._bytesjson import loads from .._output import MemoryLogger from .._message import TASK_UUID_FIELD from .. import start_action, Message, write_traceback try: from ..journald import sd_journal_send, JournaldDestination except ImportError: sd_journal_send = None def _journald_available(): """ :return: Boolean indicating whether journald is available to use. """ if sd_journal_send is None: return False try: check_output(["journalctl", "-b", "-n1"], stderr=STDOUT) except CalledProcessError: return False return True def last_journald_message(): """ @return: Last journald message from this process as a dictionary in journald JSON format. """ # It may take a little for messages to actually reach journald, so we # write out marker message and wait until it arrives. We can then be # sure the message right before it is the one we want. marker = unicode(uuid4()) sd_journal_send(MESSAGE=marker.encode("ascii")) for i in range(500): messages = check_output( [b"journalctl", b"-a", b"-o", b"json", b"-n2", b"_PID=" + str(getpid()).encode("ascii")]) messages = [loads(m) for m in messages.splitlines()] if len(messages) == 2 and messages[1]["MESSAGE"] == marker: return messages[0] sleep(0.01) raise RuntimeError("Message never arrived?!") class SdJournaldSendTests(TestCase): """ Functional tests for L{sd_journal_send}. """ @skipUnless(_journald_available(), "journald unavailable or inactive on this machine.") def setUp(self): pass def assert_roundtrip(self, value): """ Write a value as a C{MESSAGE} field, assert it is output. @param value: Value to write as unicode. """ sd_journal_send(MESSAGE=value) result = last_journald_message() self.assertEqual(value, result["MESSAGE"].encode("utf-8")) def test_message(self): """ L{sd_journal_send} can write a C{MESSAGE} field. """ self.assert_roundtrip(b"hello") def test_percent(self): """ L{sd_journal_send} can write a C{MESSAGE} field with a percent. Underlying C API calls does printf formatting so this is a plausible failure mode. """ self.assert_roundtrip(b"hello%world") def test_large(self): """ L{sd_journal_send} can write a C{MESSAGE} field with a large message. """ self.assert_roundtrip(b"hello world" * 20000) def test_multiple_fields(self): """ L{sd_journal_send} can send multiple fields. """ sd_journal_send(MESSAGE=b"hello", BONUS_FIELD=b"world") result = last_journald_message() self.assertEqual((b"hello", b"world"), (result["MESSAGE"].encode("ascii"), result["BONUS_FIELD"].encode("ascii"))) def test_error(self): """ L{sd_journal_send} raises an error when it gets a non-0 result from the underlying API. """ with self.assertRaises(IOError) as context: sd_journal_send(**{"": b"123"}) exc = context.exception self.assertEqual((exc.errno, exc.strerror), (EINVAL, strerror(EINVAL))) class JournaldDestinationTests(TestCase): """ Tests for L{JournaldDestination}. """ @skipUnless(_journald_available(), "journald unavailable or inactive on this machine.") def setUp(self): self.destination = JournaldDestination() self.logger = MemoryLogger() def test_json(self): """ The message is stored as JSON in the MESSAGE field. """ Message.new(hello="world", key=123).write(self.logger) message = self.logger.messages[0] self.destination(message) self.assertEqual(loads(last_journald_message()["MESSAGE"]), message) def assert_field_for(self, message, field_name, field_value): """ If the given message is logged by Eliot, the given journald field has the expected value. @param message: Dictionary to log. @param field_name: Journald field name to check. @param field_value: Expected value for the field. """ self.destination(message) self.assertEqual(last_journald_message()[field_name], field_value) def test_action_type(self): """ The C{action_type} is stored in the ELIOT_TYPE field. """ action_type = "test:type" start_action(self.logger, action_type=action_type) self.assert_field_for(self.logger.messages[0], "ELIOT_TYPE", action_type) def test_message_type(self): """ The C{message_type} is stored in the ELIOT_TYPE field. """ message_type = "test:type:message" Message.new(message_type=message_type).write(self.logger) self.assert_field_for(self.logger.messages[0], "ELIOT_TYPE", message_type) def test_no_type(self): """ An empty string is stored in ELIOT_TYPE if no type is known. """ Message.new().write(self.logger) self.assert_field_for(self.logger.messages[0], "ELIOT_TYPE", "") def test_uuid(self): """ The task UUID is stored in the ELIOT_TASK field. """ start_action(self.logger, action_type="xxx") self.assert_field_for(self.logger.messages[0], "ELIOT_TASK", self.logger.messages[0][TASK_UUID_FIELD]) def test_info_priorities(self): """ Untyped messages, action start, successful action end, random typed message all get priority 6 ("info"). """ with start_action(self.logger, action_type="xxx"): Message.new(message_type="msg").write(self.logger) Message.new(x=123).write(self.logger) priorities = [] for message in self.logger.messages: self.destination(message) priorities.append(last_journald_message()["PRIORITY"]) self.assertEqual(priorities, [u"6", u"6", u"6", u"6"]) def test_error_priority(self): """ A failed action gets priority 3 ("error"). """ try: with start_action(self.logger, action_type="xxx"): raise ZeroDivisionError() except ZeroDivisionError: pass self.assert_field_for(self.logger.messages[-1], "PRIORITY", u"3") def test_critical_priority(self): """ A traceback gets priority 2 ("critical"). """ try: raise ZeroDivisionError() except ZeroDivisionError: write_traceback(logger=self.logger) self.assert_field_for(self.logger.serialize()[-1], "PRIORITY", u"2") def test_identifier(self): """ C{SYSLOG_IDENTIFIER} defaults to C{os.path.basename(sys.argv[0])}. """ identifier = "/usr/bin/testing123" try: original = argv[0] argv[0] = identifier # Recreate JournaldDestination with the newly set argv[0]. self.destination = JournaldDestination() Message.new(message_type="msg").write(self.logger) self.assert_field_for(self.logger.messages[0], "SYSLOG_IDENTIFIER", u"testing123") finally: argv[0] = original PKGQeliot/tests/test_traceback.py""" Tests for L{eliot._traceback}. """ from __future__ import unicode_literals from unittest import TestCase, SkipTest from warnings import catch_warnings, simplefilter import traceback import sys try: from twisted.python.failure import Failure except ImportError: Failure = None from .._traceback import writeTraceback, writeFailure, _writeTracebackMessage from ..testing import ( assertContainsFields, validateLogging, capture_logging, MemoryLogger, ) from .._errors import register_exception_extractor from .test_action import make_error_extraction_tests class TracebackLoggingTests(TestCase): """ Tests for L{writeTraceback} and L{writeFailure}. """ @validateLogging(None) def test_writeTraceback(self, logger): """ L{writeTraceback} writes the current traceback to the log. """ e = None def raiser(): raise RuntimeError("because") try: raiser() except Exception as exception: expectedTraceback = traceback.format_exc() writeTraceback(logger) e = exception lines = expectedTraceback.split("\n") # Remove source code lines: expectedTraceback = "\n".join( [l for l in lines if not l.startswith(" ")]) message = logger.messages[0] assertContainsFields(self, message, {"message_type": "eliot:traceback", "exception": RuntimeError, "reason": e, "traceback": expectedTraceback}) logger.flushTracebacks(RuntimeError) @capture_logging(None) def test_writeTracebackDefaultLogger(self, logger): """ L{writeTraceback} writes to the default log, if none is specified. """ def raiser(): raise RuntimeError("because") try: raiser() except Exception: writeTraceback() message = logger.messages[0] assertContainsFields(self, message, {"message_type": "eliot:traceback"}) logger.flushTracebacks(RuntimeError) @validateLogging(None) def test_writeFailure(self, logger): """ L{writeFailure} writes a L{Failure} to the log. """ if Failure is None: raise SkipTest("Twisted unavailable") try: raise RuntimeError("because") except: failure = Failure() expectedTraceback = failure.getBriefTraceback() writeFailure(failure, logger) message = logger.messages[0] assertContainsFields(self, message, {"message_type": "eliot:traceback", "exception": RuntimeError, "reason": failure.value, "traceback": expectedTraceback}) logger.flushTracebacks(RuntimeError) @capture_logging(None) def test_writeFailureDefaultLogger(self, logger): """ L{writeFailure} writes to the default log, if none is specified. """ if Failure is None: raise SkipTest("Twisted unavailable") try: raise RuntimeError("because") except: failure = Failure() writeFailure(failure) message = logger.messages[0] assertContainsFields(self, message, {"message_type": "eliot:traceback"}) logger.flushTracebacks(RuntimeError) @validateLogging(None) def test_writeFailureResult(self, logger): """ L{writeFailure} returns C{None}. """ if Failure is None: raise SkipTest("Twisted unavailable") try: raise RuntimeError("because") except: result = writeFailure(Failure(), logger) self.assertIs(result, None) logger.flushTracebacks(RuntimeError) @validateLogging(None) def test_serialization(self, logger): """ L{_writeTracebackMessage} serializes exceptions to string values and types to FQPN. """ try: raise KeyError(123) except: exc_info = sys.exc_info() _writeTracebackMessage(logger, *exc_info) serialized = logger.serialize()[0] assertContainsFields(self, serialized, {"exception": "%s.KeyError" % (KeyError.__module__,), "reason": "123"}) logger.flushTracebacks(KeyError) @validateLogging(None) def test_badException(self, logger): """ L{_writeTracebackMessage} logs a message even if given a bad exception. """ class BadException(Exception): def __str__(self): raise TypeError() try: raise BadException() except BadException: exc_info = sys.exc_info() _writeTracebackMessage(logger, *exc_info) self.assertEqual(logger.serialize()[0]["reason"], "eliot: unknown, unicode() raised exception") logger.flushTracebacks(BadException) def test_systemDeprecatedWriteTraceback(self): """ L{writeTraceback} warns with C{DeprecationWarning} if a C{system} argument is passed in. """ logger = MemoryLogger() with catch_warnings(record=True) as warnings: simplefilter("always") try: raise Exception() except: writeTraceback(logger, "system") self.assertEqual(warnings[-1].category, DeprecationWarning) def test_systemDeprecatedWriteFailure(self): """ L{writeTraceback} warns with C{DeprecationWarning} if a C{system} argument is passed in. """ if Failure is None: raise SkipTest("Twisted unavailable") logger = MemoryLogger() with catch_warnings(record=True) as warnings: simplefilter("always") try: raise Exception() except: writeFailure(Failure(), logger, "system") self.assertEqual(warnings[-1].category, DeprecationWarning) def get_traceback_messages(exception): """ Given an exception instance generate a traceback Eliot message. """ logger = MemoryLogger() try: raise exception except exception.__class__: writeTraceback(logger) # MemoryLogger.validate() mutates messages: # https://github.com/ClusterHQ/eliot/issues/243 messages = [message.copy() for message in logger.messages] logger.validate() return messages class TracebackExtractionTests( make_error_extraction_tests(get_traceback_messages)): """ Error extraction tests for tracebacks. """ def test_regular_fields(self): """ The normal traceback fields are still present when error extraction is used. """ class MyException(Exception): pass register_exception_extractor(MyException, lambda e: {"key": e.args[0]}) exception = MyException("because") messages = get_traceback_messages(exception) assertContainsFields(self, messages[0], {"message_type": "eliot:traceback", "reason": exception, "exception": MyException}) PKW=G#>WWeliot/tests/test_output.py""" Tests for L{eliot._output}. """ from __future__ import unicode_literals from sys import stdout from unittest import TestCase, skipIf # Make sure to use StringIO that only accepts unicode: from io import BytesIO, StringIO import json as pyjson from tempfile import mktemp from time import time from uuid import UUID from six import PY3, PY2 from zope.interface.verify import verifyClass from .._output import ( MemoryLogger, ILogger, Destinations, Logger, fast_json as json, to_file, FileDestination, _DestinationsSendError ) from .._validation import ValidationError, Field, _MessageSerializer from .._traceback import writeTraceback from ..testing import assertContainsFields class MemoryLoggerTests(TestCase): """ Tests for L{MemoryLogger}. """ def test_interface(self): """ L{MemoryLogger} implements L{ILogger}. """ verifyClass(ILogger, MemoryLogger) def test_write(self): """ Dictionaries written with L{MemoryLogger.write} are stored on a list. """ logger = MemoryLogger() logger.write({'a': 'b'}) logger.write({'c': 1}) self.assertEqual(logger.messages, [{'a': 'b'}, {'c': 1}]) logger.validate() def test_notStringFieldKeys(self): """ Field keys must be unicode or bytes; if not L{MemoryLogger.validate} raises a C{TypeError}. """ logger = MemoryLogger() logger.write({123: 'b'}) self.assertRaises(TypeError, logger.validate) @skipIf(PY3, "Python 3 json module makes it impossible to use bytes as keys") def test_bytesFieldKeys(self): """ Field keys can be bytes containing utf-8 encoded Unicode. """ logger = MemoryLogger() logger.write({u'\u1234'.encode("utf-8"): 'b'}) logger.validate() def test_bytesMustBeUTF8(self): """ Field keys can be bytes, but only if they're UTF-8 encoded Unicode. """ logger = MemoryLogger() logger.write({'\u1234'.encode("utf-16"): 'b'}) self.assertRaises(UnicodeDecodeError, logger.validate) def test_serializer(self): """ L{MemoryLogger.validate} calls the given serializer's C{validate()} method with the message. """ class FakeValidator(list): def validate(self, message): self.append(message) def serialize(self, obj): return obj validator = FakeValidator() logger = MemoryLogger() message = {"message_type": "mymessage", "X": 1} logger.write(message, validator) self.assertEqual(validator, []) logger.validate() self.assertEqual(validator, [message]) def test_failedValidation(self): """ L{MemoryLogger.validate} will allow exceptions raised by the serializer to pass through. """ serializer = _MessageSerializer( [Field.forValue("message_type", "mymessage", u"The type")]) logger = MemoryLogger() logger.write({"message_type": "wrongtype"}, serializer) self.assertRaises(ValidationError, logger.validate) def test_JSON(self): """ L{MemoryLogger.validate} will encode the output of serialization to JSON. """ serializer = _MessageSerializer( [Field.forValue("message_type", "type", u"The type"), Field("foo", lambda value: object(), u"The type")]) logger = MemoryLogger() logger.write({"message_type": "type", "foo": "will become object()"}, serializer) self.assertRaises(TypeError, logger.validate) def test_serialize(self): """ L{MemoryLogger.serialize} returns a list of serialized versions of the logged messages. """ serializer = _MessageSerializer( [Field.forValue("message_type", "mymessage", "The type"), Field("length", len, "The length")]) messages = [{"message_type": "mymessage", "length": "abc"}, {"message_type": "mymessage", "length": "abcd"}] logger = MemoryLogger() for message in messages: logger.write(message, serializer) self.assertEqual(logger.serialize(), [{"message_type": "mymessage", "length": 3}, {"message_type": "mymessage", "length": 4}]) def test_serializeCopies(self): """ L{MemoryLogger.serialize} does not mutate the original logged messages. """ serializer = _MessageSerializer( [Field.forValue("message_type", "mymessage", "The type"), Field("length", len, "The length")]) message = {"message_type": "mymessage", "length": "abc"} logger = MemoryLogger() logger.write(message, serializer) logger.serialize() self.assertEqual(logger.messages[0]["length"], "abc") def writeTraceback(self, logger, exception): """ Write an exception as a traceback to the logger. """ try: raise exception except: writeTraceback(logger) def test_tracebacksCauseTestFailure(self): """ Logging a traceback to L{MemoryLogger} will add its exception to L{MemoryLogger.tracebackMessages}. """ logger = MemoryLogger() exception = Exception() self.writeTraceback(logger, exception) self.assertEqual(logger.tracebackMessages[0]["reason"], exception) def test_flushTracebacksNoTestFailure(self): """ Any tracebacks cleared by L{MemoryLogger.flushTracebacks} (as specified by exception type) are removed from L{MemoryLogger.tracebackMessages}. """ logger = MemoryLogger() exception = RuntimeError() self.writeTraceback(logger, exception) logger.flushTracebacks(RuntimeError) self.assertEqual(logger.tracebackMessages, []) def test_flushTracebacksReturnsExceptions(self): """ L{MemoryLogger.flushTracebacks} returns the traceback messages. """ exceptions = [ZeroDivisionError(), ZeroDivisionError()] logger = MemoryLogger() logger.write({"x": 1}) for exc in exceptions: self.writeTraceback(logger, exc) logger.write({"x": 1}) flushed = logger.flushTracebacks(ZeroDivisionError) self.assertEqual(flushed, logger.messages[1:3]) def test_flushTracebacksUnflushedTestFailure(self): """ Any tracebacks uncleared by L{MemoryLogger.flushTracebacks} (because they are of a different type) are still listed in L{MemoryLogger.tracebackMessages}. """ logger = MemoryLogger() exception = RuntimeError() self.writeTraceback(logger, exception) logger.flushTracebacks(KeyError) self.assertEqual(logger.tracebackMessages[0]["reason"], exception) def test_flushTracebacksUnflushedUnreturned(self): """ Any tracebacks uncleared by L{MemoryLogger.flushTracebacks} (because they are of a different type) are not returned. """ logger = MemoryLogger() exception = RuntimeError() self.writeTraceback(logger, exception) self.assertEqual(logger.flushTracebacks(KeyError), []) def test_reset(self): """ L{MemoryLogger.reset} clears all logged messages and tracebacks. """ logger = MemoryLogger() logger.write({"key": "value"}, None) logger.reset() self.assertEqual( (logger.messages, logger.serializers, logger.tracebackMessages), ([], [], [])) class MyException(Exception): """ Custom exception. """ class BadDestination(list): """ A destination that throws an exception the first time it is called. """ called = 0 def __call__(self, msg): if not self.called: self.called = True raise MyException("ono") self.append(msg) class DestinationsTests(TestCase): """ Tests for L{Destinations}. """ def test_send(self): """ L{Destinations.send} calls all destinations added with L{Destinations.add} with the given dictionary. """ destinations = Destinations() message = {"hoorj": "blargh"} dest = [] dest2 = [] destinations.add(dest.append) destinations.add(dest2.append) destinations.send(message) self.assertEqual(dest, [message]) self.assertEqual(dest2, [message]) def test_destinationExceptionMultipleDestinations(self): """ If one destination throws an exception, other destinations still get the message. """ destinations = Destinations() dest = [] dest2 = BadDestination() dest3 = [] destinations.add(dest.append) destinations.add(dest2) destinations.add(dest3.append) message = {u"hello": 123} self.assertRaises(_DestinationsSendError, destinations.send, {u"hello": 123}) self.assertEqual((dest, dest3), ([message], [message])) def test_destinationExceptionContinue(self): """ If a destination throws an exception, future messages are still sent to it. """ destinations = Destinations() dest = BadDestination() destinations.add(dest) self.assertRaises(_DestinationsSendError, destinations.send, {u"hello": 123}) destinations.send({u"hello": 200}) self.assertEqual(dest, [{u"hello": 200}]) def test_remove(self): """ A destination removed with L{Destinations.remove} will no longer receive messages from L{Destionations.add} calls. """ destinations = Destinations() message = {u"hello": 123} dest = [] destinations.add(dest.append) destinations.remove(dest.append) destinations.send(message) self.assertEqual(dest, []) def test_removeNonExistent(self): """ Removing a destination that has not previously been added with result in a C{ValueError} being thrown. """ destinations = Destinations() self.assertRaises(ValueError, destinations.remove, [].append) def test_addGlobalFields(self): """ L{Destinations.addGlobalFields} adds the given fields and values to the messages being passed in. """ destinations = Destinations() dest = [] destinations.add(dest.append) destinations.addGlobalFields(x=123, y="hello") destinations.send({"z": 456}) self.assertEqual(dest, [{"x": 123, "y": "hello", "z": 456}]) def test_addGlobalFieldsCumulative(self): """ L{Destinations.addGlobalFields} adds the given fields to those set by previous calls. """ destinations = Destinations() dest = [] destinations.add(dest.append) destinations.addGlobalFields(x=123, y="hello") destinations.addGlobalFields(x=456, z=456) destinations.send({"msg": "X"}) self.assertEqual(dest, [{"x": 456, "y": "hello", "z": 456, "msg": "X"}]) def makeLogger(): """ Return a tuple (L{Logger} instance, C{list} of written messages). """ logger = Logger() logger._destinations = Destinations() written = [] logger._destinations.add(written.append) return logger, written class LoggerTests(TestCase): """ Tests for L{Logger}. """ def test_interface(self): """ L{Logger} implements L{ILogger}. """ verifyClass(ILogger, Logger) def test_global(self): """ A global L{Destinations} is used by the L{Logger} class. """ self.assertIsInstance(Logger._destinations, Destinations) def test_write(self): """ L{Logger.write} sends the given dictionary L{Destinations} object. """ logger, written = makeLogger() d = {"hello": 1} logger.write(d) self.assertEqual(written, [d]) def test_serializer(self): """ If a L{_MessageSerializer} is passed to L{Logger.write}, it is used to serialize the message before it is passed to the destination. """ logger, written = makeLogger() serializer = _MessageSerializer( [Field.forValue("message_type", "mymessage", u"The type"), Field("length", len, "The length of a thing"), ]) logger.write({"message_type": "mymessage", "length": "thething"}, serializer) self.assertEqual(written, [{"message_type": "mymessage", "length": 8}]) def test_passedInDictionaryUnmodified(self): """ The dictionary passed in to L{Logger.write} is not modified. """ logger, written = makeLogger() serializer = _MessageSerializer( [Field.forValue("message_type", "mymessage", u"The type"), Field("length", len, "The length of a thing"), ]) d = {"message_type": "mymessage", "length": "thething"} original = d.copy() logger.write(d, serializer) self.assertEqual(d, original) def test_safeUnicodeDictionary(self): """ L{Logger._safeUnicodeDictionary} converts the given dictionary's values and keys to unicode using C{safeunicode}. """ class badobject(object): def __repr__(self): raise TypeError() dictionary = {badobject(): 123, 123: badobject()} badMessage = "eliot: unknown, unicode() raised exception" self.assertEqual(eval(Logger()._safeUnicodeDictionary(dictionary)), {badMessage: "123", "123": badMessage}) def test_safeUnicodeDictionaryFallback(self): """ If converting the dictionary failed for some reason, L{Logger._safeUnicodeDictionary} runs C{repr} on the object. """ self.assertEqual(Logger()._safeUnicodeDictionary(None), "None") def test_safeUnicodeDictionaryFallbackFailure(self): """ If all else fails, L{Logger._safeUnicodeDictionary} just gives up. """ class badobject(object): def __repr__(self): raise TypeError() self.assertEqual(Logger()._safeUnicodeDictionary(badobject()), "eliot: unknown, unicode() raised exception") def test_serializationErrorTraceback(self): """ If serialization fails in L{Logger.write}, a traceback is logged, along with a C{eliot:serialization_failure} message for debugging purposes. """ logger, written = makeLogger() def raiser(i): raise RuntimeError("oops") serializer = _MessageSerializer( [Field.forValue("message_type", "mymessage", u"The type"), Field("fail", raiser, "Serialization fail"), ]) message = {"message_type": "mymessage", "fail": "will"} logger.write(message, serializer) self.assertEqual(len(written), 2) tracebackMessage = written[0] assertContainsFields(self, tracebackMessage, {'exception': '%s.RuntimeError' % (RuntimeError.__module__,), 'message_type': 'eliot:traceback'}) self.assertIn("RuntimeError: oops", tracebackMessage['traceback']) # Calling _safeUnicodeDictionary multiple times leads to # inconsistent results due to hash ordering, so compare contents: assertContainsFields(self, written[1], {"message_type": "eliot:serialization_failure"}) self.assertEqual(eval(written[1]["message"]), dict((repr(key), repr(value)) for (key, value) in message.items())) def test_destinationExceptionCaught(self): """ If a destination throws an exception, an appropriate error is logged. """ logger = Logger() logger._destinations = Destinations() dest = BadDestination() logger._destinations.add(dest) message = {"hello": 123} logger.write({"hello": 123}) assertContainsFields( self, dest[0], {"message_type": "eliot:destination_failure", "message": logger._safeUnicodeDictionary(message), "reason": "ono", "exception": "eliot.tests.test_output.MyException"}) def test_destinationMultipleExceptionsCaught(self): """ If multiple destinations throw an exception, an appropriate error is logged for each. """ logger = Logger() logger._destinations = Destinations() logger._destinations.add(BadDestination()) logger._destinations.add(lambda msg: 1/0) messages = [] logger._destinations.add(messages.append) try: 1/0 except ZeroDivisionError as e: zero_divide = str(e) zero_type = ZeroDivisionError.__module__ + ".ZeroDivisionError" message = {"hello": 123} logger.write({"hello": 123}) def remove(key): return [message.pop(key) for message in messages[1:]] # Make sure we have task_level & task_uuid in exception messages. task_levels = remove(u"task_level") task_uuids = remove(u"task_uuid") timestamps = remove(u"timestamp") self.assertEqual( (abs(timestamps[0] + timestamps[1] - 2 * time()) < 1, task_levels == [[1], [1]], len([UUID(uuid) for uuid in task_uuids]) == 2, messages), (True, True, True, [message, {"message_type": "eliot:destination_failure", "message": logger._safeUnicodeDictionary(message), "reason": "ono", "exception": "eliot.tests.test_output.MyException"}, {"message_type": "eliot:destination_failure", "message": logger._safeUnicodeDictionary(message), "reason": zero_divide, "exception": zero_type}])) def test_destinationExceptionCaughtTwice(self): """ If a destination throws an exception, and the logged error about it also causes an exception, then just drop that exception on the floor, since there's nothing we can do with it. """ logger = Logger() logger._destinations = Destinations() def always_raise(message): raise ZeroDivisionError() logger._destinations.add(always_raise) # No exception raised; since everything is dropped no other # assertions to be made. logger.write({"hello": 123}) class JSONTests(TestCase): """ Tests for the L{json} object exposed by L{eliot._output}. """ @skipIf(PY3, "Python 3 json does not support bytes as keys") def test_bytes(self): """ L{json.dumps} uses a JSON encoder that assumes any C{bytes} are UTF-8 encoded Unicode. """ d = {"hello \u1234".encode("utf-8"): "\u5678".encode("utf-8")} result = json.dumps(d) self.assertEqual(json.loads(result), {"hello \u1234": "\u5678"}) class PEP8Tests(TestCase): """ Tests for PEP 8 method compatibility. """ def test_flush_tracebacks(self): """ L{MemoryLogger.flush_tracebacks} is the same as L{MemoryLogger.flushTracebacks} """ self.assertEqual(MemoryLogger.flush_tracebacks, MemoryLogger.flushTracebacks) class ToFileTests(TestCase): """ Tests for L{to_file}. """ def test_to_file_adds_destination(self): """ L{to_file} adds a L{FileDestination} destination with the given file. """ f = stdout to_file(f) expected = FileDestination(file=f) self.addCleanup(Logger._destinations.remove, expected) self.assertIn(expected, Logger._destinations._destinations) def test_filedestination_writes_json_bytes(self): """ L{FileDestination} writes JSON-encoded messages to a file that accepts bytes. """ message1 = {"x": 123} message2 = {"y": None, "x": "abc"} bytes_f = BytesIO() destination = FileDestination(file=bytes_f) destination(message1) destination(message2) self.assertEqual( [json.loads(line) for line in bytes_f.getvalue().splitlines()], [message1, message2]) def test_filedestination_flushes(self): """ L{FileDestination} flushes after every write, to ensure logs get written out even if the local buffer hasn't filled up. """ path = mktemp() # File with large buffer: f = open(path, "wb", 1024 * 1024 * 10) # and a small message that won't fill the buffer: message1 = {"x": 123} destination = FileDestination(file=f) destination(message1) # Message got written even though buffer wasn't filled: self.assertEqual( [json.loads(line) for line in open(path, "rb").read().splitlines()], [message1]) @skipIf(PY2, "Python 2 files always accept bytes") def test_filedestination_writes_json_unicode(self): """ L{FileDestination} writes JSON-encoded messages to file that only accepts Unicode. """ message = {"x": "\u1234"} unicode_f = StringIO() destination = FileDestination(file=unicode_f) destination(message) self.assertEqual(pyjson.loads(unicode_f.getvalue()), message) PKPxE;z eliot/tests/test_serializers.py""" Tests for L{eliot.serializers}. """ from __future__ import unicode_literals from unittest import TestCase from datetime import datetime from hashlib import md5 from ..serializers import timestamp, identity, md5hex class SerializerTests(TestCase): """ Tests for standard serializers. """ def test_timestamp(self): """ L{timestamp} converts a UTC L{datetime} to a Unicode strings. """ dt = datetime(2012, 9, 28, 14, 53, 6, 123456) self.assertEqual(timestamp(dt), "2012-09-28T14:53:06.123456Z") def test_identity(self): """ L{identity} returns the input object. """ obj = object() self.assertIs(identity(obj), obj) def test_md5hex(self): """ L{md5hex} returns the hex value of a MD5 checksum. """ data = b"01234456789" self.assertEqual(md5hex(data), md5(data).hexdigest()) PKGpOreliot/tests/test_util.py""" Tests for L{eliot._util}. """ from __future__ import unicode_literals from unittest import TestCase import pprint from .._util import load_module class LoadModuleTests(TestCase): """ Tests for L{load_module}. """ maxDiff = None def test_returns_module(self): """ L{load_module} returns an object with same methods as original module. """ loaded = load_module(str("copy"), pprint) obj = [1, 2, b"hello"] self.assertEqual(loaded.pformat(obj), pprint.pformat(obj)) def test_name(self): """ L{load_module} returns an object with the given name. """ name = str("my_copy") loaded = load_module(name, pprint) self.assertEqual(loaded.__name__, name) def test_distinct_from_original(self): """ L{load_module} returns a distinct object from the original module. """ loaded = load_module(str("copy"), pprint) # Override repr in copy: loaded.repr = lambda o: str("OVERRIDE") # Demonstrate that override applies to copy but not original: self.assertEqual( dict(original=pprint.pformat(123), loaded=loaded.pformat(123)), dict(original='123', loaded="OVERRIDE")) PKPxEuBBeliot/tests/test_tai64n.py""" Tests for L{eliot.tai64n}. """ from __future__ import unicode_literals import errno import time import subprocess from unittest import TestCase, SkipTest from ..tai64n import encode, decode class CodecTests(TestCase): """ Tests for L{encode} and L{decode}. """ def test_encode(self): """ L{encode} encodes timestamps in TAI64N format. """ t = 1387299889.153187625 self.assertEqual(encode(t), "@4000000052b0843b092174b9") def test_decode(self): """ L{decode} decodes timestamps from TAI64N format. """ t = time.time() self.assertAlmostEqual(t, decode(encode(t)), 9) class FunctionalTests(TestCase): """ Functional tests for L{encode}. """ def test_encode(self): """ The daemontools tai64nlocal tool can correctly decode timestamps output by L{encode}. """ try: process = subprocess.Popen(["tai64nlocal"], bufsize=4096, stdin=subprocess.PIPE, stdout=subprocess.PIPE) except OSError as e: if e.errno == errno.ENOENT: raise SkipTest("This test requires the daemontools package") else: raise # Because of limitations of the time libraries tai64nlocal uses we # apparently can't verify beyond this level of accuracy. timestamp = int(time.time()) + 0.12345 process.stdin.write((encode(timestamp) + "\n").encode("ascii")) process.stdin.close() decodedToLocalTime = process.stdout.read().strip() self.assertEqual(time.strftime("%Y-%m-%d %H:%M:%S.12345", time.localtime(timestamp)).encode("ascii"), decodedToLocalTime[:25]) PKG^ByByeliot/tests/test_validation.py""" Tests for L{eliot._validation}. """ from __future__ import unicode_literals from unittest import TestCase from six import text_type as unicode from .._validation import ( Field, MessageType, ActionType, ValidationError, fields, _MessageSerializer, ) from .._action import startAction, startTask from .._output import MemoryLogger from ..serializers import identity from .. import add_destination, remove_destination class TypedFieldTests(TestCase): """ Tests for L{Field.forTypes}. """ def test_validateCorrectType(self): """ L{Field.validate} will not raise an exception if the given value is in the list of supported classes. """ field = Field.forTypes("path", [unicode, int], u"A path!") field.validate(123) field.validate("hello") def test_validateNone(self): """ When given a "class" of C{None}, L{Field.validate} will support validating C{None}. """ field = Field.forTypes("None", [None], u"Nothing!") field.validate(None) def test_validateWrongType(self): """ L{Field.validate} will raise a L{ValidationError} exception if the given value's type is not in the list of supported classes. """ field = Field.forTypes("key", [int], u"An integer key") self.assertRaises(ValidationError, field.validate, "lala") self.assertRaises(ValidationError, field.validate, None) self.assertRaises(ValidationError, field.validate, object()) def test_extraValidatorPasses(self): """ L{Field.validate} will not raise an exception if the extra validator does not raise an exception. """ def validate(i): if i > 10: return else: raise ValidationError("too small") field = Field.forTypes("key", [int], u"An integer key", validate) field.validate(11) def test_extraValidatorFails(self): """ L{Field.validate} will raise a L{ValidationError} exception if the extra validator raises one. """ def validate(i): if i > 10: return else: raise ValidationError("too small") field = Field.forTypes("key", [int], u"An int", validate) self.assertRaises(ValidationError, field.validate, 10) def test_onlyValidTypes(self): """ Only JSON supported types can be passed to L{Field.forTypes}. """ self.assertRaises(TypeError, Field.forTypes, "key", [complex], "Oops") def test_listIsValidType(self): """ A C{list} is a valid type for L{Field.forTypes}. """ Field.forTypes("key", [list], "Oops") def test_dictIsValidType(self): """ A C{dict} is a valid type for L{Field.forTypes}. """ Field.forTypes("key", [dict], "Oops") class FieldTests(TestCase): """ Tests for L{Field}. """ def test_description(self): """ L{Field.description} stores the passed in description. """ field = Field("path", identity, u"A path!") self.assertEqual(field.description, u"A path!") def test_optionalDescription(self): """ L{Field} can be constructed with no description. """ field = Field("path", identity) self.assertEqual(field.description, "") def test_key(self): """ L{Field.key} stores the passed in field key. """ field = Field("path", identity, u"A path!") self.assertEqual(field.key, u"path") def test_serialize(self): """ L{Field.serialize} calls the given serializer function. """ result = [] Field("key", result.append, u"field").serialize(123) self.assertEqual(result, [123]) def test_serializeResult(self): """ L{Field.serialize} returns the result of the given serializer function. """ result = Field("key", lambda obj: 456, u"field").serialize(None) self.assertEqual(result, 456) def test_serializeCallsValidate(self): """ L{Field.validate} calls the serializer, in case that raises an exception for the given input. """ class MyException(Exception): pass def serialize(obj): raise MyException() field = Field("key", serialize, u"") self.assertRaises(MyException, field.validate, 123) def test_noExtraValidator(self): """ L{Field.validate} doesn't break if there is no extra validator. """ field = Field("key", identity, u"") field.validate(123) def test_extraValidatorPasses(self): """ L{Field.validate} will not raise an exception if the extra validator does not raise an exception. """ def validate(i): if i > 10: return else: raise ValidationError("too small") field = Field("path", identity, u"A path!", validate) field.validate(11) def test_extraValidatorFails(self): """ L{Field.validate} will raise a L{ValidationError} exception if the extra validator raises one. """ def validate(i): if i > 10: return else: raise ValidationError("too small") field = Field("path", identity, u"A path!", validate) self.assertRaises(ValidationError, field.validate, 10) class FieldForValueTests(TestCase): """ Tests for L{Field.forValue}. """ def test_forValue(self): """ L{Field.forValue} creates a L{Field} with the given key and description. """ field = Field.forValue("key", None, "description") self.assertEqual(field.key, "key") self.assertEqual(field.description, "description") def test_forValueGoodValue(self): """ The L{Field.forValue}-created L{Field} validates the value it was constructed with. """ field = Field.forValue("key", 1234, "description") field.validate(1234) def test_valueFieldWrongValue(self): """ The L{Field.forValue}-created L{Field} raises a L{ValidationError} for different values. """ field = Field.forValue("key", 1234, "description") self.assertRaises(ValidationError, field.validate, 5678) def test_serialize(self): """ The L{Field.forValue}-created L{Field} returns the given object when serializing, regardless of input. If the caller is buggy, no need to log garbage if we know what needs logging. These bugs will be caught by unit tests, anyway, if author of code is doing things correctly. """ field = Field.forValue("key", 1234, "description") self.assertEqual(field.serialize(None), 1234) class FieldsTests(TestCase): """ Tests for L{fields}. """ def test_positional(self): """ L{fields} accepts positional arguments of L{Field} instances and combines them with fields specied as keyword arguments. """ a_field = Field(u'akey', identity) l = fields(a_field, another=str) self.assertIn(a_field, l) self.assertEqual( {(type(field), field.key) for field in l}, {(Field, 'akey'), (Field, 'another')}) def test_keys(self): """ L{fields} creates L{Field} instances with the given keys. """ l = fields(key=int, status=str) self.assertEqual({(type(field), field.key) for field in l}, {(Field, "key"), (Field, "status")}) def test_validTypes(self): """ The L{Field} instances constructed by L{fields} validate the specified types. """ field, = fields(key=int) self.assertRaises(ValidationError, field.validate, "abc") def test_noSerialization(self): """ The L{Field} instances constructed by L{fields} do no special serialization. """ field, = fields(key=int) self.assertEqual(field.serialize("abc"), "abc") class MessageSerializerTests(TestCase): """ Tests for L{_MessageSerializer}. """ def test_noMultipleFields(self): """ L{_MessageSerializer.__init__} will raise a L{ValueError} exception if constructed with more than object per field name. """ self.assertRaises(ValueError, _MessageSerializer, [Field("akey", identity, ""), Field("akey", identity, ""), Field("message_type", identity, "")]) def test_noBothTypeFields(self): """ L{_MessageSerializer.__init__} will raise a L{ValueError} exception if constructed with both a C{"message_type"} and C{"action_type"} field. """ self.assertRaises(ValueError, _MessageSerializer, [Field("message_type", identity, ""), Field("action_type", identity, "")]) def test_missingTypeField(self): """ L{_MessageSerializer.__init__} will raise a L{ValueError} if there is neither a C{"message_type"} nor a C{"action_type"} field. """ self.assertRaises(ValueError, _MessageSerializer, []) def test_noTaskLevel(self): """ L{_MessageSerializer.__init__} will raise a L{ValueError} if there is a C{"task_level"} field included. """ self.assertRaises(ValueError, _MessageSerializer, [Field("message_type", identity, ""), Field("task_level", identity, "")]) def test_noTaskUuid(self): """ L{_MessageSerializer.__init__} will raise a L{ValueError} if there is a C{"task_uuid"} field included. """ self.assertRaises(ValueError, _MessageSerializer, [Field("message_type", identity, ""), Field("task_uuid", identity, "")]) def test_noTimestamp(self): """ L{_MessageSerializer.__init__} will raise a L{ValueError} if there is a C{"timestamp"} field included. """ self.assertRaises(ValueError, _MessageSerializer, [Field("message_type", identity, ""), Field("timestamp", identity, "")]) def test_noUnderscoreStart(self): """ L{_MessageSerializer.__init__} will raise a L{ValueError} if there is a field included whose name starts with C{"_"}. """ self.assertRaises(ValueError, _MessageSerializer, [Field("message_type", identity, ""), Field("_key", identity, "")]) def test_serialize(self): """ L{_MessageSerializer.serialize} will serialize all values in the given dictionary using the respective L{Field}. """ serializer = _MessageSerializer( [Field.forValue("message_type", "mymessage", u"The type"), Field("length", len, "The length of a thing"), ]) message = {"message_type": "mymessage", "length": "thething"} serializer.serialize(message) self.assertEqual(message, {"message_type": "mymessage", "length": 8}) def test_missingSerializer(self): """ If a value in the dictionary passed to L{_MessageSerializer.serialize} has no respective field, it is unchanged. Logging attempts to capture everything, with minimal work; with any luck this value is JSON-encodable. Unit tests should catch such bugs, in any case. """ serializer = _MessageSerializer( [Field.forValue("message_type", "mymessage", u"The type"), Field("length", len, "The length of a thing"), ]) message = {"message_type": "mymessage", "length": "thething", "extra": 123} serializer.serialize(message) self.assertEqual(message, {"message_type": "mymessage", "length": 8, "extra": 123}) def test_fieldInstances(self): """ Fields to L{_MessageSerializer.__init__} should be instances of L{Field}. """ a_field = Field('a_key', identity) arg = object() with self.assertRaises(TypeError) as cm: _MessageSerializer([a_field, arg]) self.assertEqual( (u'Expected a Field instance but got', arg), cm.exception.args) class MessageTypeTests(TestCase): """ Tests for L{MessageType}. """ def messageType(self): """ Return a L{MessageType} suitable for unit tests. """ return MessageType("myapp:mysystem", [Field.forTypes("key", [int], u""), Field.forTypes("value", [int], u"")], u"A message type") def test_validateMissingType(self): """ L{MessageType._serializer.validate} raises a L{ValidationError} exception if the given dictionary has no C{"message_type"} field. """ messageType = self.messageType() self.assertRaises(ValidationError, messageType._serializer.validate, {"key": 1, "value": 2}) def test_validateWrongType(self): """ L{MessageType._serializer.validate} raises a L{ValidationError} exception if the given dictionary has the wrong value for the C{"message_type"} field. """ messageType = self.messageType() self.assertRaises(ValidationError, messageType._serializer.validate, {"key": 1, "value": 2, "message_type": "wrong"}) def test_validateExtraField(self): """ L{MessageType._serializer.validate} raises a L{ValidationError} exception if the given dictionary has an extra unknown field. """ messageType = self.messageType() self.assertRaises(ValidationError, messageType._serializer.validate, {"key": 1, "value": 2, "message_type": "myapp:mysystem", "extra": "hello"}) def test_validateMissingField(self): """ L{MessageType._serializer.validate} raises a L{ValidationError} exception if the given dictionary has a missing field. """ messageType = self.messageType() self.assertRaises(ValidationError, messageType._serializer.validate, {"key": 1, "message_type": "myapp:mysystem"}) def test_validateFieldValidation(self): """ L{MessageType._serializer.validate} raises a L{ValidationError} exception if the one of the field values fails field-specific validation. """ messageType = self.messageType() self.assertRaises(ValidationError, messageType._serializer.validate, {"key": 1, "value": None, "message_type": "myapp:mysystem"}) def test_validateStandardFields(self): """ L{MessageType._serializer.validate} does not raise an exception if the dictionary has the standard fields that are added to all messages. """ messageType = self.messageType() messageType._serializer.validate( {"key": 1, "value": 2, "message_type": "myapp:mysystem", "task_level": "/", "task_uuid": "123", "timestamp": "xxx"}) def test_call(self): """ L{MessageType.__call__} creates a new L{Message} with correct C{message_type} field value added. """ messageType = self.messageType() message = messageType() self.assertEqual(message._contents, {"message_type": messageType.message_type}) def test_callSerializer(self): """ L{MessageType.__call__} creates a new L{Message} with the L{MessageType._serializer} as its serializer. """ messageType = self.messageType() message = messageType() self.assertIs(message._serializer, messageType._serializer) def test_callWithFields(self): """ L{MessageType.__call__} creates a new L{Message} with the additional given fields. """ messageType = self.messageType() message = messageType(key=2, value=3) self.assertEqual(message._contents, {"message_type": messageType.message_type, "key": 2, "value": 3}) def test_description(self): """ L{MessageType.description} stores the passed in description. """ messageType = self.messageType() self.assertEqual(messageType.description, u"A message type") def test_optionalDescription(self): """ L{MessageType} can be constructed without a description. """ messageType = MessageType("name", []) self.assertEqual(messageType.description, "") class ActionTypeTestsMixin(object): """ Mixin for tests for the three L{ActionType} message variants. """ def getValidMessage(self): """ Return a dictionary of a message that is of the action status being tested. """ raise NotImplementedError("Override in subclasses") def getSerializer(self, actionType): """ Given a L{ActionType}, return the L{_MessageSerializer} for this variant. """ raise NotImplementedError("Override in subclasses") def actionType(self): """ Return a L{ActionType} suitable for unit tests. """ return ActionType("myapp:mysystem:myaction", [Field.forTypes("key", [int], "")], # start fields [Field.forTypes("value", [int], "")], # success fields "A action type") def test_validateMissingType(self): """ L{ActionType.validate} raises a L{ValidationError} exception if the given dictionary has no C{"action_type"} field. """ actionType = self.actionType() message = self.getValidMessage() del message["action_type"] self.assertRaises(ValidationError, self.getSerializer(actionType).validate, message) def test_validateWrongType(self): """ L{ActionType.validate} raises a L{ValidationError} exception if the given dictionary has the wrong value for the C{"action_type"} field. """ actionType = self.actionType() message = self.getValidMessage() message["action_type"] = "xxx" self.assertRaises(ValidationError, self.getSerializer(actionType).validate, message) def test_validateExtraField(self): """ L{ActionType.validate} raises a L{ValidationError} exception if the given dictionary has an extra unknown field. """ actionType = self.actionType() message = self.getValidMessage() message["extra"] = "ono" self.assertRaises(ValidationError, self.getSerializer(actionType).validate, message) def test_validateMissingField(self): """ L{ActionType.validate} raises a L{ValidationError} exception if the given dictionary has a missing field. """ actionType = self.actionType() message = self.getValidMessage() for key in message: if key != "action_type": del message[key] break self.assertRaises(ValidationError, self.getSerializer(actionType).validate, message) def test_validateFieldValidation(self): """ L{ActionType.validate} raises a L{ValidationError} exception if the one of the field values fails field-specific validation. """ actionType = self.actionType() message = self.getValidMessage() for key in message: if key != "action_type": message[key] = object() break self.assertRaises(ValidationError, self.getSerializer(actionType).validate, message) def test_validateStandardFields(self): """ L{ActionType.validate} does not raise an exception if the dictionary has the standard fields that are added to all messages. """ actionType = self.actionType() message = self.getValidMessage() message.update( {"task_level": "/", "task_uuid": "123", "timestamp": "xxx"}) self.getSerializer(actionType).validate(message) class ActionTypeStartMessage(TestCase, ActionTypeTestsMixin): """ Tests for L{ActionType} validation of action start messages. """ def getValidMessage(self): """ Return a dictionary of a valid action start message. """ return {"action_type": "myapp:mysystem:myaction", "action_status": "started", "key": 1} def getSerializer(self, actionType): return actionType._serializers.start class ActionTypeSuccessMessage(TestCase, ActionTypeTestsMixin): """ Tests for L{ActionType} validation of action success messages. """ def getValidMessage(self): """ Return a dictionary of a valid action success message. """ return {"action_type": "myapp:mysystem:myaction", "action_status": "succeeded", "value": 2} def getSerializer(self, actionType): return actionType._serializers.success class ActionTypeFailureMessage(TestCase, ActionTypeTestsMixin): """ Tests for L{ActionType} validation of action failure messages. """ def getValidMessage(self): """ Return a dictionary of a valid action failure message. """ return {"action_type": "myapp:mysystem:myaction", "action_status": "failed", "exception": "exceptions.RuntimeError", "reason": "because", } def getSerializer(self, actionType): return actionType._serializers.failure def test_validateExtraField(self): """ Additional fields (which can be added by exception extraction) don't cause a validation failure for failed action messages. """ actionType = self.actionType() message = self.getValidMessage() message.update( {"task_level": "/", "task_uuid": "123", "timestamp": "xxx"}) message.update({"extra_field": "hello"}) self.getSerializer(actionType).validate(message) class ChildActionTypeStartMessage(TestCase): """ Tests for validation of child actions created with L{ActionType}. """ def test_childActionUsesChildValidator(self): """ Validation of child actions uses the child's validator. """ A = ActionType( "myapp:foo", [Field.forTypes("a", [int], "")], [], "") B = ActionType( "myapp:bar", [Field.forTypes("b", [int], "")], [], "") logger = MemoryLogger() with A(logger, a=1): with B(logger, b=2): pass # If wrong serializers/validators were used, this will fail: logger.validate() class ActionTypeTests(TestCase): """ General tests for L{ActionType}. """ def actionType(self): """ Return a L{ActionType} suitable for unit tests. """ return ActionType("myapp:mysystem:myaction", [], [], "An action type") def test_call(self): """ L{ActionType.__call__} returns the result of calling C{self._startAction}. """ actionType = self.actionType() actionType._startAction = lambda *args, **kwargs: 1234 result = actionType(object()) self.assertEqual(result, 1234) def test_callArguments(self): """ L{ActionType.__call__} calls C{self._startAction} with the logger, action type, serializers and passed in fields. """ called = [] actionType = self.actionType() actionType._startAction = lambda *args, **kwargs: called.append( (args, kwargs)) logger = object() actionType(logger, key=5) self.assertEqual(called, [((logger, "myapp:mysystem:myaction", actionType._serializers), {"key": 5})]) def test_defaultStartAction(self): """ L{ActionType._startAction} is L{eliot.startAction} by default. """ self.assertEqual(ActionType._startAction, startAction) def test_asTask(self): """ L{ActionType.asTask} returns the result of calling C{self._startTask}. """ actionType = self.actionType() actionType._startTask = lambda *args, **kwargs: 1234 result = actionType.asTask(object()) self.assertEqual(result, 1234) def test_asTaskArguments(self): """ L{ActionType.asTask} calls C{self._startTask} with the logger, action type and passed in fields. """ called = [] actionType = self.actionType() actionType._startTask = lambda *args, **kwargs: called.append( (args, kwargs)) logger = object() actionType.asTask(logger, key=5) self.assertEqual(called, [((logger, "myapp:mysystem:myaction", actionType._serializers), {"key": 5})]) def test_defaultStartTask(self): """ L{ActionType._startTask} is L{eliot.startTask} by default. """ self.assertEqual(ActionType._startTask, startTask) def test_description(self): """ L{ActionType.description} stores the passed in description. """ actionType = self.actionType() self.assertEqual(actionType.description, "An action type") def test_optionalDescription(self): """ L{ActionType} can be constructed without a description. """ actionType = ActionType("name", [], []) self.assertEqual(actionType.description, "") class EndToEndValidationTests(TestCase): """ Test validation of messages created using L{MessageType} and L{ActionType}. """ MESSAGE = MessageType("myapp:mymessage", [Field.forTypes("key", [int], "The key")], "A message for testing.") ACTION = ActionType("myapp:myaction", [Field.forTypes("key", [int], "The key")], [Field.forTypes("result", [unicode], "The result")], "An action for testing.") def test_correctFromMessageType(self): """ A correct message created using L{MessageType} will be logged to a L{MemoryLogger}. """ logger = MemoryLogger() msg = self.MESSAGE().bind(key=123) msg.write(logger) self.assertEqual(logger.messages[0]["key"], 123) def test_incorrectFromMessageType(self): """ An incorrect message created using L{MessageType} will raise a L{ValidationError} in L{MemoryLogger.validate}. """ logger = MemoryLogger() msg = self.MESSAGE().bind(key="123") msg.write(logger) self.assertRaises(ValidationError, logger.validate) def test_correctStartFromActionType(self): """ A correct start message created using a L{ActionType} will be logged to a L{MemoryLogger}. """ logger = MemoryLogger() with self.ACTION(logger, key=123) as action: action.addSuccessFields(result="foo") self.assertEqual(logger.messages[0]["key"], 123) def test_omitLoggerFromActionType(self): """ If no logger is given to the L{ActionType} the default logger is used. """ messages = [] add_destination(messages.append) self.addCleanup(remove_destination, messages.append) with self.ACTION(key=123) as action: action.add_success_fields(result="foo") self.assertEqual(messages[0]["key"], 123) def test_incorrectStartFromActionType(self): """ An incorrect start message created using a L{ActionType} will raise a L{ValidationError}. """ logger = MemoryLogger() with self.ACTION(logger, key="123") as action: action.addSuccessFields(result="foo") self.assertRaises(ValidationError, logger.validate) def test_correctSuccessFromActionType(self): """ A correct success message created using a L{ActionType} will be logged to a L{MemoryLogger}. """ logger = MemoryLogger() with self.ACTION(logger, key=123) as action: action.addSuccessFields(result="foo") self.assertEqual(logger.messages[1]["result"], "foo") def test_incorrectSuccessFromActionType(self): """ An incorrect success message created using a L{ActionType} will raise a L{ValidationError}. """ logger = MemoryLogger() with self.ACTION(logger, key=123) as action: action.addSuccessFields(result=-1) self.assertRaises(ValidationError, logger.validate) def test_correctFailureFromActionType(self): """ A correct failure message created using a L{ActionType} will be logged to a L{MemoryLogger}. """ logger = MemoryLogger() def run(): with self.ACTION(logger, key=123): raise RuntimeError("hello") self.assertRaises(RuntimeError, run) self.assertEqual(logger.messages[1]["reason"], "hello") class PEP8Tests(TestCase): """ Tests for PEP 8 method compatibility. """ def test_for_value(self): """ L{Field.for_value} is the same as L{Field.forValue}. """ self.assertEqual(Field.for_value, Field.forValue) def test_for_types(self): """ L{Field.for_types} is the same as L{Field.forTypes}. """ self.assertEqual(Field.for_types, Field.forTypes) def test_as_task(self): """ L{ActionType.as_task} is the same as L{ActionType.asTask}. """ self.assertEqual(ActionType.as_task, ActionType.asTask) PKGâ**&eliot-0.11.0.dist-info/DESCRIPTION.rstEliot: Logging for Complex & Distributed Systems ================================================ .. image:: https://coveralls.io/repos/ClusterHQ/eliot/badge.png?branch=master :target: https://coveralls.io/r/ClusterHQ/eliot :alt: Coveralls test coverage information .. image:: https://travis-ci.org/ClusterHQ/eliot.png?branch=master :target: http://travis-ci.org/ClusterHQ/eliot :alt: Build Status Eliot is a Python logging system that outputs causal chains of actions happening within and across process boundaries: a logical trace of the system's operation. Eliot is released by `ClusterHQ`_ under the Apache 2.0 License. Download from `PyPI`_, read the `documentation`_, file bugs at `Github`_. Need help? Join the ``#eliot`` IRC channel on ``irc.freenode.net``. To install:: $ pip install eliot Features: * Structured, optionally-typed log messages and actions. * Logged actions can span processes and threads. * Excellent support for unit testing your code's logging. * Optional Twisted support. * Native journald support, easily usable by Logstash/Elasticsearch. * Supports CPython 2.7, 3.3, 3.4, 3.5 and PyPy. .. _PEP 8: http://legacy.python.org/dev/peps/pep-0008/ .. _Twisted: https://twistedmatrix.com/documents/current/core/development/policy/coding-standard.html .. _documentation: https://eliot.readthedocs.org/ .. _Github: https://github.com/ClusterHQ/eliot .. _PyPI: https://pypi.python.org/pypi/eliot .. _ClusterHQ: https://clusterhq.com .. _eliot-tree: https://warehouse.python.org/project/eliot-tree/ PKGT??'eliot-0.11.0.dist-info/entry_points.txt[console_scripts] eliot-prettyprint = eliot.prettyprint:_main PKGŚI$eliot-0.11.0.dist-info/metadata.json{"classifiers": ["Intended Audience :: Developers", "License :: OSI Approved :: Apache Software License", "Operating System :: OS Independent", "Programming Language :: Python", "Programming Language :: Python :: 2", "Programming Language :: Python :: 2.7", "Programming Language :: Python :: 3", "Programming Language :: Python :: 3.3", "Programming Language :: Python :: 3.4", "Programming Language :: Python :: 3.5", "Programming Language :: Python :: Implementation :: CPython", "Programming Language :: Python :: Implementation :: PyPy", "Topic :: System :: Logging"], "extensions": {"python.commands": {"wrap_console": {"eliot-prettyprint": "eliot.prettyprint:_main"}}, "python.details": {"contacts": [{"email": "itamar@clusterhq.com", "name": "Itamar Turner-Trauring", "role": "author"}], "document_names": {"description": "DESCRIPTION.rst"}, "project_urls": {"Home": "https://github.com/ClusterHQ/eliot/"}}, "python.exports": {"console_scripts": {"eliot-prettyprint": "eliot.prettyprint:_main"}}}, "extras": ["dev", "journald"], "generator": "bdist_wheel (0.26.0)", "keywords": ["logging"], "license": "Apache 2.0", "metadata_version": "2.0", "name": "eliot", "run_requires": [{"extra": "journald", "requires": ["cffi (>=1.1.2)"]}, {"extra": "dev", "requires": ["coverage", "hypothesis (>=1.14.0)", "testtools"]}, {"requires": ["pyrsistent (>=0.11.8)", "six", "zope.interface"]}], "summary": "Logging for Complex & Distributed Systems", "version": "0.11.0"}PKG~$eliot-0.11.0.dist-info/top_level.txteliot PKGndnneliot-0.11.0.dist-info/WHEELWheel-Version: 1.0 Generator: bdist_wheel (0.26.0) Root-Is-Purelib: true Tag: py2-none-any Tag: py3-none-any PKG6  eliot-0.11.0.dist-info/METADATAMetadata-Version: 2.0 Name: eliot Version: 0.11.0 Summary: Logging for Complex & Distributed Systems Home-page: https://github.com/ClusterHQ/eliot/ Author: Itamar Turner-Trauring Author-email: itamar@clusterhq.com License: Apache 2.0 Keywords: logging Platform: UNKNOWN Classifier: Intended Audience :: Developers Classifier: License :: OSI Approved :: Apache Software License Classifier: Operating System :: OS Independent Classifier: Programming Language :: Python Classifier: Programming Language :: Python :: 2 Classifier: Programming Language :: Python :: 2.7 Classifier: Programming Language :: Python :: 3 Classifier: Programming Language :: Python :: 3.3 Classifier: Programming Language :: Python :: 3.4 Classifier: Programming Language :: Python :: 3.5 Classifier: Programming Language :: Python :: Implementation :: CPython Classifier: Programming Language :: Python :: Implementation :: PyPy Classifier: Topic :: System :: Logging Requires-Dist: pyrsistent (>=0.11.8) Requires-Dist: six Requires-Dist: zope.interface Provides-Extra: dev Requires-Dist: coverage; extra == 'dev' Requires-Dist: hypothesis (>=1.14.0); extra == 'dev' Requires-Dist: testtools; extra == 'dev' Provides-Extra: journald Requires-Dist: cffi (>=1.1.2); extra == 'journald' Eliot: Logging for Complex & Distributed Systems ================================================ .. image:: https://coveralls.io/repos/ClusterHQ/eliot/badge.png?branch=master :target: https://coveralls.io/r/ClusterHQ/eliot :alt: Coveralls test coverage information .. image:: https://travis-ci.org/ClusterHQ/eliot.png?branch=master :target: http://travis-ci.org/ClusterHQ/eliot :alt: Build Status Eliot is a Python logging system that outputs causal chains of actions happening within and across process boundaries: a logical trace of the system's operation. Eliot is released by `ClusterHQ`_ under the Apache 2.0 License. Download from `PyPI`_, read the `documentation`_, file bugs at `Github`_. Need help? Join the ``#eliot`` IRC channel on ``irc.freenode.net``. To install:: $ pip install eliot Features: * Structured, optionally-typed log messages and actions. * Logged actions can span processes and threads. * Excellent support for unit testing your code's logging. * Optional Twisted support. * Native journald support, easily usable by Logstash/Elasticsearch. * Supports CPython 2.7, 3.3, 3.4, 3.5 and PyPy. .. _PEP 8: http://legacy.python.org/dev/peps/pep-0008/ .. _Twisted: https://twistedmatrix.com/documents/current/core/development/policy/coding-standard.html .. _documentation: https://eliot.readthedocs.org/ .. _Github: https://github.com/ClusterHQ/eliot .. _PyPI: https://pypi.python.org/pypi/eliot .. _ClusterHQ: https://clusterhq.com .. _eliot-tree: https://warehouse.python.org/project/eliot-tree/ PKGwQ""eliot-0.11.0.dist-info/RECORDeliot/__init__.py,sha256=_J4dNcDc2nEJrDM-W668enb-ZwkxIvMP7BVx21aFZ6M,1521 eliot/_action.py,sha256=GcdQFXUTdCItPdIWdRWsXW6zl_BBAbC5svzDci7bYYc,27839 eliot/_bytesjson.py,sha256=u1jwRNY1Oqe9uIiT5xhfFVD_m-hf4sukaebTjXpxT7E,936 eliot/_errors.py,sha256=-zY4gcmpyUWBeeuCgmtq4bTSysSLa6R6tPzvSzXNYis,1879 eliot/_message.py,sha256=Ivoqs3NeVSjHhRr3AAIF50qSvPAjot6SAyuk3YBPW7k,6043 eliot/_output.py,sha256=DceChxFdgGMJglsAOuIATqYEqIj0YRMW0_DEnjWOjNg,12190 eliot/_parse.py,sha256=nitJTN4Vl4R3TwHm8tRvv1dOYH-G_HeJwMaeFGpYPuo,6010 eliot/_traceback.py,sha256=SzJZoDg8NDs4LOLqgSstgA4xceovY7N5gargmqocyeE,3724 eliot/_util.py,sha256=ujBqd4qe4hkMf2hcF278hyaeQGHm9mzqBNZaK1HqGnQ,1501 eliot/_validation.py,sha256=7rGAAFYGA09XnbY-SGIr8k159VbXzJnsHyK0k8BOk-o,15915 eliot/_version.py,sha256=uJxERdKYSdikuyLObp4g9Mtf3Y1DH5kPAk2d8ePo484,418 eliot/filter.py,sha256=AkqUzONF8NTF9xzVQzkXVnbuFGOpaTXtXOj20Vx8NY4,3464 eliot/journald.py,sha256=kZezI0962u7FMEfmcjYdr1CwRlf0WWN1CtRbYSU29TY,2672 eliot/logwriter.py,sha256=L9ARrDCXsFZnQ29FK6d5ltXJgJIatyInyE62Yn7ocd4,4049 eliot/prettyprint.py,sha256=yXPHNHP9ApQWgkNponNru32Uqx5Sw-vafA5FSAKoKk0,3770 eliot/serializers.py,sha256=PcMpWY-eYEqd0FMGmNMkWnhTnEVCTtvL8H4CZp8iH0M,617 eliot/tai64n.py,sha256=tl0mY647hhxBUuvSdwmr_ZbiIOGXUA7HjHJ-LIcaEpM,1345 eliot/testing.py,sha256=k5czu9wgRAsOVwDHQotCNFL3BaaqXVoPvTNhM6v7asM,13194 eliot/twisted.py,sha256=ze_Af8Ic5wEqrhhhOQExoPPyRd5rRtG7fc7Qcgpt0dA,7203 eliot/tests/__init__.py,sha256=9dVgFmlmGtlue7bgYgXTvIfcAZB5s5mcKBkmAlvxdMM,37 eliot/tests/common.py,sha256=7epFCFqcpFi9lJvprX3s5aSWzmxGzZ5dgccAdw7vHIM,446 eliot/tests/strategies.py,sha256=DxVVskSLRGSz2MEYBykIyf_uvsyePt94Y0zZO8PnaUg,7229 eliot/tests/test_action.py,sha256=2s-tue4SOrmrZGDeiNJgf0SXUMXgUb0DJNx0_X47pTM,52639 eliot/tests/test_api.py,sha256=0UCEHX-mVPFs1cw1RV5Bhc54G9C72ap-iqE1N84ho9Q,2516 eliot/tests/test_filter.py,sha256=zf6qJZ9RshhbrOZQHNPil4oscfz8LSCBE_oLped5WOY,3609 eliot/tests/test_journald.py,sha256=93SV0JgZstaUmQ28xQdNecKCKmU0Hpup64R-TU-NsWw,7852 eliot/tests/test_logwriter.py,sha256=nkowQahm-Bl-RxgRWapa8djW-07c358FODzXGjl0hJA,10412 eliot/tests/test_message.py,sha256=TewGMJHHHrfXGndEH-P2gJXBFAanoF-ZXAPcJInK3c4,9002 eliot/tests/test_output.py,sha256=g1NFZEL9tlK6ZVqmxM9Cqu_8J-UUct59rWNaqWsjwFg,22278 eliot/tests/test_parse.py,sha256=6vVXcqw1i6imtgo4EcP1BKKYSQtXlwpCusr9vTOPOfM,10298 eliot/tests/test_prettyprint.py,sha256=dyT6rxo_sVBYlHpq7oFSL_X0JaO8RqLo53I-a4pvmOo,5970 eliot/tests/test_serializers.py,sha256=kZGFwGjmuSPdc3VDd2ogepwKOedUnPjRn_NFaxuF3QQ,952 eliot/tests/test_tai64n.py,sha256=XJ-_PlBRHI_JC7eLUwgMzNZogWEJ6V7mdvz9v2spLxw,1858 eliot/tests/test_testing.py,sha256=3OscfNm2f3idi58piQyjCQLnGWfBWrGQw7PeRcj1wRQ,29292 eliot/tests/test_traceback.py,sha256=0-ct2SOdNZMyZ6cmNN8ywPLgVGF4qIxwAFIBcQ37Cso,7592 eliot/tests/test_twisted.py,sha256=LJ-i6GRFFMneQS8POeAweVwhA7TcMrdeGkffgygyTr0,20182 eliot/tests/test_util.py,sha256=piSsCFLHqdXVNsFE2Zi3Jo0DFpDt8jLjRuJYkFdDvhE,1306 eliot/tests/test_validation.py,sha256=UNXVlmbrNE0sbDD8FhKsTEj1ysdOJXXRSdOXMtV0opc,31042 eliot-0.11.0.dist-info/DESCRIPTION.rst,sha256=GFS9lJdgmjUNKc46TPeyYeX5pjOjKgtcIUC_ooHJIi4,1578 eliot-0.11.0.dist-info/METADATA,sha256=dgZcgJhxqsjIzcqzHTHY65z5NzdllDTsQHgjAPi-0Dw,2838 eliot-0.11.0.dist-info/RECORD,, eliot-0.11.0.dist-info/WHEEL,sha256=GrqQvamwgBV4nLoJe0vhYRSWzWsx7xjlt74FT0SWYfE,110 eliot-0.11.0.dist-info/entry_points.txt,sha256=p0FrcAwcaM6ouXCbZxcwq3M4nxfKlGgbcu6YtPBCnoI,63 eliot-0.11.0.dist-info/metadata.json,sha256=UZ0lrSPyJ6cpc-BdtOUIQ7u-h0cQDj9V0MvpWg5YLmo,1465 eliot-0.11.0.dist-info/top_level.txt,sha256=cOGfGs9N6GOJIbYUBl27ZoIV_BaEJ-UeCQacfHjCL04,6 PKG][eliot/_version.pyPK⡁Gw!gzzeliot/_parse.pyPKGzyܺxeliot/prettyprint.pyPKæG&SJ##d(eliot/twisted.pyPKYuAGL&vDeliot/_bytesjson.pyPKGֆ{Heliot/__init__.pyPKPxE돷AANeliot/tai64n.pyPKGd#nc//Teliot/_output.pyPK⡁G;ZFfeliot/_message.pyPKYuAGFeliot/logwriter.pyPKG+>+>eliot/_validation.pyPKG>~33eliot/testing.pyPKGe7 eliot/_traceback.pyPK⡁GyWW,eliot/_errors.pyPKPxE4ii 4eliot/serializers.pyPK⡁Gluip p 6eliot/journald.pyPKGV :llDAeliot/_action.pyPKYuAGeP{ 1eliot/filter.pyPKG/eliot/_util.pyPKæGxa eliot/tests/test_api.pyPK⡁G{==eliot/tests/strategies.pyPKæG2NNleliot/tests/test_twisted.pyPKGB6{7eliot/tests/test_action.pyPKPxEd!%%Reliot/tests/__init__.pyPK; GY*#*#eliot/tests/test_message.pyPKGRw1RR)eliot/tests/test_prettyprint.pyPKYuAG5((@eliot/tests/test_logwriter.pyPKPxEd7hieliot/tests/common.pyPKYuAG`ŏvkeliot/tests/test_filter.pyPK⡁G~g:(:(yeliot/tests/test_parse.pyPKرGjAlrlr8eliot/tests/test_testing.pyPK⡁GƬeliot/tests/test_journald.pyPKGQ3eliot/tests/test_traceback.pyPKW=G#>WWQeliot/tests/test_output.pyPKPxE;z eliot/tests/test_serializers.pyPKGpOr٬eliot/tests/test_util.pyPKPxEuBB)eliot/tests/test_tai64n.pyPKG^ByByeliot/tests/test_validation.pyPKGâ**&!3eliot-0.11.0.dist-info/DESCRIPTION.rstPKGT??'9eliot-0.11.0.dist-info/entry_points.txtPKGŚI$:eliot-0.11.0.dist-info/metadata.jsonPKG~$@eliot-0.11.0.dist-info/top_level.txtPKGndnnV@eliot-0.11.0.dist-info/WHEELPKG6  @eliot-0.11.0.dist-info/METADATAPKGwQ""QLeliot-0.11.0.dist-info/RECORDPK--> Z