If I run
$ py.test -F testing/ -s
this is the beginning of the output:
testing/functest_config.py [libtaskotron:config.py:150] 2014-04-11 09:48:14 DEBUG Trying to open configuration file: /tmp/pytest-37/test_devel_profile_empty_confi0/test_conf.yaml [libtaskotron:config.py:160] 2014-04-11 09:48:14 DEBUG Trying to parse configuration file: /tmp/pytest-37/test_devel_profile_empty_confi0/test_conf.yaml [libtaskotron:config.py:61] 2014-04-11 09:48:14 DEBUG Using config profile: development .[libtaskotron:config.py:150] 2014-04-11 09:48:14 DEBUG Trying to open configuration file: /tmp/pytest-37/test_profile_override_in_conf0/test_conf.yaml [libtaskotron:config.py:160] 2014-04-11 09:48:14 DEBUG Trying to parse configuration file: /tmp/pytest-37/test_profile_override_in_conf0/test_conf.yaml [libtaskotron:config.py:61] 2014-04-11 09:48:14 DEBUG Using config profile: production
One debug line per line, everything is correct. But in the end, there's this:
[libtaskotron:config.py:61] 2014-04-11 09:48:14 DEBUG Using config profile: development DEBUG:libtaskotron:Using config profile: development . testing/test_koji_directive.py [libtaskotron:koji_directive.py:56] 2014-04-11 09:48:14 INFO getting koji builds for foo-1.2-3.fc99 (['noarch']) and downloading to /var/tmp/foo INFO:libtaskotron:getting koji builds for foo-1.2-3.fc99 (['noarch']) and downloading to /var/tmp/foo .[libtaskotron:koji_directive.py:71] 2014-04-11 09:48:14 INFO getting koji builds for tag tagfoo and downloading to /var/tmp/foo INFO:libtaskotron:getting koji builds for tag tagfoo and downloading to /var/tmp/foo . testing/test_koji_utils.py [libtaskotron:koji_utils.py:28] 2014-04-11 09:48:14 INFO Querying Koji for a list of RPMS for: foo-1.2-3.fc99 INFO:libtaskotron:Querying Koji for a list of RPMS for: foo-1.2-3.fc99 .[libtaskotron:koji_utils.py:28] 2014-04-11 09:48:14 INFO Querying Koji for a list of RPMS for: foo-1.2-3.fc99 INFO:libtaskotron:Querying Koji for a list of RPMS for: foo-1.2-3.fc99 .[libtaskotron:koji_utils.py:28] 2014-04-11 09:48:14 INFO Querying Koji for a list of RPMS for: foo-1.2-3.fc99 INFO:libtaskotron:Querying Koji for a list of RPMS for: foo-1.2-3.fc99
All those lines are duplicated, displaying twice.
I have narrowed down the problem to test_check.py, once it is executed, all other tests running after it have duplicated lines. Here's how it looks like:
test_check.py
$ py.test -F testing/test_check.py -s [libtaskotron:logger.py:63] 2014-04-11 09:52:28 DEBUG doing stream logging ================================================================================== test session starts ================================================================================== platform linux2 -- Python 2.7.5 -- py-1.4.20 -- pytest-2.5.2 plugins: cov collected 25 items testing/test_check.py ...............[libtaskotron:check.py:306] 2014-04-11 09:52:28 WARNING Reserved key 'summary' found in keyvals. Ignoring for export purposes. WARNING:libtaskotron:Reserved key 'summary' found in keyvals. Ignoring for export purposes. [libtaskotron:check.py:306] 2014-04-11 09:52:28 WARNING Reserved key 'item' found in keyvals. Ignoring for export purposes. WARNING:libtaskotron:Reserved key 'item' found in keyvals. Ignoring for export purposes. [libtaskotron:check.py:306] 2014-04-11 09:52:28 WARNING Reserved key 'details' found in keyvals. Ignoring for export purposes. WARNING:libtaskotron:Reserved key 'details' found in keyvals. Ignoring for export purposes. [libtaskotron:check.py:306] 2014-04-11 09:52:28 WARNING Reserved key 'outcome' found in keyvals. Ignoring for export purposes. WARNING:libtaskotron:Reserved key 'outcome' found in keyvals. Ignoring for export purposes. [libtaskotron:check.py:306] 2014-04-11 09:52:28 WARNING Reserved key 'type' found in keyvals. Ignoring for export purposes. WARNING:libtaskotron:Reserved key 'type' found in keyvals. Ignoring for export purposes. .......... =============================================================================== 25 passed in 0.08 seconds ===============================================================================
I have further narrowed the problem down to class TestExportTAP and class TestImportTAP. If you call tap = check.export_TAP(self.cd) or cds = check.import_TAP(self.tap), it triggers the issue. In check.py, the lines causing the problem are tap = TAP13() and tapgen = tap.TAPGenerator().
class TestExportTAP
class TestImportTAP
tap = check.export_TAP(self.cd)
cds = check.import_TAP(self.tap)
check.py
tap = TAP13()
tapgen = tap.TAPGenerator()
I didn't have time to further narrow it down. It's somehow connected with our TAP libraries, maybe some of their dependencies (yamlish?).
Investigate the issue and find out the reason why these calls cause double occurrence of debug lines in our test output (maybe even regular check output, needs to be tested).
This ticket had assigned some Differential requests: D106
I can confirm that this is happening in the regular output. While it isn't a horrible thing, it does make the logs far more verbose than they need to be.
OK, so this is caused by both yamlish and bayeux. I know next to nothing about the logging interactions, but both yamlish and bayeux use code like this: import logging <snip> logging.debug("data:\n%s", data)
yamlish
bayeux
If the code is commented out, or changed to using a custom logger (as a library should be doing anyway), the line duplication stops. I know that "not using logging directly in the libraries" is probably just a workaround, but at least until we find out the core reason (once again, it might be obvious, but I'm not skilled with the python logging's interactions), it should be an easy way to "solve" this bug.
OK, so brief investigation is over and, I think I'm on the right track. The thing is, that we (as a library) quite rightfully do not set a RootLooger's behaviour, so all the time we (libtaskotron) run, the logging.root.handlers is empty.
logging.root.handlers
Once the bayeux/yamlish use logging.debug directly, the logging.root.handlers is set to a basic handler.
logging.debug
Because (as it seems to be, and as it makes quite a lot of sense), all the "non-root" loggers pass the logged messages "up" (I do not know whether hierarchically, or directly to the root logger), the "visible" logging messages are doubled, since we once print them through own our logger's handler, and then these get printed via the (now set) root logger's handler.
The ultimate question now is - what is the best way to deal with this? I need to check the guidelines for logging, but at the moment, the most straightforward step would be for us to find a way to stop our logs from "going up", and set it this way for "DEVELOP" runs. This would stop the mal-written libraries from causing the issues like this in the future, and it seems much cleaner than simply moving all the root logger's output to /dev/null.
Thoughts?
(also reassigning to Honza, as he shown interest in the task)
Outcome of a face-to-face discussion is that we need to cover 2 situations - running through runner.py - importing libtaskotron
runner.py
When we just import libtaskotron, no logging configuration is done by default - i.e. all the logs are just passed up to the root logger, and the importing party needs to decide what to do with logs by setting whatever it wants.
When we run using runner.py we set our logger to print stuff on the screen, and so when someone (a library, as in this example) sets a handler for root logger to also print stuff on screen, we get duplicate logs.
Based on It would make sense to use Logger.propagate = False for our logging, when we run using runner.py, and leave it be otherwise.
Logger.propagate = False
Honza will investigate the actual behaviour in different situation in the mean time.
Yes, it seems that it works. When you run task through runner.py, every log is shown only once. If you import libtaskotron as a library, it shows output, but you have to configure root logger (e. g. by running basicConfig()), which is expected behaviour.
libtaskotron
This has been fixed in D106.
Login to comment on this ticket.