neutron doesn't log tenant_id and user_id along side req-id in logs

[Joe Gordon]

neutron logs: [req-94a39f87-e470-4032-82af-9a6b429b60fa None]
while nova logs: [req-c0b4dfb9-8af3-40eb-b0dd-7b576cfd1d55 AggregatesAdminTestJSON-917687995 AggregatesAdminTestJSON-394398414]

Nova uses the format: #logging_context_format_string=%(asctime)s.%(msecs)03d %(process)d %(levelname)s %(name)s [%(request_id)s %(user_identity)s] %(instance)s%(message)s

Without knowing the user and tenant its hard to understand what the logs are doing when multiple tenants are using the cloud.

[venkata anil (anil-venkata)]

neutron is also logging user and tenant id like nova

neutron log(./screen-q-svc.2014-12-02-110757.log) -
2014-12-08 12:06:27.066 INFO neutron.wsgi [req-83c0557d-512e-4664-bf15-61646fd83539 demo b0243233dced4975b4c61b66184bdb03] 10.43.99.5 - - [08/Dec/2014 12:06:27] "GET /v2.0/networks.json HTTP/1.1" 200 714 0.096734

nova log(./screen-n-api.2014-12-02-110757.log)-
2014-12-08 12:03:26.450 INFO nova.osapi_compute.wsgi.server [req-aaba771c-3c3e-4fca-ba01-fa78931cd216 demo demo] 10.43.99.5 "GET /v2/b0243233dced4975b4c61b66184bdb03/servers/detail HTTP/1.1" status: 200 len: 1699 time: 0.3682060

So I think this bug is invalid.

[Joe Gordon (jogo)]

I am not seeing user and tenant id being listed in the gate: http://logs.openstack.org/80/139880/3/check/check-tempest-dsvm-neutron-full/1fee100/logs/screen-q-svc.txt.gz#_2014-12-08_14_22_34_996

[Joe Gordon (jogo)]

Perhaps this is a devstack or devstack-gate bug instead.

[venkata anil (anil-venkata)]

I think so(devstack issue).

In my devstack, ./lib/neutron(line 830) is

setup_colorized_logging $NEUTRON_CONF DEFAULT project_id

2014-11-25 08:22:07.563 | + setup_colorized_logging /etc/neutron/neutron.conf DEFAULT project_id
2014-11-25 08:22:07.563 | + local conf_file=/etc/neutron/neutron.conf
2014-11-25 08:22:07.563 | + local conf_section=DEFAULT
2014-11-25 08:22:07.563 | + local project_var=project_id
2014-11-25 08:22:07.563 | + local user_var=user_name
2014-11-25 08:22:07.563 | + iniset /etc/neutron/neutron.conf DEFAULT logging_context_format_string '%(asctime)s.%(msecs)03d %(color)s%(levelname)s %(name)s [^[[01;36m%(request_id)s ^[[00;36m%(user_name)s %(project_id)s%(color)s] ^[[01;35m%(instance)s%(color)s%(message)s^[[00m'

So, in my /etc/neutron/neutron.conf
logging_context_format_string = %(asctime)s.%(msecs)03d %(color)s%(levelname)s %(name)s [^[[01;36m%(request_id)s ^[[00;36m%(user_name)s %(project_id)s%(color)s] ^[[01;35m%(instance)s%(color)s%(message)s

and in screen-q-svc.2014-12-02-110757.log
2014-12-02 11:12:06.219 DEBUG neutron.service [-] logging_context_format_string = %(asctime)s.%(msecs)03 d %(color)s%(levelname)s %(name)s [%(request_id)s %(user_name)s %(project_id)s%(color)s] %(instance)s%(color)s%(message)s

So please check your devstack setup.
As this is a devstack/setup issue, I am setting the status of the bug as 'invalid'

[Joe Gordon (jogo)]

Note this is the gate devstack setup.

This is neutron.conf http://logs.openstack.org/80/139880/3/check/check-tempest-dsvm-neutron-full/1fee100/logs/etc/neutron/neutron.conf.txt.gz

so we are using the default logging_context_format_string which looks to be:

%(asctime)s.%(msecs)03d %(process)d %(levelname)s %(name)s [%(request_id)s %(user_identity)s] %(instance)s%(message)s

from

http://logs.openstack.org/80/139880/3/check/check-tempest-dsvm-neutron-full/1fee100/logs/screen-q-svc.txt.gz#_2014-12-08_14_22_29_990

It looks like the important difference is

[%(request_id)s %(user_name)s %(project_id)s%(color)s]
vs.
 [%(request_id)s %(user_identity)s]

[Joe Gordon (jogo)]

Hmm logging_context_format_string is set in neutron/openstack/common/log.py so maybe oslo related?

[Doug Hellmann (doug-hellmann)]

We're working on graduating the incubated version of log.py. The version in oslo.log has the same features, and we might fix it just by migrating and making sure the new library is being used properly. It could be prudent to wait until the conversion has happened before doing too much work on this.

[venkata anil (anil-venkata)]

change proposed https://review.openstack.org/#/c/147413/

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/147413
Committed: https://git.openstack.org/cgit/openstack-dev/devstack/commit/?id=9b1df576342e2151df4b6e8daec3ccb72abc238a
Submitter: Jenkins
Branch: master

commit 9b1df576342e2151df4b6e8daec3ccb72abc238a
Author: venkata anil <email address hidden>
Date: Thu Jan 15 07:38:22 2015 +0000

    neutron should log user_name and project_name by default like in nova

    neutron doesn't log user_name and project_name along side req-id in
    devstack logs. So, Openstack jenkins neutron check and gate jobs also
    not logging user_name and project_name along side req-id.
    Without knowing the user and tenant, its hard to understand what the
    logs are doing when multiple tenants are using the cloud.

    Nova is logging user_name and project_name by default.
    So porting the same changes to neutron.

    Change-Id: I10eac2e4177a898e9bcc60c08f3bd39a2ec9f31b
    Closes-Bug: #1399788