Merge pull request #1041 from M4rtinK/master-structured_logging_plus

Structured logging

anaconda.py

@@ -189,7 +189,7 @@ def parse_arguments(argv=None, boot_cmdline=None):
     :returns: namespace of parsed options and a list of deprecated
               anaconda options that have been found
     """
-    from pyanaconda.anaconda_argparse import getArgumentParser
+    from pyanaconda.argument_parsing import getArgumentParser
     ap = getArgumentParser(startup_utils.get_anaconda_version_string(),
                            boot_cmdline)
 
@@ -251,7 +251,7 @@ def start_debugger(signum, frame):
         # this much (redirect any log messages to stdout) to get rid of the
         # harmless but annoying "no handlers found" message on stdout
         import logging
-        log = logging.getLogger("anaconda")
+        log = logging.getLogger("anaconda.main")
         log.addHandler(logging.StreamHandler(stream=sys.stdout))
         parse_arguments()
 
@@ -270,9 +270,9 @@ def start_debugger(signum, frame):
 
     # init threading before Gtk can do anything and before we start using threads
     # initThreading initializes the threadMgr instance, import it afterwards
-    from pyanaconda.threads import initThreading, AnacondaThread
+    from pyanaconda.threading import initThreading, AnacondaThread
     initThreading()
-    from pyanaconda.threads import threadMgr
+    from pyanaconda.threading import threadMgr
 
     from pyanaconda.i18n import _
 
@@ -291,16 +291,16 @@ def start_debugger(signum, frame):
         flags.dirInstall = True
 
     # Set up logging as early as possible.
-    import logging
-    from pyanaconda import anaconda_log
-    anaconda_log.init()
-    anaconda_log.logger.setupVirtio()
+    from pyanaconda import anaconda_logging
+    from pyanaconda import anaconda_loggers
+    anaconda_logging.init()
+    anaconda_logging.logger.setupVirtio()
 
     from pyanaconda import network
     network.setup_ifcfg_log()
 
-    log = logging.getLogger("anaconda")
-    stdout_log = logging.getLogger("anaconda.stdout")
+    log = anaconda_loggers.get_main_logger()
+    stdout_log = anaconda_loggers.get_stdout_logger()
 
     if os.geteuid() != 0:
         stdout_log.error("anaconda must be run as root.")
@@ -633,7 +633,7 @@ def _earlyExceptionHandler(ty, value, traceback):
     storage_checker.add_constraint(constants.STORAGE_MIN_RAM, min_ram)
     anaconda.instClass.setStorageChecker(storage_checker)
 
-    from pyanaconda.anaconda_argparse import name_path_pairs
+    from pyanaconda.argument_parsing import name_path_pairs
 
     image_count = 0
     try:

anaconda.spec.in

@@ -85,7 +85,7 @@ The anaconda package is a metapackage for the Anaconda installer.
 Summary: Core of the Anaconda installer
 Requires: python3-libs
 Requires: python3-dnf >= %{dnfver}
-Requires: python3-blivet >= 1:2.1.7-3
+Requires: python3-blivet >= 1:2.1.9-1
 Requires: python3-blockdev >= %{libblockdevver}
 Requires: libblockdev-plugins-all >= %{libblockdevver}
 Requires: python3-meh >= %{mehver}

pyanaconda/addons.py

@@ -21,13 +21,13 @@
 
 import os
 import functools
-import logging
 from pykickstart.sections import Section
 
 from pyanaconda.progress import progress_message
 from pyanaconda.i18n import N_
 
-log = logging.getLogger("anaconda")
+from pyanaconda.anaconda_loggers import get_module_logger
+log = get_module_logger(__name__)
 
 PLACEHOLDER_NAME = "ADDON_placeholder"
 

pyanaconda/anaconda.py

@@ -30,9 +30,11 @@
 from pyanaconda import iutil
 from pyanaconda import addons
 
-import logging
-log = logging.getLogger("anaconda")
-stdoutLog = logging.getLogger("anaconda.stdout")
+from pyanaconda.anaconda_loggers import get_stdout_logger
+stdoutLog = get_stdout_logger()
+
+from pyanaconda.anaconda_loggers import get_module_logger
+log = get_module_logger(__name__)
 
 class Anaconda(object):
     def __init__(self):

pyanaconda/anaconda_loggers.py

@@ -0,0 +1,72 @@
+#
+# anaconda_loggers.py : provides Anaconda specififc loggers
+#
+# Copyright (C) 2017  Red Hat, Inc.  All rights reserved.
+#
+# This program is free software; you can redistribute it and/or modify
+# it under the terms of the GNU General Public License as published by
+# the Free Software Foundation; either version 2 of the License, or
+# (at your option) any later version.
+#
+# This program is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+# GNU General Public License for more details.
+#
+# You should have received a copy of the GNU General Public License
+# along with this program.  If not, see <http://www.gnu.org/licenses/>.
+#
+
+# Q: Why do we have a separate module for this?
+#
+# A: To avoid import cycles. The anaconda_logging module would be a natural
+#    place for this function, but it unfrotunatelly imports the flags module.
+#    And the flags module would have to import anaconda_logging to obtain the
+#    get_module_logger() function, resulting in an import cycle.
+#    We should be able to avoid this be placing the get_logger() function
+#    in its own module that does not import any Anaconda modules other
+#    than the constants module.
+
+import logging
+from pyanaconda import constants
+
+def get_module_logger(module_name):
+    """Return anaconda sub-logger based on a module __name__ attribute.
+
+    Currently we just strip the "pyanaconda." prefix (if any) and then
+    put the string behind "anaconda.". After thet we use the result
+    to get the correspondong sub-logger.
+    """
+    if module_name.startswith("pyanaconda."):
+        module_name = module_name[11:]
+    return logging.getLogger("anaconda.%s" % module_name)
+
+def get_main_logger():
+    return logging.getLogger(constants.LOGGER_MAIN)
+
+def get_stdout_logger():
+    return logging.getLogger(constants.LOGGER_STDOUT)
+
+def get_stderr_logger():
+    return logging.getLogger(constants.LOGGER_STDERR)
+
+def get_program_logger():
+    return logging.getLogger(constants.LOGGER_PROGRAM)
+
+def get_storage_logger():
+    return logging.getLogger(constants.LOGGER_STORAGE)
+
+def get_packaging_logger():
+    return logging.getLogger(constants.LOGGER_PACKAGING)
+
+def get_dnf_logger():
+    return logging.getLogger(constants.LOGGER_DNF)
+
+def get_blivet_logger():
+    return logging.getLogger(constants.LOGGER_BLIVET)
+
+def get_ifcfg_logger():
+    return logging.getLogger(constants.LOGGER_IFCFG)
+
+def get_sensitive_info_logger():
+    return logging.getLogger(constants.LOGGER_SENSITIVE_INFO)

pyanaconda/anaconda_log.py → pyanaconda/anaconda_logging.py

@@ -1,8 +1,9 @@
 #
-# anaconda_log.py: Support for logging to multiple destinations with log
-# levels.
+# anaconda_logging.py: Support for logging to multiple destinations with log
+#                      levels - basically an extension to the Python logging
+#                      module with Anaconda specififc enhancements.
 #
-# Copyright (C) 2000, 2001, 2002, 2005  Red Hat, Inc.  All rights reserved.
+# Copyright (C) 2000, 2001, 2002, 2005, 2017  Red Hat, Inc.  All rights reserved.
 #
 # This program is free software; you can redistribute it and/or modify
 # it under the terms of the GNU General Public License as published by
@@ -26,12 +27,17 @@
 import wrapt
 
 from pyanaconda.flags import flags
+from pyanaconda import constants
 
 DEFAULT_LEVEL = logging.INFO
 ENTRY_FORMAT = "%(asctime)s,%(msecs)03d %(levelname)s %(name)s: %(message)s"
 STDOUT_FORMAT = "%(asctime)s %(message)s"
 DATE_FORMAT = "%H:%M:%S"
 
+# the Anaconda log uses structured logging
+ANACONDA_ENTRY_FORMAT = "%(asctime)s,%(msecs)03d %(levelname)s %(log_prefix)s: %(message)s"
+ANACONDA_SYSLOG_FORMAT = "anaconda: %(log_prefix)s: %(message)s"
+
 MAIN_LOG_FILE = "/tmp/anaconda.log"
 PROGRAM_LOG_FILE = "/tmp/program.log"
 STORAGE_LOG_FILE = "/tmp/storage.log"
@@ -111,10 +117,13 @@ def __init__(self,
         SysLogHandler.__init__(self, address, facility)
 
     def emit(self, record):
-        original_msg = record.msg
-        record.msg = '%s: %s' % (self.tag, original_msg)
-        SysLogHandler.emit(self, record)
-        record.msg = original_msg
+        if self.tag:
+            original_msg = record.msg
+            record.msg = '%s: %s' % (self.tag, original_msg)
+            SysLogHandler.emit(self, record)
+            record.msg = original_msg
+        else:
+            SysLogHandler.emit(self, record)
 
     def mapPriority(self, levelName):
         """Map the priority level to a syslog level """
@@ -130,6 +139,25 @@ class AnacondaFileHandler(_AnacondaLogFixer, logging.FileHandler):
 class AnacondaStreamHandler(_AnacondaLogFixer, logging.StreamHandler):
     pass
 
+class AnacondaPrefixFilter(logging.Filter):
+    """Add a log_prefix field, which is based on the name property,
+    but without the "anaconda." prefix.
+
+    Also if name is equal to "anaconda", generally meaning some sort of
+    general (or miss-directed) log message, set the log_prefix to "misc".
+    """
+
+    def filter(self, record):
+        record.log_prefix = ""
+        if record.name:
+            # messages going to the generic "anaconda" logger get the log prefix "misc"
+            if record.name == "anaconda":
+                record.log_prefix = "misc"
+            elif record.name.startswith("anaconda."):
+                # drop "anaconda." from the log prefix
+                record.log_prefix = record.name[9:]
+        return True
+
 class AnacondaLog:
     SYSLOG_CFGFILE = "/etc/rsyslog.conf"
     VIRTIO_PORT = "/dev/virtio-ports/org.fedoraproject.anaconda.log.0"
@@ -138,40 +166,49 @@ def __init__(self):
         self.loglevel = DEFAULT_LEVEL
         self.remote_syslog = None
         # Rename the loglevels so they are the same as in syslog.
-        logging.addLevelName(logging.WARNING, "WARN")
+        logging.addLevelName(logging.CRITICAL, "CRT")
         logging.addLevelName(logging.ERROR, "ERR")
-        logging.addLevelName(logging.CRITICAL, "CRIT")
+        logging.addLevelName(logging.WARNING, "WRN")
+        logging.addLevelName(logging.INFO, "INF")
+        logging.addLevelName(logging.DEBUG, "DBG")
 
         # Create the base of the logger hierarchy.
         # Disable propagation to the parent logger, since the root logger is
         # handled by a FileHandler(/dev/null), which can deadlock.
         self.anaconda_logger = logging.getLogger("anaconda")
         self.anaconda_logger.propagate = False
         self.addFileHandler(MAIN_LOG_FILE, self.anaconda_logger,
-                            minLevel=logging.DEBUG)
+                            minLevel=logging.DEBUG,
+                            fmtStr=ANACONDA_ENTRY_FORMAT,
+                            log_filter=AnacondaPrefixFilter())
         warnings.showwarning = self.showwarning
 
         # Create the storage logger.
-        storage_logger = logging.getLogger("blivet")
+        storage_logger = logging.getLogger(constants.LOGGER_BLIVET)
         storage_logger.propagate = False
         self.addFileHandler(STORAGE_LOG_FILE, storage_logger,
                             minLevel=logging.DEBUG)
 
         # Set the common parameters for anaconda and storage loggers.
         for logr in [self.anaconda_logger, storage_logger]:
             logr.setLevel(logging.DEBUG)
-            self.forwardToSyslog(logr)
+
+        # forward both logs to syslog
+        self.forwardToSyslog(self.anaconda_logger,
+                             log_filter=AnacondaPrefixFilter(),
+                             log_formatter=logging.Formatter(ANACONDA_SYSLOG_FORMAT))
+        self.forwardToSyslog(storage_logger)
 
         # External program output log
-        program_logger = logging.getLogger("program")
+        program_logger = logging.getLogger(constants.LOGGER_PROGRAM)
         program_logger.propagate = False
         program_logger.setLevel(logging.DEBUG)
         self.addFileHandler(PROGRAM_LOG_FILE, program_logger,
                             minLevel=logging.DEBUG)
         self.forwardToSyslog(program_logger)
 
         # Create the packaging logger.
-        packaging_logger = logging.getLogger("packaging")
+        packaging_logger = logging.getLogger(constants.LOGGER_PACKAGING)
         packaging_logger.setLevel(logging.DEBUG)
         packaging_logger.propagate = False
         self.addFileHandler(PACKAGING_LOG_FILE, packaging_logger,
@@ -180,7 +217,7 @@ def __init__(self):
         self.forwardToSyslog(packaging_logger)
 
         # Create the dnf logger and link it to packaging
-        dnf_logger = logging.getLogger("dnf")
+        dnf_logger = logging.getLogger(constants.LOGGER_DNF)
         dnf_logger.setLevel(logging.DEBUG)
         self.addFileHandler(PACKAGING_LOG_FILE, dnf_logger,
                             minLevel=logging.NOTSET)
@@ -190,7 +227,7 @@ def __init__(self):
         # * the sensitive-info.log file is not copied to the installed
         # system, as it might contain sensitive information that
         # should not be persistently stored by default
-        sensitive_logger = logging.getLogger("sensitive-info")
+        sensitive_logger = logging.getLogger(constants.LOGGER_SENSITIVE_INFO)
         sensitive_logger.propagate = False
         self.addFileHandler(SENSITIVE_INFO_LOG_FILE, sensitive_logger,
                             minLevel=logging.DEBUG)
@@ -199,47 +236,61 @@ def __init__(self):
         # stdout.  Anything written here will also get passed up to the
         # parent loggers for processing and possibly be written to the
         # log.
-        stdout_logger = logging.getLogger("anaconda.stdout")
+        stdout_logger = logging.getLogger(constants.LOGGER_STDOUT)
         stdout_logger.setLevel(logging.INFO)
         # Add a handler for the duped stuff.  No fancy formatting, thanks.
         self.addFileHandler(sys.stdout, stdout_logger,
                             fmtStr=STDOUT_FORMAT, minLevel=logging.INFO)
 
         # Stderr logger
-        stderr_logger = logging.getLogger("anaconda.stderr")
+        stderr_logger = logging.getLogger(constants.LOGGER_STDERR)
         stderr_logger.setLevel(logging.INFO)
         self.addFileHandler(sys.stderr, stderr_logger,
                             fmtStr=STDOUT_FORMAT, minLevel=logging.INFO)
 
     # Add a simple handler - file or stream, depending on what we're given.
     def addFileHandler(self, dest, addToLogger, minLevel=DEFAULT_LEVEL,
                        fmtStr=ENTRY_FORMAT,
-                       autoLevel=False):
+                       autoLevel=False,
+                       log_filter=None):
         try:
             if isinstance(dest, str):
                 logfile_handler = AnacondaFileHandler(dest)
             else:
                 logfile_handler = AnacondaStreamHandler(dest)
 
+            if log_filter:
+                logfile_handler.addFilter(log_filter)
             logfile_handler.setLevel(minLevel)
             logfile_handler.setFormatter(logging.Formatter(fmtStr, DATE_FORMAT))
             autoSetLevel(logfile_handler, autoLevel)
             addToLogger.addHandler(logfile_handler)
         except IOError:
             pass
 
-    def forwardToSyslog(self, logr):
+    def forwardToSyslog(self, logr, log_formatter=None, log_filter=None):
         """Forward everything that goes in the logger to the syslog daemon.
         """
         if flags.imageInstall or flags.dirInstall:
             # don't clutter up the system logs when doing an image install
             return
 
+        # Don't add syslog tag if custom formatter is in use.
+        # This also means that custom formatters need to make sure they
+        # add the tag correctly themselves.
+        if log_formatter:
+            tag = None
+        else:
+            tag = logr.name
         syslog_handler = AnacondaSyslogHandler(
             '/dev/log',
             ANACONDA_SYSLOG_FACILITY,
-            logr.name)
+            tag=tag)
         syslog_handler.setLevel(logging.DEBUG)
+        if log_filter:
+            syslog_handler.addFilter(log_filter)
+        if log_formatter:
+            syslog_handler.setFormatter(log_formatter)
         logr.addHandler(syslog_handler)
 
     # pylint: disable=redefined-builtin