Duplicated eventlet.wsgi.server log entries

[Dolph Mathews]

Every entry in the keystone logs, at least those produced by ./run_tests.sh, are duplicated three times each:

I don't see any reason why this is occurring. The logger is also inappropriately promoting INFO events to WARNING's.

Sample log (line breaks added for emphasis):

2011-09-08 11:00:35 WARNING [eventlet.wsgi.server] 127.0.0.1 - - [08/Sep/2011 11:00:35] "POST /v2.0/tokens HTTP/1.1" 200 16552 0.037845
2011-09-08 11:00:35 WARNING [eventlet.wsgi.server] 127.0.0.1 - - [08/Sep/2011 11:00:35] "POST /v2.0/tokens HTTP/1.1" 200 16552 0.037845
2011-09-08 11:00:35 WARNING [eventlet.wsgi.server] 127.0.0.1 - - [08/Sep/2011 11:00:35] "POST /v2.0/tokens HTTP/1.1" 200 16552 0.037845

2011-09-08 11:00:36 WARNING [eventlet.wsgi.server] 127.0.0.1 - - [08/Sep/2011 11:00:36] "GET /v2.0/users?username=admin HTTP/1.1" 200 2096 0.919888
2011-09-08 11:00:36 WARNING [eventlet.wsgi.server] 127.0.0.1 - - [08/Sep/2011 11:00:36] "GET /v2.0/users?username=admin HTTP/1.1" 200 2096 0.919888
2011-09-08 11:00:36 WARNING [eventlet.wsgi.server] 127.0.0.1 - - [08/Sep/2011 11:00:36] "GET /v2.0/users?username=admin HTTP/1.1" 200 2096 0.919888

2011-09-08 11:00:36 WARNING [eventlet.wsgi.server] 127.0.0.1 - - [08/Sep/2011 11:00:36] "POST /v2.0/tenants HTTP/1.1" 201 307 0.027509
2011-09-08 11:00:36 WARNING [eventlet.wsgi.server] 127.0.0.1 - - [08/Sep/2011 11:00:36] "POST /v2.0/tenants HTTP/1.1" 201 307 0.027509
2011-09-08 11:00:36 WARNING [eventlet.wsgi.server] 127.0.0.1 - - [08/Sep/2011 11:00:36] "POST /v2.0/tenants HTTP/1.1" 201 307 0.027509

2011-09-08 11:00:36 WARNING [eventlet.wsgi.server] 127.0.0.1 - - [08/Sep/2011 11:00:36] "POST /v2.0/users HTTP/1.1" 201 417 0.041388
2011-09-08 11:00:36 WARNING [eventlet.wsgi.server] 127.0.0.1 - - [08/Sep/2011 11:00:36] "POST /v2.0/users HTTP/1.1" 201 417 0.041388
2011-09-08 11:00:36 WARNING [eventlet.wsgi.server] 127.0.0.1 - - [08/Sep/2011 11:00:36] "POST /v2.0/users HTTP/1.1" 201 417 0.041388

2011-09-08 11:00:36 WARNING [eventlet.wsgi.server] 127.0.0.1 - - [08/Sep/2011 11:00:36] "POST /v2.0/roles HTTP/1.1" 201 240 0.029248
2011-09-08 11:00:36 WARNING [eventlet.wsgi.server] 127.0.0.1 - - [08/Sep/2011 11:00:36] "POST /v2.0/roles HTTP/1.1" 201 240 0.029248
2011-09-08 11:00:36 WARNING [eventlet.wsgi.server] 127.0.0.1 - - [08/Sep/2011 11:00:36] "POST /v2.0/roles HTTP/1.1" 201 240 0.029248

[Paul Voccio (pvo)]

It seems the load_paste_app method is being called twice from bin/keystone. This causes two log handlers to open the same file, keystone.log, and write the same information to the file.

    # Start services
    try:
        # Load Service API server
        conf, app = config.load_paste_app(
            'keystone-legacy-auth', options, args)
        admin_conf, admin_app = config.load_paste_app(
            'admin', options, args)

if I add the options['log_file'] line below, logging returns to "normal" though the log files are exactly the same.

In keystone/common/config.py: 321
    try:
        # Setup logging early, supplying both the CLI options and the
        # configuration mapping from the config file
        options['log_file'] = "%s.log" % app_name
        setup_logging(options, conf)

[Openstack Gerrit (openstack-gerrit)]

Reviewed: https://review.openstack.org/922
Committed: http://github.com/openstack/keystone/commit/ec72417b9fb625f0d0323ddf738d2aa3fc87a7cd
Submitter: Jenkins
Branch: master

 status fixcommitted
 done

commit ec72417b9fb625f0d0323ddf738d2aa3fc87a7cd
Author: Paul Voccio <email address hidden>
Date: Tue Oct 18 11:55:45 2011 -0500

    Fixes LP844959, typo in Authors file

    Change-Id: I72f84c8277fb3f59a39e6a679f13460f778f1b06

[Paul Voccio (pvo)]

Hmm. In thinking about this after, I realize that it now completely ignores the log_file directive in the conf file. Need to either document that and remove the reference in the conf template or revert this patch.

log_dir directive still works and will place both files in the correct directory. These should automatically work with any new paste apps that are launched with the piplines (I think).

I wasn't sure if this was the right approach for this double logging problem, but it made sense to me.

[Openstack Gerrit (openstack-gerrit)]

Reviewed: https://review.openstack.org/1339
Committed: http://github.com/openstack/keystone/commit/2407248cb8a07fe2d85fddec1011419116e3322d
Submitter: Jenkins
Branch: stable/diablo

 status fixcommitted
 done

commit 2407248cb8a07fe2d85fddec1011419116e3322d
Author: Paul Voccio <email address hidden>
Date: Tue Oct 18 11:55:45 2011 -0500

    Fixes LP844959, typo in Authors file

    Change-Id: I72f84c8277fb3f59a39e6a679f13460f778f1b06

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/2621
Committed: http://github.com/openstack/keystone/commit/6babef79065882d9076a4940fb697bb5cb5e3aea
Submitter: Jenkins
Branch: master

commit 6babef79065882d9076a4940fb697bb5cb5e3aea
Author: Ziad Sawalha <email address hidden>
Date: Mon Dec 26 16:27:02 2011 -0600

    Fix duplicate logging

    - when running bin/keystone, duplicate FileHandlers
      were intialized. A check now prevents this.
    - Fixes bug 844959
    - Addresses some of blueprint keystone-logging

    Change-Id: Ic017423091c35f37721dbda7af0fa253541647c6