def test_novaclient_exception(self, logger): """ The details of ``novaclient.exceptions.ClientException`` are logged when it is raised by the decorated method and the exception is still raised. """ result = NovaClientException( code=INTERNAL_SERVER_ERROR, message="Some things went wrong with some other things.", details={"key": "value"}, request_id="abcdefghijklmnopqrstuvwxyz", url="/foo/bar", method="POST", ) logging_dummy = LoggingDummy(Dummy(result)) self.assertRaises(NovaClientException, logging_dummy.raise_method) logged = LoggedMessage.of_type( logger.messages, NOVA_CLIENT_EXCEPTION, )[0] assertContainsFields( self, logged.message, { u"code": result.code, u"message": result.message, u"details": result.details, u"request_id": result.request_id, u"url": result.url, u"method": result.method, }, )
def got_messages(messages): assertContainsFields( self, messages[1], {u"message_type": u"twisted:log", u"message": u"stdout!", u"error": False} ) assertContainsFields( self, messages[2], {u"message_type": u"twisted:log", u"message": u"stderr!", u"error": True} )
def test_multiple_iterations(self, logger): """ If the predicate returns something falsey followed by something truthy, then ``loop_until`` returns it immediately. """ result = object() results = [None, False, result] expected_results = results[:-1] def predicate(): return results.pop(0) clock = Clock() d = loop_until(clock, predicate) clock.advance(0.1) self.assertNoResult(d) clock.advance(0.1) self.assertEqual(self.successResultOf(d), result) action = LoggedAction.of_type(logger.messages, LOOP_UNTIL_ACTION)[0] assertContainsFields(self, action.start_message, {"predicate": predicate}) assertContainsFields(self, action.end_message, {"result": result}) self.assertTrue(action.succeeded) messages = LoggedMessage.of_type(logger.messages, LOOP_UNTIL_ITERATION_MESSAGE) self.assertEqual(action.children, messages) self.assertEqual([messages[0].message["result"], messages[1].message["result"]], expected_results)
def _assertTracebackLogged(self, logger): """ Assert that a traceback for an L{ArbitraryException} was logged as a child of a L{REQUEST} action. """ # Get rid of it so it doesn't fail the test later. tracebacks = logger.flushTracebacks(exceptionType) if len(tracebacks) > 1: self.fail("Multiple tracebacks: %s" % tracebacks) traceback = tracebacks[0] # Verify it contains what it's supposed to contain. assertContainsFields(self, traceback, { u"exception": exceptionType, u"message_type": u"eliot:traceback", # Just assume the traceback it contains is correct. The code # that generates that string isn't part of this unit, anyway. }) # Verify that it is a child of one of the request actions. for request in LoggedAction.ofType(logger.messages, REQUEST): if LoggedMessage(traceback) in request.descendants(): break else: self.fail( "Traceback was logged outside of the context of a request " "action.")
def actuallyAssert(self, logger): request = LoggedAction.ofType(logger.messages, REQUEST)[0] assertContainsFields(self, request.startMessage, { u"request_path": path.decode("ascii"), u"method": method, }) return request
def test_keystone_client_exception(self, logger): """ ``keystoneclient.openstack.common.apiclient.exceptions.BadRequest`` is treated similarly to ``novaclient.exceptions.ClientException``. See ``test_novaclient_exception``. """ response = Response() response._content = "hello world" result = KeystoneHttpError( message="Some things went wrong with some other things.", details={"key": "value"}, response=response, request_id="abcdefghijklmnopqrstuvwxyz", url="/foo/bar", method="POST", http_status=INTERNAL_SERVER_ERROR, ) logging_dummy = LoggingDummy(Dummy(result)) self.assertRaises(KeystoneHttpError, logging_dummy.raise_method) logged = LoggedMessage.of_type( logger.messages, KEYSTONE_HTTP_ERROR, )[0] assertContainsFields( self, logged.message, { u"code": result.http_status, u"message": result.message, u"details": result.details, u"request_id": result.request_id, u"url": result.url, u"method": result.method, u"response": "hello world", }, )
def _assertTracebackLogged(self, logger): """ Assert that a traceback for an L{ArbitraryException} was logged as a child of a L{REQUEST} action. """ # Get rid of it so it doesn't fail the test later. tracebacks = logger.flushTracebacks(exceptionType) if len(tracebacks) > 1: self.fail("Multiple tracebacks: %s" % tracebacks) traceback = tracebacks[0] # Verify it contains what it's supposed to contain. assertContainsFields( self, traceback, { u"exception": exceptionType, u"message_type": u"eliot:traceback", # Just assume the traceback it contains is correct. The code # that generates that string isn't part of this unit, anyway. }) # Verify that it is a child of one of the request actions. for request in LoggedAction.ofType(logger.messages, REQUEST): if LoggedMessage(traceback) in request.descendants(): break else: self.fail( "Traceback was logged outside of the context of a request " "action.")
def got_messages(messages): assertContainsFields(self, messages[1], {u"message_type": u"twisted:log", u"error": True}) self.assertTrue(messages[1][u"message"].startswith( u"Unhandled Error\nTraceback (most recent call last):\n")) self.assertTrue(messages[1][u"message"].endswith( u"ZeroDivisionError: ono\n"))
def test_run_successful_test(self, logger): """ Running a test with the Eliot reporter logs an action. """ reporter = make_reporter() test = make_successful_test() test.run(reporter) [action] = LoggedAction.of_type(logger.serialize(), TEST) assertContainsFields(self, action.start_message, {"test": test.id()})
def got_messages(messages): assertContainsFields(self, messages[1], {u"message_type": u"twisted:log", u"message": u"stdout!", u"error": False}) assertContainsFields(self, messages[2], {u"message_type": u"twisted:log", u"message": u"stderr!", u"error": True})
def test_successful_test(self, logger): """ Starting and stopping a test logs a whole action. """ reporter = make_reporter() test = make_successful_test() reporter.startTest(test) reporter.stopTest(test) [action] = LoggedAction.of_type(logger.serialize(), TEST) assertContainsFields(self, action.start_message, {"test": test.id()})
def assert_call_parameters_logged(self, action, arg, kwarg, result): """ Assert 'action' has start message that includes the argument and keyword argument given, and an end message that includes the result. """ assertContainsFields( self, action.start_message, {'args': (arg,), 'kwargs': {'bar': kwarg}}) assertContainsFields( self, action.end_message, {'result': result})
def _assert_logfile_messages(self, stdout_messages, logfile): """ Verify that the messages have been logged to a file rather than to stdout. """ self.assertEqual([], stdout_messages) logfile_messages = map(loads, logfile.getContent().splitlines()) assertContainsFields( # message[0] contains a twisted log message. self, logfile_messages[1], {u"key": 123} )
def error_status_logged(case, logger): """ Validate the error logging behavior of ``_sync_command_error_squashed``. """ errors = LoggedMessage.ofType(logger.messages, ZFS_ERROR) assertContainsFields( case, errors[0].message, {'status': 1, 'zfs_command': 'python -c raise SystemExit(1)', 'output': '', u'message_type': 'filesystem:zfs:error', u'task_level': u'/'}) case.assertEqual(1, len(errors))
def no_such_executable_logged(case, logger): """ Validate the error logging behavior of ``_sync_command_error_squashed``. """ errors = LoggedMessage.ofType(logger.messages, ZFS_ERROR) assertContainsFields( case, errors[0].message, {'status': 1, 'zfs_command': 'nonsense garbage made up no such command', 'output': '[Errno 2] No such file or directory', u'message_type': 'filesystem:zfs:error', u'task_level': u'/'}) case.assertEqual(1, len(errors))
def assertMissingGetLogging(self, logger): """ When a I{GET} results in I{Not found}, a successful action is logged with a C{None} value. """ [get] = LoggedAction.of_type(logger.messages, LOG_LOOKUP_GET) assertContainsFields( self, get.start_message, {'environment': u'someenv', 'indexType': u'sometype', 'key': u'somekey'}) assertContainsFields(self, get.end_message, {'value': None}) self.assertTrue(get.succeeded)
def test_connection_error(self, logger): """ Returns ``None`` if it can't connect to the metadata server. """ result = metadata_from_service( metadata_service_endpoint=find_free_port()) self.assertIs(None, result) [message] = logger.messages assertContainsFields( self, message, { "message_type": ("flocker:node:agents:blockdevice:openstack:" "compute_instance_id:metadataservice_connection_error") })
def test_eliot_messages(self): """ Logged ``eliot`` messages get written to standard out. """ d = self.run_script(EliotScript) d.addCallback(lambda messages: assertContainsFields(self, messages[1], {u"key": 123})) return d
def test_eliot_messages(self): """ Logged ``eliot`` messages get written to standard out. """ d = self.run_script(EliotScript) d.addCallback(lambda messages: assertContainsFields( self, messages[1], {u"key": 123})) return d
def test_journald(self): """ When ``--journald`` option is used messages end up in the journal. """ d = self.run_journald_script(EliotScript) d.addCallback(lambda messages: assertContainsFields( self, messages[1], {u"key": 123})) return d
def test_connection_error(self, logger): """ Returns ``None`` if it can't connect to the metadata server. """ result = metadata_from_service( metadata_service_endpoint=find_free_port() ) self.assertIs(None, result) [message] = logger.messages assertContainsFields( self, message, {"message_type": ( "flocker:node:agents:blockdevice:openstack:" "compute_instance_id:metadataservice_connection_error" )} )
def test_journald(self): """ When ``--journald`` option is used messages end up in the journal. """ d = self.run_journald_script(EliotScript) d.addCallback(lambda messages: assertContainsFields(self, messages[1], {u"key": 123})) return d
def test_timeout_error(self, logger): """ Returns ``None`` if there is a timeout while connecting to the metadata server. """ # Simulate a connect timeout by attempting to connect to an unroutable # IP address. result = metadata_from_service(metadata_service_endpoint=("10.0.0.0", 80), connect_timeout=1.0) self.assertIs(None, result) [message] = logger.messages assertContainsFields( self, message, { "message_type": ("flocker:node:agents:blockdevice:openstack:" "compute_instance_id:metadataservice_connect_timeout") })
def assertTransitionLogging(self, logger): """ State transitions by L{IFiniteStateMachine} are logged. """ loggedTransition = LoggedAction.ofType( logger.messages, LOG_FSM_TRANSITION)[0] assertContainsFields( self, loggedTransition.startMessage, {u"fsm_identifier": u"<AnimalWorld>", u"fsm_state": u"<MoreState=amber>", u"fsm_rich_input": u"<Gravenstein>", u"fsm_input": u"<Input=apple>", }) self.assertTrue(loggedTransition.succeeded) assertContainsFields(self, loggedTransition.endMessage, {u"fsm_next_state": u"<MoreState=blue>", u"fsm_output": [u"<Output=aardvark>"], })
def test_journald_percent(self): """ When ``--journald`` option is used messages with a ``%`` in them can be logged correctly. """ d = self.run_journald_script(EliotPercentScript) d.addCallback(lambda messages: assertContainsFields( self, messages[1], {u"key": u"hello%s"})) return d
def test_immediate_success(self, logger): """ If the predicate returns something truthy immediately, then ``loop_until`` returns a deferred that has already fired with that value. """ result = object() def predicate(): return result clock = Clock() d = loop_until(clock, predicate) self.assertEqual(self.successResultOf(d), result) action = LoggedAction.of_type(logger.messages, LOOP_UNTIL_ACTION)[0] assertContainsFields(self, action.start_message, {"predicate": predicate}) assertContainsFields(self, action.end_message, {"action_status": "succeeded", "result": result})
def test_partial_predicate(self, logger): """ Predicate can be a functools.partial function. """ result = object() def check(): return result predicate = partial(check) clock = Clock() d = loop_until(clock, predicate) self.assertEqual(self.successResultOf(d), result) [action] = LoggedAction.of_type(logger.messages, LOOP_UNTIL_ACTION) assertContainsFields(self, action.start_message, {"predicate": predicate}) assertContainsFields(self, action.end_message, {"action_status": "succeeded", "result": result})
def test_sigint(self): """ A script that is killed by signal exits, logging the signal. """ d = self.run_script(SigintScript) d.addCallback(lambda messages: assertContainsFields( self, messages[1], {u"message_type": u"twisted:log", u"message": u"Received SIGINT, shutting down.", u"error": False})) return d
def assertTransitionLogging(self, logger): """ State transitions by L{IFiniteStateMachine} are logged. """ loggedTransition = LoggedAction.ofType(logger.messages, LOG_FSM_TRANSITION)[0] assertContainsFields( self, loggedTransition.startMessage, { u"fsm_identifier": u"<AnimalWorld>", u"fsm_state": u"<MoreState=amber>", u"fsm_rich_input": u"<Gravenstein>", u"fsm_input": u"<Input=apple>", }) self.assertTrue(loggedTransition.succeeded) assertContainsFields( self, loggedTransition.endMessage, { u"fsm_next_state": u"<MoreState=blue>", u"fsm_output": [u"<Output=aardvark>"], })
def test_journald_large_message(self): """ When ``--journald`` option is used large messages end up in the journal and are not broken up, demonstrating we're not hitting https://bugs.freedesktop.org/show_bug.cgi?id=86465 """ d = self.run_journald_script(EliotLargeScript) d.addCallback(lambda messages: assertContainsFields( self, messages[1], {u"key": EliotLargeScript.key})) return d
def test_twisted_messages(self): """ Logged Twisted messages get written to standard out as ``eliot`` messages. """ d = self.run_script(TwistedScript) d.addCallback(lambda messages: assertContainsFields( self, messages[1], {u"message_type": u"twisted:log", u"message": u"hello", u"error": False})) return d
def test_timeout_error(self, logger): """ Returns ``None`` if there is a timeout while connecting to the metadata server. """ # Simulate a connect timeout by attempting to connect to an unroutable # IP address. result = metadata_from_service( metadata_service_endpoint=("10.0.0.0", 80), connect_timeout=1.0 ) self.assertIs(None, result) [message] = logger.messages assertContainsFields( self, message, {"message_type": ( "flocker:node:agents:blockdevice:openstack:" "compute_instance_id:metadataservice_connect_timeout" )} )
def test_iterates(self, logger): """ If the predicate returns something falsey followed by something truthy, then ``loop_until`` returns it immediately. """ result = object() results = [None, result] def predicate(): return results.pop(0) clock = Clock() d = loop_until(clock, predicate) self.assertNoResult(d) clock.advance(0.1) self.assertEqual(self.successResultOf(d), result) action = LoggedAction.of_type(logger.messages, LOOP_UNTIL_ACTION)[0] assertContainsFields(self, action.start_message, { 'predicate': predicate, }) assertContainsFields(self, action.end_message, { 'result': result, }) self.assertTrue(action.succeeded) message = LoggedMessage.of_type(logger.messages, LOOP_UNTIL_ITERATION_MESSAGE)[0] self.assertEqual(action.children, [message]) assertContainsFields(self, message.message, { 'result': None, })
def test_iterates(self, logger): """ If the predicate returns something falsey followed by something truthy, then ``loop_until`` returns it immediately. """ result = object() results = [None, result] def predicate(): return results.pop(0) clock = Clock() d = loop_until(clock, predicate) self.assertNoResult(d) clock.advance(0.1) self.assertEqual( self.successResultOf(d), result) action = LoggedAction.of_type(logger.messages, LOOP_UNTIL_ACTION)[0] assertContainsFields(self, action.start_message, { 'predicate': predicate, }) assertContainsFields(self, action.end_message, { 'result': result, }) self.assertTrue(action.succeeded) message = LoggedMessage.of_type( logger.messages, LOOP_UNTIL_ITERATION_MESSAGE)[0] self.assertEqual(action.children, [message]) assertContainsFields(self, message.message, { 'result': None, })
def test_twisted_errors(self): """ Logged Twisted errors get written to standard out as ``eliot`` messages. """ message = (u'A zero division ono\nTraceback (most recent call ' u'last):\nFailure: exceptions.ZeroDivisionError: onoes\n') d = self.run_script(TwistedErrorScript) d.addCallback(lambda messages: assertContainsFields( self, messages[1], {u"message_type": u"twisted:log", u"message": message, u"error": True})) return d
def test_partial_predicate(self, logger): """ Predicate can be a functools.partial function. """ result = object() def check(): return result predicate = partial(check) clock = Clock() d = loop_until(clock, predicate) self.assertEqual(self.successResultOf(d), result) [action] = LoggedAction.of_type(logger.messages, LOOP_UNTIL_ACTION) assertContainsFields(self, action.start_message, { 'predicate': predicate, }) assertContainsFields(self, action.end_message, { 'action_status': 'succeeded', 'result': result, })
def test_immediate_success(self, logger): """ If the predicate returns something truthy immediately, then ``loop_until`` returns a deferred that has already fired with that value. """ result = object() def predicate(): return result clock = Clock() d = loop_until(clock, predicate) self.assertEqual(self.successResultOf(d), result) action = LoggedAction.of_type(logger.messages, LOOP_UNTIL_ACTION)[0] assertContainsFields(self, action.start_message, { 'predicate': predicate, }) assertContainsFields(self, action.end_message, { 'action_status': 'succeeded', 'result': result, })
def assertLookupLogging(self, logger): """ The put action is logged, followed by the get action. """ [put] = LoggedAction.of_type(logger.messages, LOG_LOOKUP_PUT) assertContainsFields( self, put.start_message, {'environment': u'someenv', 'indexType': u'sometype', 'key': u'somekey'}) assertContainsFields(self, put.end_message, {'value': b'data'}) self.assertTrue(put.succeeded) [get] = LoggedAction.of_type(logger.messages, LOG_LOOKUP_GET) assertContainsFields( self, get.start_message, {'environment': u'someenv', 'indexType': u'sometype', 'key': u'somekey'}) assertContainsFields(self, get.end_message, {'value': b'data'}) self.assertTrue(get.succeeded)
def actuallyAssert(self, logger): request = LoggedAction.ofType(logger.messages, REQUEST)[0] assertContainsFields(self, request.startMessage, { u"request_path": repr(path).decode("ascii"), })
def assertSearchLogging2(self, logger): """ The two put actions are logged, followed by the two get actions. """ [put1, put2] = LoggedAction.of_type(logger.messages, LOG_SEARCH_PUT) assertContainsFields( self, put1.start_message, {'searchClass': SearchClasses.EXACT, 'environment': u'e', 'indexType': u'i', 'searchType': u'type1', 'result': u'result1'}) assertContainsFields( self, put1.end_message, {'searchValue': u'value'}) self.assertTrue(put1.succeeded) assertContainsFields( self, put2.start_message, {'searchClass': SearchClasses.PREFIX, 'environment': u'e', 'indexType': u'i', 'searchType': u'type2', 'result': u'result2'}) assertContainsFields( self, put2.end_message, {'searchValue': u'value'}) self.assertTrue(put2.succeeded) [get1, get2] = LoggedAction.of_type(logger.messages, LOG_SEARCH_GET) assertContainsFields( self, get1.start_message, {'searchClass': SearchClasses.EXACT, 'environment': u'e', 'indexType': u'i', 'searchValue': u'value', 'searchType': None}) assertContainsFields(self, get1.end_message, {'results': [u'result1']}) self.assertTrue(get1.succeeded) assertContainsFields( self, get2.start_message, {'searchClass': SearchClasses.PREFIX, 'environment': u'e', 'indexType': u'i', 'searchValue': u'va', 'searchType': None}) assertContainsFields(self, get2.end_message, {'results': [u'result2']}) self.assertTrue(get2.succeeded)
def assertSearchLogging(self, logger): """ The put action is logged, followed by the get action, followed by the delete, followed by the second get. """ [put] = LoggedAction.of_type(logger.messages, LOG_SEARCH_PUT) assertContainsFields( self, put.start_message, {'searchClass': SearchClasses.EXACT, 'environment': u'someenv', 'indexType': u'someindex', 'result': u'result', 'searchType': u'type'}) assertContainsFields( self, put.end_message, {'searchValue': u'somevalue'}) self.assertTrue(put.succeeded) [delete] = LoggedAction.of_type(logger.messages, LOG_SEARCH_DELETE) assertContainsFields( self, delete.start_message, {'searchClass': SearchClasses.EXACT, 'environment': u'someenv', 'indexType': u'someindex', 'result': u'result', 'searchType': u'type'}) self.assertTrue(delete.succeeded) [get1, get2] = LoggedAction.of_type(logger.messages, LOG_SEARCH_GET) assertContainsFields( self, get1.start_message, {'searchClass': SearchClasses.EXACT, 'environment': u'someenv', 'indexType': u'someindex', 'searchValue': u'somevalue', 'searchType': None}) assertContainsFields(self, get1.end_message, {'results': [u'result']}) self.assertTrue(get1.succeeded) assertContainsFields( self, get2.start_message, {'searchClass': SearchClasses.EXACT, 'environment': u'someenv', 'indexType': u'someindex', 'searchValue': u'somevalue', 'searchType': None}) assertContainsFields(self, get2.end_message, {'results': []}) self.assertTrue(get2.succeeded)
def assertSearchLogging(self, logger): """ The put action is logged, followed by the get action, followed by the delete, followed by the second get. """ [put] = LoggedAction.of_type(logger.messages, LOG_SEARCH_PUT) assertContainsFields( self, put.start_message, {'searchClass': SearchClasses.EXACT, 'environment': u'someenv', 'indexType': u'someindex', 'result': u'result', 'searchType': u'type'}) assertContainsFields( self, put.end_message, {'searchValue': u'somevalue'}) self.assertTrue(put.succeeded) [delete] = LoggedAction.of_type(logger.messages, LOG_SEARCH_DELETE) assertContainsFields( self, delete.start_message, {'searchClass': SearchClasses.EXACT, 'environment': u'someenv', 'indexType': u'someindex', 'result': u'result', 'searchType': u'type'}) self.assertTrue(delete.succeeded) [get1, get2] = LoggedAction.of_type(logger.messages, LOG_SEARCH_GET) assertContainsFields( self, get1.start_message, {'searchClass': SearchClasses.EXACT, 'environment': u'someenv', 'indexType': u'someindex', 'searchValue': u'somevalue', 'searchType': None}) assertContainsFields( self, get1.end_message, {'results': [{u'result': u'result', u'type': u'type'}]}) self.assertTrue(get1.succeeded) assertContainsFields( self, get2.start_message, {'searchClass': SearchClasses.EXACT, 'environment': u'someenv', 'indexType': u'someindex', 'searchValue': u'somevalue', 'searchType': None}) assertContainsFields(self, get2.end_message, {'results': []}) self.assertTrue(get2.succeeded)
def assertSearchLogging2(self, logger): """ The two put actions are logged, followed by the two get actions. """ [put1, put2] = LoggedAction.of_type(logger.messages, LOG_SEARCH_PUT) assertContainsFields( self, put1.start_message, {'searchClass': SearchClasses.EXACT, 'environment': u'e', 'indexType': u'i', 'searchType': u'type1', 'result': u'result1'}) assertContainsFields( self, put1.end_message, {'searchValue': u'value'}) self.assertTrue(put1.succeeded) assertContainsFields( self, put2.start_message, {'searchClass': SearchClasses.PREFIX, 'environment': u'e', 'indexType': u'i', 'searchType': u'type2', 'result': u'result2'}) assertContainsFields( self, put2.end_message, {'searchValue': u'value'}) self.assertTrue(put2.succeeded) [get1, get2] = LoggedAction.of_type(logger.messages, LOG_SEARCH_GET) assertContainsFields( self, get1.start_message, {'searchClass': SearchClasses.EXACT, 'environment': u'e', 'indexType': u'i', 'searchValue': u'value', 'searchType': None}) assertContainsFields( self, get1.end_message, {'results': [{u'result': u'result1', u'type': u'type1'}]}) self.assertTrue(get1.succeeded) assertContainsFields( self, get2.start_message, {'searchClass': SearchClasses.PREFIX, 'environment': u'e', 'indexType': u'i', 'searchValue': u'va', 'searchType': None}) assertContainsFields( self, get2.end_message, {'results': [{u'result': u'result2', u'type': u'type2'}]}) self.assertTrue(get2.succeeded)