KeyError: 'user_identity' showing up all over cinder-api logs

Bug #1290503 reported by Matt Riedemann on 2014-03-10
24
This bug affects 4 people
Affects Status Importance Assigned to Milestone
Cinder
Critical
John Griffith
oslo-incubator
Critical
Luis A. Garcia

Bug Description

Saw this while looking at logs for bug 1290468:

http://logs.openstack.org/85/78385/3/gate/gate-grenade-dsvm/2b66f90/logs/new/screen-c-api.txt.gz

You'll see a ton of errors like this:

Traceback (most recent call last):
  File "/usr/lib/python2.7/logging/__init__.py", line 846, in emit
    msg = self.format(record)
  File "/opt/stack/new/cinder/cinder/openstack/common/log.py", line 705, in format
    return logging.StreamHandler.format(self, record)
  File "/usr/lib/python2.7/logging/__init__.py", line 723, in format
    return fmt.format(record)
  File "/opt/stack/new/cinder/cinder/openstack/common/log.py", line 669, 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_identity'
Logged from file middleware.py, line 100

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiS2V5RXJyb3I6IFxcJ3VzZXJfaWRlbnRpdHlcXCdcIiBBTkQgZmlsZW5hbWU6bG9ncypzY3JlZW4tYy1hcGkudHh0IiwiZmllbGRzIjpbXSwib2Zmc2V0IjowLCJ0aW1lZnJhbWUiOiI2MDQ4MDAiLCJncmFwaG1vZGUiOiJjb3VudCIsInRpbWUiOnsidXNlcl9pbnRlcnZhbCI6MH0sInN0YW1wIjoxMzk0NDc2MTE4MTQ2fQ==

Thinking it's related to this:

https://github.com/openstack/cinder/blob/master/cinder/openstack/common/log.py#L370

Does that need to be popped off kwargs?

From the review https://review.openstack.org/#/c/55938/ it looks like Ben and Doug were questioning it.

Also wondering if that's somehow impacted by the logging format condition used here:

https://github.com/openstack/cinder/blob/master/cinder/openstack/common/log.py#L657

Because logging_context_format_string is the format that uses user_identity.

This started showing up on 3/7 which is when the lazy translation code was enabled in Cinder so it looks like that is exposing the bug.

Matt Riedemann (mriedem) wrote :

Could this be a duplicate of bug 1288049?

Ben Nemec (bnemec) wrote :

That seems likely since it started happening when lazy translation was turned on and user_identity _should_ always exist in the original dict. Message may be filtering it out though.

I just approved https://review.openstack.org/#/c/78806/ so it would be worth trying the updated Message class once that gets through the gate.

Matt,

[15:41] <dims_> mriedem, see the differences in the log format string
[15:41] <dims_> oslo-incubator/etc/openstack.conf.sample: #logging_context_format_string=%(asctime)s.%(msecs)03d %(process)d %(levelname)s %(name)s [%(request_id)s %(user_identity)s] %(instance)s%(message)s
[15:41] <dims_> nova/etc/nova.conf.sample: #logging_context_format_string=%(asctime)s.%(msecs)03d %(process)d %(levelname)s %(name)s [%(request_id)s %(user)s %(tenant)s] %(instance)s%(message)s
[15:41] <dims_> cinder may be using user
[15:43] <dims_> mriedem, try switching https://github.com/openstack/cinder/blob/master/cinder/openstack/common/log.py#L144 to look like Nova's

James Carey (jecarey) wrote :

In comment #3, for the bug mentioned in #2, I would have expected the key that was missing would be 'msecs' since that is the one with the additional formatting. I don't think there is any reason the code would have removed the entry for 'user_identity', which is what is in the key error in the description.

Here's the output of running the regex in oslo the cinder format string:
  ['asctime', 'process', 'levelname', 'name', 'request_id', 'user_identity', 'instance', 'message']

So this may not be the oslo bug.

Luis A. Garcia (luisg-8) on 2014-03-10
Changed in cinder:
assignee: nobody → Luis A. Garcia (luisg-8)
Changed in oslo:
assignee: nobody → Luis A. Garcia (luisg-8)
Luis A. Garcia (luisg-8) wrote :

Just want to mention that this bug is happening with and without lazy translation, therefore I don't think it is related to that.

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

Changed in oslo:
status: New → In Progress
Changed in cinder:
importance: Undecided → Critical
milestone: none → icehouse-rc1
Attila Fazekas (afazekas) wrote :

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOiBLZXlFcnJvciBtYXNzYWdlOiB1c2VyX2lkZW50aXR5IiwiZmllbGRzIjpbXSwib2Zmc2V0IjowLCJ0aW1lZnJhbWUiOiI2MDQ4MDAiLCJncmFwaG1vZGUiOiJjb3VudCIsInRpbWUiOnsidXNlcl9pbnRlcnZhbCI6MH0sInN0YW1wIjoxMzk0NTM1MjE5MTcyfQ==

"message: KeyError massage: user_identity"

1,362,056 hit in the past 7 days.

logs/new/screen-c-api.txt 27.2%
logs/new/screen-c-vol.txt 26%
logs/screen-c-vol.txt 24%
logs/new/screen-c-sch.txt 12.2%
logs/screen-c-api.txt 9%

Jay Bryant (jsbryant) on 2014-03-11
Changed in cinder:
status: New → Confirmed

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

Changed in cinder:
assignee: Luis A. Garcia (luisg-8) → Davanum Srinivas (DIMS) (dims-v)
status: Confirmed → In Progress

This is not a oslo bug per se. the log format in cinder has to match the details available in cinder's context which is 'user' and 'tenant'

Changed in oslo:
status: In Progress → Invalid

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

Changed in cinder:
assignee: Davanum Srinivas (DIMS) (dims-v) → Luis A. Garcia (luisg-8)
Changed in oslo:
status: Invalid → In Progress
importance: Undecided → Critical
milestone: none → icehouse-rc1

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

commit 346884d48c88e1b2d550e8cef878e604c39bf10d
Author: Luis A. Garcia <email address hidden>
Date: Mon Mar 10 22:03:08 2014 -0600

    Add default user_identity to logging record

    Just like instance and color formatting parameters we can't assume that
    the user_identity will always be in the logging record. This patch adds
    a default value for it if missing to avoid exceptions.

    Change-Id: Id02902adb2579d44f1f4f066757ef3855b5ece87
    Closes-Bug: #1290503

Changed in oslo:
status: In Progress → Fix Committed

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

Changed in cinder:
assignee: Luis A. Garcia (luisg-8) → John Griffith (john-griffith)

Reviewed: https://review.openstack.org/79652
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=bb5228cf79ff5bea543abc321b2dfad9fea5e9a5
Submitter: Jenkins
Branch: master

commit bb5228cf79ff5bea543abc321b2dfad9fea5e9a5
Author: Luis A. Garcia <email address hidden>
Date: Tue Mar 11 09:34:02 2014 -0600

    Adding domain to context

    Add support for upcoming "domain" concept in Keystone V3 API in
    the context.

    This fix ensures there is a user_identity in the context for the
    corresponding new attribute in the log format string added in oslo. The
    oslo change has the same change-id as this one.

    Closes-Bug: #1290503
    Change-Id: Ic2cf3e52cfcc0b8adccdf9c59afaa4014708a303

Changed in cinder:
status: In Progress → Fix Committed

Reviewed: https://review.openstack.org/80000
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=1553a1e78ec262b044ce99b418103c91b7b580f6
Submitter: Jenkins
Branch: master

commit 1553a1e78ec262b044ce99b418103c91b7b580f6
Author: john-griffith <email address hidden>
Date: Wed Mar 12 10:59:45 2014 -0600

    Sync log.py from oslo-incubator

    This pulls in the latest version of log.py from oslo-incubator
    which elminates the constant user_identity key error.

    Note that this sync does a full sync, in other words it uses
    the oslo update script and pulls in the log.py file and all
    of the associated dependendencies for that module.

    Current HEAD in OSLO:
    --------------------
    Merge: d9ea4f0 fd33d1e
    Date: Wed Mar 12 17:00:13 2014 +0000
    Merge "Fix gettextutil.Message handling of deep copy failures"
    --------------------

    Change-Id: I7c9f8acd22787f9649a5a1e796238c7788a0484a
    Fixes-Bug: 1290503

Thierry Carrez (ttx) on 2014-03-27
Changed in cinder:
status: Fix Committed → Fix Released
Thierry Carrez (ttx) on 2014-04-04
Changed in oslo:
status: Fix Committed → Fix Released
Thierry Carrez (ttx) on 2014-04-17
Changed in oslo:
milestone: icehouse-rc1 → 2014.1
Thierry Carrez (ttx) on 2014-04-17
Changed in cinder:
milestone: icehouse-rc1 → 2014.1
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers