LOG.debug not working in LDAP code

Bug #1274715 reported by Matt Fischer
14
This bug affects 2 people
Affects Status Importance Assigned to Milestone
OpenStack Identity (keystone)
Expired
Medium
Unassigned

Bug Description

When I was first setting up a connection to LDAP via keystone I fought through some configuration issues. One of the first issues is that I had user_name_attribute incorrect so that it could not validate my specified user on a a request like "keystone user-list". Unfortunately when the failure scenario here happens, you get no useful logging, even with Debug and Verbose enabled. The only message available is:

2014-01-30 21:41:45.461 9499 WARNING keystone.common.wsgi [-] Authorization failed. Could not find user, foo. from 10.33.0.17

and from the CLI:

root@test-03:~# keystone user-list
Could not find user, foo. (HTTP 401)

It's not even obvious from this that LDAP was used at all much less what the issue might be. I ended up adding my own logging and
once I dumped the query that get_by_name ends up calling the issue was obvious:

(&(cn=foo)(objectClass=inetUser))

Since in my case cn was incorrect.

I've been digging some to see if I can add logging here without logging every query call without too much success, although I've not had a ton of time. If someone has a suggestion I'd be happy to work on it.

Tags: ldap
Revision history for this message
Dolph Mathews (dolph) wrote :

We used to have this level of logging -- I'd suggest adding a `keystone.conf [ldap] verbose` option to control that specifically for those that need it.

Changed in keystone:
importance: Undecided → Wishlist
status: New → Triaged
Revision history for this message
Matt Fischer (mfisch) wrote :

I'm updating this bug with new info. Some (if not all) of the LOG.debug calls in common/core/ldap.py are non-functional even when debugging is enabled in the logs. I've had to go through and mark each as LOG.warn to get anything useful out. I'm not sure where the debug setting is getting lost here, but it is.

summary: - dearth of debug logs when LDAP user_name_attribute is incorrect
+ LOG.debug not working in LDAP code
Revision history for this message
Matt Fischer (mfisch) wrote :

And given that LOG.debug is non-functional, I'd think this is no longer Wishlist, can you change the severity?

Revision history for this message
Matt Fischer (mfisch) wrote :

I dug into this some in the LDAP module the logging level is unset (0) which I assume means that it defaults to INFO since INFO and above get shown. I still haven't figured out why it's unset.

Dolph Mathews (dolph)
Changed in keystone:
importance: Wishlist → Medium
tags: added: ldap
Revision history for this message
Alexander Makarov (amakarov) wrote :

Looks like loggers do not inherit log_level from parent loggers using default value instead.

Revision history for this message
Alexander Makarov (amakarov) wrote :

Python logger facility documentation contains:

Logger.setLevel(lvl)

    Sets the threshold for this logger to lvl. Logging messages which are less severe than lvl will be ignored. When a logger is created, the level is set to NOTSET (which causes all messages to be processed when the logger is the root logger, or delegation to the parent when the logger is a non-root logger). Note that the root logger is created with level WARNING.

    The term ‘delegation to the parent’ means that if a logger has a level of NOTSET, its chain of ancestor loggers is traversed until either an ancestor with a level other than NOTSET is found, or the root is reached.

    If an ancestor is found with a level other than NOTSET, then that ancestor’s level is treated as the effective level of the logger where the ancestor search began, and is used to determine how a logging event is handled.

    If the root is reached, and it has a level of NOTSET, then all messages will be processed. Otherwise, the root’s level will be used as the effective level.

Default loglevel value 'NOTSET' is a flag meaning implicit level inheritance. So if you want to get effective log level used, call LOG.logger.getEffectiveLevel().

Revision history for this message
Alexander Makarov (amakarov) wrote :

Is this bug still actual?
LOG.debug in common/ldap/core.py works for me
and path common/core/ldap.py does not exist.

Dolph Mathews (dolph)
Changed in keystone:
status: Triaged → Incomplete
Revision history for this message
Launchpad Janitor (janitor) wrote :

[Expired for Keystone because there has been no activity for 60 days.]

Changed in keystone:
status: Incomplete → Expired
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.