novaclient logs are logged as keystoneauth.session

[Radomir Dopieralski]

This is possibly as old as Train, but I only just noticed this when I tried to debug something.

All logs that should be logged as novaclient, instead get logged as keystoneauth.session — this means we can't easily configure the log level for novaclient, and makes it hard to search the logs.

[Radomir Dopieralski (deshipu)]

DEBUG keystoneauth.session REQ: curl -g -i -X GET http://192.168.110.137:8774/v2.1 -H "Accept: application/json" -H "User-Agent: python-novaclient" -H "X-Auth-Token: [redacted]"
DEBUG keystoneauth.session RESP: [200] Content-Encoding: gzip Content-Type: application/json Date: Thu, 25 Mar 2021 12:54:35 GMT OpenStack-API-Version: compute 2.1 Server: Apache Transfer-Encoding: chunked Vary: OpenStack-API-Version,X-OpenStack-Nova-API-Version,Accept-Encoding X-OpenStack-Nova-API-Version: 2.1 x-compute-request-id: req-58ebaa15-ee8d-4b3a-b5ce-7676b96f8d52 x-openstack-request-id: req-58ebaa15-ee8d-4b3a-b5ce-7676b96f8d52
DEBUG keystoneauth.session RESP BODY: {"version": {"id": "v2.1", "status": "CURRENT", "version": "2.87", "min_version": "2.1", "updated": "2013-07-23T11:33:21Z", "links": [{"rel": "self", "href": "http://192.168.110.137:8774/v2.1/"}, {"rel": "describedby", "type": "text/html", "href": "http://docs.openstack.org/"}], "media-types": [{"base": "application/json", "type": "application/vnd.openstack.compute+json;version=2.1"}]}}
DEBUG keystoneauth.session GET call to compute for http://192.168.110.137:8774/v2.1 used request id req-58ebaa15-ee8d-4b3a-b5ce-7676b96f8d52

[melanie witt (melwitt)]

The log messages you show are actually logged by the keystoneauth.session module:

https://docs.openstack.org/keystoneauth/latest/using-sessions.html#logging

and they don't come from novaclient itself. As far as I can tell, it was in Ocata when novaclient began using the keystoneauth.session to handle all authentication outside of novaclient:

https://github.com/openstack/python-novaclient/commit/8409e006c5f362922baae9470f14c12e0443dd70

[Radomir Dopieralski (deshipu)]

It doesn't matter which module logs it, it matters which logger is used. I found that novaclient creates a default logger as it should, but then doesn't use it, so instead a default logger created by keystoneauth is used. I submitted a fix here: https://review.opendev.org/c/openstack/python-novaclient/+/783010

[melanie witt (melwitt)]

Apologies, I mixed up the calls to the /identity API with calls to the /compute API.

I had been thinking that it would make sense for the auth-related calls that keystoneauth is handling to be logged under its logger, but for the calls to the compute API that novaclient is directly making, I agree it would be more useful to log them under novaclient's logger.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/python-novaclient 17.5.0 release.

[Akihiro Motoki (amotoki)]

Radomir,
The status in horizon is "Fix Committed". Did you make any change to the horizon repository regarding this issue?

I am marking the status in python-novaclient as "Fix Released" as python-novaclient 17.5.0 has been released.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/wallaby
Review: https://review.opendev.org/c/openstack/python-novaclient/+/804440

[Radosław Piliszek (yoctozepto)]

Copying this from the review ( https://review.opendev.org/c/openstack/python-novaclient/+/783010 ) for posterity:
It seems, without this fix, novaclient does not pick up the service logging config (as it picks up the level for keystoneauth which defaults to WARN). I have observed this with Masakari where turning debug on did not make novaclient log debug (before this).

[melanie witt (melwitt)]

In considering whether to backport this change, I went to look how far back in versions is the issue present. I found that the use of the keystoneauth logger goes back to Train and I found the original change that caused python-novaclient to stop using its own logger:

https://review.opendev.org/c/openstack/python-novaclient/+/581218

This change ^ was intended to enable logging to be compartmentalized so that it would be possible to log cinder-nova interactions as WARN while the rest of nova logged at DEBUG, for example. It also enabled the "split loggers" feature in keystoneauth [1] to be used and this was the associated bug report "Novaclient uses logger name as ‘novaclient.v2.client’ instead of 'keystoneauth.session' for keystoneauth logs":

https://bugs.launchpad.net/python-novaclient/+bug/1782134

Since we "fixed" novaclient to use its own logger, it's now no longer possible to compartmentalize logging in the way the bug reporter described or use the split logging in keystoneauth with novaclient.

I'm not immediately sure what to do here. These two bug reports are at odds with each other.

I guess we could add a conf option to novaclient "use_keystoneauth_logger" that defaults to False and people could set it to True if they wanted to set a different log level for inter-service interactions in nova and/or use split loggers in keystoneauth.

If anyone has opinions on how to handle it, please add a comment.

[1] https://docs.openstack.org/keystoneauth/latest/using-sessions.html#logging

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/c/openstack/python-novaclient/+/804440
Committed: https://opendev.org/openstack/python-novaclient/commit/5ee44275f64fe43aa4917301a9af63d81c0db9ee
Submitter: "Zuul (22348)"
Branch: stable/wallaby

commit 5ee44275f64fe43aa4917301a9af63d81c0db9ee
Author: Radomir Dopieralski <email address hidden>
Date: Thu Mar 25 15:08:20 2021 +0100

    When creating a client, pass the default logger

    When a client is created without a logger, novaclient creates a
    default logger, but it's then not used, because it's not passed
    to the factory function. Because of that, all novaclient calls
    are getting logged as 'keystoneauth.session' instead of
    'novaclient.v2.client' as they should.

    Closes-bug: 1921388
    Change-Id: I53caceb08667eb12e27016731868e8015dd10e34
    (cherry picked from commit d4399d3d36c456c1001b96178ce9b3e7ec082460)

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/python-novaclient 17.4.1 release.