Nova conductor throws ERROR messages, which is forbidden in our contract

Bug #1324793 reported by Attila Fazekas
10
This bug affects 2 people
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
Fix Released
Critical
Andrew Laski

Bug Description

http://logs.openstack.org/90/96090/2/check/check-tempest-dsvm-postgres-full/3580e69/console.html
failed with:
2014-05-30 06:30:40.384 | Log File Has Errors: n-cond
2014-05-30 06:30:40.384 | *** Not Whitelisted *** 2014-05-30 05:57:53.811 ERROR oslo.messaging.rpc.dispatcher [req-2640541d-c534-4c60-a049-118ef1dd468b ListServersNegativeTestXML-2141645177 ListServersNegativeTestXML-2043014598] Exception during message handling: Info cache for instance 891ce253-aeed-4d99-bb35-461085856ae9 could not be found.
2014-05-30 06:30:40.385 | *** Not Whitelisted *** 2014-05-30 05:57:53.812 ERROR oslo.messaging._drivers.common [req-2640541d-c534-4c60-a049-118ef1dd468b ListServersNegativeTestXML-2141645177 ListServersNegativeTestXML-2043014598] Returning exception Info cache for instance 891ce253-aeed-4d99-bb35-461085856ae9 could not be found. to caller
2014-05-30 06:30:40.422 | *** Not Whitelisted *** 2014-05-30 05:57:53.812 ERROR oslo.messaging._drivers.common [req-2640541d-c534-4c60-a049-118ef1dd468b ListServersNegativeTestXML-2141645177 ListServersNegativeTestXML-2043014598] ['Traceback (most recent call last):\n', ' File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 134, in _dispatch_and_reply\n incoming.message))\n', ' File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 177, in _dispatch\n return self._do_dispatch(endpoint, method, ctxt, args)\n', ' File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 123, in _do_dispatch\n result = getattr(endpoint, method)(ctxt, **new_args)\n', ' File "/opt/stack/new/nova/nova/conductor/manager.py", line 811, in build_instances\n instance.refresh()\n', ' File "/opt/stack/new/nova/nova/objects/base.py", line 187, in wrapper\n return fn(self, ctxt, *args, **kwargs)\n', ' File "/opt/stack/new/nova/nova/objects/instance.py", line 500, in refresh\n self.info_cache.refresh()\n', ' File "/opt/stack/new/nova/nova/objects/base.py", line 187, in wrapper\n return fn(self, ctxt, *args, **kwargs)\n', ' File "/opt/stack/new/nova/nova/objects/instance_info_cache.py", line 103, in refresh\n self.instance_uuid)\n', ' File "/opt/stack/new/nova/nova/objects/base.py", line 146, in wrapper\n result = fn(cls, context, *args, **kwargs)\n', ' File "/opt/stack/new/nova/nova/objects/instance_info_cache.py", line 70, in get_by_instance_uuid\n instance_uuid=instance_uuid)\n', 'InstanceInfoCacheNotFound: Info cache for instance

....
Logs have errors
2014-05-30 06:30:41.562 | Log: n-cond not allowed to have ERRORS or TRACES

message: "Info cache for instance" and message: "could not be found" AND tags: "screen-n-cond.txt"

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOiBcIkluZm8gY2FjaGUgZm9yIGluc3RhbmNlXCIgYW5kIG1lc3NhZ2U6IFwiY291bGQgbm90IGJlIGZvdW5kXCIgQU5EICB0YWdzOiBcInNjcmVlbi1uLWNvbmQudHh0XCIgIiwiZmllbGRzIjpbXSwib2Zmc2V0IjowLCJ0aW1lZnJhbWUiOiI2MDQ4MDAiLCJncmFwaG1vZGUiOiJjb3VudCIsInRpbWUiOnsidXNlcl9pbnRlcnZhbCI6MH0sInN0YW1wIjoxNDAxNDMzOTkxODQ3LCJtb2RlIjoiIiwiYW5hbHl6ZV9maWVsZCI6IiJ9

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

Good catch, http://goo.gl/f5AFMP - 564 hits in 7 days, check and gate, all failures. Looks like it started on 5/29.

Changed in nova:
status: New → Confirmed
importance: Undecided → High
Revision history for this message
Matt Riedemann (mriedem) wrote :
Revision history for this message
Andrew Laski (alaski) wrote :

Not sure why this didn't update, but https://review.openstack.org/#/c/96824/ is open for this.

Changed in nova:
assignee: nobody → Andrew Laski (alaski)
status: Confirmed → In Progress
tags: added: icehouse-backport-potential
Sean Dague (sdague)
summary: - Info cache for instance <instance_id> could not be found
+ Nova conductor throws ERROR messages, which is forbidden in our contract
Changed in nova:
importance: High → Critical
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to nova (master)

Reviewed: https://review.openstack.org/96824
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=847e6e3c85e8b006366dec67c2459fdc85b27b9f
Submitter: Jenkins
Branch: master

commit 847e6e3c85e8b006366dec67c2459fdc85b27b9f
Author: Andrew Laski <email address hidden>
Date: Fri May 30 12:17:19 2014 -0400

    Catch InstanceInfoCacheNotFound during build_instances

    instance.refresh() is raising InstanceInfoCacheNotFound which is logged
    by the conductor and would cause all following builds to fail in a
    multiple build request situation. The cause appears to be a race
    condition which should be addressed separately, but for now this
    exception should be caught, logged, then ignored.

    Change-Id: Ibf9e6687933ee90dad54b1998b243ef7256d79ca
    Closes-bug: 1324793

Changed in nova:
status: In Progress → Fix Committed
Revision history for this message
Andrew Laski (alaski) wrote :

This is coming up due to an elastic re-check query, but the failures appear to be related to https://review.openstack.org/#/c/98186/ being in the check queue.

Thierry Carrez (ttx)
Changed in nova:
milestone: none → juno-1
status: Fix Committed → Fix Released
Thierry Carrez (ttx)
Changed in nova:
milestone: juno-1 → 2014.2
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.