nova-network logs exception when starting up

[Thierry Carrez]

Installed from scratch bzr807 on Ubuntu Natty using PPA packages.

On first startup, nova-network logged the following exception:

2011-03-16 09:34:56,748 DEBUG nova.rpc [-] Initing the Adapter Consumer for network.magellan from (pid=4717) __init__ /usr/lib/pymodules/python2.7/nova/rpc.py:160
2011-03-16 09:35:56,797 ERROR nova [-] in looping call
(nova): TRACE: Traceback (most recent call last):
(nova): TRACE: File "/usr/lib/pymodules/python2.7/nova/utils.py", line 437, in _inner
(nova): TRACE: self.f(*self.args, **self.kw)
(nova): TRACE: File "/usr/lib/pymodules/python2.7/nova/service.py", line 196, in periodic_tasks
(nova): TRACE: self.manager.periodic_tasks(context.get_admin_context())
(nova): TRACE: File "/usr/lib/pymodules/python2.7/nova/network/manager.py", line 151, in periodic_tasks
(nova): TRACE: time)
(nova): TRACE: File "/usr/lib/pymodules/python2.7/nova/db/api.py", line 348, in fixed_ip_disassociate_all_by_timeout
(nova): TRACE: return IMPL.fixed_ip_disassociate_all_by_timeout(context, host, time)
(nova): TRACE: File "/usr/lib/pymodules/python2.7/nova/db/sqlalchemy/api.py", line 98, in wrapper
(nova): TRACE: return f(*args, **kwargs)
(nova): TRACE: File "/usr/lib/pymodules/python2.7/nova/db/sqlalchemy/api.py", line 660, in fixed_ip_disassociate_all_by_timeout
(nova): TRACE: 'leased': 0})
(nova): TRACE: File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2184, in update
(nova): TRACE: "Could not evaluate current criteria in Python. "
(nova): TRACE: InvalidRequestError: Could not evaluate current criteria in Python. Specify 'fetch' or False for the synchronize_session parameter.
(nova): TRACE:

This doesn't seem to prevent it from working afterwards, though I didn't specifically test fixed_ips disassociation.

[Thierry Carrez (ttx)]

Apparently only happens on first startup...

[Kevin Jackson (kevin-linuxservices)]

I've just had this (Maverick + and it does seem to happen only on the first instance start up - subsequent running seems fine:

ii nova-api 2011.2~bzr815-0ubuntu0ppa1~maverick1 OpenStack Compute - Nova - API frontend
ii nova-common 2011.2~bzr815-0ubuntu0ppa1~maverick1 OpenStack Compute - Nova - common files
ii nova-compute 2011.2~bzr815-0ubuntu0ppa1~maverick1 OpenStack Compute - Nova - compute node
ii nova-network 2011.2~bzr815-0ubuntu0ppa1~maverick1 OpenStack Compute - Nova - Network thingamajig
ii nova-objectstore 2011.2~bzr815-0ubuntu0ppa1~maverick1 OpenStack Compute - Nova - object store
ii nova-scheduler 2011.2~bzr815-0ubuntu0ppa1~maverick1 OpenStack Compute - Nova - Scheduler
ii python-nova 2011.2~bzr815-0ubuntu0ppa1~maverick1 OpenStack Compute - Nova - Python libraries
ii python-novaclient 2.4-0ubuntu1~ppa1 client library for OpenStack Compute API

1. start nova services
2. euca-run-instances ....
3. euca-describe-instances shows instance stuck at "launching"
4. /var/log/nova/nova-network.log has above error
5. euca-terminate-instances ....
6. euca-run-instances... works

[Masanori Itoh (itohm)]

I also got this error, and the symptom is exactly the same with Kevin's case.
I tried trunk rev 912 and rpm packages (openstack-nova-2011.2-0.31.bzr912...) by GridDyamics.

One of my colleagues says that vm launching process proceeds in case of trunk rev 905. Thus, I guess the problem would be between rev 905 and 912, and maybe another bug.

[Masanori Itoh (itohm)]

Hi,

Sorry, in my case on RHEL6, it turned out that my symptom was cause by a configuration error. I succeeded to launch a vm using trunk rev 912 even if we got the above error messages regarding fixed_ip_disassociate_all_by_timeout.

But, anyway it looks like that we can suppress the above error messages by suppliyng
an additional parameter 'synchronize_session' as the error message line says.

Explanation of 'synchronize_session' is available below:
  http://www.sqlalchemy.org/docs/orm/query.html?highlight=synchronize_session
and, I would suggest the fix below.

Signed-off-by: Masaori Itoh <email address hidden>

=== modified file 'nova/db/sqlalchemy/api.py'
--- nova/db/sqlalchemy/api.py 2011-03-25 14:21:03 +0000
+++ nova/db/sqlalchemy/api.py 2011-03-30 09:13:29 +0000
@@ -660,7 +660,7 @@
                      filter(models.FixedIp.instance_id != None).\
                      filter_by(allocated=0).\
                      update({'instance_id': None,
- 'leased': 0})
+ 'leased': 0}, synchronize_session='fetch')
     return result

[Masanori Itoh (itohm)]

I pushed a bug fix branch, lp:~itoumsn/nova/lp735974, and changed Status from Confirmed to In Progress.
I hope the fix makes sense...