Logging to stream to /var/log/taskotron/taskotron.log is set by
default. If the file doesn't exist or taskotron doesn't have
permissions to write it logs to newly created tempfile.
Logging level and logfile name can be set in config.
--debug command line option is added.
Details
Details
I tried runtask with existing log file with and without permission to write,
also with non-existent log file. It behave as expected. I tried to change
debug_level configuration in config_defaults and --debug option. It
seems to work correctly too
Diff Detail
Diff Detail
- Repository
- rLTRN libtaskotron
- Lint
Lint Skipped - Unit
Unit Tests Skipped
There are a very large number of changes, so older changes are hidden. Show Older Changes
Comment Actions
Your patch has raised some question I haven't considered before. I haven't thought about adjusting logging levels in the config file, and I haven't thought about adding cmdline options. But since you voluntarily implemented it, we'll need to ensure that it works really well :-)
After consulting with @mkrizek and @jskladan, we think that there should be three different configuration options in taskotron.yaml:
- log_level_stream - setting the logging level for process output (stderr)
- log_level_file - setting the logging level for the log file
- log_file_enabled - whether logging to a file should be enabled
The defaults would be:
| Development | Production | |
|---|---|---|
| log_level_stream | INFO | WARNING |
| log_level_file | DEBUG | DEBUG |
| log_file_enabled | False | True |
With this scheme, it would make sense to adjust all log messages which indicate some waiting (rpms being downloaded, bodhi being queried, etc) to use INFO level.
Then there would be a --debug option that would override log_level_stream to DEBUG if provided.
A few more notes:
- I believe libtaskotron.spec needs to have /var/log/taskotron/ directory added.
- Unit tests will be needed for this.
| conf/taskotron.yaml.example | ||
|---|---|---|
| 86–87 | Hmm, maybe I would leave this name hardcoded, at least until someone needs it to be configurable. Less choice is sometimes better. Internally, this could be maybe renamed to simple log_name to match better all other proposed options (starting with log_). | |
| 89 | It's not clear whether this affects only the file log, the stderr output, or all. | |
| 90 | Is there a reason to offer just the two logging levels? We're using a standard logging library, its levels are quite well known, I'd offer here the full range of options. Let's link to https://docs.python.org/2.7/library/logging.html#logging-levels and let the user choose. | |
| 92 | How do they differ? You need to specify that. Look at line 19 or line 30 for examples how to provide that information. | |
| libtaskotron/config_defaults.py | ||
| 62 | Please include #: comment to make sure this appears in Sphinx documentation. | |
| 84 | Ditto. Also, for production config, I suggest to use 'WARNING'. | |
| libtaskotron/logger.py | ||
| 65 | I know why the import is after the log initialization. It's because we run from libtaskotron.logger import log in config.py. Otherwise we could have a cyclic dependency. And I don't like the fact that now depends on some specific import order to be able to run. The proper solution would be to get rid of log as a global attribute and create get_logger() function instead. Then, this function would get called from functions in other modules. However, that's really inconvenient. Together with @jskladan we agree that we're OK with leaving this as it is, but carefully documenting it. Please add an extensive comment explaining why this important can't be moved before log initialization. | |
| 173 | I haven't realized this before, but the fact that we need to use Config to set up logging means we need to initialize it first, and that means some messages are going to be produced before we set up the location where to forward them to. That means that messages like Config loading will never be saved to the log file. I think it's possible to work around this. We should be able to add some custom handler as the first thing when our program starts. That handler would be a temporary storage for "init/bootup" messages. Once we set up the log file properly, this temporary handler would forward all messages it captured into relevant targets (the log file, stdout if applicable, etc) and we would remove it completely. This might be a separate ticket/patch. | |
| 177 | mode has to be specified with bitwise OR [1], like this os.R_OK | os.W_OK. According to docs [2], you can't combine F_OK with that. I think that W_OK implies F_OK, and thus you could do just: if not os.access(log_path, os.W_OK): [ 1 ] https://docs.python.org/2/reference/expressions.html#binary-bitwise-operations | |
| 180 | Please use dir=config.get_config().tmpdir. Also, let's have prefix='taskotron-',suffix='.log'. | |
| 181–182 | Please avoid \ to break lines. As a bonus, you will be able to keep indentation. | |
| 184 | I think it would make sense to update Config.logpath and Config.main_log_name as well here. | |
| libtaskotron/runner.py | ||
| 171–172 | Something like this could make the description clearer:
| |
| 214–220 | Let's use log_level.upper() and then using getattr on logging. If it returns a number, everything's fine and we can use it, otherwise it was an invalid input string. | |
| 221 | This line a remnant of an old patch, should be removed in the final version. | |
Comment Actions
Overall, I don't have much to add that @kparal didn't already cover.
My only question is whether WARNING is best choice for stream logging in production? I wonder if having INFO messages inline with the task execution would be helpful.
| libtaskotron/logger.py | ||
|---|---|---|
| 184 | A small stylistic nit - please don't use Config for a variable name. Something like local_config, conf or configuration would be better since python convention is that Config would be a class name | |
| libtaskotron/runner.py | ||
| 171 | would --verbose and -v be closer to common convention? I feel as if that's a more common option to increase log verbosity for command line programs | |
Comment Actions
My only question is whether WARNING is best choice for stream logging in production? I wonder if having INFO messages inline with the task execution would be helpful.
Yeah, it might need a bit of tuning. And also our needs will change as we improve our buildbot+logging support. Currently I know about following important things to mention:
- There are no item-specific logs yet, we have just the single main log. Currently we print all the item-specific logs (as part of the TAP) into the main log a the end of execution. We're not yet ready to get rid of that printout yet.
- The stdout and stderr stream interleave really badly in buildbot. That is an issue of unsynchronised streams, which they are by nature. There are some better or worse solutions for this, but no silver bullet, AFAIK. At present, the more logging output we produce, the more it messes up the standard check output.
It also depends how we want to use the logging levels. I imagined that INFO could be used for anything that is useful for interactive (local, development) executions - like information about long-running tasks (e.g. package downloading, querying systems, etc). This information make it more pleasant to work on this check, but I'm not sure we want to display them in production profile by default - they are not useful when you're looking on an already finished task. But we can of course decide to use it for other purposes.
I don't care too much about what we set as default at the moment, as long as we can easily change it in the config file. INFO in production is fine by me now (as mentioned above, we still need to adjust a lot of related stuff).
| libtaskotron/logger.py | ||
|---|---|---|
| 184 | I meant it as a class name :-) A bit incorrectly perhaps, of course he should change the instance values. | |
| libtaskotron/runner.py | ||
| 171 | It definitely is, even though I frequently see --debug as well. But I think there a slight difference in meaning (I might be wrong):
My idea of how our logging system could work was closer to the --debug meaning - I wouldn't be afraid to dump a of lot structures and other large data into that stream, if we don't display it by default. But I'm totally open to other opinions, I don't insist on it. | |
Comment Actions
Features added:
- different logging levels for streaming and file logging, also
there is new option to turn on/off file logging
- --debug command line option now set logging level just for
streaming
- all logging levels can be used in config file
Comment Actions
I forgot to mention that I had to swap some imports because it caused problems due to cyclic dependencies. So there are some changes not related to patch itself.
Comment Actions
one minor nit but overall, looks pretty good to me. I want to test it a bit to see how the logs are routed but I don't see anything major that needs to be changed at the moment.
I think that @pschindl isn't quite done with this yet (something about adding tests, not quite sure about the details) so I'll hold off on accepting until I've tested it more and the tests are in place.
| libtaskotron/logger.py | ||
|---|---|---|
| 68 | this shouldn't be duplicated as a comment | |
Comment Actions
The change that needs to happen before this is pushed is to remove the duplicate comment on line 22 of logging.py that I mentioned before.
As far as tests go, the thing to test here is mostly the init:
- make sure that the correct logfiles are used in the case of /var/log/taskotron being accessible and not
- verify that valid and invalid log levels are handled properly
I don't see a whole lot else that makes a lot of sense to write tests for.
Comment Actions
Thanks, Peter. Most of my inline comments are just polishing requests. I still think we're going to run into cyclic dependency issues in some cases, but I'll explore that later, I think it's corner-casey enough.
Unit tests I'd like to see:
- verify that --debug on cmdline sets debug level on stream
- verify that log_file_enabled logs/doesn't log to the file
- verify that e.g. a debug message is not printed to stream/file when a higher level is selected (this might be already tested somewhere in our suite, I haven't looked)
- verify that invalid level configuration is reverted to default values
| conf/taskotron.yaml.example | ||
|---|---|---|
| 97 | This is False by default for development. Please add documentation. | |
| libtaskotron/config_defaults.py | ||
| 59 | Personally I'd simplify this to just log_name (it would match all other log_* variables), but it's not important. | |
| 84 | This is missing #:. | |
| libtaskotron/logger.py | ||
| 182–184 | When I see this in the check output, it's a bit hard to read - file paths in the middle of a long paragraph. Could you please change it to something like this? logger.warning("Log file can't be opened for writing: %s", log_path)
logger.warning("Using a temporary log file instead: %s", tmp_path) | |
| 188 | Should this be os.path.split(tmp_path)[-1] ? | |
| libtaskotron/runner.py | ||
| 211–249 | This is a long block of code and I think it would deserve a separate function. When I think about it... why not put it into libtaskotron.logger? That seems to be the most appropriate place. | |
| 224 | I'm not really happy that you're basically duplicating config defaults and hard-coding them in here (and on line 223). The best approach is to reset the default values from ProductionConfig/DevelopmentConfig/TestingConfig. However, that's hard to do at the moment, some config refactoring would be needed. If you don't want to do deal with it right now, please make a separate ticket for it. | |
| 225–226 | Please include the "unknown" level in the error message. | |
| 231–236 | This code is basically same as above. A simple function for this would be nice. | |
| 240 | If I read documentation correctly, NOTSET has the lowest value, therefore everything gets logger. It's the same as DEBUG in our case. Do we even need to bother with this? I'd execute the code on lines 218-225 in any case, regardless whether file logging is enabled or not. | |
| 248–249 | Wouldn't it be simpler to use log.warn() in those two places? I'm not sure why you keep them in a list. | |
| testing/conftest.py | ||
| 13–16 | Please put a note here that we need to keep this order because of cyclic dependencies. | |
| libtaskotron/runner.py | ||
|---|---|---|
| 224 | I was wrong, we can do this already: conf_defaults = config._load_defaults(conf.profile) conf_defaults.log_level_stream | |
Comment Actions
Updated to fulfil all requests in comments
Main changes in this update are:
- config is now imported after basic initiation of logger, so messages
from loading config aren't lost
- import of config is put into functions which use it so no problems with
cyclic dependencies appears
- there is new function for setting logging levels. It reads configured level
and if this value isn't valid it sets default loaded from config-defaults.
- if log file doesn't exist it is created (if we have writing rights)
- logger.init now doesn't return logger, it just changes rootlogger
Update now contains set of unit tests which should test basic funtionality.
Comment Actions
Since I helped Petr with this patch, I'm resigning as a reviewer.
| testing/functest_runner.py | ||
|---|---|---|
| 17–35 | I'm not exactly happy about how I implemented this test case, but I saw no better way. Of course we could take these two lines from runner.py: # full logging initialization level_stream = logging.DEBUG if args.debug else None logger.init(level_stream=level_stream) and move it into a separate function. Then simply test the function. But that was a bit... silly :) But I can adjust it as needed, if somebody has a strong opinion about this. | |
Comment Actions
Hey guys, just reminder, I'm leaving for vacation on Thursday and I won't be able to respond to your review and comments for the following almost 2 weeks.
I know this patch is not really simple. I and Peter ended up re-working it from scratch several times, as our logging framework understanding slowly increased and we discovered several obstacles on the road (for example, if you initialize your loggers on module import, py.test stream capture functionality doesn't work with it). You should probably ignore previous patches and compare the latest patch directly to the base commit. I'll be glad to explain the sections of code that you find difficult or confusing.
| libtaskotron/logger.py | ||
|---|---|---|
| 9 | why? | |
| 19–63 | Please change all these '''-type comment-doc _under_ the respective item to the #: style above the item. | |
| 92 | Although this works, please move the _log_excepthook method above the first usage. | |
| 182 | Document why the import is here and not at the beginning of the file - I guess it is because of the cyclic deps, but you know the Zen of Python, don't you ;) | |
Hmm, maybe I would leave this name hardcoded, at least until someone needs it to be configurable. Less choice is sometimes better.
Internally, this could be maybe renamed to simple log_name to match better all other proposed options (starting with log_).