DescribeInstances fails sporadically

[Scott Moser]

by 'sporadically' i mean roughly every-other time.
We have a nova cloud installed with the daily ppa:
  python-nova at version 2012.1~e1~20110920.1604-0ubuntu0ppa1~oneiric2

We would see:
$ euca-describe-instances
UnknownError: An unknown error has occurred. Please try your request again.

We saw the following trace in logs:
ubuntu@mabolo:~$ 2011-09-21 11:03:47,041 DEBUG nova.api [-] action: DescribeInstances from (pid=25529) __call__ /usr/lib/python2.7/dist-packages/nova/api/ec2/__init__.py:290
2011-09-21 11:03:47,042 DEBUG nova.compute.api [-] Searching by: {'deleted': False} from (pid=25529) get_all /usr/lib/python2.7/dist-packages/nova/compute/api.py:862
2011-09-21 11:03:47,162 ERROR nova.api [70460539-3492-4108-b805-3e73f00c0e3c 35a1d80e-ab85-42ab-81f8-7fb7e0197ccb novaproject] Unexpected error raised: Parent instance <Instance at 0x5413310> is not bound to a Session; lazy load operation of attribute 'fixed_ips' cannot proceed
(nova.api): TRACE: Traceback (most recent call last):
(nova.api): TRACE: File "/usr/lib/python2.7/dist-packages/nova/api/ec2/__init__.py", line 398, in __call__
(nova.api): TRACE: result = api_request.invoke(context)
(nova.api): TRACE: File "/usr/lib/python2.7/dist-packages/nova/api/ec2/apirequest.py", line 78, in invoke
(nova.api): TRACE: result = method(context, **args)
(nova.api): TRACE: File "/usr/lib/python2.7/dist-packages/nova/api/ec2/cloud.py", line 1151, in describe_instances
(nova.api): TRACE: instance_id=instance_id)
(nova.api): TRACE: File "/usr/lib/python2.7/dist-packages/nova/api/ec2/cloud.py", line 1160, in _format_describe_instances
(nova.api): TRACE: return {'reservationSet': self._format_instances(context, **kwargs)}
(nova.api): TRACE: File "/usr/lib/python2.7/dist-packages/nova/api/ec2/cloud.py", line 1260, in _format_instances
(nova.api): TRACE: if instance['fixed_ips']:
(nova.api): TRACE: File "/usr/lib/python2.7/dist-packages/nova/db/sqlalchemy/models.py", line 76, in __getitem__
(nova.api): TRACE: return getattr(self, key)
(nova.api): TRACE: File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/attributes.py", line 168, in __get__
(nova.api): TRACE: instance_dict(instance))
(nova.api): TRACE: File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/attributes.py", line 388, in get
(nova.api): TRACE: value = callable_(passive=passive)
(nova.api): TRACE: File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/strategies.py", line 599, in __call__
(nova.api): TRACE: (mapperutil.state_str(state), self.key)
(nova.api): TRACE: DetachedInstanceError: Parent instance <Instance at 0x5413310> is not bound to a Session; lazy load operation of attribute 'fixed_ips' cannot proceed
(nova.api): TRACE:
2011-09-21 11:03:47,162 ERROR nova.api [70460539-3492-4108-b805-3e73f00c0e3c 35a1d80e-ab85-42ab-81f8-7fb7e0197ccb novaproject] Environment: {"CONTENT_TYPE": "application/x-www-form-urlencoded; charset=UTF-8", "SCRIPT_NAME": "/services/Cloud", "REQUEST_METHOD": "POST", "HTTP_HOST": "10.55.55.5:8773", "PATH_INFO": "/", "SERVER_PROTOCOL": "HTTP/1.0", "HTTP_USER_AGENT": "Boto/2.0 (linux2)", "SERVER_NAME": "10.55.55.5", "REMOTE_ADDR": "10.55.55.5", "wsgi.url_scheme": "http", "SERVER_PORT": "8773", "GATEWAY_INTERFACE": "CGI/1.1", "HTTP_ACCEPT_ENCODING": "identity"}
2011-09-21 11:03:47,162 ERROR nova.api [70460539-3492-4108-b805-3e73f00c0e3c 35a1d80e-ab85-42ab-81f8-7fb7e0197ccb novaproject] UnknownError: An unknown error has occurred. Please try your request again.
2011-09-21 11:03:47,163 INFO nova.api [70460539-3492-4108-b805-3e73f00c0e3c 35a1d80e-ab85-42ab-81f8-7fb7e0197ccb novaproject] 0.121898s 10.55.55.5 POST /services/Cloud/ CloudController:DescribeInstances 400 [Boto/2.0 (linux2)] application/x-www-form-urlencoded text/xml

[Dave Walker (davewalker)]

running the command sequentially for 300 times, i got:
132 passes and 168 failures.

[Vish Ishaya (vishvananda)]

So this is trunk only, due to some joinedloads being removed in
nova/db/sqlalchemy/api:instance_get_all_by_filters

[Chris Behrens (cbehrens)]

And the backref for virtual_interfaces was removed. I guess the idea here is to prepare to query quantum for this info. The merge prop that removed this completely unties virtual_interfaces from Instance when you do most queries for an instance. References to instance['virtual_interfaces'] need to now query the network service.

[Chris Behrens (cbehrens)]

BTW, when you do not get an exception.... any queries (like doing a servers/detail via OS API) return no IP addresses. So, in trunk right now, if you do a 'nova list' via OS API1.1, you get no IP address information. Same with 'nova show'. Ran into this part of it while functional testing an unrelated branch. Have a fix OS API here:

http://paste.openstack.org/show/2553/

EC2 will need something similar... I'll get a merge prop RSN unless someone beats me to it.

[Chris Behrens (cbehrens)]

Decided compute_api.get() and get_all() should return the instance(s) with 'virtual_interfaces' set, instead of above kludge.

Also: I'm changing everything that references instance['fixed_ips'] to use 'virtual_interfaces', instead, so we can remove the joining of 'fixed_ips.floating_ips' when doing a 'db.instance_get', etc. This is more in line with the intent of the earlier merge to force grabbing network information separately for an instance (possibly via an external service).

https://github.com/comstud/nova/compare/master...bugs/855660

Propping when tests are clean..

[Kevin Bringard (kbringard)]

I should mention I'm also seeing this sporadically on 2011.3-0ubuntu2~ppa1~natty1, but it's a different table (FixedIp)

Session; lazy load operation of attribute 'network' cannot proceed
(nova.api): TRACE: Traceback (most recent call last):
(nova.api): TRACE: File "/usr/lib/python2.7/dist-packages/nova/api/ec2/__init__.py", line 347, in __call__
(nova.api): TRACE: result = api_request.invoke(context)
(nova.api): TRACE: File "/usr/lib/python2.7/dist-packages/nova/api/ec2/apirequest.py", line 78, in invoke
(nova.api): TRACE: result = method(context, **args)
(nova.api): TRACE: File "/usr/lib/python2.7/dist-packages/nova/api/ec2/cloud.py", line 1151, in describe_instances
(nova.api): TRACE: instance_id=instance_id)
(nova.api): TRACE: File "/usr/lib/python2.7/dist-packages/nova/api/ec2/cloud.py", line 1160, in _format_describe_instances
(nova.api): TRACE: return {'reservationSet': self._format_instances(context, **kwargs)}
(nova.api): TRACE: File "/usr/lib/python2.7/dist-packages/nova/api/ec2/cloud.py", line 1265, in _format_instances
(nova.api): TRACE: if fixed['network'] and use_v6:
(nova.api): TRACE: File "/usr/lib/python2.7/dist-packages/nova/db/sqlalchemy/models.py", line 76, in __getitem__
(nova.api): TRACE: return getattr(self, key)
(nova.api): TRACE: File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/attributes.py", line 163, in __get__
(nova.api): TRACE: instance_dict(instance))
(nova.api): TRACE: File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/attributes.py", line 383, in get
(nova.api): TRACE: value = callable_(passive=passive)
(nova.api): TRACE: File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/strategies.py", line 595, in __call__
(nova.api): TRACE: (mapperutil.state_str(state), self.key)
(nova.api): TRACE: DetachedInstanceError: Parent instance <FixedIp at 0x4330d50> is not bound to a Session; lazy load operation of attribute 'network' cannot proceed
(nova.api): TRACE:

Additionally (and this should probably be it's own bug, so I can file it if necessary), when attempting to add source security groups I get:

2011-09-25 19:00:44,507 CRITICAL nova [-] Parent instance <SecurityGroup at 0x4f628d0> is not bound to a Session; lazy load operation of attribute 'instances' cannot proceed
(nova): TRACE: Traceback (most recent call last):
(nova): TRACE: File "/usr/bin/nova-compute", line 49, in <module>
(nova): TRACE: service.wait()
(nova): TRACE: File "/usr/lib/python2.7/dist-packages/nova/service.py", line 357, in wait
(nova): TRACE: _launcher.wait()
(nova): TRACE: File "/usr/lib/python2.7/dist-packages/nova/service.py", line 107, in wait
(nova): TRACE: service.wait()
(nova): TRACE: File "/usr/local/lib/python2.7/dist-packages/eventlet/greenthread.py", line 166, in wait
(nova): TRACE: return self._exit_event.wait()
(nova): TRACE: File "/usr/local/lib/python2.7/dist-packages/eventlet/event.py", line 116, in wait
(nova): TRACE: return hubs.get_hub().switch()
(nova): TRACE: File "/usr/local/lib/python2.7/dist-packages/eventlet/hubs/hub.py", line 177, in switch
(nova): TRACE: return self.greenlet.switch()
(nova): TRACE: File "/usr/local/li...

[Openstack Gerrit (openstack-gerrit)]

Reviewed: https://review.openstack.org/641
Committed: http://github.com/openstack/nova/commit/4584e552a653904c36cf04cb295a7bf09d2def28
Submitter: Jenkins
Branch: master

 status fixcommitted
 done

commit 4584e552a653904c36cf04cb295a7bf09d2def28
Author: Chris Behrens <email address hidden>
Date: Wed Sep 28 22:56:34 2011 +0000

    Fixes euca-describe-instances failing or not showing IPs

    Fixes bug 855660

    Makes EC2 call network manager to get IP information now, to match the
    same change to OS API
    Also refactors a bit of OS API's calls... moving some code into 'common'

    Fixed tests. Some tests for OS API v1.0 were not properly testing.

    Fixed imports per HACKING in files touched.

    Change-Id: I455637a9feb802291dfaf2ef694dabc2607784f9

[Kiall Mac Innes (kiall)]

I've just started noticing this with the latest stable/diablo branch, should this (or part of this) make its way in there as well?

[Mark McLoughlin (markmc)]

Kiall: would be good to file a separate bug against the stable branch and include the full details of what you're seeing. There's been major changes around this code, so it may not be the same thing