diff --git a/CHANGELOG.rst b/CHANGELOG.rst index 3a56a59aa..331bb820d 100644 --- a/CHANGELOG.rst +++ b/CHANGELOG.rst @@ -6,6 +6,9 @@ Changelog Next ---- +* The ``wait_for_dcos_oss`` and ``wait_for_dcos_ee`` methods no longer log output of node poststart check command run. +* The ``Node.run`` method logs the command that is going to execute with ``debug`` level if ``output`` is configured to ``LOG_AND_CAPTURE``. + 2019.04.23.0 ------------ diff --git a/src/dcos_e2e/cluster.py b/src/dcos_e2e/cluster.py index a36ea48d3..3cafce4ff 100644 --- a/src/dcos_e2e/cluster.py +++ b/src/dcos_e2e/cluster.py @@ -3,6 +3,7 @@ """ import json +import logging import subprocess from contextlib import ContextDecorator from pathlib import Path @@ -21,6 +22,8 @@ from .exceptions import DCOSTimeoutError from .node import Node, Output, Transport +LOGGER = logging.getLogger(__name__) + @retry( exceptions=(subprocess.CalledProcessError), @@ -148,6 +151,8 @@ def _wait_for_node_poststart(self) -> None: reading the CA certificate used by certain checks. """ for node in self.masters: + log_msg = 'Running a poststart check on `{}`'.format(str(node)) + LOGGER.debug(log_msg) node.run( args=[ 'sudo', @@ -164,7 +169,7 @@ def _wait_for_node_poststart(self) -> None: '--diag', ], # Keep in mind this must be run as privileged user. - output=Output.LOG_AND_CAPTURE, + output=Output.NO_CAPTURE, shell=True, ) diff --git a/src/dcos_e2e/node.py b/src/dcos_e2e/node.py index a9fcc6962..e460eae78 100644 --- a/src/dcos_e2e/node.py +++ b/src/dcos_e2e/node.py @@ -2,6 +2,7 @@ Tools for managing DC/OS cluster nodes. """ +import logging import subprocess import tarfile import uuid @@ -15,6 +16,8 @@ from ._node_transports import DockerExecTransport, NodeTransport, SSHTransport +LOGGER = logging.getLogger(__name__) + class Role(Enum): """ @@ -487,6 +490,13 @@ def run( Output.NO_CAPTURE: False, }[output] + if log_output_live: + log_msg = 'Running command `{cmd}` on a node `{node}`'.format( + cmd=' '.join(args), + node=str(self), + ) + LOGGER.debug(log_msg) + return node_transport.run( args=args, user=user, diff --git a/tests/test_dcos_e2e/test_node.py b/tests/test_dcos_e2e/test_node.py index b0228de3d..344437ed8 100644 --- a/tests/test_dcos_e2e/test_node.py +++ b/tests/test_dcos_e2e/test_node.py @@ -794,14 +794,26 @@ def test_log_and_capture( # stderr is merged into stdout. # This is not ideal but for now it is the case. # The order is not necessarily preserved. + expected_command = ( + 'Running command `/bin/sh -c echo {stdout_message} && >&2 echo ' + '{stderr_message}` on a node `{node}`'.format( + stdout_message=stdout_message, + stderr_message=stderr_message, + node=str(dcos_node), + ) + ) expected_messages = set([stdout_message, stderr_message]) result_stdout = result.stdout.strip().decode() assert set(result_stdout.split('\n')) == expected_messages - first_log, second_log = caplog.records + # Ignore the first message which is the command being logged by ``run`` + # method call. + command_log, first_log, second_log = caplog.records assert first_log.levelno == logging.DEBUG assert second_log.levelno == logging.DEBUG + assert command_log.message == expected_command + messages = set([first_log.message, second_log.message]) assert messages == expected_messages @@ -820,9 +832,18 @@ def test_not_utf_8_log_and_capture( args = ['head', '-c', '100', '/bin/cat'] dcos_node.run(args=args, output=Output.LOG_AND_CAPTURE) # We do not test the output, but we at least test its length for now. - [log] = caplog.records + # Ignore the first message which is the command being logged by ``run`` + # method call. + [command_log, log] = caplog.records assert len(log.message) >= 100 + expected_command = ( + 'Running command `head -c 100 /bin/cat` on a node `{node}`'.format( + node=str(dcos_node), + ) + ) + assert command_log.message == expected_command + def test_not_utf_8_capture( self, caplog: LogCaptureFixture,