So I have been finally able to decipher the arcane incantations from the Anaconda logging module needed to enable syslog logging also in Initial Setup! :)
So, no more "Initial setup failed - good luck finding out why!", but detailed logging messages - if everything goes right: http://paste.fedoraproject.org/142509/77076141
And even if not :P : http://paste.fedoraproject.org/142507/13476904
All directly to the system log/Journal. :)
Martin Kolman (1): Add syslog logging support (#1145122)
initial_setup/__main__.py | 44 ++++++++++++++++++++++++++++++---- initial_setup/initial_setup_log.py | 48 ++++++++++++++++++++++++++++++++++++++ initial_setup/product.py | 5 +++- 3 files changed, 92 insertions(+), 5 deletions(-) create mode 100644 initial_setup/initial_setup_log.py
Add an Initial Setup specific log handling module that forwards nicely formated log messages to the system log and also correctly maps message log levels to system log priorities (in journalctl: info & debug - no highlight, warning - bold, error & critical - red).
This finally makes it possible to report in detail what's going on during the Initial Setup run, with emphasis on providing enough information on problematic areas, such as Kickstart parsing.
BTW, to check for all Initial Setup log messages in Journal you can use the -u flag with the Initial Setup unit name:
journalctl -u initial-setup-graphical
or
journalctl -u initial-setup-text
Signed-off-by: Martin Kolman mkolman@redhat.com --- initial_setup/__main__.py | 44 ++++++++++++++++++++++++++++++---- initial_setup/initial_setup_log.py | 48 ++++++++++++++++++++++++++++++++++++++ initial_setup/product.py | 5 +++- 3 files changed, 92 insertions(+), 5 deletions(-) create mode 100644 initial_setup/initial_setup_log.py
diff --git a/initial_setup/__main__.py b/initial_setup/__main__.py index 807a51b..82edb9f 100644 --- a/initial_setup/__main__.py +++ b/initial_setup/__main__.py @@ -3,26 +3,37 @@ import os import sys import signal import pykickstart +import logging from pyanaconda.users import Users from initial_setup.post_installclass import PostInstallClass +from initial_setup import initial_setup_log from pyanaconda import iutil
+INPUT_KICKSTART_PATH = "/root/anaconda-ks.cfg" +OUTPUT_KICKSTART_PATH = "/root/initial-setup-ks.cfg" + # set root to "/", we are now in the installed system iutil.setSysroot("/")
signal.signal(signal.SIGINT, signal.SIG_IGN)
+initial_setup_log.init() +log = logging.getLogger("initial-setup") + if "DISPLAY" in os.environ and os.environ["DISPLAY"]: mode="gui" else: mode="tui"
+log.debug("display mode detected: %s", mode) + if mode == "gui": # We need this so we can tell GI to look for overrides objects # also in anaconda source directories import gi.overrides for p in os.environ.get("ANACONDA_WIDGETS_OVERRIDES", "").split(":"): gi.overrides.__path__.insert(0, p) + log.debug("GI overrides imported")
from pyanaconda.addons import collect_addon_paths
@@ -32,18 +43,24 @@ addon_paths = ["/usr/share/initial-setup/modules", "/usr/share/anaconda/addons"] sys.path.extend(addon_paths)
addon_module_paths = collect_addon_paths(addon_paths, mode) +log.info("found %d addon modules:", len(addon_module_paths)) +for addon_path in addon_module_paths: + log.debug(addon_path)
# Too bad anaconda does not have modularized logging +log.debug("initializing the Anaconda log") from pyanaconda import anaconda_log anaconda_log.init()
# init threading before Gtk can do anything and before we start using threads # initThreading initializes the threadMgr instance, import it afterwards +log.debug("initializing threading") from pyanaconda.threads import initThreading initThreading()
# initialize network logging (needed by the Network spoke that may be shown) +log.debug("initializing network logging") from pyanaconda.network import setup_ifcfg_log setup_ifcfg_log()
@@ -66,18 +83,23 @@ commandMap = dict((k, kickstart.commandMap[k]) for k in kickstart_commands) # Prepare new data object data = kickstart.AnacondaKSHandler(addon_module_paths["ks"], commandUpdates=commandMap)
+log.info("parsing input kickstart %s", INPUT_KICKSTART_PATH) try: # Read the installed kickstart parser = kickstart.AnacondaKSParser(data) - parser.readKickstart("/root/anaconda-ks.cfg") + parser.readKickstart(INPUT_KICKSTART_PATH) + log.info("kickstart parsing done") except pykickstart.errors.KickstartError as kserr: + log.exception("kickstart parsing failed") sys.exit(1)
if mode == "gui": try: # Try to import IS gui specifics + log.debug("trying to import GUI") import gui except ImportError: + log.error("GUI import failed, falling back to TUI") mode = "tui"
if mode == "gui": @@ -87,6 +109,7 @@ if mode == "gui": gui.InitialSetupGraphicalUserInterface.update_paths(addon_module_paths)
# Initialize the UI + log.debug("initializing GUI") ui = gui.InitialSetupGraphicalUserInterface(None, None, PostInstallClass()) else: # Import IS gui specifics @@ -96,17 +119,21 @@ else: tui.InitialSetupTextUserInterface.update_paths(addon_module_paths)
# Initialize the UI + log.debug("initializing TUI") ui = tui.InitialSetupTextUserInterface(None, None, None)
# Pass the data object to user inteface +log.debug("setting up the UI") ui.setup(data)
# Start the application +log.info("starting the UI") ret = ui.run()
# TUI returns False if the app was ended prematurely # all other cases return True or None if ret == False: + log.warning("ended prematurely in TUI") sys.exit(0)
# Do not execute sections that were part of the original @@ -117,9 +144,13 @@ sections = [data.keyboard, data.lang, data.timezone] # data.selinux # data.firewall
+log.info("executing kickstart") for section in sections: + section_msg = "%s on line %d" % (repr(section), section.lineno) if section.seen: + log.debug("skipping %s", section_msg) continue + log.debug("executing %s", section_msg) section.execute(None, data, None)
# Prepare the user database tools @@ -127,14 +158,19 @@ u = Users()
sections = [data.group, data.user, data.rootpw] for section in sections: + section_msg = "%s on line %d" % (repr(section), section.lineno) if section.seen: + log.debug("skipping %s", section_msg) continue + log.debug("executing %s", section_msg) section.execute(None, data, None, u)
# Configure all addons +log.info("executing addons") data.addons.execute(None, data, None, u)
-# Print the kickstart data to file -with open("/root/initial-setup-ks.cfg", "w") as f: +# Write the kickstart data to file +log.info("writing the Initial Setup kickstart file %s", OUTPUT_KICKSTART_PATH) +with open(OUTPUT_KICKSTART_PATH, "w") as f: f.write(str(data)) - +log.info("finished writing the Initial Setup kickstart file") diff --git a/initial_setup/initial_setup_log.py b/initial_setup/initial_setup_log.py new file mode 100644 index 0000000..998eb3a --- /dev/null +++ b/initial_setup/initial_setup_log.py @@ -0,0 +1,48 @@ +# +# initial_setup_log.py: Support for logging to syslog during the +# Initial Setup run +# +# Copyright (C) 2014 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/. +# +# Author(s): Martin Kolman mkolman@redhat.com + +import logging +from logging.handlers import SysLogHandler, SYSLOG_UDP_PORT + +STDOUT_FORMAT = "%(asctime)s %(message)s" + +class InitialSetupSyslogHandler(SysLogHandler): + + def __init__(self, + address=('localhost', SYSLOG_UDP_PORT), + facility=SysLogHandler.LOG_USER, + tag=''): + self.tag = tag + 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 + +def init(): + log = logging.getLogger("initial-setup") + log.setLevel(logging.DEBUG) + #syslogHandler = SyslogHandler('/dev/log', SysLogHandler.LOG_LOCAL1) + syslogHandler = InitialSetupSyslogHandler('/dev/log', SysLogHandler.LOG_LOCAL1, "initial-setup") + syslogHandler.setLevel(logging.DEBUG) + log.addHandler(syslogHandler) diff --git a/initial_setup/product.py b/initial_setup/product.py index 82f9b0f..0445293 100644 --- a/initial_setup/product.py +++ b/initial_setup/product.py @@ -1,7 +1,10 @@ """Module providing information about the installed product.""" +import logging
RELEASE_STRING_FILE = "/etc/os-release"
+log = logging.getLogger("initial-setup") + def product_title(): """ Get product title. @@ -20,7 +23,7 @@ def product_title(): if key == "PRETTY_NAME": return value.strip('"') except IOError: - pass + log.exception("failed to check the release string file")
return ""
On Thu, 2014-10-16 at 18:34 +0200, Martin Kolman wrote:
So I have been finally able to decipher the arcane incantations from the Anaconda logging module needed to enable syslog logging also in Initial Setup! :)
So, no more "Initial setup failed - good luck finding out why!", but detailed logging messages - if everything goes right: http://paste.fedoraproject.org/142509/77076141
And even if not :P : http://paste.fedoraproject.org/142507/13476904
All directly to the system log/Journal. :)
Martin Kolman (1): Add syslog logging support (#1145122)
initial_setup/__main__.py | 44 ++++++++++++++++++++++++++++++---- initial_setup/initial_setup_log.py | 48 ++++++++++++++++++++++++++++++++++++++ initial_setup/product.py | 5 +++- 3 files changed, 92 insertions(+), 5 deletions(-) create mode 100644 initial_setup/initial_setup_log.py
Forgot to note that this is for master & f21-branch. :)
On Thu, Oct 16, 2014 at 06:34:23PM +0200, Martin Kolman wrote:
So I have been finally able to decipher the arcane incantations from the Anaconda logging module needed to enable syslog logging also in Initial Setup! :)
So, no more "Initial setup failed - good luck finding out why!", but detailed logging messages - if everything goes right: http://paste.fedoraproject.org/142509/77076141
And even if not :P : http://paste.fedoraproject.org/142507/13476904
Are you sure it is ok to dump text into the log without prefixing it with the timestamp and source info?
The only other thing I've seen do this is sealert (I think) and it confuses the heck out of epylog when it happens. I've been meaning to track down whether it's a problem in epylog (handling extra lines w/o timestamp) or sealert/whatever.
anaconda-patches@lists.fedorahosted.org