keystone is ignoring debug=True

[Zoltan Arnold Nagy]

even after setting debug = True and verbose = True in keystone.conf, default_log_levels["keystone"] stays on INFO, preventing (for example) the identity drivers from producing any debug output, thus making it impossible to track problems with them.

[Zoltan Arnold Nagy (zoltan)]

adding "default_log_levels = keystone=DEBUG" to keystone.conf fixes the issue, as a workaround.

[David Stanek (dstanek)]

Is the expected behavior that we want to set the keystone loglevel to debug when CONF.debug is True? I couldn't find any documentation saying what should happen. There are a few different ways that we can handle this:

1. wontfix and recommend that the logging.conf be used to control this
2. we can add a small bit of code to override the loglevel http://paste.openstack.org/show/54329/

[Dolph Mathews (dolph)]

Existing expectations across openstack rule option #1 out. Option #2 looks acceptable to me, but I'm not clear on how that differs from the previous line calling CONF.log_opt_values(...) ?

[David Stanek (dstanek)]

@Zoltan, Are you using the `log_config_append` option in your keystone.conf?

Details on a possible failure:

From what I can tell if a keystone.conf specifies the `log_config_append` the loglevel on the root logger will not be set to debug. This is because the setup[1] function doesn't call `_setup_logging_from_conf` and this is where that loglevel rigging happens[2]. Maybe that code should be moved into setup so that it happens in all cases?

1. http://git.openstack.org/cgit/openstack/oslo-incubator/tree/openstack/common/log.py?id=5c2ad3103ca9dd40ed2394abb1cf7cc7b9230cd5#n423
2. http://git.openstack.org/cgit/openstack/oslo-incubator/tree/openstack/common/log.py?id=5c2ad3103ca9dd40ed2394abb1cf7cc7b9230cd5#n505

[Brant Knudson (blk-u)]

Take look at https://github.com/openstack/oslo-incubator/blob/master/openstack/common/log.py#L511

If CONF.debug it sets the root logger to DEBUG... then at line 511-515 it overrides the levels for all the loggers? That seems wrong. Shouldn't it skip 511-515 if CONF.debug so you don't lose the debug on the keystone logger?

[Brant Knudson (blk-u)]

keystone=INFO is listed in the defaut_log_levels. It's always been there.

https://github.com/openstack/oslo-incubator/blob/16916b6129f075e54c1ead915d5131f6d34218ed/openstack/common/log.py

Maybe it had something to do with the auth_token middleware, but that's been moved to keystoneclient and logging is different there.

I thought that it might be put in there during a sync from oslo-incubator into keystone but it's hardcoded.

I'll submit a patch to remove it and then we'll have to get it to keystone.

[Brant Knudson (blk-u)]

Alternatively, I think keystone could override the default_log_levels by calling set_defaults. We may want to do that anyways because then we could filter out debug message from libraries (such as dogpile!)

[Brant Knudson (blk-u)]

Turns out oslo-incubator's set_defaults only allows you to set the logging_context_format_string , so we can't use it to override the default_log_levels .

[Ben Nemec (bnemec)]

Feel free to add dogpile to the default_log_levels if it's logging a bunch of stuff we don't care about. That's how we've handled stuff like iso8601 logging inane debug messages.

It definitely seems like keystone should be removed from that list too.

[Brant Knudson (blk-u)]

bnemec - I think for iso8601 it makes sense to have that in oslo's default_log_levels because every project uses it, but I'm pretty sure keystone is the only user of dogpile. Would you still want it in oslo if it's only used by 1 project?

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.openstack.org/62068

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/62048
Committed: https://git.openstack.org/cgit/openstack/oslo-incubator/commit/?id=fe18bfa4c19d6a18cf922a40af37b327b68e3aed
Submitter: Jenkins
Branch: master

commit fe18bfa4c19d6a18cf922a40af37b327b68e3aed
Author: Brant Knudson <email address hidden>
Date: Fri Dec 13 11:17:25 2013 -0600

    Remove keystone from default_log_levels default

    "keystone=INFO" was in the default_log_levels. This made it
    more difficult than necessary to debug the Keystone server,
    since you can set debug=True but then the keystone logging
    level is overridden and you get no debug output for keystone.

    "keystone=INFO" may have been in the default_log_levels because
    of the auth_token middleware, but this has been moved to
    python-keystoneclient now and the logging config for the
    python APIs is done differently.

    Closes-Bug: 1245629

    Change-Id: Ifc4187188f2be2fc876893e9b75e062f0dfcce97

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/63006

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/63006
Committed: https://git.openstack.org/cgit/openstack/keystone/commit/?id=509f0f6f2e0aaf66643b8d8f337d6ae64a5c071e
Submitter: Jenkins
Branch: master

commit 509f0f6f2e0aaf66643b8d8f337d6ae64a5c071e
Author: Brant Knudson <email address hidden>
Date: Wed Dec 18 16:39:52 2013 -0600

    Sync several modules from oslo-incubator

    This change syncronizes excutils,lockutils,log, and
    db.sqlalchemy.session modules from oslo-incubator
    commit 19e0a51204df247dc38de880d08e6d66e89e6572 .

     $ python update.py --nodeps --base keystone --dest-dir ../keystone \
         --modules excutils,lockutils,log,db.sqlalchemy.session

    This includes fixes for 2 problems:

    "keystone=INFO" was in the default_log_levels. This made it
    more difficult than necessary to debug the Keystone server,
    since you can set debug=True but then the keystone logging
    level is overridden and you get no debug output for keystone.

    "keystone=INFO" may have been in the default_log_levels because
    of the auth_token middleware, but this has been moved to
    python-keystoneclient now and the logging config for the
    python APIs is done differently.

    Closes-Bug: 1245629

    Also, fixes some warnings and errors when docs are generated.

    Change-Id: I53868bef975f73b4aee35695b6387b718c4179f9

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/62068
Committed: https://git.openstack.org/cgit/openstack/keystone/commit/?id=27f9221722071eb047ff7691a01eceb37fd3c108
Submitter: Jenkins
Branch: master

commit 27f9221722071eb047ff7691a01eceb37fd3c108
Author: Brant Knudson <email address hidden>
Date: Fri Dec 13 13:43:21 2013 -0600

    Update the default_log_levels defaults

    The default for default_log_levels didn't set the log levels
    for some packages that Keystone uses (for example, dogpile). This
    caused the server to output a lot of extra logs when debug=True
    is used.

    You can get the debug output for dogpile and routes by setting
    default_log_levels explicitly in your keystone.conf file.

    Change-Id: Ib797fa7b98f0e501047b72b094d07ad204385cc6
    Related-bug: #1245629
    Closes-Bug: #1269987