OpenStack Compute (nova)

"Failed storing info cache" in n-cpu log after good tempest run

Bug #1084698 reported by David Kranz
20
This bug affects 3 people
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
Fix Released
Low
Unassigned

Bug Description

From http://logs.openstack.org/periodic/periodic-tempest-devstack-vm-check-hourly/404/logs/screen-n-cpu.txt.
There is one of these:

2012-11-29 19:30:04 29538 DEBUG nova.openstack.common.rpc.amqp [-] Making asynchronous call on network ... multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:352
2012-11-29 19:30:04 29538 DEBUG nova.openstack.common.rpc.amqp [-] MSG_ID is 4b5562fdcef246ddb75641b25f75d892 multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:355
2012-11-29 19:30:04 DEBUG nova.openstack.common.lockutils [req-1496b2e0-5b61-4bb7-bc7c-5a2efe4357c5 ListServersNegativeTest-user ListServersNegativeTest-tenant] Got semaphore "compute_resources" for method "update_usage"... inner /opt/stack/nova/nova/openstack/common/lockutils.py:185
2012-11-29 19:30:04 29538 DEBUG nova.openstack.common.rpc.amqp [-] Making asynchronous call on network ... multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:352
2012-11-29 19:30:04 29538 DEBUG nova.openstack.common.rpc.amqp [-] MSG_ID is b26e316ba4d840348fe3e23da336761d multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:355
2012-11-29 19:30:04 29538 ERROR nova.network.api [-] [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] Failed storing info cache
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] Traceback (most recent call last):
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] File "/opt/stack/nova/nova/network/api.py", line 71, in update_instance_cache_with_nw_info
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] nw_info = nw_info or api._get_instance_nw_info(context, instance)
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] File "/opt/stack/nova/nova/network/api.py", line 245, in _get_instance_nw_info
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] nw_info = self.network_rpcapi.get_instance_nw_info(context, **args)
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] File "/opt/stack/nova/nova/network/rpcapi.py", line 166, in get_instance_nw_info
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] rxtx_factor=rxtx_factor, host=host, project_id=project_id))
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] File "/opt/stack/nova/nova/openstack/common/rpc/proxy.py", line 80, in call
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] return rpc.call(context, self._get_topic(topic), msg, timeout)
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] File "/opt/stack/nova/nova/openstack/common/rpc/__init__.py", line 108, in call
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] return _get_impl().call(cfg.CONF, context, topic, msg, timeout)
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] File "/opt/stack/nova/nova/openstack/common/rpc/impl_kombu.py", line 754, in call
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] rpc_amqp.get_connection_pool(conf, Connection))
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] File "/opt/stack/nova/nova/openstack/common/rpc/amqp.py", line 369, in call
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] rv = list(rv)
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] File "/opt/stack/nova/nova/openstack/common/rpc/amqp.py", line 337, in __iter__
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] raise result
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] InstanceNotFound_Remote: Instance 3e25e151-726a-4db8-bec3-6dc61ce0c1fe could not be found.
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] Traceback (most recent call last):
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe]
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] File "/opt/stack/nova/nova/openstack/common/rpc/amqp.py", line 276, in _process_data
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] rval = self.proxy.dispatch(ctxt, version, method, **args)
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe]
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] File "/opt/stack/nova/nova/openstack/common/rpc/dispatcher.py", line 145, in dispatch
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] return getattr(proxyobj, method)(ctxt, **kwargs)
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe]
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] File "/opt/stack/nova/nova/network/manager.py", line 266, in wrapped
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] return func(self, context, *args, **kwargs)
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe]
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] File "/opt/stack/nova/nova/network/manager.py", line 1152, in get_instance_nw_info
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] instance_uuid)
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe]
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] File "/opt/stack/nova/nova/db/api.py", line 523, in virtual_interface_get_by_instance
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] return IMPL.virtual_interface_get_by_instance(context, instance_id)
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe]
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] File "/opt/stack/nova/nova/db/sqlalchemy/api.py", line 127, in wrapper
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] return f(*args, **kwargs)
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe]
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] File "/opt/stack/nova/nova/db/sqlalchemy/api.py", line 139, in wrapper
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] db.instance_get_by_uuid(context, instance_uuid)
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe]
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] File "/opt/stack/nova/nova/db/api.py", line 570, in instance_get_by_uuid
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] return IMPL.instance_get_by_uuid(context, uuid)
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe]
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] File "/opt/stack/nova/nova/db/sqlalchemy/api.py", line 127, in wrapper
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] return f(*args, **kwargs)
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe]
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] File "/opt/stack/nova/nova/db/sqlalchemy/api.py", line 1493, in instance_get_by_uuid
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] raise exception.InstanceNotFound(instance_id=uuid)
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe]
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] InstanceNotFound: Instance 3e25e151-726a-4db8-bec3-6dc61ce0c1fe could not be found.
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe]
2012-11-29 19:30:04 29538 TRACE nova.network.api [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe]

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

Looks like the instance was just deleted by us! we should avoid flooding the logs with this exception

2012-11-29 19:30:02 29538 INFO nova.virt.libvirt.driver [-] [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] Instance destroyed successfully.
...
2012-11-29 19:30:04 29538 ERROR nova.network.api [-] [instance: 3e25e151-726a-4db8-bec3-6dc61ce0c1fe] Failed storing info cache

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

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

Changed in nova:
assignee: nobody → Davanum Srinivas (dims-v)
status: New → In Progress
Revision history for this message
Davanum Srinivas (DIMS) (dims-v) wrote :

please see review, this is a spurious error and can be ignored

Changed in nova:
assignee: Davanum Srinivas (dims-v) → nobody
Revision history for this message
David Kranz (david-kranz) wrote :

I looked at the review but still think this issue needs to b e addressed. The point of this ticket, and the other tickets about ERRORs in the logs, is that we want to be able to fail gating tests and allow operators to alert if there are ERRORs in the logs. It is not necessary to remove the information from the log, but the message should be changed to DEBUG if it is there for debugging reasons.

Thierry Carrez (ttx)
Changed in nova:
importance: Undecided → Low
status: In Progress → Confirmed
Revision history for this message
Sean Dague (sdague) wrote :

As far as I can tell, this bug is no longer seen.

Changed in nova:
status: Confirmed → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Duplicates of this bug

Subscribing...

Other bug subscribers

Remote bug watches

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