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 validate(case, logger):
assertHasAction(case, logger, parent_action_type, succeeded=True)
# Remember what the docstring said? Ideally this would inspect the
# children of the action returned by assertHasAction but the interfaces
# don't seem to line up.
iptables = LoggedAction.ofType(logger.messages, IPTABLES)
case.assertNotEqual(iptables, [])
def assert_nested_logging(self, combo, action_type, logger):
"""
All the underlying ``IStateChange`` will be run in Eliot context in
which the sequential ``IStateChange`` is run, even if they are not
run immediately.
:param combo: ``sequentially`` or ``in_parallel``.
:param action_type: ``eliot.ActionType`` we expect to be parent of
sub-changes' log entries.
:param logger: A ``MemoryLogger`` where messages go.
"""
actions = [ControllableAction(result=Deferred()),
ControllableAction(result=succeed(None))]
for action in actions:
self.patch(action, "_logger", logger)
run_state_change(combo(actions), None)
# For sequentially this will ensure second action doesn't
# automatically run in context of LOG_ACTION:
actions[0].result.callback(None)
parent = assertHasAction(self, logger, action_type, succeeded=True)
self.assertEqual(
dict(messages=parent.children, length=len(parent.children)),
dict(
messages=LoggedAction.ofType(
logger.messages, CONTROLLABLE_ACTION_TYPE),
length=2))
def test_error_sending(self, logger):
"""
An error sending to one agent does not prevent others from being
notified.
"""
control_amp_service = build_control_amp_service(self)
self.patch(control_amp_service, 'logger', logger)
connected_protocol = ControlAMP(control_amp_service)
# Patching is bad.
# https://clusterhq.atlassian.net/browse/FLOC-1603
connected_protocol.callRemote = lambda *args, **kwargs: succeed({})
error = ConnectionLost()
disconnected_protocol = ControlAMP(control_amp_service)
results = [succeed({}), fail(error)]
# Patching is bad.
# https://clusterhq.atlassian.net/browse/FLOC-1603
disconnected_protocol.callRemote = (
lambda *args, **kwargs: results.pop(0))
control_amp_service.connected(disconnected_protocol)
control_amp_service.connected(connected_protocol)
control_amp_service.node_changed(NodeState(hostname=u"1.2.3.4"))
actions = LoggedAction.ofType(logger.messages, LOG_SEND_TO_AGENT)
self.assertEqual(
[action.end_message["exception"] for action in actions
if not action.succeeded],
[u"twisted.internet.error.ConnectionLost"])
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 assertOutputLogging(self, logger):
"""
The L{IOutputExecutor} is invoked in the FSM's transition action
context.
"""
loggedTransition = LoggedAction.ofType(
logger.messages, LOG_FSM_TRANSITION)[0]
loggedAnimal = LoggedMessage.ofType(logger.messages, LOG_ANIMAL)[0]
self.assertIn(loggedAnimal, loggedTransition.children)
def test_read_headers_fails(capture_logging):
unparseable = io.BytesIO(b'21:'
b'missing trailing null'
b',')
with pytest.raises(RuntimeError), capture_logging() as logger:
receiver.read_headers(unparseable)
fail_actions = LoggedAction.ofType(logger.messages, types.SCGI_PARSE)
assert fail_actions and not fail_actions[0].succeeded
def test_read_headers_succeeds(capture_logging):
parseable = io.BytesIO(SPEC_REQUEST_HEADERS)
expected = {'CONTENT_LENGTH': '27',
'SCGI': '1',
'REQUEST_METHOD': 'POST',
'REQUEST_URI': '/deepthought'}
with capture_logging() as logger:
assert receiver.read_headers(parseable) == expected
actions = LoggedAction.ofType(logger.messages, types.SCGI_PARSE)
assert actions and actions[0].succeeded
def test_responseResultContainsIncident(self, logger):
"""
If the decorated function raises an exception, the HTTP response body
is a json-encoded object with a item set to an incident
identifier.
"""
request = dummyRequest(b"GET", b"/foo/exception", Headers(), b"")
app = self.application(logger, None)
self.render(app.app.resource(), request)
logger.flushTracebacks(ArbitraryException)
incident = loads(request._responseBody)
action = LoggedAction.ofType(logger.messages, REQUEST)[0]
# First message in action was action start with task_level /1, so
# next task_level is /2:
self.assertEqual(u"{}@/2".format(action.startMessage[u"task_uuid"]), incident)
def test_read_headers_succeeds_with_latin_1(capture_logging):
latin1 = io.BytesIO()
latin1.writelines([b'29:'
b'CONTENT_LENGTH', _NULL, b'1', _NULL,
b'X_LATIN_1', _NULL, b'\xbf', _NULL,
b','])
latin1.seek(0)
expected = {'CONTENT_LENGTH': '1',
'X_LATIN_1': u'\N{INVERTED QUESTION MARK}'}
with capture_logging() as logger:
assert receiver.read_headers(latin1) == expected
actions = LoggedAction.ofType(logger.messages, types.SCGI_PARSE)
assert actions and actions[0].succeeded
def test_responseResultContainsIncident(self, logger):
"""
If the decorated function raises an exception, the HTTP response body
is a json-encoded object with a item set to an incident
identifier.
"""
request = dummyRequest(b"GET", b"/foo/exception", Headers(), b"")
app = self.application(logger, None)
self.render(app.app.resource(), request)
logger.flushTracebacks(ArbitraryException)
incident = loads(request._responseBody)
action = LoggedAction.ofType(logger.messages, REQUEST)[0]
# First message in action was action start with task_level /1, so
# next task_level is /2:
self.assertEqual(
u"{}@/2".format(action.startMessage[u"task_uuid"]),
incident)
def test_app_returns_empty_iterable(
capture_logging, processor_with_environ, outstream):
expected_environ = {'PATH_INFO': 'blah'}
expected_response = _OK_STATUS_HEADERS_PREPARED
def hello_world(environ, start_response):
assert expected_environ == environ
start_response(_OK_STATUS, _OK_HEADERS)
return []
with capture_logging() as logger:
processor_with_environ(expected_environ).run_app(hello_world)
assert outstream.getvalue() == expected_response
fail_actions = LoggedAction.ofType(logger.messages, types.WSGI_REQUEST)
assert fail_actions and fail_actions[0].succeeded
def test_serialized_task(self, logger):
"""
If the ``X-Eliot-Task-Id`` header containers a serialized task level,
it is used as a parent of the logged actions from the handler.
"""
parent = ActionType("parent", [], [])
with parent() as context:
task_id = context.serialize_task_id()
app = self.Application()
app.logger = logger
request = dummyRequest(b"GET", b"/foo/bar", Headers({b"X-Eliot-Task-Id": [task_id]}), b"")
render(app.app.resource(), request)
logged_parent = LoggedAction.ofType(logger.messages, parent)[0]
child = _assertRequestLogged(b"/foo/bar")(self, logger)
self.assertIn(child, logged_parent.descendants())
def test_responseResultContainsIncident(self, logger):
"""
If the decorated function raises an exception, the HTTP response body
is a json-encoded object with a C{u"result"} item set to an incident
identifier.
"""
request = dummyRequest(b"GET", b"/foo/exception", Headers(), b"")
app = self.application(logger, None)
self.render(app.app.resource(), request)
logger.flushTracebacks(ArbitraryException)
response = loads(request._responseBody)
incident = response[u"result"]
action = LoggedAction.ofType(logger.messages, REQUEST)[0]
self.assertEqual(
u",".join((
action.startMessage[u"task_uuid"],
action.startMessage[u"task_level"])),
incident)
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_serialized_task(self, logger):
"""
If the ``X-Eliot-Task-Id`` header containers a serialized task level,
it is used as a parent of the logged actions from the handler.
"""
parent = ActionType("parent", [], [])
with parent() as context:
task_id = context.serialize_task_id()
app = self.Application()
app.logger = logger
request = dummyRequest(
b"GET", b"/foo/bar", Headers({b"X-Eliot-Task-Id": [task_id]}), b"")
render(app.app.resource(), request)
logged_parent = LoggedAction.ofType(logger.messages, parent)[0]
child = _assertRequestLogged(b"/foo/bar")(self, logger)
self.assertIn(child, logged_parent.descendants())
def some_iptables_logged(parent_action_type):
"""
Create a validator which assert that some ``IPTABLES`` actions got logged.
They should be logged as children of a ``parent_action_type`` action (but
this function will not verify that). No other assertions are made about
the particulars of the message because that would be difficult (by virtue
of requiring we duplicate the exact iptables commands from the
implementation here, in the tests, which is tedious and produces fragile
tests).
"""
def validate(case, logger):
assertHasAction(case, logger, parent_action_type, succeeded=True)
# Remember what the docstring said? Ideally this would inspect the
# children of the action returned by assertHasAction but the interfaces
# don't seem to line up.
iptables = LoggedAction.ofType(logger.messages, IPTABLES)
case.assertNotEqual(iptables, [])
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 got_response(_):
parent = LoggedAction.ofType(logger.messages, my_action)[0]
child = LoggedAction.ofType(logger.messages, JSON_REQUEST)[0]
self.assertIn(child, list(parent.descendants()))
def actuallyAssert(self, logger):
request = LoggedAction.ofType(logger.messages, REQUEST)[0]
assertContainsFields(self, request.startMessage, {
u"request_path": repr(path).decode("ascii"),
})
