From 7c5f2040ad2bfcf668e3dbbfcb7ad7c1376e8cbb Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=C5=A0t=C4=9Bp=C3=A1n=20Tomsa?= Date: Mon, 1 Apr 2024 17:03:14 +0200 Subject: [PATCH] Log shell commands MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 --- src/insights_client/__init__.py | 105 ++++++++++++++++++++++---------- 1 file changed, 72 insertions(+), 33 deletions(-) diff --git a/src/insights_client/__init__.py b/src/insights_client/__init__.py index 70da23d0..a417a550 100644 --- a/src/insights_client/__init__.py +++ b/src/insights_client/__init__.py @@ -55,6 +55,20 @@ 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 @@ -62,19 +76,18 @@ def egg_version(egg): 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,11 +234,8 @@ 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) @@ -218,19 +243,33 @@ def run_phase(phase, client, validated_eggs): 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 = []