Structured logging #1041

M4rtinK · 2017-04-25T14:14:09Z

This pull request adds support for structured logging to Anaconda and coverts all modules to use it. You can check the individual commit messages for how it works and and for examples.

Also as this PS is quite substantially changing how the logs look like (due to replacing the always present "anaconda" prefix with the structured logging prefixes), it is currently targeting master only.

M4rtinK · 2017-04-25T14:24:25Z

This is an example how the resulting log output looks like: https://paste.fedoraproject.org/paste/qQhmZY~BLOMzpl9BWgQCgF5M1UNdIGYhyRLivL9gydE=

jkonecny12 · 2017-04-26T08:43:26Z

jenkins, test this please

M4rtinK · 2017-04-26T10:52:45Z

jenkins, test this please

jkonecny12

Except that one idea for improvement it looks good to me. Good work!

jkonecny12 · 2017-04-26T13:31:30Z

pyanaconda/anaconda_log.py

+                record.log_prefix = "misc"
+            else:
+                # drop "anaconda." from the log prefix
+                record.log_prefix = re.sub(REMOVE_ANACONDA_PREFIX_RE, "", record.name)


I would recommend you to change re. solution to startswith. It is better for performance which is good for logging.
I would go for something like:

if record.name.startswith("anaconda."): record.log_prefix = record.name[9:]

That's a good idea - and even though using a constant like this is slightly terrifying, this part of the code is indeed potentially quite performance sensitive & we are not likely to change the number any time soon. :)

jaymzh · 2017-04-27T04:51:01Z

😀

CC @dcavalca125

poncovka

Looks good to me, just some suggestions :-)

poncovka · 2017-04-27T09:25:30Z

pyanaconda/anaconda_log.py

@@ -130,6 +137,25 @@ class AnacondaFileHandler(_AnacondaLogFixer, logging.FileHandler):
 class AnacondaStreamHandler(_AnacondaLogFixer, logging.StreamHandler):
    pass

+class AanacondaPrefixFilter(logging.Filter):


A typo Aa... :-)

Fixed, thanks! :)

poncovka · 2017-04-27T10:22:14Z

pyanaconda/kickstart.py

 stderrLog = logging.getLogger("anaconda.stderr")
 storage_log = logging.getLogger("blivet")
 stdoutLog = logging.getLogger("anaconda.stdout")
 from pyanaconda import anaconda_log

+# command specififc loggers
+authconfig_log = logging.getLogger("anaconda.kickstart.authconfig")


Is it really necessary to create a new logger for every kickstart command? Isn't there a way, how to add these prefixes, when we log the messages? We could use log.debug("Message about a command xyz", extra={"prefix": "xyz"}) or modify the logger to be able to do something like: log.debug_with_prefix("xyz", "Message about a command xyz")

Example with extra arguments is here: https://docs.python.org/3/library/logging.html#logging.debug

Or create the prefix automatically. Something like use class.__name__ or similar.
Or implement create new "base class" with log_prefix variable which will be inherited by these kickstart classes and they just fill the log_prefix variable, everything else will be done inside of the "base class".

That sounds good - and it indeed looks like our kickstart command subclasses look like a good use case for the class instance log (eq. just call self.log.info() and the appropriate prefix will be added automatically based on the class). But as we subclass the kickstart commands in this case, it will probably have to a mixin that adds the logging functionality to the given kickstart command class.

BTW, a potential show-stopper - looks like the instantiated kickstart command classes for some reason get serialized when a storage snapshot is being created and I've seen it die when it tried to serialize a logger instance (eq. self.log = getLogger("kickstart.timezone") was enough to make it crash during serialization). It might not be an issue if self.log is is a proper property, or the serialization could be fixed to skip the kickstart command instances, but it's certainly something to watch for.

For that reason I would like to be careful and merge this method first (statically defined loggers on top of file) before investigating using the class instance loggers as there is less chance of immediate breakage like this.

I like the statically defined loggers on top of a file per module, but I don't like the loggers for kickstart commands, because I think we should treat them the same way as the class loggers (in the future). Then the self.log might be a way to go. Good point about the serialization ;-)

poncovka · 2017-04-27T10:24:39Z

pyanaconda/addons.py

@@ -27,7 +27,7 @@
 from pyanaconda.progress import progress_message
 from pyanaconda.i18n import N_

-log = logging.getLogger("anaconda")
+log = logging.getLogger("anaconda.addons")


Have you experimented with %(module)s?
https://docs.python.org/3/library/logging.html#logrecord-attributes

I thought about just basing the prefix on folder structure (which I think is basically what the module property contains), but then decided against that, for a couple reasons:

the prefix would change if we move the file around, making it less stable

manually specifying the prefix is simple (a single line per module) and provides greater flexibility

related modules can be grouped together with a single prefix without needlessly exposing filesystem details (eq. all non spoke & hub modules can just live in the ui.gui.* namespace while spokes log to ui.gui.spoke.* and hubs log to ui.gui.hub.*)

as the prefix is not based on folder structure a more meaningful & better readable prefix can be used

ui.gui.spoke.network instead of ui.gui.spokes.network - the log messages come from the network spoke, not one of the network spokes

ui.gui.spoke.custom_storage_config instead of ui.gui.spokes.custom - even though anaconda developers, contributors and the QA community probably know that "custom spoke" is actually the "custom storage configuration spoke", not everyone might know that, especially when reading a log message prefix

it should be pretty easy to track message origin by grepping for the prefix in the Anaconda source code (the module based approach would have a similar benefit though)

there might actually be more than one logger in a file, if the functionality contained in it is disparate enough (as for example in the kickstart module)

In short - I want the log prefix to understandably describe what is being logged and to be reasonably stable over time.

I have done some research as well and I agree.

poncovka · 2017-04-27T10:30:01Z

pyanaconda/anaconda_log.py

@@ -32,6 +32,10 @@
 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"


Couldn't we have a boot option inst.debug, that would enable more detailed structured messages?
It looks like there are a lot of attributes we could log:
https://docs.python.org/3/library/logging.html#logrecord-attributes

Yeah, there is a lot of stuff to log - and especially stuff like path to file where the log message originated from or the line number could certainly be useful for debugging. But at the same time I'm not sure how readable the log file would be in such a case.

So I'm thinking about two things that could be done:

we can do a detailed/verbose (anaconda-verbose.log, etc.) log that is created if inst.debug=1 is used, which h could contain path to file, function name and line number

like this we still have a readable anaconda.log for general debugging and the new detailed log for detailed debugging

if we switched from using the SyslongHandler to actual Journal handler for forwarding of Anaconda log messages to journal, all the extra data fields should end up in Journal as well

we might need to change our log grabbing procedures to either grab the full journal or some expert that has the extra fields

we might also want to investigate how journalctl can present the extra fields in it's output, as just displaying all of them at once would make the log mostly unreadable

I guess that the extra data fields can be useful for kickstart tests and other forms of testing

I think that we should at least investigate the second option, but we can do that in a different issue :-)

poncovka · 2017-04-27T10:32:18Z

pyanaconda/anaconda_log.py

+            # 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."):


I have looked at the logs and I miss the anaconda prefix a little :-) But I can get used to it.

jkonecny12

Still looks good to me ;)

poncovka

It looks great to me. I like the new names of modules. Just some questions :-)

poncovka · 2017-05-30T09:18:42Z

pyanaconda/anaconda.py

 stdoutLog = logging.getLogger("anaconda.stdout")

+from pyanaconda.ilog import get_logger


Why is the submodule called ilog? I know we had problems with name collisions between anaconda submodules and python modules, but that should be fixed now. Same for ihelp, iutil and isignal. Is there another reason for these names?

It's all due to naming collisions as far as I can tell (the i likely means Installer):

ilog - we mostly call the logger we use "log", so a module name should not collide with it

ihelp - there is built-in Python function called "help" and we should not shadow that

isys - there is the standard library "sys" module and isys was probably originally meant as an installer specific extension of the sys module

iutil - could be that there used to be a util module somewhere in the path so iutil was used to avoid naming collisions

isignal - there is a module called signal in the Python standard library

So it's basically a sort of a custom - add in in front of stuff that would shadow existing modules and built-in functions. But that does not necessarily mean it's correct and could not be improved (using a different name that does not collide, using installer_ prefix instead of just i, etc.).

Still I think that should probably be (with the possible exception of the ilog module) a separate pull request as we already change quite a bit in this one.

Ok, thanks for the explanation!

poncovka · 2017-05-30T09:28:15Z

pyanaconda/network.py

@@ -34,6 +34,7 @@
 from uuid import uuid4
 import itertools
 import glob
+import logging


This is needed in the function setup_ifcfg_log. Is the function fine as it is?

It should be - it sets-up its own separate logger & log file for ficfg related logging, so I don't really see a need to change it.

poncovka · 2017-05-30T09:33:54Z

pyanaconda/startup_utils.py

@@ -20,9 +20,11 @@
 from pyanaconda.i18n import _

 import logging
-log = logging.getLogger("anaconda")
 stdout_log = logging.getLogger("anaconda.stdout")


Isn't it a little confusing that we combine logging with anaconda.ilog?

poncovka · 2017-05-30T09:45:06Z

pyanaconda/ilog.py

+
+import logging
+
+def get_logger(module_name):


I guess that this could be done also in the __init__ method of the custom Logger class, that could be set as default with logging.setLoggerClass. Then we could get loggers as:

import logging log = logging.getLogger(__name__)

Have you considered that?

poncovka · 2017-05-30T09:50:13Z

pyanaconda/storage_utils.py

@@ -47,7 +47,9 @@
 from pykickstart.constants import AUTOPART_TYPE_LVM, AUTOPART_TYPE_LVM_THINP

 import logging


It would be nice to have all the logging logic in one file, so we wouldn't need to import the logging anymore.

Should be done now - the anaconda_loggers module now has getters for the module loggers and for all the specialized loggers.

jkonecny12

The anaconda_logging and anaconda_loggers modules should be changed.

jkonecny12 · 2017-05-31T13:38:36Z

anaconda.py

-    from pyanaconda import anaconda_log
-    anaconda_log.init()
-    anaconda_log.logger.setupVirtio()
+    from pyanaconda import anaconda_logging


Why the anaconda_logging doesn't provide us loggers?

I have a bad feeling for typos in anaconda_logging and anaconda_loggers.

Check the header of the anaconda_loggers module[0] - it's to avoid circular imports. The anaconda_logging module imports the flags module and the flags module also does logging, so it would have to import the get_module_logger() function from the anaconda_logging module, creating an import circle.

It's likely there could be other such circles, especially once we account for all the specialized loggers the anaconda_loggers module now provides getters for.

[0] https://github.com/rhinstaller/anaconda/pull/1041/files#diff-5c8919b8315eecb9a03a32af4f2bc02eR20

I was curious what we log in flags.py and maybe the function can_touch_runtime_system could be moved somewhere else?

I think this is a good idea.

That sounds promising - but that's just the firs module where the import cycle blew up. So I'm not sure there are not other places - or how easy it is to create a new cycle by incident.

Still certainly worth investigating in the future though.

poncovka

I have no more comments. This solution looks very nice. Thank you!

M4rtinK · 2017-05-31T15:59:39Z

PR for Blivet to account for the anaconda_log module name change:
storaged-project/blivet#598

rvykydal · 2017-06-01T07:58:03Z