logging context format error

[chenglch]

I use the latest devstack with LOG_COLOR enabled to setup the environment.
Devstack will set logging_context_format_string with a default value.

in devstack/functions setup_colorized_logging
iniset $conf_file $conf_section logging_context_format_string "%(asctime)s.%(msecs)03d %(color)s%(levelname)s %(name)s [%(request_id)s %("$user_var")s %("$project_var")s%(color)s] %(instance)s%(color)s%(message)s"
https://github.com/openstack-dev/devstack/blob/master/functions#L530

When I start the ironic conductor in the debug mode,
I will see the following message :
Traceback (most recent call last):
  File "/usr/lib/python2.7/logging/__init__.py", line 851, in emit
    msg = self.format(record)
  File "/usr/lib/python2.7/logging/__init__.py", line 724, in format
    return fmt.format(record)
  File "/usr/local/lib/python2.7/dist-packages/oslo_log/formatters.py", line 235, in format
    return logging.Formatter.format(self, record)
  File "/usr/lib/python2.7/logging/__init__.py", line 467, in format
    s = self._fmt % record.__dict__
KeyError: 'user_name'
Logged from file amqp.py, line 97
Traceback (most recent call last):
  File "/usr/lib/python2.7/logging/__init__.py", line 851, in emit
    msg = self.format(record)
  File "/usr/local/lib/python2.7/dist-packages/oslo_log/handlers.py", line 69, in format
    return logging.StreamHandler.format(self, record)
  File "/usr/lib/python2.7/logging/__init__.py", line 724, in format
    return fmt.format(record)
  File "/usr/local/lib/python2.7/dist-packages/oslo_log/formatters.py", line 235, in format
    return logging.Formatter.format(self, record)
  File "/usr/lib/python2.7/logging/__init__.py", line 467, in format
    s = self._fmt % record.__dict__
KeyError: 'user_name'
Logged from file amqp.py, line 97

Nova also set the logging_context_format_string in nova.conf with the default value, but no such message in the log file.

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

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

[Dmitry Tantsur (divius)]

Shouldn't fix go to oslo.context instead?

[Thiago Paiva Brito (outbrito)]

IMHO, Devstack should be adapted to work with Ironic and oslo_context, not the reverse. And I also think that inserting 'user_name' is duplicating the already existing 'user' injected by oslo_context.

[chenglch (chenglch)]

The 'user' and 'tenant' in oslo_context is ID value, 'user_name' is name string value. Maybe 'user_name' parameter in the context log is friendly purpose. Devstack can remove the default 'user_name' and 'project_name' parameters for ironic log context, but I think Ironic should add these parameters in context object like nova.

[OpenStack Infra (hudson-openstack)]

Change abandoned by Thiago Paiva Brito (<email address hidden>) on branch: master
Review: https://review.openstack.org/184568
Reason: Hey Jim!

It appears that someone has already done that on the Ironic plugin. Abandoning this then.

[Pavlo Shchelokovskyy (pshchelo)]

I am running fresh devstack with colorized logging (which is default if run in a proper/interactive terminal instead of CI) and do not see such errors.

Moving the bug to incomplete for Ironic and Invalid for DevStack (patch was abandoned and Ironic has moved to devstack plugin anyway).

[Launchpad Janitor (janitor)]

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

[OpenStack Infra (hudson-openstack)]

Change abandoned by Ruby Loo (<email address hidden>) on branch: master
Review: https://review.openstack.org/184714

[Ruby Loo (rloo)]

This bug has been around for awhile and I don't actually know whether there is an issue with oslo.context or not. Since it had been 'incomplete' anyway, I just changed it to invalid. Feel free to re-open or open a new bug if you have more details.