""" Tests for L{eliot._action}. """ import pickle import time from unittest import TestCase from unittest.mock import patch from threading import Thread from hypothesis import assume, given, settings, HealthCheck from hypothesis.strategies import integers, lists, just, text from pyrsistent import pvector, v import testtools from testtools.matchers import MatchesStructure from .._action import ( Action, current_action, startTask, start_action, ACTION_STATUS_FIELD, ACTION_TYPE_FIELD, FAILED_STATUS, STARTED_STATUS, SUCCEEDED_STATUS, DuplicateChild, InvalidStartMessage, InvalidStatus, TaskLevel, WrittenAction, WrongActionType, WrongTask, WrongTaskLevel, TooManyCalls, log_call, ) 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 ( 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 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_task_uuid(self): """ L{Action.task_uuid} return the task's UUID. """ logger = MemoryLogger() action = Action(logger, "unique", TaskLevel(level=[]), "sys:thename") self.assertEqual(action.task_uuid, "unique") 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(current_action())) self.assertEqual(result, [action]) def test_per_thread_context(self): """Different threads have different contexts.""" in_thread = [] def run_in_thread(): action = Action(None, "", TaskLevel(level=[]), "") with action.context(): time.sleep(0.5) in_thread.append(current_action()) thread = Thread(target=run_in_thread) thread.start() time.sleep(0.2) self.assertEqual(current_action(), None) thread.join() self.assertIsInstance(in_thread[0], 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(current_action(), 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(current_action(), None) def test_withSetsContext(self): """ L{Action.__enter__} sets the action as the current action. """ action = Action(MemoryLogger(), "", TaskLevel(level=[]), "") with action: self.assertIs(current_action(), 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(current_action(), 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(current_action(), 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(current_action(), action) def test_withContextReturnsaction(self): """ L{Action.context().__enter__} returns the action. """ action = Action(MemoryLogger(), "", TaskLevel(level=[]), "") with action.context() as action2: self.assertIs(action, action2) 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(current_action(), 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(current_action(), 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{str()}. """ 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, str() 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) class StartActionAndTaskTests(TestCase): """ Tests for L{start_action} 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_start_task_default_action_type(self): """ L{start_task} sets a default C{action_type} if none is set. """ logger = MemoryLogger() startTask(logger) assertContainsFields(self, logger.messages[0], {"action_type": ""}) 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{start_action} they are attached to the resulting L{Action}. """ logger = MemoryLogger() serializers = _ActionSerializers(start=None, success=None, failure=None) action = start_action(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_start_action_default_action_type(self): """ L{start_action} sets a default C{action_type} if none is set. """ logger = MemoryLogger() start_action(logger) assertContainsFields(self, logger.messages[0], {"action_type": ""}) def test_startActionNoParent(self): """ L{start_action} when C{current_action()} is C{None} creates a top-level L{Action}. """ logger = MemoryLogger() action = start_action(logger, "sys:do") self.assertIsInstance(action, Action) self.assertEqual(action._task_level, TaskLevel(level=[])) def test_startActionNoParentLogStart(self): """ L{start_action} when C{current_action()} is C{None} logs a start message. """ logger = MemoryLogger() action = start_action(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{start_action} uses the C{current_action()} as parent for a new L{Action}. """ logger = MemoryLogger() parent = Action(logger, "uuid", TaskLevel(level=[2]), "other:thing") with parent: action = start_action(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{start_action} when C{current_action()} is an L{Action} logs a start message. """ logger = MemoryLogger() parent = Action(logger, "uuid", TaskLevel(level=[]), "other:thing") with parent: start_action(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{start_action} logs to the default ``Logger``. """ messages = [] add_destination(messages.append) self.addCleanup(remove_destination, messages.append) action = start_action(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.serialize_task_id} 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.serialize_task_id(), action._nextTaskLevel(), ], [TaskLevel(level=[1, 2, 1]), b"uniq123@/1/2/2", TaskLevel(level=[1, 2, 3])], ) def test_continueTaskReturnsAction(self): """ L{Action.continue_task} 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.continue_task(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_continueTaskUnicode(self): """ L{Action.continue_task} can take a Unicode task identifier. """ original_action = Action(None, "uniq790", TaskLevel(level=[3, 4]), "mytype") task_id = str(original_action.serialize_task_id(), "utf-8") new_action = Action.continue_task(MemoryLogger(), task_id) self.assertEqual(new_action._identification["task_uuid"], "uniq790") def test_continueTaskStartsAction(self): """ L{Action.continue_task} starts the L{Action} it creates. """ originalAction = Action(None, "uniq456", TaskLevel(level=[3, 4]), "mytype") taskId = originalAction.serializeTaskId() logger = MemoryLogger() Action.continue_task(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_continueTaskCustomType(self): """ L{Action.continue_task} uses the provided action type and extra fields. """ originalAction = Action(None, "uniq456", TaskLevel(level=[3, 4]), "mytype") taskId = originalAction.serializeTaskId() logger = MemoryLogger() Action.continue_task(logger, taskId, action_type="custom:action", field="value") assertContainsFields( self, logger.messages[0], { "task_uuid": "uniq456", "task_level": [3, 4, 1, 1], "action_type": "custom:action", "action_status": "started", "field": "value", }, ) def test_continueTaskNoLogger(self): """ L{Action.continue_task} 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.continue_task(task_id=taskId) assertContainsFields( self, messages[-1], { "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.continue_task) 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, ] ) ) def test_equality(self): """ L{TaskChild} correctly implements equality and hashing. """ a = TaskLevel(level=[1, 2]) a2 = TaskLevel(level=[1, 2]) b = TaskLevel(level=[2, 999]) self.assertTrue( all( [ a == a2, a2 == a, a != b, b != a, not b == a, not a == b, not a == 1, a != 1, hash(a) == hash(a2), hash(b) != hash(a), ] ) ) def test_as_list(self): """ L{TaskChild.as_list} returns the level. """ self.assertEqual(TaskLevel(level=[1, 2, 3]).as_list(), [1, 2, 3]) @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(suppress_health_check=[HealthCheck.too_slow]) 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) def task_level(m): return 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 start_action(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 start_action(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 start_action(action_type="parent"): wrapped = preserve_context(self.add) wrapped(1, 2) self.assertRaises(TooManyCalls, wrapped, 3, 4) @log_call def for_pickling(): pass class LogCallTests(TestCase): """Tests for log_call decorator.""" def assert_logged(self, logger, action_type, expected_params, expected_result): """Assert that an action of given structure was logged.""" [tree] = Parser.parse_stream(logger.messages) root = tree.root() self.assertEqual(root.action_type, action_type) message = dict(root.start_message.contents) for field in [ACTION_STATUS_FIELD, ACTION_TYPE_FIELD]: message.pop(field) self.assertEqual(message, expected_params) self.assertEqual(root.end_message.contents["result"], expected_result) self.assertEqual(root.status, SUCCEEDED_STATUS) @capture_logging(None) def test_no_args_return(self, logger): """ C{@log_call} with no arguments logs return result, arguments, and has action type based on the action name. """ @log_call def myfunc(x, y): return 4 myfunc(2, 3) self.assert_logged(logger, self.id() + "..myfunc", {"x": 2, "y": 3}, 4) @capture_logging(None) def test_exception(self, logger): """C{@log_call} with an exception logs a failed action.""" @log_call def myfunc(x, y): 1 / 0 with self.assertRaises(ZeroDivisionError): myfunc(2, 4) [tree] = Parser.parse_stream(logger.messages) root = tree.root() self.assertIn("ZeroDivisionError", root.end_message.contents["exception"]) self.assertEqual(root.status, FAILED_STATUS) @capture_logging(None) def test_action_type(self, logger): """C{@log_call} can take an action type.""" @log_call(action_type="myaction") def myfunc(x, y): return 4 myfunc(2, 3) self.assert_logged(logger, "myaction", {"x": 2, "y": 3}, 4) @capture_logging(None) def test_default_argument_given(self, logger): """C{@log_call} logs default arguments that were passed in.""" @log_call def myfunc(x, y=1): return 4 myfunc(2, y=5) self.assert_logged(logger, self.id() + "..myfunc", {"x": 2, "y": 5}, 4) @capture_logging(None) def test_default_argument_missing(self, logger): """C{@log_call} logs default arguments that weren't passed in.""" @log_call def myfunc(x, y=1): return 6 myfunc(2) self.assert_logged(logger, self.id() + "..myfunc", {"x": 2, "y": 1}, 6) @capture_logging(None) def test_star_args_kwargs(self, logger): """C{@log_call} logs star args and kwargs.""" @log_call def myfunc(x, *y, **z): return 6 myfunc(2, 3, 4, a=1, b=2) self.assert_logged( logger, self.id() + "..myfunc", {"x": 2, "y": (3, 4), "z": {"a": 1, "b": 2}}, 6, ) @capture_logging(None) def test_whitelist_args(self, logger): """C{@log_call} only includes whitelisted arguments.""" @log_call(include_args=("x", "z")) def myfunc(x, y, z): return 6 myfunc(2, 3, 4) self.assert_logged(logger, self.id() + "..myfunc", {"x": 2, "z": 4}, 6) def test_wrong_whitelist_args(self): """If C{include_args} doesn't match function, raise an exception.""" with self.assertRaises(ValueError): @log_call(include_args=["a", "x", "y"]) def f(x, y): pass @capture_logging(None) def test_no_result(self, logger): """C{@log_call} can omit logging the result.""" @log_call(include_result=False) def myfunc(x, y): return 6 myfunc(2, 3) [tree] = Parser.parse_stream(logger.messages) root = tree.root() self.assertNotIn("result", root.end_message.contents) self.assertEqual(root.status, SUCCEEDED_STATUS) def test_pickleable(self): """Functions decorated with C{log_call} are pickleable. This is necessary for e.g. Dask usage. """ self.assertIs(for_pickling, pickle.loads(pickle.dumps(for_pickling))) @capture_logging(None) def test_methods(self, logger): """self is not logged.""" class C(object): @log_call def f(self, x): pass C().f(2) self.assert_logged(logger, self.id() + "..C.f", {"x": 2}, None) class IndividualMessageLogTests(TestCase): """Action.log() tests.""" def test_log_creates_new_dictionary(self): """ L{Action.log} creates a new dictionary on each call. This is important because we might mutate the dictionary in ``Logger.write``. """ messages = [] add_destination(messages.append) self.addCleanup(remove_destination, messages.append) with start_action(action_type="x") as action: action.log("mymessage", key=4) action.log(message_type="mymessage2", key=5) self.assertEqual(messages[1]["key"], 4) self.assertEqual(messages[2]["key"], 5) self.assertEqual(messages[1]["message_type"], "mymessage") self.assertEqual(messages[2]["message_type"], "mymessage2") @patch("time.time") def test_log_adds_timestamp(self, time_func): """ L{Action.log} adds a C{"timestamp"} field to the dictionary written to the logger, with the current time in seconds since the epoch. """ messages = [] add_destination(messages.append) self.addCleanup(remove_destination, messages.append) time_func.return_value = timestamp = 1387299889.153187625 with start_action(action_type="x") as action: action.log("mymessage", key=4) self.assertEqual(messages[-2]["message_type"], "mymessage") self.assertEqual(messages[-2]["timestamp"], timestamp) def test_part_of_action(self): """ L{Action.log} adds the identification fields from the given L{Action} to the dictionary written to the logger. """ messages = [] add_destination(messages.append) self.addCleanup(remove_destination, messages.append) action = Action(None, "unique", TaskLevel(level=[37, 4]), "sys:thename") action.log("me", key=2) written = messages[0] del written["timestamp"] self.assertEqual( written, { "task_uuid": "unique", "task_level": [37, 4, 1], "key": 2, "message_type": "me", }, )