Merge pull request #1736 from dcos/mh/logging-improvements

improve logging

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
 ------------
 

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,
             )
 

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,

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,