def test_separate_eliot_log(self, base_test_case):
"""
Flocker base test cases attach the eliot log as a detail separate from
the Twisted log.
"""
message_type = MessageType(u'foo', fields(name=str), u'test message')
class SomeTest(base_test_case):
def test_something(self):
from twisted.python import log
log.msg('foo')
message_type(name='qux').write()
test = SomeTest('test_something')
test.run()
self.assertThat(
test.getDetails(),
MatchesDict({
'twisted-log':
match_text_content(
MatchesRegex(
r'^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}[+-]\d{4} \[-\] foo'
)),
_SplitEliotLogs._ELIOT_LOG_DETAIL_NAME:
match_text_content(
Contains(" message_type: 'foo'\n"
" name: 'qux'\n")),
}))
def test_separate_eliot_log(self, base_test_case):
"""
Flocker base test cases attach the eliot log as a detail separate from
the Twisted log.
"""
message_type = MessageType(u"foo", fields(name=str), u"test message")
class SomeTest(base_test_case):
def test_something(self):
from twisted.python import log
log.msg("foo")
message_type(name="qux").write()
test = SomeTest("test_something")
test.run()
self.assertThat(
test.getDetails(),
MatchesDict(
{
"twisted-log": match_text_content(
MatchesRegex(r"^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}[+-]\d{4} \[-\] foo")
),
_SplitEliotLogs._ELIOT_LOG_DETAIL_NAME: match_text_content(
Contains(" message_type: 'foo'\n" " name: 'qux'\n")
),
}
),
)
def test_separate_eliot_log(self, base_test_case):
"""
Flocker base test cases attach the eliot log as a detail separate from
the Twisted log.
"""
# XXX: If debugging is enabled (either by setting this to True or by
# removing this line and running --debug-stacktraces, then the log
# fixtures in this test are empty. However, if we run a failing test
# manually, the logs appear in the details. Not sure what's going on,
# so disabling debugging for now.
self.useFixture(DebugTwisted(False))
message_type = MessageType(u'foo', fields(name=str), u'test message')
class SomeTest(base_test_case):
def test_something(self):
from twisted.python import log
log.msg('foo')
message_type(name='qux').write()
test = SomeTest('test_something')
result = TestResult()
test.run(result)
self.expectThat(result, has_results(tests_run=Equals(1)))
self.assertThat(
test.getDetails(),
MatchesDict({
'twisted-log': match_text_content(MatchesRegex(
r'^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}[+-]\d{4} \[-\] foo'
)),
_SplitEliotLogs._ELIOT_LOG_DETAIL_NAME: match_text_content(
Contains(" message_type: 'foo'\n"
" name: 'qux'\n")
),
}))
def test_logs_after_timeout(self):
"""
We include logs for tests, even if they time out.
"""
message_type = MessageType(u'foo', fields(name=str), u'test message')
class SomeTest(AsyncTestCase):
# Set the timeout super low, because we're not doing anything.
run_tests_with = async_runner(timeout=timedelta(seconds=0.00005))
def test_something(self):
from twisted.python import log
log.msg('foo')
message_type(name='qux').write()
# Return a Deferred that never fires to guarantee a timeout.
return Deferred()
test = SomeTest('test_something')
result = TestResult()
test.run(result)
self.assertThat(
result,
has_results(
tests_run=Equals(1),
errors=MatchesListwise([
MatchesListwise([
Equals(test),
MatchesAll(
Contains('[-] foo\n'),
Contains("message_type: 'foo'"),
),
])
]),
))
def test_logs_after_timeout(self):
"""
We include logs for tests, even if they time out.
"""
message_type = MessageType(u'foo', fields(name=str), u'test message')
class SomeTest(AsyncTestCase):
# Set the timeout super low, because we're not doing anything.
run_tests_with = async_runner(timeout=timedelta(seconds=0.00005))
def test_something(self):
from twisted.python import log
log.msg('foo')
message_type(name='qux').write()
# Return a Deferred that never fires to guarantee a timeout.
return Deferred()
test = SomeTest('test_something')
result = TestResult()
test.run(result)
self.assertThat(
result,
has_results(
tests_run=Equals(1),
errors=MatchesListwise([MatchesListwise([
Equals(test),
MatchesAll(
Contains('[-] foo\n'),
Contains("message_type: 'foo'"),
),
])]),
)
)
def test_separate_eliot_log(self, base_test_case):
"""
Flocker base test cases attach the eliot log as a detail separate from
the Twisted log.
"""
# XXX: If debugging is enabled (either by setting this to True or by
# removing this line and running --debug-stacktraces, then the log
# fixtures in this test are empty. However, if we run a failing test
# manually, the logs appear in the details. Not sure what's going on,
# so disabling debugging for now.
self.useFixture(DebugTwisted(False))
message_type = MessageType(u'foo', fields(name=str), u'test message')
class SomeTest(base_test_case):
def test_something(self):
from twisted.python import log
log.msg('foo')
message_type(name='qux').write()
test = SomeTest('test_something')
result = TestResult()
test.run(result)
self.expectThat(result, has_results(tests_run=Equals(1)))
self.assertThat(
test.getDetails(),
MatchesDict({
'twisted-log':
match_text_content(
MatchesRegex(
r'^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}[+-]\d{4} \[-\] foo'
)),
_SplitEliotLogs._ELIOT_LOG_DETAIL_NAME:
match_text_content(
Contains(" message_type: 'foo'\n"
" name: 'qux'\n")),
}))
self.assertEqual(self.clock.getDelayedCalls(), [])
def test_timeout_cleaned_up_on_failure(self):
"""
If the deferred is failed before the timeout, the timeout is not still
pending on the reactor.
"""
timeout(self.clock, self.deferred, self.timeout)
self.deferred.errback(CustomException(self.id()))
# We need to handle the errback so that Trial and/or testtools don't
# fail with unhandled errors.
self.addCleanup(self.deferred.addErrback, lambda _: None)
self.assertEqual(self.clock.getDelayedCalls(), [])
ITERATION_MESSAGE = MessageType("iteration_message", fields(iteration=int))
class RetryFailureTests(SynchronousTestCase):
"""
Tests for :py:func:`retry_failure`.
"""
def test_immediate_success(self):
"""
If the function returns a successful value immediately, then
``retry_failure`` returns a deferred that has already fired with that
value.
"""
result = object()
def function():
import eliot
HANDOFF = eliot.ActionType(
u'wip:handoff',
eliot.fields(
path=str),
eliot.fields(
family=int, type=int, proto=int),
u'A listening socket is being handed off.')
SCGI_ACCEPTED = eliot.MessageType(
u'wip:scgi_accepted',
[],
u'A listening SCGI socket has accepted a connection.')
SCGI_REQUEST = eliot.ActionType(
u'wip:scgi_request',
[],
[],
u'An SCGI request is being handled.')
SCGI_PARSE = eliot.ActionType(
u'wip:scgi_parse',
[],
[],
u'A new SCGI request is being parsed.')
WSGI_REQUEST = eliot.ActionType(
u'wip:wsgi_request',
eliot.fields(
"""
cluster_state = compute_cluster_state(node_state, additional_node_states,
nonmanifest_datasets)
cluster_configuration = Deployment(
nodes={node_config} | additional_node_config,
leases=leases,
)
changes = deployer.calculate_changes(
cluster_configuration, cluster_state, local_state
)
case.assertEqual(expected_changes, changes)
ADDRESS_IN_USE = MessageType(
u"flocker:test:address_in_use",
fields(ip=unicode, port=int, name=bytes),
)
def _find_process_name(port_number):
"""
Get the name of the process using the given port number.
"""
for connection in psutil.net_connections():
if connection.laddr[1] == port_number:
return psutil.Process(connection.pid).name()
return None
def _retry_on_port_collision(reason, add, cleanup):
"""
:param dict options: A dictionary of configuration options.
:return: A ``Deferred`` which fires when the script has completed.
"""
def eliot_logging_service(destination, reactor, capture_stdout):
service = MultiService()
ThreadedWriter(destination, reactor).setServiceParent(service)
EliotObserver(capture_stdout=capture_stdout).setServiceParent(service)
return service
# This should probably be built-in functionality in Eliot;
# see https://github.com/ClusterHQ/eliot/issues/143
TWISTED_LOG_MESSAGE = MessageType("twisted:log",
fields(error=bool, message=unicode),
u"A log message from Twisted.")
class EliotObserver(Service):
"""
A Twisted log observer that logs to Eliot.
"""
def __init__(self, publisher=twisted_log, capture_stdout=True):
"""
:param publisher: A ``LogPublisher`` to capture logs from, or if no
argument is given the default Twisted log system.
:param bool capture_stdout: Wether to capture standard output and
standard error to eliot.
"""
self.logger = Logger()
:param dict options: A dictionary of configuration options.
:return: A ``Deferred`` which fires when the script has completed.
"""
def eliot_logging_service(destination, reactor, capture_stdout):
service = MultiService()
ThreadedWriter(destination, reactor).setServiceParent(service)
EliotObserver(capture_stdout=capture_stdout).setServiceParent(service)
return service
# This should probably be built-in functionality in Eliot;
# see https://github.com/ClusterHQ/eliot/issues/143
TWISTED_LOG_MESSAGE = MessageType("twisted:log",
fields(error=bool, message=unicode),
u"A log message from Twisted.")
def eliot_to_stdout(message_formats, action_formats, stdout=sys.stdout):
"""
Write pretty versions of eliot log messages to stdout.
"""
def eliot_output(message):
message_type = message.get('message_type')
action_type = message.get('action_type')
action_status = message.get('action_status')
message_format = ''
if message_type is not None:
if message_type == 'twisted:log' and message.get('error'):
"""
Eliot message and action definitions.
"""
from operator import methodcaller
from eliot import ActionType, Field, fields
from twisted.python.compat import unicode
NONCE = Field(u'nonce', lambda nonce: nonce.encode('hex').decode('ascii'),
u'A nonce value')
LOG_JWS_SIGN = ActionType(u'txacme:jws:sign',
fields(NONCE, key_type=unicode, alg=unicode),
fields(), u'Signing a message with JWS')
LOG_JWS_HEAD = ActionType(u'txacme:jws:http:head', fields(), fields(),
u'A JWSClient HEAD request')
LOG_JWS_GET = ActionType(u'txacme:jws:http:get', fields(), fields(),
u'A JWSClient GET request')
LOG_JWS_POST = ActionType(u'txacme:jws:http:post', fields(), fields(),
u'A JWSClient POST request')
LOG_JWS_REQUEST = ActionType(
u'txacme:jws:http:request', fields(url=unicode),
fields(Field.for_types(u'content_type', [unicode, None],
u'Content-Type header field'),
code=int), u'A JWSClient request')
LOG_JWS_CHECK_RESPONSE = ActionType(
import eliot
HANDOFF = eliot.ActionType(u'wip:handoff', eliot.fields(path=str),
eliot.fields(family=int, type=int, proto=int),
u'A listening socket is being handed off.')
SCGI_ACCEPTED = eliot.MessageType(
u'wip:scgi_accepted', [],
u'A listening SCGI socket has accepted a connection.')
SCGI_REQUEST = eliot.ActionType(u'wip:scgi_request', [], [],
u'An SCGI request is being handled.')
SCGI_PARSE = eliot.ActionType(u'wip:scgi_parse', [], [],
u'A new SCGI request is being parsed.')
WSGI_REQUEST = eliot.ActionType(u'wip:wsgi_request', eliot.fields(path=str),
[], u'A WSGI application is being called.')
RESPONSE_STARTED = eliot.MessageType(
u'wip:response_started', eliot.fields(status=str),
u'A WSGI application has called start_response.')
# TWISTED_LOG_MESSAGE and EliotObserver licensed under APL 2.0 from
# ClusterHQ/flocker
# https://github.com/ClusterHQ/flocker/blob/master/flocker/common/script.py#L81-L106
import json
import os
import pkg_resources
import socket
import sys
import raven
from eliot import add_destination, fields, Logger, MessageType
from twisted.python.log import textFromEventDict, startLoggingWithObserver
HOSTNAME = socket.getfqdn()
LOGGER = None
TWISTED_LOG_MESSAGE = MessageType("twisted:log", fields(error=bool, message=unicode), u"A log message from Twisted.")
HUMAN = False
class EliotObserver(object):
"""A Twisted log observer that logs to Eliot"""
def __init__(self):
"""Create the Eliot Observer"""
if os.environ.get("SENTRY_DSN"):
self.raven_client = raven.Client(release=raven.fetch_package_version("autopush"))
else:
self.raven_client = None
self.logger = Logger()
def raven_log(self, event):
LOG_START_SERVICE = ActionType(
u'fusion_index:service:start',
[_SERVICE_DESCRIPTION],
[],
u'Indexing service is starting')
LOG_STOP_SERVICE = ActionType(
u'fusion_index:service:stop', [], [], u'Indexing service is stopping')
LOG_LOOKUP_GET = ActionType(
u'fusion_index:lookup:get',
fields(environment=unicode, indexType=unicode, key=unicode),
[Field.for_types('value', [bytes, None], u'Value in the index, if any')],
u'Retrieving a value from the lookup index')
LOG_LOOKUP_PUT = ActionType(
u'fusion_index:lookup:put',
fields(environment=unicode, indexType=unicode, key=unicode),
fields(value=bytes),
u'Storing a value in the lookup index')
_SEARCH_TYPE = Field.for_types(
'searchType', [unicode, None], u'The search type')
LOG_SEARCH_GET = ActionType(
u'fusion_index:search:get',
"""
Eliot message and action definitions.
"""
from operator import methodcaller
from eliot import ActionType, Field, fields
from twisted.python.compat import unicode
NONCE = Field(u'nonce', lambda nonce: nonce.encode('hex').decode('ascii'),
u'A nonce value')
LOG_JWS_SIGN = ActionType(
u'txacme:jws:sign',
fields(NONCE, key_type=unicode, alg=unicode, kid=unicode), fields(),
u'Signing a message with JWS')
LOG_JWS_HEAD = ActionType(u'txacme:jws:http:head', fields(), fields(),
u'A JWSClient HEAD request')
LOG_JWS_GET = ActionType(u'txacme:jws:http:get', fields(), fields(),
u'A JWSClient GET request')
LOG_JWS_POST = ActionType(u'txacme:jws:http:post', fields(), fields(),
u'A JWSClient POST request')
LOG_JWS_REQUEST = ActionType(
u'txacme:jws:http:request', fields(url=unicode),
fields(Field.for_types(u'content_type', [unicode, None],
u'Content-Type header field'),
code=int), u'A JWSClient request')
self.assertEqual(self.clock.getDelayedCalls(), [])
def test_timeout_cleaned_up_on_failure(self):
"""
If the deferred is failed before the timeout, the timeout is not still
pending on the reactor.
"""
timeout(self.clock, self.deferred, self.timeout)
self.deferred.errback(CustomException(self.id()))
# We need to handle the errback so that Trial and/or testtools don't
# fail with unhandled errors.
self.addCleanup(self.deferred.addErrback, lambda _: None)
self.assertEqual(self.clock.getDelayedCalls(), [])
ITERATION_MESSAGE = MessageType("iteration_message", fields(iteration=int))
class RetryFailureTests(TestCase):
"""
Tests for :py:func:`retry_failure`.
"""
def test_immediate_success(self):
"""
If the function returns a successful value immediately, then
``retry_failure`` returns a deferred that has already fired with that
value.
"""
result = object()
"""
result = run_process([executable] + [b"--help"])
self.assertIn(executable, result.output)
return ScriptTests
class CustomException(Exception):
"""
An exception that will never be raised by real code, useful for
testing.
"""
TWISTED_CHILD_PROCESS_ACTION = ActionType(
u"flocker:testtools:logged_run_process", fields(command=list), [], u"A child process is spawned using Twisted"
)
STDOUT_RECEIVED = MessageType(
u"flocker:testtools:logged_run_process:stdout",
fields(output=str),
u"A chunk of stdout received from a child process",
)
STDERR_RECEIVED = MessageType(
u"flocker:testtools:logged_run_process:stdout",
fields(output=str),
u"A chunk of stderr received from a child process",
)
PROCESS_ENDED = MessageType(
"""
result = run_process([executable] + [b"--help"])
self.assertIn(executable, result.output)
return ScriptTests
class CustomException(Exception):
"""
An exception that will never be raised by real code, useful for
testing.
"""
TWISTED_CHILD_PROCESS_ACTION = ActionType(
u'flocker:testtools:logged_run_process',
fields(command=list),
[],
u'A child process is spawned using Twisted',
)
STDOUT_RECEIVED = MessageType(
u'flocker:testtools:logged_run_process:stdout',
fields(output=str),
u'A chunk of stdout received from a child process',
)
STDERR_RECEIVED = MessageType(
u'flocker:testtools:logged_run_process:stdout',
fields(output=str),
u'A chunk of stderr received from a child process',
)
from eliot import ActionType, Field, fields
_SEARCH_CLASS = Field(u'searchClass', lambda c: c.value, u'The search class')
LOG_LOOKUP_GET = ActionType(
u'fusion_index:lookup:get',
fields(environment=unicode, indexType=unicode, key=unicode),
[Field.for_types('value', [bytes, None], u'Value in the index, if any')],
u'Retrieving a value from the lookup index')
LOG_LOOKUP_PUT = ActionType(
u'fusion_index:lookup:put',
fields(environment=unicode, indexType=unicode, key=unicode),
fields(value=bytes), u'Storing a value in the lookup index')
_SEARCH_TYPE = Field.for_types('searchType', [unicode, None],
u'The search type')
LOG_SEARCH_GET = ActionType(
u'fusion_index:search:get',
fields(_SEARCH_CLASS,
_SEARCH_TYPE,
environment=unicode,
indexType=unicode,
searchValue=unicode), fields(results=list),
u'Searching the search index')
LOG_SEARCH_PUT = ActionType(
u'fusion_index:search:put',
fields(_SEARCH_CLASS,
environment=unicode,
indexType=unicode,
"""
result = run_process([executable] + [b"--help"])
self.assertIn(executable, result.output)
return ScriptTests
class CustomException(Exception):
"""
An exception that will never be raised by real code, useful for
testing.
"""
TWISTED_CHILD_PROCESS_ACTION = ActionType(
u'flocker:testtools:logged_run_process',
fields(command=list),
[],
u'A child process is spawned using Twisted',
)
STDOUT_RECEIVED = MessageType(
u'flocker:testtools:logged_run_process:stdout',
fields(output=str),
u'A chunk of stdout received from a child process',
)
STDERR_RECEIVED = MessageType(
u'flocker:testtools:logged_run_process:stdout',
fields(output=str),
u'A chunk of stderr received from a child process',
)
This starts a Docker-based container convergence agent.
"""
def deployer_factory(cluster_uuid, **kwargs):
return ApplicationNodeDeployer(**kwargs)
service_factory = AgentServiceFactory(
deployer_factory=deployer_factory
).get_service
agent_script = AgentScript(service_factory=service_factory)
return FlockerScriptRunner(
script=agent_script,
options=ContainerAgentOptions()
).main()
LOG_GET_EXTERNAL_IP = ActionType(u"flocker:node:script:get_external_ip",
fields(host=unicode, port=int),
fields(local_ip=unicode),
"An attempt to discover the local IP.")
def _get_external_ip(host, port):
"""
Get an external IP address for this node that can in theory connect to
the given host and port.
Failures are retried until a successful connect.
See https://clusterhq.atlassian.net/browse/FLOC-1751 for a possibly
better solution.
:param host: A host to connect to.
result = run_process([executable] + [b"--help"])
self.assertIn(executable, result.output)
return ScriptTests
class CustomException(Exception):
"""
An exception that will never be raised by real code, useful for
testing.
"""
TWISTED_CHILD_PROCESS_ACTION = ActionType(
u'flocker:testtools:logged_run_process',
fields(command=list),
[],
u'A child process is spawned using Twisted',
)
STDOUT_RECEIVED = MessageType(
u'flocker:testtools:logged_run_process:stdout',
fields(output=str),
u'A chunk of stdout received from a child process',
)
STDERR_RECEIVED = MessageType(
u'flocker:testtools:logged_run_process:stdout',
fields(output=str),
u'A chunk of stderr received from a child process',
)
"""
Eliot message and action definitions.
"""
from operator import methodcaller
from eliot import ActionType, Field, fields
from twisted.python.compat import unicode
NONCE = Field(
u'nonce',
lambda nonce: nonce.encode('hex').decode('ascii'),
u'A nonce value')
LOG_JWS_SIGN = ActionType(
u'txacme:jws:sign',
fields(NONCE, key_type=unicode, alg=unicode),
fields(),
u'Signing a message with JWS')
LOG_JWS_HEAD = ActionType(
u'txacme:jws:http:head',
fields(),
fields(),
u'A JWSClient HEAD request')
LOG_JWS_GET = ActionType(
u'txacme:jws:http:get',
fields(),
fields(),
u'A JWSClient GET request')
for dataset in nonmanifest_datasets
},
)
cluster_configuration = Deployment(
nodes={node_config} | additional_node_config,
leases=leases,
)
changes = deployer.calculate_changes(
cluster_configuration, cluster_state,
)
case.assertEqual(expected_changes, changes)
ADDRESS_IN_USE = MessageType(
u"flocker:test:address_in_use",
fields(ip=unicode, port=int, name=bytes),
)
def _find_process_name(port_number):
"""
Get the name of the process using the given port number.
"""
for connection in psutil.net_connections():
if connection.laddr[1] == port_number:
return psutil.Process(connection.pid).name()
return None
def _retry_on_port_collision(reason, add, cleanup):
"""
def test_bad_message(self):
# This message does not validate because "Hello" is not an
# int.
MSG = MessageType("test:eliotutil", fields(foo=int))
MSG(foo="Hello").write()
service_factory = AgentServiceFactory(
deployer_factory=deployer_factory).get_service
agent_script = AgentScript(service_factory=service_factory)
# Use CPU time instead of wallclock time.
pr = cProfile.Profile(clock)
signal.signal(signal.SIGUSR1, partial(enable_profiling, pr))
signal.signal(signal.SIGUSR2, partial(disable_profiling, pr, 'container'))
return FlockerScriptRunner(script=agent_script,
options=ContainerAgentOptions()).main()
LOG_GET_EXTERNAL_IP = ActionType(u"flocker:node:script:get_external_ip",
fields(host=unicode, port=int),
fields(local_ip=unicode),
"An attempt to discover the local IP.")
def _get_external_ip(host, port):
"""
Get an external IP address for this node that can in theory connect to
the given host and port.
Failures are retried until a successful connect.
See https://clusterhq.atlassian.net/browse/FLOC-1751 for a possibly
better solution.
:param host: A host to connect to.
of the cluster state without manifestations on any node.
:param set additional_node_states: A set of ``NodeState`` for other nodes.
:param set additional_node_config: A set of ``Node`` for other nodes.
:param expected_changes: The ``IStateChange`` expected to be returned.
:param ILocalState local_state: The ``local_state`` to pass into
``calculate_changes``. Must be the correct type for the type of
``IDeployer`` being tested.
:param Leases leases: Currently configured leases. By default none exist.
"""
cluster_state = compute_cluster_state(node_state, additional_node_states, nonmanifest_datasets)
cluster_configuration = Deployment(nodes={node_config} | additional_node_config, leases=leases)
changes = deployer.calculate_changes(cluster_configuration, cluster_state, local_state)
case.assertEqual(expected_changes, changes)
ADDRESS_IN_USE = MessageType(u"flocker:test:address_in_use", fields(ip=unicode, port=int, name=bytes))
def _find_process_name(port_number):
"""
Get the name of the process using the given port number.
"""
for connection in psutil.net_connections():
if connection.laddr[1] == port_number:
return psutil.Process(connection.pid).name()
return None
def _retry_on_port_collision(reason, add, cleanup):
"""
Cleanup and re-add a container if it failed to start because of a port