[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,65 @@ 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"):
+        """
+        Initialize the handler with the buffer size.
+
+        :param int capacity: Buffer size for the handler
+        :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
+        """
+        if super(LogfileBufferHandler, self).shouldFlush(record):
+            self.buffer = self.buffer[1:]
+        return False
+
+
+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 +134,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 +147,46 @@ def setup_logger_handler(log_name, log_dir):
     stdout_handler.setLevel(logging.DEBUG)
     logger.addHandler(stdout_handler)
 
-    # create file handler
+    # can flush logs to the file that were logged before initializing the file handler
+    logger.addHandler(LogfileBufferHandler(capacity=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,24 +44,38 @@ 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.
+    and setup for logger handlers that do not require root.
+    """
+
+    return logger_module.setup_logger_handler()
+
+
+def initialize_file_logging(log_name, log_dir):
+    """
+    Archive existing file logs and setup all logging handlers that require
+    root, like FileHandlers.
+
+    This function should be called after
+    :func:`~convert2rhel.main.initialize_logger`.
 
     .. warning::
         Setting log_dir underneath a world-writable directory (including
         letting it be user settable) is insecure.  We will need to write
         some checks for all calls to `os.makedirs()` if we allow changing
         log_dir.
-    """
 
+    :param str log_name: Name of the logfile to archive and log to
+    :param str log_dir: Directory where logfiles are stored
+    """
     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 +87,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 +110,11 @@ def main_locked():
 
     pre_conversion_results = None
     process_phase = ConversionPhase.POST_CLI
+
+    # since we now have root, we can add the FileLogging
+    # and also archive previous logs
+    initialize_file_logging("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 InitializeFileLoggingMocked(MockFunctionObject):
+    spec = main.initialize_file_logging
+
+
 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
@@ -107,8 +107,12 @@ def pkg_root():
 
 
 @pytest.fixture(autouse=True)
-def setup_logger(tmpdir):
-    setup_logger_handler(log_name="convert2rhel", log_dir=str(tmpdir))
+def setup_logger(tmpdir, request):
+    # This makes it so we can skip this using @pytest.mark.noautofixtures
+    if "noautofixtures" in request.keywords:
+        return
+    setup_logger_handler()
+    add_file_handler(log_name="convert2rhel", log_dir=str(tmpdir))
 
 
 @pytest.fixture