[RHELC-1131, RHELC-1234] Refactor logger to not require root

convert2rhel/logger.py

@@ -35,11 +35,15 @@
 import shutil
 import sys
 
+from logging.handlers import BufferingHandler
 from time import gmtime, strftime
 
 
 LOG_DIR = "/var/log/convert2rhel"
 
+# get root logger
+logger = logging.getLogger("convert2rhel")
+
 
 class LogLevelCriticalNoExit:
     level = 50
@@ -58,11 +62,61 @@ class LogLevelFile:
     label = "DEBUG"
 
 
-def setup_logger_handler(log_name, log_dir):
+class LogfileBufferHandler(BufferingHandler):
+    """
+    FileHandler we use in Convert2RHEL requries root due to the location and the
+    tool itself checking for root user explicitly. Since we cannot obviously
+    use the logger if we aren't root in that case we simply add the FileHandler
+    after determining we're root.
+
+    Caveat of that approach is that any logging prior to the initialization of
+    the FileHandler would be lost, to help with this we have this custom handler
+    which will keep a buffer of the logs and flush it to the FileHandler
+    """
+
+    name = "logfile_buffer_handler"
+
+    def __init__(self, capacity, handler_name="file_handler"):
+        """_summary_
+
+        :param int capacity: Initialize with a buffer size
+        :param str handler_name: Handler to flush buffer to, defaults to "file_handler"
+        """
+        super(LogfileBufferHandler, self).__init__(capacity)
+        # the FileLogger handler that we are logging to
+        self._handler_name = handler_name
+
+    @property
+    def target(self):
+        """The computed Filehandler target that we are supposed to send to. This
+        is mostly copied over from logging's MemoryHandler but instead of setting
+        the target manually we find it automatically given the name of the handler
+
+        :return logging.Handler: Either the found FileHandler setup or temporary NullHandler
+        """
+        for handler in logger.handlers:
+            if handler.name == self._handler_name:
+                return handler
+        return logging.NullHandler()
+
+    def flush(self):
+        for record in self.buffer:
+            self.target.handle(record)
+
+    def shouldFlush(self, record):
+        """We should never flush automatically, so we set this to always return false, that way we need to flush
+        manually each time. Which is exactly what we want when it comes to keeping a buffer before we confirm we are
+        a root user.
+
+        :param logging.LogRecord record: The record to log
+        :return bool: Always returns false
+        """
+        return False  # pragma: no cover
+
+
+def setup_logger_handler():
     """Setup custom logging levels, handlers, and so on. Call this method
     from your application's main start point.
-        log_name = the name for the log file
-        log_dir = path to the dir where log file will be presented
     """
     # set custom labels
     logging.addLevelName(LogLevelTask.level, LogLevelTask.label)
@@ -76,8 +130,6 @@ def setup_logger_handler(log_name, log_dir):
 
     # enable raising exceptions
     logging.raiseExceptions = True
-    # get root logger
-    logger = logging.getLogger("convert2rhel")
     # propagate
     logger.propagate = True
     # set default logging level
@@ -91,22 +143,47 @@ def setup_logger_handler(log_name, log_dir):
     stdout_handler.setLevel(logging.DEBUG)
     logger.addHandler(stdout_handler)
 
-    # create file handler
+    # Setup a buffer for the file handler that we will add later, that way we
+    # can flush logs to the file that were logged before initializing the file handler
+    logger.addHandler(LogfileBufferHandler(100))
+
+
+def add_file_handler(log_name, log_dir):
+    """Create a file handler for the logger instance
+
+    :param str log_name: Name of the log file
+    :param str log_dir: Full path location
+    """
     if not os.path.isdir(log_dir):
         os.makedirs(log_dir)  # pragma: no cover
-    handler = logging.FileHandler(os.path.join(log_dir, log_name), "a")
+    filehandler = logging.FileHandler(os.path.join(log_dir, log_name), "a")
+    filehandler.name = "file_handler"
     formatter = CustomFormatter("%(message)s")
+
+    # With a file we don't really need colors
+    # This might change in the future depending on customer requests
+    # or if we do something with UI work in the future that would be more
+    # helpful with colors
     formatter.disable_colors(True)
-    handler.setFormatter(formatter)
-    handler.setLevel(LogLevelFile.level)
-    logger.addHandler(handler)
+    filehandler.setFormatter(formatter)
+    filehandler.setLevel(LogLevelFile.level)
+    logger.addHandler(filehandler)
+
+    # We now have a FileHandler added, but we still need the logs from before
+    # this point. Luckily we have the memory buffer that we can flush logs from
+    for handler in logger.handlers:
+        if handler.name == "logfile_buffer_handler":
+            handler.flush()
+            # after we've flushed to the file we don't need the handler anymore
+            logger.removeHandler(handler)
+            break
 
 
 def should_disable_color_output():
     """
     Return whether NO_COLOR exists in environment parameter and is true.
 
-    See http://no-color.org/
+    See https://no-color.org/
     """
     if "NO_COLOR" in os.environ:
         NO_COLOR = os.environ["NO_COLOR"]

convert2rhel/main.py

@@ -44,7 +44,7 @@ class ConversionPhase:
     POST_PONR_CHANGES = 4
 
 
-def initialize_logger(log_name, log_dir):
+def initialize_logger():
     """
     Entrypoint function that aggregates other calls for initialization logic
     and setup for logger handlers.
@@ -56,12 +56,16 @@ def initialize_logger(log_name, log_dir):
         log_dir.
     """
 
+    return logger_module.setup_logger_handler()
+
+
+def finalize_logger(log_name, log_dir):
     try:
         logger_module.archive_old_logger_files(log_name, log_dir)
     except (IOError, OSError) as e:
-        print("Warning: Unable to archive previous log: %s" % e)
+        loggerinst.warning("Unable to archive previous log: %s" % e)
 
-    logger_module.setup_logger_handler(log_name, log_dir)
+    logger_module.add_file_handler(log_name, log_dir)
 
 
 def main():
@@ -73,23 +77,21 @@ def main():
     the application lock, to do the conversion process.
     """
 
-    # Make sure we're being run by root
-    utils.require_root()
-
     # initialize logging
-    initialize_logger("convert2rhel.log", logger_module.LOG_DIR)
+    initialize_logger()
 
     # handle command line arguments
     toolopts.CLI()
 
+    # Make sure we're being run by root
+    utils.require_root()
+
     try:
         with applock.ApplicationLock("convert2rhel"):
             return main_locked()
     except applock.ApplicationLockedError:
-        # We have not rotated the log files at this point because main.initialize_logger()
-        # has not yet been called.  So we use sys.stderr.write() instead of loggerinst.error()
-        sys.stderr.write("Another copy of convert2rhel is running.\n")
-        sys.stderr.write("\nNo changes were made to the system.\n")
+        loggerinst.warning("Another copy of convert2rhel is running.\n")
+        loggerinst.warning("\nNo changes were made to the system.\n")
         return 1
 
 
@@ -98,6 +100,11 @@ def main_locked():
 
     pre_conversion_results = None
     process_phase = ConversionPhase.POST_CLI
+
+    # since we now have root, we can add the FileLogger
+    # and also archive previous logs
+    finalize_logger("convert2rhel.log", logger_module.LOG_DIR)
+
     try:
         perform_boilerplate()
 

convert2rhel/unit_tests/__init__.py

@@ -373,6 +373,10 @@ class InitializeLoggerMocked(MockFunctionObject):
     spec = main.initialize_logger
 
 
+class FinalizeLoggerMocked(MockFunctionObject):
+    spec = main.finalize_logger
+
+
 class MainLockedMocked(MockFunctionObject):
     spec = main.main_locked
 

convert2rhel/unit_tests/conftest.py

@@ -8,7 +8,7 @@
 import six
 
 from convert2rhel import backup, cert, pkgmanager, redhatrelease, systeminfo, toolopts, utils
-from convert2rhel.logger import setup_logger_handler
+from convert2rhel.logger import add_file_handler, setup_logger_handler
 from convert2rhel.systeminfo import system_info
 from convert2rhel.toolopts import tool_opts
 from convert2rhel.unit_tests import MinimalRestorable
@@ -108,7 +108,8 @@ def pkg_root():
 
 @pytest.fixture(autouse=True)
 def setup_logger(tmpdir):
-    setup_logger_handler(log_name="convert2rhel", log_dir=str(tmpdir))
+    setup_logger_handler()
+    add_file_handler(log_name="convert2rhel", log_dir=str(tmpdir))
 
 
 @pytest.fixture

convert2rhel/unit_tests/logger_test.py

@@ -32,7 +32,8 @@ def test_logger_handlers(monkeypatch, tmpdir, caplog, read_std, is_py2, global_t
     # initializing the logger first
     log_fname = "convert2rhel.log"
     global_tool_opts.debug = True  # debug entries > stdout if True
-    logger_module.setup_logger_handler(log_name=log_fname, log_dir=str(tmpdir))
+    logger_module.setup_logger_handler()
+    logger_module.add_file_handler(log_name=log_fname, log_dir=str(tmpdir))
     logger = logging.getLogger(__name__)
 
     # emitting some log entries
@@ -53,7 +54,7 @@ def test_logger_handlers(monkeypatch, tmpdir, caplog, read_std, is_py2, global_t
 def test_tools_opts_debug(monkeypatch, tmpdir, read_std, is_py2, global_tool_opts, clear_loggers):
     monkeypatch.setattr("convert2rhel.toolopts.tool_opts", global_tool_opts)
     log_fname = "convert2rhel.log"
-    logger_module.setup_logger_handler(log_name=log_fname, log_dir=str(tmpdir))
+    logger_module.setup_logger_handler()
     logger = logging.getLogger(__name__)
     global_tool_opts.debug = True
     logger.debug("debug entry 1: %s", "data")
@@ -88,7 +89,7 @@ class TestCustomLogger:
     def test_logger_custom_logger(self, log_method_name, level_name, caplog, monkeypatch, tmpdir, clear_loggers):
         """Test CustomLogger."""
         log_fname = "convert2rhel.log"
-        logger_module.setup_logger_handler(log_name=log_fname, log_dir=str(tmpdir))
+        logger_module.setup_logger_handler()
         logger = logging.getLogger(__name__)
         log_method = getattr(logger, log_method_name)
 
@@ -101,7 +102,7 @@ def test_logger_custom_logger(self, log_method_name, level_name, caplog, monkeyp
     def test_logger_critical(self, caplog, tmpdir, clear_loggers):
         """Test CustomLogger."""
         log_fname = "convert2rhel.log"
-        logger_module.setup_logger_handler(log_name=log_fname, log_dir=str(tmpdir))
+        logger_module.setup_logger_handler()
         logger = logging.getLogger(__name__)
 
         with pytest.raises(SystemExit):
@@ -125,7 +126,7 @@ def test_logger_custom_logger_insufficient_level(
     ):
         """Test CustomLogger."""
         log_fname = "convert2rhel.log"
-        logger_module.setup_logger_handler(log_name=log_fname, log_dir=str(tmpdir))
+        logger_module.setup_logger_handler()
         logger = logging.getLogger(__name__)
         logger.setLevel(logging.CRITICAL + 40)
         log_method = getattr(logger, log_method_name)
@@ -138,7 +139,7 @@ def test_logger_custom_logger_insufficient_level(
     def test_logger_critical_insufficient_level(self, caplog, tmpdir, clear_loggers):
         """Test CustomLogger."""
         log_fname = "convert2rhel.log"
-        logger_module.setup_logger_handler(log_name=log_fname, log_dir=str(tmpdir))
+        logger_module.setup_logger_handler()
         logger = logging.getLogger(__name__)
         logger.setLevel(logging.CRITICAL + 40)