It's not possible to configure logging when other frameworks or scripts are using logging.
The logging module is shared by anything importing logging. The most common idom is to hang all loggers off of the anonymous unamed root logger belonging to the logging module.
A typical issue for modules which would like to perform logging is determining if they have to initialize the handlers, that should only be done once. Usually it's done like this:
if len(logging.getLogger().handlers) == 0: # perform configuration
This says if the root logger does not have any handlers then we assume no one before us has configured logging so we should configure it, otherwise we'll use the existing configuration performed elsewhere.
This is what we do in the api bootstrap in pluggable.py
log = logging.getLogger() object.__setattr__(self, 'log', log) # If logging has already been configured somewhere else (like in the # installer), don't add handlers or change levels: if len(log.handlers) > 0 or self.env.validate_api: return # Do IPA logging configuration based on IPA config file
But there is a problem with this. Suppose we're embedded in some other framework or script which uses logging then we'll never configure our logging if they've configured logging first. Also the two users of logging will cross pollute each others loggers.
This is exactly what occurs when we run the unit tests. The nose unit test framework uses logging, it's loaded and configured first. Then the unit test framework loads IPA. Thus IPA's logging inherits it's logging configuration from the unit test framework. A consequence of this is it's impossible to enable debug logging in IPA via the IPA configuration files while running the unit tests because IPA defers it's logging configuration to the first entity to configure logging, in this instance the unit test framework. The same issue would occur if we were loaded via any other module or script.
The solution is establish an IPA specific root logger avoiding the anonymous unamed root logger. This provides us with an IPA logging namespace where we won't collide with any other users of logging. Loggers form a hierarchy with each logger name being separated by a dot ('.'). This just means all our loggers need to be created in the IPA namespace (e.g. they all start with "ipa.").
That's simple, what's not simple is that we have 14 places where we configure logging, most of it is cut-n-paste duplicated code instead of one common utility to configure logging. Here's the places where we have logging configuration code:
ipalib/plugable.py ipapython/nsslib.py install/tools/ipa-csreplica-manage install/tools/ipa-nis-manage install/tools/ipa-managed-entries install/tools/ipa-replica-conncheck install/tools/ipa-ldap-updater ipaserver/install/installutils.py ipa-client/ipa-install/ipa-client-install install/tools/ipa-replica-manage ipaserver/install/installutils.py install/tools/ipa-replica-conncheck contrib/RHEL4/ipa-client-setup ipa-client/ipa-install/ipa-client-install
We should have just one common function that configures logging and call into that. The few remaining places which add loggers after logging is configured just need to always do so in the IPA namespace,
A patch to accomplish will follow shortly.
Moving the ticket to the next month iteration.
Linked to Bugzilla bug: https://bugzilla.redhat.com/show_bug.cgi?id=751968
documentation and code posted for review here:
http://jdennis.fedorapeople.org/log_manager_doc/
master:[[BR]] 730f122[[BR]] 56401c1
Reopening the ticket - Apache's /var/log/httpd/error_log log filters DEBUG level messages, i.e. IPA commands and their results are no longer logged.
/var/log/httpd/error_log
I just tested this and it works as expected. /var/log/httpd/error only get DEBUG messages if you've configured IPA to emit debug messages. The debug flag is in api.env, the most typical way to set it is via /etc/ipa/default.conf and set debug=True.
To the best of my knowledge this is the way it has always worked and the behaviour has been preserved. Did you have debug enabled in the config?
I checked this and I do not have the flag set. I checked its behavior and this is not what I had in mind. I see I confused both of us here. What I had in mind are messages like this:
[Tue Nov 29 02:43:53 2011] [error] ipa: INFO: *** PROCESS START *** [Tue Nov 29 02:44:21 2011] [error] ipa: INFO: admin@IDM.LAB.BOS.REDHAT.COM: dnsrecord_show(u'example.com', u'foo', rights=False, all=False, raw=False, version=u'2.15'): NotFound
Obviously, these are INFO level messages and not DEBUG as I wrote above. These should be printed to Apache's log all the time without any need to change the configuration.
fixed and submitted as:
[PATCH 55/55-1] Restore default log level in server to INFO
master: 167813f
Metadata Update from @jdennis: - Issue assigned to jdennis - Issue set to the milestone: FreeIPA 3.0 Core Effort - 2011/11
Login to comment on this ticket.