Replace some prints by log messages

Signed-off-by: Andrea Waltlova <[email protected]>

scripts/c2r_script.py

@@ -1,4 +1,5 @@
 import json
+import logging
 import os
 import re
 import shutil
@@ -8,6 +9,11 @@
 
 from urllib2 import urlopen, URLError
 
+# NOTE: What are all possible levels we can get from rhc?
+log_level = os.getenv("LOG_LEVEL", "INFO").upper()
+log_level = getattr(logging, log_level, logging.INFO)
+logging.basicConfig(level=log_level, format="%(asctime)s - %(levelname)s - %(message)s")
+
 # SCRIPT_TYPE is either 'CONVERSION' or 'ANALYSIS'
 # Value is set in signed yaml envelope in content_vars (SCRIPT_MODE)
 SCRIPT_TYPE = os.getenv("RHC_WORKER_SCRIPT_MODE", "").upper()
@@ -68,46 +74,52 @@ def _create(self, data):
         try:
             directory = os.path.dirname(self.path)
             if not os.path.exists(directory):
-                print("Creating directory at '%s'" % directory)
+                logging.info("Creating directory at '%s'", directory)
                 os.makedirs(directory, mode=0o755)
 
-            print("Writing file to destination: '%s'" % self.path)
+            logging.info("Writing file to destination: '%s'", self.path)
             with open(self.path, mode="w") as handler:
                 handler.write(data)
                 os.chmod(self.path, 0o644)
         except OSError as err:
-            print(err)
+            logging.warning(err)
             return False
         return True
 
     def delete(self):
         try:
-            print("Removing the file '%s' as it was previously downloaded." % self.path)
+            logging.info(
+                "Removing the file '%s' as it was previously downloaded.", self.path
+            )
             os.remove(self.path)
         except OSError as err:
-            print(err)
+            logging.warning(err)
             return False
         return True
 
     def restore(self):
         """Restores file backup (rename). Returns True if restored, otherwise False."""
         try:
-            print("Trying to restore %s" % (self.path + self.backup_suffix))
+            logging.info("Restoring backed up file %s.", (self.path + self.backup_suffix))
             os.rename(self.path + self.backup_suffix, self.path)
             print("File restored (%s)." % (self.path))
         except OSError as err:
-            print("Failed to restore %s (%s)" % (self.path + self.backup_suffix, err))
+            logging.warning("Failed to restore %s (%s)" % (self.path + self.backup_suffix, err))
             return False
         return True
 
     def backup(self):
         """Creates backup file (rename). Returns True if backed up, otherwise False."""
         try:
-            print("Trying to create back up of %s" % (self.path))
+            logging.info(
+                "File %s already present on system, backing up to %s.",
+                self.path,
+                self.backup_suffix,
+            )
             os.rename(self.path, self.path + self.backup_suffix)
             print("Back up created (%s)." % (self.path + self.backup_suffix))
         except OSError as err:
-            print("Failed to create back up of %s (%s)" % (self.path, err))
+            logging.warning("Failed to create back up of %s (%s)" % (self.path, err))
             return False
         return True
 
@@ -164,7 +176,9 @@ def to_dict(self):
 
 def check_for_inhibitors_in_rollback():
     """Returns lines with errors in rollback section of c2r log file, or empty string."""
-    print("Checking content of '%s' for possible rollback problems ..." % C2R_LOG_FILE)
+    logging.info(
+        "Checking content of '%s' for possible rollback problems ...", C2R_LOG_FILE
+    )
     matches = ""
     start_of_rollback_section = "WARNING - Abnormal exit! Performing rollback ..."
     try:
@@ -181,12 +195,13 @@ def check_for_inhibitors_in_rollback():
             matches = list(filter(DETECT_ERROR_IN_ROLLBACK_PATTERN.match, actual_data))
             matches = "\n".join(matches)
     except ValueError:
-        print(
-            "Failed to find rollback section ('%s') in '%s' file."
-            % (start_of_rollback_section, C2R_LOG_FILE)
+        logging.info(
+            "Failed to find rollback section ('%s') in '%s' file.",
+            start_of_rollback_section,
+            C2R_LOG_FILE,
         )
     except IOError:
-        print("Failed to read '%s' file.")
+        logging.warning("Failed to read '%s' file.", C2R_LOG_FILE)
 
     return matches
 
@@ -220,9 +235,10 @@ def check_convert2rhel_inhibitors_before_run():
     """
     default_ini_path = "/etc/convert2rhel.ini"
     custom_ini_path = os.path.expanduser("~/.convert2rhel.ini")
-    print(
-        "Checking that '%s' wasn't modified and '%s' doesn't exist ..."
-        % (default_ini_path, custom_ini_path)
+    logging.info(
+        "Checking that '%s' wasn't modified and '%s' doesn't exist ...",
+        default_ini_path,
+        custom_ini_path,
     )
 
     if os.path.exists(custom_ini_path):
@@ -250,7 +266,7 @@ def check_convert2rhel_inhibitors_before_run():
 
 def get_system_distro_version():
     """Currently we execute the task only for RHEL 7 or 8"""
-    print("Checking OS distribution and version ID ...")
+    logging.info("Checking OS distribution and version ID ...")
     try:
         distribution_id = None
         version_id = None
@@ -266,9 +282,13 @@ def get_system_distro_version():
             if match:
                 version_id = "%s.%s" % (match.group(1), match.group(2))
     except IOError:
-        print("Couldn't read /etc/system-release")
+        logging.warning("Couldn't read /etc/system-release")
 
-    print("Detected distribution='%s' in version='%s'" % (distribution_id, version_id))
+    logging.info(
+        "Detected distribution='%s' in version='%s'",
+        distribution_id,
+        version_id,
+    )
     return distribution_id, version_id
 
 
@@ -302,7 +322,7 @@ def archive_analysis_report(file):
 
 def gather_json_report():
     """Collect the json report generated by convert2rhel."""
-    print("Collecting JSON report.")
+    logging.info("Collecting JSON report.")
 
     if not os.path.exists(C2R_REPORT_FILE):
         return {}
@@ -330,7 +350,7 @@ def gather_textual_report():
             It's fine if the textual report does not exist, but the JSON one is
             required.
     """
-    print("Collecting TXT report.")
+    logging.info("Collecting TXT report.")
     data = ""
     if os.path.exists(C2R_REPORT_TXT_FILE):
         with open(C2R_REPORT_TXT_FILE, mode="r") as handler:
@@ -375,7 +395,7 @@ def generate_report_message(highest_status):
 
 def setup_convert2rhel(required_files):
     """Setup convert2rhel tool by downloading the required files."""
-    print("Downloading required files.")
+    logging.info("Downloading required files.")
     try:
         for required_file in required_files:
             required_file.backup()
@@ -411,7 +431,7 @@ def run_subprocess(cmd, print_cmd=True, env=None):
         raise TypeError("cmd should be a list, not a str")
 
     if print_cmd:
-        print("Calling command '%s'" % " ".join(cmd))
+        logging.info("Calling command '%s'", " ".join(cmd))
 
     process = subprocess.Popen(
         cmd, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, bufsize=1, env=env
@@ -432,11 +452,13 @@ def _get_last_yum_transaction_id(pkg_name):
     output, return_code = run_subprocess(["/usr/bin/yum", "history", "list", pkg_name])
     if return_code:
         # NOTE: There is only print because list will exit with 1 when no such transaction exist
-        print(
+        logging.warning(
             "Listing yum transaction history for '%s' failed with exit status '%s' and output '%s'"
-            % (pkg_name, return_code, output),
-            "\nThis may cause clean up function to not remove '%s' after Task run."
-            % pkg_name,
+            "\nThis may cause clean up function to not remove '%s' after Task run.",
+            pkg_name,
+            return_code,
+            output,
+            pkg_name,
         )
         return None
 
@@ -454,7 +476,7 @@ def install_or_update_convert2rhel(required_files):
     Install the convert2rhel tool to the system.
     Returns True and transaction ID if the c2r pkg was installed, otherwise False, None.
     """
-    print("Installing & updating Convert2RHEL package.")
+    logging.info("Installing & updating Convert2RHEL package.")
 
     c2r_pkg_name = "convert2rhel"
     c2r_installed = _check_if_package_installed(c2r_pkg_name)
@@ -488,7 +510,7 @@ def run_convert2rhel():
     """
     Run the convert2rhel tool assigning the correct environment variables.
     """
-    print("Running Convert2RHEL %s" % SCRIPT_TYPE.title())
+    logging.info("Running Convert2RHEL %s" % SCRIPT_TYPE.title())
     env = os.environ
 
     for key in env:
@@ -524,9 +546,11 @@ def cleanup(required_files):
             ["/usr/bin/yum", "history", "undo", "-y", transaction_id],
         )
         if returncode:
-            print(
-                "Undo of yum transaction with ID %s failed with exit status '%s' and output:\n%s"
-                % (transaction_id, returncode, output)
+            logging.warning(
+                "Undo of yum transaction with ID %s failed with exit status '%s' and output:\n%s",
+                transaction_id,
+                returncode,
+                output,
             )
 
 
@@ -625,7 +649,7 @@ def update_insights_inventory():
     """
     Call insights-client to update insights inventory.
     """
-    print("Updating system status in Red Hat Insights.")
+    logging.info("Updating system status in Red Hat Insights.")
     output, returncode = run_subprocess(cmd=["/usr/bin/insights-client"])
 
     if returncode:
@@ -635,7 +659,7 @@ def update_insights_inventory():
             % (returncode, output.rstrip("\n")),
         )
 
-    print("System registered with insights-client successfully.")
+    logging.info("System registered with insights-client successfully.")
 
 
 # pylint: disable=too-many-branches
@@ -744,9 +768,11 @@ def main():
         if IS_CONVERSION:
             update_insights_inventory()
 
-        print("Convert2RHEL %s script finished successfully!" % SCRIPT_TYPE.title())
+        logging.info(
+            "Convert2RHEL %s script finished successfully!", SCRIPT_TYPE.title()
+        )
     except ProcessError as exception:
-        print(exception.report)
+        logging.error(exception.report)
         output = OutputCollector(
             status="ERROR",
             alert=True,
@@ -755,7 +781,7 @@ def main():
             report=exception.report,
         )
     except Exception as exception:
-        print(str(exception))
+        logging.critical(str(exception))
         output = OutputCollector(
             status="ERROR",
             alert=True,
@@ -803,7 +829,7 @@ def main():
                 output.entries = transform_raw_data(data)
 
         if do_cleanup:
-            print("Cleaning up modifications to the system.")
+            logging.info("Cleaning up modifications to the system.")
             cleanup(required_files)
 
         print("### JSON START ###")

tests/test_main_analysis.py

@@ -39,12 +39,13 @@ def test_main_success_c2r_installed(
     mock_install_or_update_convert2rhel,
     mock_gather_json_report,
     capsys,  # to check for rollback info in stdout
+    caplog,
 ):
     main()
 
     output = capsys.readouterr().out
-    assert "rollback" not in output
-    assert "Convert2RHEL Analysis script finished successfully!" in output
+    assert "rollback" not in caplog.text
+    assert "Convert2RHEL Analysis script finished successfully!" in caplog.text
     assert '"alert": false' in output
     assert mock_rollback_inhibitor_check.call_count == 1
     assert mock_update_insights_inventory.call_count == 0
@@ -95,12 +96,13 @@ def test_main_success_c2r_updated(
     mock_install_or_update_convert2rhel,
     mock_gather_json_report,
     capsys,  # to check for rollback info in stdout
+    caplog,
 ):
     main()
 
     output = capsys.readouterr().out
-    assert "rollback" not in output
-    assert "Convert2RHEL Analysis script finished successfully!" in output
+    assert "rollback" not in caplog.text
+    assert "Convert2RHEL Analysis script finished successfully!" in caplog.text
     assert '"alert": false' in output
     assert mock_rollback_inhibitor_check.call_count == 1
 

tests/test_main_common.py

@@ -12,13 +12,14 @@ def test_main_invalid_script_value(
     mock_cleanup,
     mock_archive,
     capsys,
+    caplog,
 ):
     mock_output_collector.return_value = OutputCollector(entries=["non-empty"])
 
     main()
 
     output = capsys.readouterr().out
-    assert "Exiting because RHC_WORKER_SCRIPT_MODE" in output
+    assert "Exiting because RHC_WORKER_SCRIPT_MODE" in caplog.text
     assert '"alert": false' in output
 
     mock_output_collector.assert_called()