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_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")), }))
AWS_MESSAGE = Field.for_types( "aws_message", [unicode], u"A human-readable error message given by the response.", ) AWS_REQUEST_ID = Field.for_types( "aws_request_id", [bytes, unicode], u"The unique identifier assigned by the server for this request.", ) DEVICES = Field.for_types( u"devices", [list], u"List of devices currently in use by the compute instance.") NO_AVAILABLE_DEVICE = MessageType( u"flocker:node:agents:blockdevice:aws:no_available_device", [DEVICES], ) IN_USE_DEVICES = MessageType( u"flocker:node:agents:blockdevice:aws:in_use_devices", [DEVICES], u"Log current devices.", ) NEW_DEVICES = Field.for_types(u"new_devices", [list], u"List of new devices in the compute instance.") NEW_DEVICES_SIZE = Field.for_types( u"new_devices_size", [list], u"List of sizes of new devices in the compute instance.") EXPECTED_SIZE = Field.for_types( u"expected_size", [int], u"Size, in bytes, of new device we are expecting to manifest."
: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'):
Raised when ``loop_until`` looped too many times. """ def __init__(self, predicate, last_result): super(LoopExceeded, self).__init__('%r never True in loop_until, last result: %r' % (predicate, last_result)) LOOP_UNTIL_ACTION = ActionType( action_type="flocker:common:loop_until", startFields=[Field("predicate", function_serializer)], successFields=[Field("result", serializer=safe_repr)], description="Looping until predicate is true.") LOOP_UNTIL_ITERATION_MESSAGE = MessageType( message_type="flocker:common:loop_until:iteration", fields=[Field("result", serializer=safe_repr)], description="Predicate failed, trying again.") def loop_until(reactor, predicate, steps=None): """Repeatedly call ``predicate``, until it returns something ``Truthy``. :param reactor: The reactor implementation to use to delay. :type reactor: ``IReactorTime``. :param predicate: Callable returning termination condition. :type predicate: 0-argument callable returning a Deferred. :param steps: An iterable of delay intervals, measured in seconds. If not provided, will default to retrying every 0.1 seconds forever.
Field("graph", _serialize_graph, "The resulting graph"), ], ) START_BLUEPRINT = ActionType("bootsteps:blueprint:start", [Field("name", str, "The name of the blueprint")], []) STOP_BLUEPRINT = ActionType("bootsteps:blueprint:stop", [Field("name", str, "The name of the blueprint")], []) NEXT_BOOTSTEPS = MessageType( "bootsteps:blueprint:next_bootsteps", [ Field("name", str, "The name of the blueprint"), Field("next_bootsteps", lambda steps: [repr(s) for s in steps]), ], ) EXECUTING_BOOTSTEP = ActionType( "bootsteps:blueprint:executing_bootstep", [Field("bootstep", repr, "The name of the step")], [], ) class BlueprintState(Enum): """An enum represeting the different lifecycle stages of a Blueprint.""" INITIALIZED = "initialized"
elif class_name == u"UUID": return UUID(dictionary[u"hex"]) elif class_name == u"datetime": return datetime.fromtimestamp(dictionary[u"seconds"], UTC) elif class_name in _CONFIG_CLASS_MAP: dictionary = dictionary.copy() dictionary.pop(_CLASS_MARKER) return _CONFIG_CLASS_MAP[class_name].create(dictionary) else: return dictionary return loads(data, object_hook=decode) _DEPLOYMENT_FIELD = Field(u"configuration", repr) _LOG_STARTUP = MessageType(u"flocker-control:persistence:startup", [_DEPLOYMENT_FIELD]) _LOG_SAVE = ActionType(u"flocker-control:persistence:save", [_DEPLOYMENT_FIELD], []) _UPGRADE_SOURCE_FIELD = Field.for_types( u"source_version", [int], u"Configuration version to upgrade from.") _UPGRADE_TARGET_FIELD = Field.for_types( u"target_version", [int], u"Configuration version to upgrade to.") _LOG_UPGRADE = ActionType(u"flocker-control:persistence:migrate_configuration", [ _DEPLOYMENT_FIELD, _UPGRADE_SOURCE_FIELD, _UPGRADE_TARGET_FIELD, ], []) _LOG_EXPIRE = MessageType( u"flocker-control:persistence:lease-expired",
: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): """
os.environ) d = connectProtocol(endpoint, _AccumulatingProtocol()) d.addCallback(lambda protocol: protocol._result) return d _ZFS_COMMAND = Field.forTypes( "zfs_command", [bytes], u"The command which was run.") _OUTPUT = Field.forTypes( "output", [bytes], u"The output generated by the command.") _STATUS = Field.forTypes( "status", [int], u"The exit status of the command") ZFS_ERROR = MessageType( "filesystem:zfs:error", [_ZFS_COMMAND, _OUTPUT, _STATUS], u"The zfs command signaled an error.") def _sync_command_error_squashed(arguments, logger): """ Synchronously run a command-line tool with the given arguments. :param arguments: A ``list`` of ``bytes``, command-line arguments to execute. :param eliot.Logger logger: The log writer to use to log errors running the zfs command. """ message = None log_arguments = b" ".join(arguments)
from twisted.internet.endpoints import UNIXClientEndpoint, connectProtocol from twisted.internet.error import ConnectionDone from twisted.protocols.basic import LineOnlyReceiver from twisted.python.filepath import FilePath import os from ...common import loop_until, timeout from ._model import (Run, Sudo, Put, Comment, RunRemotely, perform_comment, perform_put, perform_sudo) from .._effect import dispatcher as base_dispatcher RUN_OUTPUT_MESSAGE = MessageType( message_type="flocker.provision.ssh:run:output", fields=[ Field.for_types(u"line", [bytes], u"The output."), ], description=u"A line of command output.", ) def extReceived(self, type, data): from twisted.conch.ssh.connection import EXTENDED_DATA_STDERR if type == EXTENDED_DATA_STDERR: self.dataReceived(data) @attributes([ "deferred", "context", ])
except IOError: # One debugging method involves changing .py files and is incompatible # with inspecting the source. return { "function": str(function), } LOOP_UNTIL_ACTION = ActionType( action_type="flocker:testtools:loop_until", startFields=[Field("predicate", function_serializer)], successFields=[Field("result", serializer=safe_repr)], description="Looping until predicate is true.") LOOP_UNTIL_ITERATION_MESSAGE = MessageType( message_type="flocker:testtools:loop_until:iteration", fields=[Field("result", serializer=safe_repr)], description="Predicate failed, trying again.") def loop_until(predicate, reactor=reactor): """Call predicate every 0.1 seconds, until it returns something ``Truthy``. :param predicate: Callable returning termination condition. :type predicate: 0-argument callable returning a Deferred. :param reactor: The reactor implementation to use to delay. :type reactor: ``IReactorTime``. :return: A ``Deferred`` firing with the first ``Truthy`` response from ``predicate``. """
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()
INVALID_REASON = Field( u"reason", unicode, u"The reason given by the server for rejecting a pass as invalid.", ) PASS_COUNT = Field( u"count", int, u"A number of passes.", ) GET_PASSES = MessageType( u"zkapauthorizer:get-passes", [PRIVACYPASS_MESSAGE, PASS_COUNT], u"An attempt to spend passes is beginning.", ) SPENT_PASSES = MessageType( u"zkapauthorizer:spent-passes", [PASS_COUNT], u"An attempt to spend passes has succeeded.", ) INVALID_PASSES = MessageType( u"zkapauthorizer:invalid-passes", [INVALID_REASON, PASS_COUNT], u"An attempt to spend passes has found some to be invalid.", )
SNAPSHOT_CREATOR_PROCESS_ITEM = ActionType( u"magic-folder:local-snapshot-creator:processing-item", [RELPATH], [], u"Local snapshot creator is processing an input.", ) UPLOADER_SERVICE_UPLOAD_LOCAL_SNAPSHOTS = ActionType( u"magic-folder:uploader-service:upload-local-snapshot", [RELPATH], [], u"Uploader service is uploading a local snapshot", ) SNAPSHOT_COMMIT_FAILURE = MessageType( u"magic-folder:uploader-service:snapshot-commit-failure", [], u"Uploader service is unable to commit the LocalSnapshot.", ) ADD_FILE_FAILURE = MessageType( u"magic-folder:local-snapshot-creator:add-file-failure", [ABSPATH], u"file path is not a descendent of the magic folder directory", ) PROCESS_FILE_QUEUE = ActionType( u"magic-folder:local-snapshot-creator:process-queue", [RELPATH], [], u"A Magic-Folder is working through an item queue.", )
from twisted.internet.error import ProcessDone from twisted.internet.defer import Deferred from twisted.internet.protocol import ProcessProtocol from twisted.protocols.basic import LineOnlyReceiver RUN_ACTION = ActionType( action_type="admin.runner:run", startFields=[Field.for_types(u"command", [list], u"The command.")], successFields=[], description="Run a command.", ) RUN_OUTPUT_MESSAGE = MessageType( message_type="admin.runner:run:output", fields=[ Field.for_types(u"line", [bytes], u"The output."), ], description=u"A line of command output.", ) # LineOnlyReceiver is mutable, so can't use pyrsistent @attributes([ "handle_line", ]) class _LineParser(LineOnlyReceiver, object): """ Parser that breaks input into lines, and writes it to ouput. :ivar handle_line: Callable to call with parsed lines. """
from testtools.matchers import Is, Equals, Raises, MatchesException from zope.interface import Interface, implementer from .. import ( interface_decorator, provides, validate_signature_against_kwargs, InvalidSignature, ) from ...testtools import TestCase # Eliot structures for testing ``interface_decorator``. METHOD = Field.for_types(u"method", [unicode], u"The name of the decorated method.") TEST_MESSAGE = MessageType(u"flocker:common:test:interface:message", [METHOD]) TEST_EXCEPTION = MessageType(u"flocker:common:test:interface:exception", [METHOD]) class IDummy(Interface): """ Dummy interface with two test methods. """ def return_method(): """ Return something. """ def raise_method(): """
def commit(self): return self._root.commit() TARGET_OBJECT = Field( u"target_object", repr, u"The object to which the diff was applied." ) CHANGES = Field( u"changes", repr, u"The changes being applied." ) DIFF_COMMIT_ERROR = MessageType( u"flocker:control:Diff:commit_error", [TARGET_OBJECT, CHANGES], u"The target and changes that failed to apply." ) @implementer(_IDiffChange) class Diff(PClass): """ A ``_IDiffChange`` that is simply the serial application of other diff changes. This is the object that external modules get and use to apply diffs to objects. :ivar changes: A vector of ``_IDiffChange`` s that represent a diff between two objects.
from twisted.internet.threads import deferToThread from twisted.web.http import NOT_FOUND, INTERNAL_SERVER_ERROR from ..common import ( poll_until, retry_if, decorate_methods, with_retry, get_default_retry_steps, ) from ..control._model import (RestartNever, RestartAlways, RestartOnFailure, pset_field, pvector_field) LOG_CACHED_IMAGE = MessageType( u"flocker:node:docker:image_from_cache", [Field.for_types(u"image", [unicode], "The image ID.")], "An image was retrieved from the cache.") class AlreadyExists(Exception): """A unit with the given name already exists.""" @with_cmp(["address", "apierror"]) class AddressInUse(Exception): """ The listen address for an exposed port was in use and could not be bound. """ def __init__(self, address, apierror): """ :param tuple address: The conventional Python representation of the
u"magic-folder:scan-remote-collective", [], [], u"The remote collective is being scanned for peer DMDs.", ) _DMDS = Field( u"dmds", lambda participants: list(participant.name for participant in participants), u"The (D)istributed (M)utable (D)irectories belonging to each participant are being scanned for changes.", ) COLLECTIVE_SCAN = MessageType( u"magic-folder:downloader:get-latest-file:collective-scan", [_DMDS], u"Participants in the collective are being scanned.", ) SCAN_REMOTE_DMD = ActionType( u"magic-folder:scan-remote-dmd", [_NICKNAME], [], u"A peer DMD is being scanned for changes.", ) REMOTE_VERSION = Field.for_types( u"remote_version", [int], u"The version of a path found in a peer DMD.", )
"The state of the cluster, according to control service.") _FIELD_CONFIGURATION = Field( u"desired_configuration", repr, "The configuration of the cluster according to the control service.") _FIELD_ACTIONS = Field( u"calculated_actions", repr, "The actions we decided to take to converge with configuration.") LOG_CONVERGE = ActionType(u"flocker:agent:converge", [_FIELD_CLUSTERSTATE, _FIELD_CONFIGURATION], [], "The convergence action within the loop.") LOG_CALCULATED_ACTIONS = MessageType(u"flocker:agent:converge:actions", [_FIELD_ACTIONS], "The actions we're going to attempt.") class ConvergenceLoop(object): """ World object for the convergence loop state machine, executing the actions indicated by the outputs from the state machine. :ivar AMP client: An AMP client connected to the control service. Initially ``None``. :ivar Deployment configuration: Desired cluster configuration. Initially ``None``. :ivar DeploymentState cluster_state: Actual cluster state. Initially
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():
AGENT = Field( u"agent", _serialize_agent, u"The agent we're sending to", ) LOG_SEND_TO_AGENT = ActionType( "flocker:controlservice:send_state_to_agent", [AGENT], [], "Send the configuration and state of the cluster to a specific agent.") AGENT_CONNECTED = ActionType("flocker:controlservice:agent_connected", [AGENT], [], "An agent connected to the control service.") AGENT_UPDATE_ELIDED = MessageType( "flocker:controlservice:agent_update_elided", [AGENT], u"An update to an agent was elided because a subsequent update supercedes " u"it.", ) AGENT_UPDATE_DELAYED = MessageType( "flocker:controlservice:agent_update_delayed", [AGENT], u"An update to an agent was delayed because an earlier update is still in " u"progress.", ) class _UpdateState(PClass): """ Represent the state related to sending a ``ClusterStatusCommand`` to an agent.
PRIVACYPASS_MESSAGE = Field( u"message", unicode, u"The PrivacyPass request-binding data associated with a pass.", ) PASS_COUNT = Field( u"count", int, u"A number of passes.", ) GET_PASSES = MessageType( u"zkapauthorizer:get-passes", [PRIVACYPASS_MESSAGE, PASS_COUNT], u"Passes are being spent.", ) SIGNATURE_CHECK_FAILED = MessageType( u"zkapauthorizer:storage-client:signature-check-failed", [PASS_COUNT], u"Some passes the client tried to use were rejected for having invalid signatures.", ) CALL_WITH_PASSES = ActionType( u"zkapauthorizer:storage-client:call-with-passes", [PASS_COUNT], [], u"A storage operation is being started which may spend some passes.", )
""" 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( u'flocker:testtools:logged_run_process:process_ended', fields(status=int), u'The process terminated') class _LoggingProcessProtocol(ProcessProtocol):
# Copyright ClusterHQ Inc. See LICENSE file for details. from eliot import Field, MessageType CINDER_VOLUME = MessageType( u"flocker:functional:cinder:cinder_volume:created", [ Field.for_types( u"id", [bytes, unicode], u"The Cinder-assigned unique identifier for the volume that was " u"created.", ) ], )
elif class_name == u"PMap": return pmap(dictionary[u"values"]) elif class_name == u"UUID": return UUID(dictionary[u"hex"]) elif class_name in _CONFIG_CLASS_MAP: dictionary = dictionary.copy() dictionary.pop(_CLASS_MARKER) return _CONFIG_CLASS_MAP[class_name].create(dictionary) else: return dictionary return loads(data, object_hook=decode) _DEPLOYMENT_FIELD = Field(u"configuration", repr) _LOG_STARTUP = MessageType(u"flocker-control:persistence:startup", [_DEPLOYMENT_FIELD]) _LOG_SAVE = ActionType(u"flocker-control:persistence:save", [_DEPLOYMENT_FIELD], []) _UPGRADE_SOURCE_FIELD = Field.for_types( u"source_version", [int], u"Configuration version to upgrade from.") _UPGRADE_TARGET_FIELD = Field.for_types( u"target_version", [int], u"Configuration version to upgrade to.") _LOG_UPGRADE = ActionType(u"flocker-control:persistence:migrate_configuration", [ _DEPLOYMENT_FIELD, _UPGRADE_SOURCE_FIELD, _UPGRADE_TARGET_FIELD, ], [])
from twisted.internet.error import ProcessTerminated, ProcessDone from twisted.internet.defer import Deferred from twisted.internet.protocol import ProcessProtocol from twisted.protocols.basic import LineOnlyReceiver RUN_ACTION = ActionType( action_type="flocker.common.runner:run", startFields=[Field.for_types(u"command", [list], u"The command.")], successFields=[], description="Run a command.", ) RUN_OUTPUT_MESSAGE = MessageType( message_type="flocker.common.runner:run:stdout", fields=[ Field.for_types(u"line", [bytes], u"The output."), ], description=u"A line of command output.", ) RUN_ERROR_MESSAGE = MessageType( message_type="flocker.common.runner:run:stderr", fields=[ Field.for_types(u"line", [bytes], u"The error."), ], description=u"A line of command stderr.", ) # Logging for the scp, upload, and download functions SCP_ACTION = ActionType( action_type="flocker.common.runner:scp", startFields=[
AWS_CODE = Field.for_types("aws_code", [bytes, unicode], u"The error response code.") AWS_MESSAGE = Field.for_types( "aws_message", [unicode], u"A human-readable error message given by the response.", ) AWS_REQUEST_ID = Field.for_types( "aws_request_id", [bytes, unicode], u"The unique identifier assigned by the server for this request.", ) # Structures to help log ``boto.exception.EC2ResponseError`` from AWS. BOTO_EC2RESPONSE_ERROR = MessageType( u"flocker:node:agents:blockdevice:aws:boto_ec2response_error", [AWS_CODE, AWS_MESSAGE, AWS_REQUEST_ID], ) DEVICES = Field.for_types( u"devices", [list], u"List of devices currently in use by the compute instance.") NO_AVAILABLE_DEVICE = MessageType( u"flocker:node:agents:blockdevice:aws:no_available_device", [DEVICES], ) IN_USE_DEVICES = MessageType( u"flocker:node:agents:blockdevice:aws:in_use_devices", [DEVICES], u"Log current devices.", )
import time from eliot import Logger, MessageType, Field, ActionType def _ascii(s): return s.decode("ascii") F1 = Field.forTypes("integer", [int], "") F2 = Field("string", _ascii, "") F3 = Field("string2", _ascii, "") F4 = Field.forTypes("list", [list], "list of integers") M = MessageType("system:message", [F1, F2, F3, F4], "description") A = ActionType("action", [], [], [], "desc") log = Logger() N = 100000 def run(): start = time.time() with A(log): for i in xrange(N): m = M(integer=3, string=b"abcdeft", string2="dgsjdlkgjdsl", list=[1, 2, 3, 4])