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

Bug #1290503 reported by Matt Riedemann
24
This bug affects 4 people
Affects Status Importance Assigned to Milestone
Cinder
Fix Released
Critical
John Griffith
oslo-incubator
Fix Released
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.

Revision history for this message
Matt Riedemann (mriedem) wrote :

Could this be a duplicate of bug 1288049?

Revision history for this message
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.

Revision history for this message
Davanum Srinivas (DIMS) (dims-v) wrote :

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

Revision history for this message
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)
Changed in cinder:
assignee: nobody → Luis A. Garcia (luisg-8)
Changed in oslo:
assignee: nobody → Luis A. Garcia (luisg-8)
Revision history for this message
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.

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to oslo-incubator (master)

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
Revision history for this message
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)
Changed in cinder:
status: New → Confirmed
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to cinder (master)

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
Revision history for this message
Davanum Srinivas (DIMS) (dims-v) wrote :

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
Revision history for this message
Davanum Srinivas (DIMS) (dims-v) wrote :
Revision history for this message
OpenStack Infra (hudson-openstack) wrote :

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
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to oslo-incubator (master)

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
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to cinder (master)

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

Changed in cinder:
assignee: Luis A. Garcia (luisg-8) → John Griffith (john-griffith)
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to cinder (master)

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
Revision history for this message
OpenStack Infra (hudson-openstack) wrote :

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)
Changed in cinder:
status: Fix Committed → Fix Released
Thierry Carrez (ttx)
Changed in oslo:
status: Fix Committed → Fix Released
Thierry Carrez (ttx)
Changed in oslo:
milestone: icehouse-rc1 → 2014.1
Thierry Carrez (ttx)
Changed in cinder:
milestone: icehouse-rc1 → 2014.1
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.