#2022 Logging configuration problems
Closed: Fixed None Opened 12 years ago by jdennis.

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.

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.

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

Metadata Update from @jdennis:
- Issue assigned to jdennis
- Issue set to the milestone: FreeIPA 3.0 Core Effort - 2011/11

7 years ago

Login to comment on this ticket.

Metadata