[Build "Ubuntu 12.04.3 LTS" 2.0-2434~icehouse]:VM spawn failed due to exception in /usr/lib/python2.7/dist-packages/contrail_vrouter_api/vrouter_api.py", line 128, in add_port

[Sandip Dey]

VM spawn failed. Error as below.

Logs saved at http://mayamruga/Docs/bugs/<bug-id>

2014-11-03 21:47:47.503 2339 AUDIT nova.compute.manager [req-19144961-bdde-42a1-af1b-7896791594f3 0f0adedc1a284424bc86b4f89c140536 7f422a31d0e14a719697f8881c7ce7e8] [instance: cf8c7cfa-06ad-426b-ab04-4ce39ce8c689] Terminating instance
2014-11-03 21:47:47.858 2339 ERROR nova.compute.manager [req-04b601f4-a2ad-40c1-80c0-a3f027a3f39b 9b0f7f00cbe84789bceee9ede888d7cc 7f422a31d0e14a719697f8881c7ce7e8] [instance: a067ca59-eb29-48af-97c8-f976b706c965] Instance failed to spawn
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] Traceback (most recent call last):
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 1717, in _spawn
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] block_device_info)
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py", line 2265, in spawn
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] block_device_info)
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py", line 3667, in _create_domain_and_network
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] self.plug_vifs(instance, network_info)
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py", line 858, in plug_vifs
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] self.vif_driver.plug(instance, vif)
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] File "/usr/lib/python2.7/dist-packages/nova_contrail_vif/contrailvif.py", line 207, in plug
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] **kwargs)
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] File "/usr/lib/python2.7/dist-packages/contrail_vrouter_api/vrouter_api.py", line 128, in add_port
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] result = self._client.AddPort([data])
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] File "/usr/lib/python2.7/dist-packages/contrail_vrouter_api/gen_py/instance_service/InstanceService.py", line 150, in AddPort
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] return self.recv_AddPort()
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] File "/usr/lib/python2.7/dist-packages/contrail_vrouter_api/gen_py/instance_service/InstanceService.py", line 161, in recv_AddPort
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] (fname, mtype, rseqid) = self._iprot.readMessageBegin()
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] File "/usr/lib/python2.7/dist-packages/thrift/protocol/TBinaryProtocol.py", line 126, in readMessageBegin
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] sz = self.readI32()
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] File "/usr/lib/python2.7/dist-packages/thrift/protocol/TBinaryProtocol.py", line 206, in readI32
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] buff = self.trans.readAll(4)
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] File "/usr/lib/python2.7/dist-packages/thrift/transport/TTransport.py", line 58, in readAll
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] chunk = self.read(sz - have)
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] File "/usr/lib/python2.7/dist-packages/thrift/transport/TTransport.py", line 271, in read
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] self.readFrame()
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] File "/usr/lib/python2.7/dist-packages/thrift/transport/TTransport.py", line 275, in readFrame
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] buff = self.__trans.readAll(4)
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] File "/usr/lib/python2.7/dist-packages/thrift/transport/TTransport.py", line 58, in readAll
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] chunk = self.read(sz - have)
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] File "/usr/lib/python2.7/dist-packages/thrift/transport/TSocket.py", line 103, in read
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] buff = self.handle.recv(sz)
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] File "/usr/lib/python2.7/dist-packages/eventlet/greenio.py", line 262, in recv
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] timeout_exc=socket.timeout("timed out"))
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] File "/usr/lib/python2.7/dist-packages/eventlet/hubs/__init__.py", line 151, in trampoline
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] listener = hub.add(hub.READ, fileno, current.switch)
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] File "/usr/lib/python2.7/dist-packages/eventlet/hubs/epolls.py", line 48, in add
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] listener = BaseHub.add(self, evtype, fileno, cb)
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] File "/usr/lib/python2.7/dist-packages/eventlet/hubs/hub.py", line 126, in add
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] evtype, fileno, evtype))
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965] RuntimeError: Second simultaneous read on fileno 9 detected. Unless you really know what you're doing, make sure that only one greenthread can read any particular socket. Consider using a pools.Pool. If you do know what you're doing and want to disable this error, call eventlet.debug.hub_prevent_multiple_readers(False)
2014-11-03 21:47:47.858 2339 TRACE nova.compute.manager [instance: a067ca59-eb29-48af-97c8-f976b706c965]
2014-11-03 21:47:48.349 2339 ERROR nova.compute.manager [req-093c796a-27dd-41cd-8372-99ed971fa4d5 0f0adedc1a284424bc86b4f89c140536 7f422a31d0e14a719697f8881c7ce7e8] [instance: c3a7fc44-106b-4c49-ab69-2f97bd71a9cf] Instance failed to spawn
2014-11-03 21:47:48.349 2339 TRACE nova.compute.manager [instance: c3a7fc44-106b-4c49-ab69-2f97bd71a9cf] Traceback (most recent call last):
2014-11-03 21:47:48.349 2339 TRACE nova.compute.manager [instance: c3a7fc44-106b-4c49-ab69-2f97bd71a9cf] File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 1717, in _spawn
2014-11-03 21:47:48.349 2339 TRACE nova.compute.manager [instance: c3a7fc44-106b-4c49-ab69-2f97bd71a9cf] block_device_info)
2014-11-03 21:47:48.349 2339 TRACE nova.compute.manager [instance: c3a7fc44-106b-4c49-ab69-2f97bd71a9cf] File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py", line 2265, in spawn
2014-11-03 21:47:48.349 2339 TRACE nova.compute.manager [instance: c3a7fc44-106b-4c49-ab69-2f97bd71a9cf] block_device_info)
2014-11-03 21:47:48.349 2339 TRACE nova.compute.manager [instance: c3a7fc44-106b-4c49-ab69-2f97bd71a9cf] File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py", line 3667, in _create_domain_and_network
2014-11-03 21:47:48.349 2339 TRACE nova.compute.manager [instance: c3a7fc44-106b-4c49-ab69-2f97bd71a9cf] self.plug_vifs(instance, network_info)
2014-11-03 21:47:48.349 2339 TRACE nova.compute.manager [instance: c3a7fc44-106b-4c49-ab69-2f97bd71a9cf] File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py", line 858, in plug_vifs
2014-11-03 21:47:48.349 2339 TRACE nova.compute.manager [instance: c3a7fc44-106b-4c49-ab69-2f97bd71a9cf] self.vif_driver.plug(instance, vif)
2014-11-03 21:47:48.349 2339 TRACE nova.compute.manager [instance: c3a7fc44-106b-4c49-ab69-2f97bd71a9cf] File "/usr/lib/python2.7/dist-packages/nova_contrail_vif/contrailvif.py", line 207, in plug
2014-11-03 21:47:48.349 2339 TRACE nova.compute.manager [instance: c3a7fc44-106b-4c49-ab69-2f97bd71a9cf] **kwargs)
2014-11-03 21:47:48.349 2339 TRACE nova.compute.manager [instance: c3a7fc44-106b-4c49-ab69-2f97bd71a9cf] File "/usr/lib/python2.7/dist-packages/contrail_vrouter_api/vrouter_api.py", line 128, in add_port
2014-11-03 21:47:48.349 2339 TRACE nova.compute.manager [instance: c3a7fc44-106b-4c49-ab69-2f97bd71a9cf] result = self._client.AddPort([data])
2014-11-03 21:47:48.349 2339 TRACE nova.compute.manager [instance: c3a7fc44-106b-4c49-ab69-2f97bd71a9cf] AttributeError: 'NoneType' object has no attribute 'AddPort'

[Ashish Ranjan (aranjan-n)]

Pedro, Ajay

  Could you analyze this bug. From my limited understanding of python, the code for add_port in vrouter_api.py looks buggy.

https://github.com/Juniper/contrail-controller/blob/master/src/vnsw/contrail-vrouter-api/contrail_vrouter_api/vrouter_api.py

If we set _client to ‘None’, depending on where we are in the function we can have exception. Isn’t it? Is intention is to run add_port exclusively. If yes, then we should have a lock. I think from the bt it feels like there is some kind of concurrency issue. Any insight will be helpful.

Bug link:
https://bugs.launchpad.net/juniperopenstack/+bug/1389157

thanks
Ashish

[Kumar Harsh (hkumar)]

Hit this issue in [Build "Ubuntu 14.04 LTS" 2.0-22~juno] MultiNode Single Intf Sanity

While trying to spawn vm in testcase 'test_mx_gateway '

Topology :
Config Nodes : [u'nodei11', u'nodei12']
Control Nodes : [u'nodei12', u'nodei13']
Compute Nodes : [u'nodei14', u'nodei15']
Openstack Node : nodei11
WebUI Node : nodei11
Analytics Nodes : [u'nodei11']

/var/log/nova/nova-compute.log :

2014-12-24 07:35:29.582 2180 AUDIT nova.compute.claims [req-f5ae398e-014f-4ab6-821e-deae98200d10 None] [instance: c13062f0-1fbc-4425-ae07-b4e8babe785b] Claim successful
2014-12-24 07:35:29.754 2180 INFO nova.scheduler.client.report [req-f5ae398e-014f-4ab6-821e-deae98200d10 None] Compute_service record updated for ('nodei14', 'nodei14.englab.juniper.net')
2014-12-24 07:35:29.938 2180 INFO nova.scheduler.client.report [req-f5ae398e-014f-4ab6-821e-deae98200d10 None] Compute_service record updated for ('nodei14', 'nodei14.englab.juniper.net')
2014-12-24 07:35:30.524 2180 INFO nova.virt.libvirt.driver [req-f5ae398e-014f-4ab6-821e-deae98200d10 None] [instance: c13062f0-1fbc-4425-ae07-b4e8babe785b] Creating image
2014-12-24 07:35:31.093 2180 INFO nova.scheduler.client.report [-] Compute_service record updated for ('nodei14', 'nodei14.englab.juniper.net')
2014-12-24 07:35:31.303 2180 INFO nova.virt.disk.vfs.api [req-f5ae398e-014f-4ab6-821e-deae98200d10 None] Unable to import guestfsfalling back to VFSLocalFS
2014-12-24 07:35:31.861 2180 ERROR root [-] Second simultaneous read on fileno 21 detected. Unless you really know what you're doing, make sure that only one greenthread can read any particular socket. Consider using a pools.Pool. If you do know what you're doing and want to disable this error, call eventlet.debug.hub_prevent_multiple_readers(False)
2014-12-24 07:35:31.861 2180 TRACE root Traceback (most recent call last):
2014-12-24 07:35:31.861 2180 TRACE root File "/usr/lib/python2.7/dist-packages/contrail_vrouter_api/vrouter_api.py", line 171, in periodic_connection_check
2014-12-24 07:35:31.861 2180 TRACE root self._client.KeepAliveCheck()
2014-12-24 07:35:31.861 2180 TRACE root File "/usr/lib/python2.7/dist-packages/contrail_vrouter_api/gen_py/instance_service/InstanceService.py", line 176, in KeepAliveCheck
2014-12-24 07:35:31.861 2180 TRACE root return self.recv_KeepAliveCheck()
2014-12-24 07:35:31.861 2180 TRACE root File "/usr/lib/python2.7/dist-packages/contrail_vrouter_api/gen_py/instance_service/InstanceService.py", line 186, in recv_KeepAliveCheck
2014-12-24 07:35:31.861 2180 TRACE root (fname, mtype, rseqid) = self._iprot.readMessageBegin()
2014-12-24 07:35:31.861 2180 TRACE root File "/usr/lib/python2.7/dist-packages/thrift/protocol/TBinaryProtocol.py", line 126, in readMessageBegin
2014-12-24 07:35:31.861 2180 TRACE root sz = self.readI32()
2014-12-24 07:35:31.861 2180 TRACE root File "/usr/lib/python2.7/dist-packages/thrift/protocol/TBinaryProtocol.py", line 206, in readI32
2014-12-24 07:35:31.861 2180 TRACE root buff = self.trans.readAll(4)
2014-12-24 07:35:31.861 2180 TRACE root File "/usr/lib/python2.7/dist-packages/thrift/transport/TTransport.py", line 58, in readAll
2014-12-24 07:35:31.861 2180 TRACE ...

[OpenContrail Admin (ci-admin-f)]

Reviewed: https://review.opencontrail.org/7018
Committed: http://github.org/Juniper/contrail-controller/commit/4e2344356fbca3943a4eb698b0195fe680a078f1
Submitter: Zuul
Branch: R2.1

commit 4e2344356fbca3943a4eb698b0195fe680a078f1
Author: ashoksingh <email address hidden>
Date: Wed Feb 4 18:11:13 2015 +0530

Fix AttributeError exception raised by Nova-compute
Add locks to ensure that client object of ContrailVRouterApi is not used while it is being modified.
Partial-Bug: #1389157

Change-Id: I004f404e4c1101d65531865f429a694ac24553a7

[OpenContrail Admin (ci-admin-f)]

Reviewed: https://review.opencontrail.org/7073
Committed: http://github.org/Juniper/contrail-controller/commit/3b4fb07eb863e210196d1939bab165f080cab279
Submitter: Zuul
Branch: master

commit 3b4fb07eb863e210196d1939bab165f080cab279
Author: ashoksingh <email address hidden>
Date: Thu Feb 5 14:53:11 2015 +0530

Fix AttributeError exception raised by Nova-compute
Add locks to ensure that client object of ContrailVRouterApi is not used while it is being modified.
Partial-Bug: #1389157

Change-Id: I5f2a552967cafadbb950d962d428399fbc097070

[OpenContrail Admin (ci-admin-f)]

Reviewed: https://review.opencontrail.org/7074
Committed: http://github.org/Juniper/contrail-nova-vif-driver/commit/3bea814ae43ada89e2deb7dd02fc72b47f9f8d9f
Submitter: Zuul
Branch: master

commit 3bea814ae43ada89e2deb7dd02fc72b47f9f8d9f
Author: ashoksingh <email address hidden>
Date: Thu Feb 5 15:01:33 2015 +0530

Fix AttributeError exception raised by Nova-compute
Add locks to ensure that client object of ContrailVRouterApi is not used while it is being modified.
Partial-Bug: #1389157

Change-Id: I79662c7e82f31f230250597aa86c00ccb3bb51dc

[OpenContrail Admin (ci-admin-f)]

Reviewed: https://review.opencontrail.org/7019
Committed: http://github.org/Juniper/contrail-nova-vif-driver/commit/433c78b4bfa8000cdf4730a3cacb587365eb1ce6
Submitter: Zuul
Branch: R2.1

commit 433c78b4bfa8000cdf4730a3cacb587365eb1ce6
Author: ashoksingh <email address hidden>
Date: Wed Feb 4 18:18:52 2015 +0530

Fix AttributeError exception raised by Nova-compute
Add locks to ensure that client object of ContrailVRouterApi is not used while it is being modified.
Partial-Bug: #1389157

Change-Id: I8e86e900c1d7ce5e4b5a4e7f0429aea9575b7d22

[OpenContrail Admin (ci-admin-f)]

Reviewed: https://review.opencontrail.org/7191
Committed: http://github.org/Juniper/contrail-controller/commit/550babffbee9a75ce143d96c0fce5068f3fd0bb5
Submitter: Zuul
Branch: R2.0

commit 550babffbee9a75ce143d96c0fce5068f3fd0bb5
Author: ashoksingh <email address hidden>
Date: Mon Feb 9 10:34:52 2015 +0530

Fix AttributeError exception raised by Nova-compute
Add locks to ensure that client object of ContrailVRouterApi is not used while it is being modified.
Partial-Bug: #1389157

Change-Id: Ibb775b0e30b4241a2552d5698e7c4d2ccf49d338

[OpenContrail Admin (ci-admin-f)]

Reviewed: https://review.opencontrail.org/7338
Committed: http://github.org/Juniper/contrail-nova-vif-driver/commit/751a395fa92ce11f2b2e9869b6bd69e649e98954
Submitter: Zuul
Branch: R2.0

commit 751a395fa92ce11f2b2e9869b6bd69e649e98954
Author: ashoksingh <email address hidden>
Date: Thu Feb 12 09:15:06 2015 +0530

Fix AttributeError exception raised by Nova-compute
Add locks to ensure that client object of ContrailVRouterApi is not used while it is being modified.
Closes-Bug: #1389157

Change-Id: I42bff175600d61beaff24904cbb86b21543829a1