Log shell commands

An essential part of the initialization process is running subprocesses: for GPG verification and, mainly, to run the Core phases. With help of newly introduce helper function to format the commands in a familiar fashion, all launched commands are now logged together with their environment.

Signed-off-by: Štěpán Tomsa <stomsa@redhat.com>

src/insights_client/__init__.py

@@ -55,26 +55,39 @@ def tear_down_logging():
         logger.removeHandler(handler)
 
 
+def debug_environ(environ):
+    items = map(lambda item: f"{item[0]}={item[1]}", environ.items())
+    return " ".join(items)
+
+
+def debug_command(command, environ=None):
+    if environ:
+        full_command = [debug_environ(environ)] + command
+    else:
+        full_command = command
+    # Please note that neither spaces nor any other special characters are quoted.
+    return " ".join(full_command)
+
+
 def egg_version(egg):
     """
     Determine the egg version
     """
     if not sys.executable:
         return None
     try:
-        proc = Popen(
-            [
-                sys.executable,
-                "-c",
-                "from insights.client import InsightsClient; print(InsightsClient(None, False).version())",
-            ],
-            env={"PYTHONPATH": egg, "PATH": os.getenv("PATH")},
-            stdout=PIPE,
-            stderr=PIPE,
-        )
+        version_command = [
+            sys.executable,
+            "-c",
+            "from insights.client import InsightsClient; "
+            "print(InsightsClient(None, False).version())",
+        ]
+        env = {"PYTHONPATH": egg, "PATH": os.getenv("PATH")}
+        logger.debug("Running command: %s", debug_command(version_command, env))
+        proc = Popen(version_command, env=env, stdout=PIPE, stderr=PIPE)
     except OSError:
         return None
-    stdout, stderr = proc.communicate()
+    stdout, _stderr = proc.communicate()
     return stdout.decode("utf-8")
 
 
@@ -103,8 +116,10 @@ def _remove_gpg_home(home):
     :rtype: None
     """
     # Shut down GPG's home agent
+    shutdown_command = ["/usr/bin/gpgconf", "--homedir", home, "--kill", "all"]
+    logger.debug("Running command: %s", " ".join(shutdown_command))
     shutdown_process = subprocess.Popen(
-        ["/usr/bin/gpgconf", "--homedir", home, "--kill", "all"],
+        shutdown_command,
         stdout=subprocess.PIPE,
         stderr=subprocess.PIPE,
         universal_newlines=True,
@@ -116,11 +131,12 @@ def _remove_gpg_home(home):
             shutdown_process.returncode,
         )
         if stdout:
-            logger.debug(stdout)
+            logger.debug("stdout: %s", stdout)
         if stderr:
-            logger.debug(stderr)
+            logger.debug("stderr: %s", stderr)
 
     # Delete the temporary directory
+    logger.debug("Removing temporary directory: %s", home)
     shutil.rmtree(home)
 
 
@@ -155,24 +171,40 @@ def gpg_validate(path):
     # The /var/lib/insights/ directory is used instead of /tmp/ because
     # GPG needs to have RW permissions in it, and existing SELinux rules only
     # allow access here.
+    logger.debug(
+        "Creating temporary directory in %s...", TEMPORARY_GPG_HOME_PARENT_DIRECTORY
+    )
     home = tempfile.mkdtemp(dir=TEMPORARY_GPG_HOME_PARENT_DIRECTORY)
 
     # Import the public keys into temporary environment
+    import_command = ["/usr/bin/gpg", "--homedir", home, "--import", GPG_KEY]
+    logger.debug("Running command: %s", debug_command(import_command))
     import_process = subprocess.Popen(
-        ["/usr/bin/gpg", "--homedir", home, "--import", GPG_KEY],
+        import_command,
         stdout=subprocess.PIPE,
         stderr=subprocess.PIPE,
     )
     import_process.communicate()
     if import_process.returncode != 0:
+        logger.debug(
+            "Could not import the GPG key, got return code %d",
+            import_process.returncode,
+        )
         _remove_gpg_home(home)
         return False
 
     # Verify the signature
+    verify_command = [
+        "/usr/bin/gpg",
+        "--homedir",
+        home,
+        "--verify",
+        path + ".asc",
+        path,
+    ]
+    logger.debug("Running command: %s", debug_command(verify_command))
     verify_process = subprocess.Popen(
-        ["/usr/bin/gpg", "--homedir", home, "--verify", path + ".asc", path],
-        stdout=subprocess.PIPE,
-        stderr=subprocess.PIPE,
+        verify_command, stdout=subprocess.PIPE, stderr=subprocess.PIPE
     )
     verify_process.communicate()
     _remove_gpg_home(home)
@@ -190,10 +222,6 @@ def run_phase(phase, client, validated_eggs):
     Call the run script for the given phase.  If the phase succeeds returns the
     index of the egg that succeeded to be used in the next phase.
     """
-    insights_command = [
-        sys.executable,
-        os.path.join(os.path.dirname(__file__), "run.py"),
-    ] + sys.argv[1:]
     config = client.get_conf()
 
     all_eggs = [NEW_EGG] + validated_eggs
@@ -206,31 +234,42 @@ def run_phase(phase, client, validated_eggs):
             if not os.path.isfile(egg):
                 logger.debug("%s is not a file, can't GPG verify. Skipping.", egg)
                 continue
-            logger.debug("Verifying %s..." % egg)
             if not client.verify(egg)["gpg"]:
-                logger.debug(
-                    "WARNING: GPG verification failed. Not loading egg: %s", egg
-                )
+                logger.debug("Not using egg: %s", egg)
                 continue
         else:
             logger.debug("GPG disabled by --no-gpg, not verifying %s.", egg)
 
         logger.debug("phase '%s'; egg '%s'", phase["name"], egg)
 
         # prepare the environment
+        env = os.environ
+        logger.debug("Existing enviroment: %s", debug_environ(env))
+
         pythonpath = str(egg)
-        env_pythonpath = os.environ.get("PYTHONPATH", "")  # type: str
+        logger.debug("Adding to PYTHONPATH: %s", pythonpath)
+        env_pythonpath = env.get("PYTHONPATH", "")  # type: str
+
         if env_pythonpath:
             pythonpath += ":" + env_pythonpath
         insights_env = {
             "INSIGHTS_PHASE": str(phase["name"]),
             "PYTHONPATH": pythonpath,
         }
-        env = os.environ
+        logger.debug("Adding to the environment: %s", debug_environ(insights_env))
+
         env.update(insights_env)
 
+        current_path = os.path.dirname(__file__)
+        logger.debug("Current path: %s", current_path)
+
+        insights_command = [
+            sys.executable,
+            os.path.join(current_path, "run.py"),
+        ] + sys.argv[1:]
+        logger.debug("Running command: %s", debug_command(insights_command, env))
         process = subprocess.Popen(insights_command, env=env)
-        stdout, stderr = process.communicate()
+        process.communicate()
         if process.returncode == 0:
             # phase successful, don't try another egg
             logger.debug("phase '%s' successful", phase["name"])
@@ -343,11 +382,11 @@ def _main():
     for egg in [STABLE_EGG, RPM_EGG]:
         logger.debug("GPG verifying initial egg %s...", egg)
         if gpg_validate(egg):
-            logger.debug("GPG verification successful. Loading initial egg: %s", egg)
+            logger.debug("GPG verification successful. Using initial egg: %s", egg)
             validated_eggs.append(egg)
         else:
             logger.debug(
-                "WARNING: GPG verification failed. Not loading initial egg: %s", egg
+                "WARNING: GPG verification failed. Not using initial egg: %s", egg
             )
     # sort rpm and stable eggs after verification
     validated_eggs = sorted_eggs(validated_eggs)
@@ -356,11 +395,11 @@ def _main():
     #  pass it to run_phase where we load it again
     logger.debug("Verifying initial ENV_EGG: %s...", ENV_EGG)
     if gpg_validate(ENV_EGG):
-        logger.debug("GPG verification successful. Loading initial egg: %s", ENV_EGG)
+        logger.debug("GPG verification successful. Using initial egg: %s", ENV_EGG)
         valid_env_egg = [ENV_EGG]
     else:
         logger.debug(
-            "WARNING: GPG verification failed. Not loading initial egg: %s", ENV_EGG
+            "WARNING: GPG verification failed. Not using initial egg: %s", ENV_EGG
         )
         valid_env_egg = []