Improved Docker "run" command logging (opensearch-project#109)

* Improved Docker "run" command logging

* Added a new log statement that generates an equivalent
  'docker run' command to what the Docker Python SDK executes

Signed-off-by: Chris Helma <chelma+github@amazon.com>

* Minor changes per PR comments

opensearch-project#109

Signed-off-by: Chris Helma <chelma+github@amazon.com>

* More minor changes per PR comments

opensearch-project#109

Signed-off-by: Chris Helma <chelma+github@amazon.com>

---------

Signed-off-by: Chris Helma <chelma+github@amazon.com>

cluster_migration_core/cluster_migration_core/cluster_management/docker_command_gen.py

@@ -0,0 +1,58 @@
+from typing import Dict, List
+
+from docker.types import Ulimit
+
+"""
+The code in this module can be used to generate Docker CLI commands equivalent to those run by the Python Docker SDK.
+This is useful for debugging when things go wrong, as the SDK does not print the full commands at any log level.  The
+generation functions will mirror the arguments list of their corresponding SDK command.
+
+Eventually, we may end up using this module to replace the Docker SDK by running these commands directly.  The SDK has
+a number of rough edges, like the fact that it doesn't log the actual commands it is running, which makes it tough to
+use.
+"""
+
+
+def gen_docker_run(image: str, name: str, network: str, ports: Dict[str, str], volumes: Dict[str, Dict[str, str]],
+                   ulimits: List[Ulimit], detach: bool, environment: Dict[str, str],
+                   extra_hosts: Dict[str, str]) -> str:
+    prefix = "docker run"
+    name_section = f"--name {name}"
+    network_section = f"--network {network}"
+    publish_strs = [f"--publish {host_port}:{container_port}" for container_port, host_port in ports.items()]
+    publish_section = " ".join(publish_strs)
+    volumes_section = " ".join([f"--volume {k}:{v['bind']}:{v['mode']}" for k, v in volumes.items()])
+    ulimits_section = " ".join([f"--ulimit {u.name}={u.soft}:{u.hard}" for u in ulimits])
+    environment_section = " ".join([f"--env {k}='{v}'" for k, v in environment.items()])
+    extra_hosts_section = " ".join([f"--add-host {k}:{v}" for k, v in extra_hosts.items()])
+    detach_section = "--detach" if detach else ""
+    image_section = image
+
+    command_sections = [
+        prefix,
+        name_section,
+        network_section,
+        publish_section,
+        volumes_section,
+        ulimits_section,
+        environment_section,
+        extra_hosts_section,
+        detach_section,
+        image_section  # Needs to be last
+    ]
+
+    return _pretty_join(command_sections, " ")
+
+
+def _pretty_join(command_sections: List[str], delimiter: str) -> str:
+    """
+    A quick function to handle empty sections better than the default .join() method.  Avoids inserting spaces when a
+    section is blank.
+    """
+    non_empty_sections = []
+
+    for section in command_sections:
+        if section.strip():  # not empty
+            non_empty_sections.append(section)
+
+    return delimiter.join(non_empty_sections)

cluster_migration_core/cluster_migration_core/cluster_management/docker_framework_client.py

@@ -9,6 +9,7 @@
 from docker.models.volumes import Volume
 from docker.types import Ulimit
 
+import cluster_migration_core.cluster_management.docker_command_gen as dcg
 import cluster_migration_core.core.shell_interactions as shell
 
 
@@ -153,7 +154,7 @@ def create_container(self, image: str, container_name: str, network: Network, po
         if not env_variables:
             env_variables = {}
         if not extra_hosts:
-            extra_hosts = []
+            extra_hosts = {}
 
         # It doesn't appear you can just pass in a list of Volumes to the client, so we have to make this wonky mapping
         port_mapping = {str(pair.container_port): str(pair.host_port) for pair in ports}
@@ -172,8 +173,8 @@ def create_container(self, image: str, container_name: str, network: Network, po
                 volume_mapping[dv.volume.attrs["Name"]] = {"bind": dv.container_mount_point, "mode": "rw"}
 
         self.logger.debug(f"Creating container {container_name}...")
-        container = self._docker_client.containers.run(
-            image,
+        container = self._log_and_execute_command_run(
+            image=image,
             name=container_name,
             network=network.name,
             ports=port_mapping,
@@ -186,6 +187,19 @@ def create_container(self, image: str, container_name: str, network: Network, po
         self.logger.debug(f"Created container {container_name}")
         return container
 
+    def _log_and_execute_command_run(self, image: str, name: str, network: str, ports: Dict[str, str],
+                                     volumes: Dict[str, Dict[str, str]], ulimits: List[Ulimit], detach: bool,
+                                     environment: Dict[str, str], extra_hosts: Dict[str, str]) -> Container:
+
+        args = {"image": image, "name": name, "network": network, "ports": ports, "volumes": volumes,
+                "ulimits": ulimits, "detach": detach, "environment": environment, "extra_hosts": extra_hosts}
+
+        run_command = dcg.gen_docker_run(**args)
+        self.logger.debug(f"Predicted command being run by the Docker SDK: {run_command}")
+
+        container = self._docker_client.containers.run(**args)
+        return container
+
     def stop_container(self, container: Container):
         self.logger.debug(f"Stopping container {container.name}...")
         container.stop()

cluster_migration_core/unit_tests/cluster_management/test_docker_command_gen.py

@@ -0,0 +1,65 @@
+from docker.types import Ulimit
+
+import cluster_migration_core.cluster_management.docker_command_gen as dcg
+
+
+def test_WHEN_gen_run_command_THEN_as_expected():
+    # Set up our test
+    test_args = {
+        "image": "image",
+        "name": "container_name",
+        "network": "network_name",
+        "ports": {9200: 80, 6160: 42},
+        "volumes": {
+            "/mydir1": {"bind": "/path", "mode": "ro"},
+            "volume1": {"bind": "/path2", "mode": "rw"}
+        },
+        "ulimits": [
+            Ulimit(name='limit', soft=1, hard=2)
+        ],
+        "detach": True,
+        "environment": {
+            "a": "b",
+            "c": "d"
+        },
+        "extra_hosts": {
+            "name": "host"
+        }
+    }
+
+    # Run our test
+    generated_command = dcg.gen_docker_run(**test_args)
+
+    # Check our results
+    expected_command = ("docker run --name container_name --network network_name --publish 80:9200 --publish 42:6160"
+                        " --volume /mydir1:/path:ro --volume volume1:/path2:rw --ulimit limit=1:2 --env a='b'"
+                        " --env c='d' --add-host name:host --detach image")
+    assert expected_command == generated_command
+
+
+def test_WHEN_gen_run_command_2_THEN_as_expected():
+    # Set up our test
+    test_args = {
+        "image": "image",
+        "name": "container_name",
+        "network": "network_name",
+        "ports": {9200: 80, 6160: 42},
+        "volumes": {},
+        "ulimits": [
+            Ulimit(name='limit', soft=1, hard=2)
+        ],
+        "detach": False,
+        "environment": {
+            "a": "b",
+            "c": "d"
+        },
+        "extra_hosts": {}
+    }
+
+    # Run our test
+    generated_command = dcg.gen_docker_run(**test_args)
+
+    # Check our results
+    expected_command = ("docker run --name container_name --network network_name --publish 80:9200 --publish 42:6160"
+                        " --ulimit limit=1:2 --env a='b' --env c='d' image")
+    assert expected_command == generated_command

cluster_migration_core/unit_tests/cluster_management/test_docker_framework_client.py

@@ -200,7 +200,7 @@ def test_WHEN_create_container_called_THEN_executes_normally():
     # Check our results
     expected_calls = [
         mock.call(
-            test_image,
+            image=test_image,
             name=test_container_name,
             network=mock_network.name,
             ports={str(pair.container_port): str(pair.host_port) for pair in test_ports},

cluster_traffic_capture/cluster_traffic_capture/gen_haproxy_cfg.py

@@ -72,6 +72,8 @@ def _get_fe_config_haproxy(haproxy_port: int, mirror: bool) -> str:
     mirror argument is set to True, the generated configuration will also support mirroring.
     """
 
+    log_format = """%{+Q}o {"request": {"timestamp":%Ts, "uri":%[capture.req.uri,json('utf8ps')], "method":%[capture.req.method], "headers":%[capture.req.hdr(0),json('utf8ps')], "body":%[capture.req.hdr(1),json('utf8ps')]}, "response":  {"response_time_ms":%Tr, "body":%[capture.res.hdr(1),json('utf8ps')], "headers":%[capture.res.hdr(0),json('utf8ps')], "status_code": %ST}}"""  # noqa: E501
+
     config = f"""
 # This section outlines the "frontend" for this instance of HAProxy and specifies the rules by which it receives
 # traffic
@@ -85,7 +87,7 @@ def _get_fe_config_haproxy(haproxy_port: int, mirror: bool) -> str:
     declare capture response len 1048576
     http-request capture req.hdrs id 0
     http-request capture req.body id 1
-    log-format '%{{+Q}}o {{"request": {{"timestamp":%Ts, "uri":%[capture.req.uri,json('utf8ps')], "method":%[capture.req.method], "headers":%[capture.req.hdr(0),json('utf8ps')], "body":%[capture.req.hdr(1),json('utf8ps')]}}, "response":  {{"response_time_ms":%Tr, "body":%[capture.res.hdr(1),json('utf8ps')], "headers":%[capture.res.hdr(0),json('utf8ps')], "status_code": %ST}}}}'
+    log-format '{log_format}'
     # Associate this frontend with the primary cluster
     default_backend primary_cluster
 

cluster_traffic_capture/demo_haproxy.py

@@ -1,4 +1,6 @@
 #!/usr/bin/env python3
+import argparse
+import logging
 import os
 
 from docker.types import Ulimit
@@ -16,7 +18,35 @@
 TAG_DOCKER_HOST = "host.docker.internal"
 
 
+def get_command_line_args():
+    parser = argparse.ArgumentParser(
+        description="Script to build the Primary/Shadow HAProxy Docker images (see README)"
+    )
+
+    parser.add_argument('-v', '--verbose',
+                        action='store_true',
+                        help="Turns on DEBUG-level logging",
+                        dest="verbose",
+                        default=False
+                        )
+
+    return parser.parse_args()
+
+
 def main():
+    # =================================================================================================================
+    # Parse/validate args
+    # =================================================================================================================
+    args = get_command_line_args()
+    verbose = args.verbose
+
+    # =================================================================================================================
+    # Configure Logging
+    # =================================================================================================================
+    logging.basicConfig()
+    if verbose:
+        logging.root.setLevel(logging.DEBUG)
+
     # =================================================================================================================
     # Setup Clusters
     # =================================================================================================================