yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1396561] [NEW] Thrown VirtualInterfaceCreateException in state transition "REVERT_RESIZE/resize_reverting"

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Andrey Alekov <alekov.a.v@xxxxxxxxx>
Date: Wed, 26 Nov 2014 11:38:02 -0000
Reply-to: Bug 1396561 <1396561@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

During testing I'm found failed test
tempest.api.compute.servers.test_server_actions.ServerActionsTestJSON.test_resize_server_revert.

In logs I see that Nova driver can't create Virtual Interface.

nova-cpu log:
2014-11-26 02:51:31.155 ERROR nova.compute.manager [req-eccbfabd-d7e5-4bd3-ada7-e8724c26006b ServerActionsTestJSON-1358543170 ServerActionsTestJSON-1816477883] [instance: 1de4f75b-9a92-42a7-b7f5-f3d79d062ac7] Setting instance vm_state to ERROR
2014-11-26 02:51:31.155 TRACE nova.compute.manager [instance: 1de4f75b-9a92-42a7-b7f5-f3d79d062ac7] Traceback (most recent call last):
2014-11-26 02:51:31.155 TRACE nova.compute.manager [instance: 1de4f75b-9a92-42a7-b7f5-f3d79d062ac7]   File "/opt/stack/nova/nova/compute/manager.py", line 6105, in _error_out_instance_on_exception
2014-11-26 02:51:31.155 TRACE nova.compute.manager [instance: 1de4f75b-9a92-42a7-b7f5-f3d79d062ac7]     yield
2014-11-26 02:51:31.155 TRACE nova.compute.manager [instance: 1de4f75b-9a92-42a7-b7f5-f3d79d062ac7]   File "/opt/stack/nova/nova/compute/manager.py", line 3572, in finish_revert_resize
2014-11-26 02:51:31.155 TRACE nova.compute.manager [instance: 1de4f75b-9a92-42a7-b7f5-f3d79d062ac7]     block_device_info, power_on)
2014-11-26 02:51:31.155 TRACE nova.compute.manager [instance: 1de4f75b-9a92-42a7-b7f5-f3d79d062ac7]   File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 6197, in finish_revert_migration
2014-11-26 02:51:31.155 TRACE nova.compute.manager [instance: 1de4f75b-9a92-42a7-b7f5-f3d79d062ac7]     block_device_info, power_on)
2014-11-26 02:51:31.155 TRACE nova.compute.manager [instance: 1de4f75b-9a92-42a7-b7f5-f3d79d062ac7]   File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 4521, in _create_domain_and_network
2014-11-26 02:51:31.155 TRACE nova.compute.manager [instance: 1de4f75b-9a92-42a7-b7f5-f3d79d062ac7]     raise exception.VirtualInterfaceCreateException()
2014-11-26 02:51:31.155 TRACE nova.compute.manager [instance: 1de4f75b-9a92-42a7-b7f5-f3d79d062ac7] VirtualInterfaceCreateException: Virtual Interface creation failed
2014-11-26 02:51:31.282 DEBUG oslo.concurrency.lockutils [req-eccbfabd-d7e5-4bd3-ada7-e8724c26006b ServerActionsTestJSON-1358543170 ServerActionsTestJSON-1816477883] Lock "compute_resources" acquired by "update_usage" :: waited 0.000s from (pid=2213) inner /usr/local/lib/python2.7/dist-packages/oslo/concurrency/lockutils.py:310te_service record updated for ('devstack-server01', 'devstack-server01')8724c26006b ServerActionsTestJSON-1358543170 ServerActionsTestJSON-1816477883] Lock "compute_resources" released by "update_usage" :: held 0.052s from (pid=2213) inner /usr/local/lib/python2.7/dist-packages/oslo/concurrency/lockutils.py:322 "compute_resources" acquired by "update_usage" :: waited 0.000s from (pid=2213) inner /usr/local/lib/python2.7/dist-packages/oslo/concurrency/lockutils.py:310te_service record updated for ('devstack-server01', 'devstack-server01')8724c26006b ServerActionsTestJSON-1358543170 ServerActionsTestJSON-1816477883] Lock "compute_resources" released by "update_usage" :: held 0.049s from (pid=2213) inner /usr/local/lib/python2.7/dist-packages/oslo/concurrency/loc2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher Traceback (most recent call last):
2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher   File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 134, in _dispatch_and_reply
2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher     incoming.message))
2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher   File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 177, in _dispatch
2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher     return self._do_dispatch(endpoint, method, ctxt, args)
2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher   File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 123, in _do_dispatch
2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher     result = getattr(endpoint, method)(ctxt, **new_args)
2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/nova/nova/exception.py", line 88, in wrapped
2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher     payload)
2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher   File "/usr/local/lib/python2.7/dist-packages/oslo/utils/excutils.py", line 82, in __exit__
2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/nova/nova/exception.py", line 71, in wrapped
2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher     return f(self, context, *args, **kw)
2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/nova/nova/compute/manager.py", line 294, in decorated_function
2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher     pass
2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher   File "/usr/local/lib/python2.7/dist-packages/oslo/utils/excutils.py", line 82, in __exit__
2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/nova/nova/compute/manager.py", line 279, in decorated_function
2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher     return function(self, context, *args, **kwargs)
2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/nova/nova/compute/manager.py", line 344, in decorated_function
2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher     return function(self, context, *args, **kwargs)
2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/nova/nova/compute/manager.py", line 322, in decorated_function
2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher     kwargs['instance'], e, sys.exc_info())
2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher   File "/usr/local/lib/python2.7/dist-packages/oslo/utils/excutils.py", line 82, in __exit__
2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/nova/nova/compute/manager.py", line 310, in decorated_function
2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher     return function(self, context, *args, **kwargs)
2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/nova/nova/compute/manager.py", line 3572, in finish_revert_resize
2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher     block_device_info, power_on)
2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 6197, in finish_revert_migration
2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher     block_device_info, power_on)
2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 4521, in _create_domain_and_network
2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher     raise exception.VirtualInterfaceCreateException()
2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher VirtualInterfaceCreateException: Virtual Interface creation failed
2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher


Test log:
2014-11-26 02:51:31,536 28307 DEBUG    [tempest.common.rest_client] Request (ServerActionsTestJSON:tearDown): 200 GET http://192.168.75.2:8774/v2/35285e9b7d3a40c2856ae872a4843663/servers/1de4f75b-9a92-42a7-b7f5-f3d79d062ac7 0.170s
    Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: None
    Response - Headers: {'status': '200', 'content-length': '1687', 'content-location': 'http://192.168.75.2:8774/v2/35285e9b7d3a40c2856ae872a4843663/servers/1de4f75b-9a92-42a7-b7f5-f3d79d062ac7', 'x-compute-request-id': 'req-f363ab22-3bc8-4c4d-a2dc-f65c58206be9', 'connection': 'close', 'date': 'Wed, 26 Nov 2014 02:51:31 GMT', 'content-type': 'application/json'}
        Body: {"server": {"status": "ERROR", "updated": "2014-11-26T02:51:31Z", "hostId": "68c6f0346242954c65f893a4fff3fe6afda7a3327ada98b8716d6d02", "addresses": {"ServerActionsTestJSON-413601392-network": [{"OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:83:8e:fb", "version": 4, "addr": "10.100.0.2", "OS-EXT-IPS:type": "fixed"}]}, "links": [{"href": "http://192.168.75.2:8774/v2/35285e9b7d3a40c2856ae872a4843663/servers/1de4f75b-9a92-42a7-b7f5-f3d79d062ac7";, "rel": "self"}, {"href": "http://192.168.75.2:8774/35285e9b7d3a40c2856ae872a4843663/servers/1de4f75b-9a92-42a7-b7f5-f3d79d062ac7";, "rel": "bookmark"}], "key_name": null, "image": {"id": "db54e8ba-c6ae-40ec-9b39-30f739fb3a90", "links": [{"href": "http://192.168.75.2:8774/35285e9b7d3a40c2856ae872a4843663/images/db54e8ba-c6ae-40ec-9b39-30f739fb3a90";, "rel": "bookmark"}]}, "OS-EXT-STS:task_state": null, "OS-EXT-STS:vm_state": "error", "OS-SRV-USG:launched_at": "2014-11-26T02:46:22.000000", "flavor": {"id": "42", "links": [{"href": "http://192.168.75.2:8774/35285e9b7d3a40c2856ae872a4843663/flavors/42";, "rel": "bookmark"}]}, "id": "1de4f75b-9a92-42a7-b7f5-f3d79d062ac7", "security_groups": [{"name": "default"}], "OS-SRV-USG:terminated_at": null, "OS-EXT-AZ:availability_zone": "nova", "user_id": "1b9dc6614af14bb4aed296643d209ace", "name": "server-310696776", "created": "2014-11-26T02:41:52Z", "tenant_id": "35285e9b7d3a40c2856ae872a4843663", "OS-DCF:diskConfig": "MANUAL", "os-extended-volumes:volumes_attached": [], "accessIPv4": "", "accessIPv6": "", "fault": {"message": "Virtual Interface creation failed", "code": 500, "created": "2014-11-26T02:51:31Z"}, "OS-EXT-STS:power_state": 1, "config_drive": "", "metadata": {"rebuild": "server"}}}
2014-11-26 02:51:31,550 28307 INFO     [tempest.common.waiters] State transition "REVERT_RESIZE/resize_reverting" ==> "ERROR/None" after 110 second wait
2014-11-26 02:51:31,551 28307 ERROR    [tempest.api.compute.base] Server 1de4f75b-9a92-42a7-b7f5-f3d79d062ac7 failed to build and is in ERROR status
Details: {u'message': u'Virtual Interface creation failed', u'code': 500, u'created': u'2014-11-26T02:51:31Z'}
2014-11-26 02:51:31.551 28307 TRACE tempest.api.compute.base Traceback (most recent call last):
2014-11-26 02:51:31.551 28307 TRACE tempest.api.compute.base   File "tempest/api/compute/base.py", line 162, in server_check_teardown
2014-11-26 02:51:31.551 28307 TRACE tempest.api.compute.base     'ACTIVE')
2014-11-26 02:51:31.551 28307 TRACE tempest.api.compute.base   File "tempest/services/compute/json/servers_client.py", line 183, in wait_for_server_status
2014-11-26 02:51:31.551 28307 TRACE tempest.api.compute.base     ready_wait=ready_wait)
2014-11-26 02:51:31.551 28307 TRACE tempest.api.compute.base   File "tempest/common/waiters.py", line 77, in wait_for_server_status
2014-11-26 02:51:31.551 28307 TRACE tempest.api.compute.base     server_id=server_id)
2014-11-26 02:51:31.551 28307 TRACE tempest.api.compute.base BuildErrorException: Server 1de4f75b-9a92-42a7-b7f5-f3d79d062ac7 failed to build and is in ERROR status
2014-11-26 02:51:31.551 28307 TRACE tempest.api.compute.base Details: {u'message': u'Virtual Interface creation failed', u'code': 500, u'created': u'2014-11-26T02:51:31Z'}
2014-11-26 02:51:31.551 28307 TRACE tempest.api.compute.base 
2014-11-26 02:51:31,843 28307 DEBUG    [tempest.common.rest_client] Request (ServerActionsTestJSON:tearDown): 204 DELETE http://192.168.75.2:8774/v2/35285e9b7d3a40c2856ae872a4843663/servers/1de4f75b-9a92-42a7-b7f5-f3d79d062ac7 0.290s
    Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: None
    Response - Headers: {'status': '204', 'content-length': '0', 'x-compute-request-id': 'req-5381e365-594e-42e7-84e1-0807206822b7', 'connection': 'close', 'date': 'Wed, 26 Nov 2014 02:51:31 GMT', 'content-type': 'application/json'}
        Body: 
2014-11-26 02:51:31,970 28307 DEBUG    [tempest.common.rest_client] Request (ServerActionsTestJSON:tearDown): 200 GET http://192.168.75.2:8774/v2/35285e9b7d3a40c2856ae872a4843663/servers/1de4f75b-9a92-42a7-b7f5-f3d79d062ac7 0.126s
    Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: None
    Response - Headers: {'status': '200', 'content-length': '1693', 'content-location': 'http://192.168.75.2:8774/v2/35285e9b7d3a40c2856ae872a4843663/servers/1de4f75b-9a92-42a7-b7f5-f3d79d062ac7', 'x-compute-request-id': 'req-d2468758-929a-4b3c-9b6c-58c45c9f50d6', 'connection': 'close', 'date': 'Wed, 26 Nov 2014 02:51:31 GMT', 'content-type': 'application/json'}
        Body: {"server": {"status": "ERROR", "updated": "2014-11-26T02:51:31Z", "hostId": "68c6f0346242954c65f893a4fff3fe6afda7a3327ada98b8716d6d02", "addresses": {"ServerActionsTestJSON-413601392-network": [{"OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:83:8e:fb", "version": 4, "addr": "10.100.0.2", "OS-EXT-IPS:type": "fixed"}]}, "links": [{"href": "http://192.168.75.2:8774/v2/35285e9b7d3a40c2856ae872a4843663/servers/1de4f75b-9a92-42a7-b7f5-f3d79d062ac7";, "rel": "self"}, {"href": "http://192.168.75.2:8774/35285e9b7d3a40c2856ae872a4843663/servers/1de4f75b-9a92-42a7-b7f5-f3d79d062ac7";, "rel": "bookmark"}], "key_name": null, "image": {"id": "db54e8ba-c6ae-40ec-9b39-30f739fb3a90", "links": [{"href": "http://192.168.75.2:8774/35285e9b7d3a40c2856ae872a4843663/images/db54e8ba-c6ae-40ec-9b39-30f739fb3a90";, "rel": "bookmark"}]}, "OS-EXT-STS:task_state": "deleting", "OS-EXT-STS:vm_state": "error", "OS-SRV-USG:launched_at": "2014-11-26T02:46:22.000000", "flavor": {"id": "42", "links": [{"href": "http://192.168.75.2:8774/35285e9b7d3a40c2856ae872a4843663/flavors/42";, "rel": "bookmark"}]}, "id": "1de4f75b-9a92-42a7-b7f5-f3d79d062ac7", "security_groups": [{"name": "default"}], "OS-SRV-USG:terminated_at": null, "OS-EXT-AZ:availability_zone": "nova", "user_id": "1b9dc6614af14bb4aed296643d209ace", "name": "server-310696776", "created": "2014-11-26T02:41:52Z", "tenant_id": "35285e9b7d3a40c2856ae872a4843663", "OS-DCF:diskConfig": "MANUAL", "os-extended-volumes:volumes_attached": [], "accessIPv4": "", "accessIPv6": "", "fault": {"message": "Virtual Interface creation failed", "code": 500, "created": "2014-11-26T02:51:31Z"}, "OS-EXT-STS:power_state": 1, "config_drive": "", "metadata": {"rebuild": "server"}}}
}}}

traceback-1: {{{
Traceback (most recent call last):
  File "tempest/api/compute/servers/test_server_actions.py", line 51, in tearDown
    self.server_check_teardown()
  File "tempest/api/compute/base.py", line 166, in server_check_teardown
    cls.servers_client.wait_for_server_termination(cls.server_id)
  File "tempest/services/compute/json/servers_client.py", line 196, in wait_for_server_termination
    raise exceptions.BuildErrorException(server_id=server_id)
BuildErrorException: Server 1de4f75b-9a92-42a7-b7f5-f3d79d062ac7 failed to build and is in ERROR status
}}}

Traceback (most recent call last):
  File "tempest/api/compute/servers/test_server_actions.py", line 240, in test_resize_server_revert
    self.client.wait_for_server_status(self.server_id, 'ACTIVE')
  File "tempest/services/compute/json/servers_client.py", line 183, in wait_for_server_status
    ready_wait=ready_wait)
  File "tempest/common/waiters.py", line 97, in wait_for_server_status
    raise exceptions.TimeoutException(message)
TimeoutException: Request timed out
Details: (ServerActionsTestJSON:test_resize_server_revert) Server 1de4f75b-9a92-42a7-b7f5-f3d79d062ac7 failed to reach ACTIVE status and task state "None" within the required time (196 s). Current status: REVERT_RESIZE. Current task state: resize_reverting.



Also looks like it's same problem
https://bugs.launchpad.net/nova/+bug/1337860.

** Affects: nova
     Importance: Undecided
         Status: New

** Summary changed:

- Thrown VirtualInterfaceCreateException in state State transition "REVERT_RESIZE/resize_reverting"
+ Thrown VirtualInterfaceCreateException in state transition "REVERT_RESIZE/resize_reverting"

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/1396561

Title:
  Thrown VirtualInterfaceCreateException in state transition
  "REVERT_RESIZE/resize_reverting"

Status in OpenStack Compute (Nova):
  New

Bug description:
  During testing I'm found failed test
  tempest.api.compute.servers.test_server_actions.ServerActionsTestJSON.test_resize_server_revert.

  In logs I see that Nova driver can't create Virtual Interface.

  nova-cpu log:
  2014-11-26 02:51:31.155 ERROR nova.compute.manager [req-eccbfabd-d7e5-4bd3-ada7-e8724c26006b ServerActionsTestJSON-1358543170 ServerActionsTestJSON-1816477883] [instance: 1de4f75b-9a92-42a7-b7f5-f3d79d062ac7] Setting instance vm_state to ERROR
  2014-11-26 02:51:31.155 TRACE nova.compute.manager [instance: 1de4f75b-9a92-42a7-b7f5-f3d79d062ac7] Traceback (most recent call last):
  2014-11-26 02:51:31.155 TRACE nova.compute.manager [instance: 1de4f75b-9a92-42a7-b7f5-f3d79d062ac7]   File "/opt/stack/nova/nova/compute/manager.py", line 6105, in _error_out_instance_on_exception
  2014-11-26 02:51:31.155 TRACE nova.compute.manager [instance: 1de4f75b-9a92-42a7-b7f5-f3d79d062ac7]     yield
  2014-11-26 02:51:31.155 TRACE nova.compute.manager [instance: 1de4f75b-9a92-42a7-b7f5-f3d79d062ac7]   File "/opt/stack/nova/nova/compute/manager.py", line 3572, in finish_revert_resize
  2014-11-26 02:51:31.155 TRACE nova.compute.manager [instance: 1de4f75b-9a92-42a7-b7f5-f3d79d062ac7]     block_device_info, power_on)
  2014-11-26 02:51:31.155 TRACE nova.compute.manager [instance: 1de4f75b-9a92-42a7-b7f5-f3d79d062ac7]   File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 6197, in finish_revert_migration
  2014-11-26 02:51:31.155 TRACE nova.compute.manager [instance: 1de4f75b-9a92-42a7-b7f5-f3d79d062ac7]     block_device_info, power_on)
  2014-11-26 02:51:31.155 TRACE nova.compute.manager [instance: 1de4f75b-9a92-42a7-b7f5-f3d79d062ac7]   File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 4521, in _create_domain_and_network
  2014-11-26 02:51:31.155 TRACE nova.compute.manager [instance: 1de4f75b-9a92-42a7-b7f5-f3d79d062ac7]     raise exception.VirtualInterfaceCreateException()
  2014-11-26 02:51:31.155 TRACE nova.compute.manager [instance: 1de4f75b-9a92-42a7-b7f5-f3d79d062ac7] VirtualInterfaceCreateException: Virtual Interface creation failed
  2014-11-26 02:51:31.282 DEBUG oslo.concurrency.lockutils [req-eccbfabd-d7e5-4bd3-ada7-e8724c26006b ServerActionsTestJSON-1358543170 ServerActionsTestJSON-1816477883] Lock "compute_resources" acquired by "update_usage" :: waited 0.000s from (pid=2213) inner /usr/local/lib/python2.7/dist-packages/oslo/concurrency/lockutils.py:310te_service record updated for ('devstack-server01', 'devstack-server01')8724c26006b ServerActionsTestJSON-1358543170 ServerActionsTestJSON-1816477883] Lock "compute_resources" released by "update_usage" :: held 0.052s from (pid=2213) inner /usr/local/lib/python2.7/dist-packages/oslo/concurrency/lockutils.py:322 "compute_resources" acquired by "update_usage" :: waited 0.000s from (pid=2213) inner /usr/local/lib/python2.7/dist-packages/oslo/concurrency/lockutils.py:310te_service record updated for ('devstack-server01', 'devstack-server01')8724c26006b ServerActionsTestJSON-1358543170 ServerActionsTestJSON-1816477883] Lock "compute_resources" released by "update_usage" :: held 0.049s from (pid=2213) inner /usr/local/lib/python2.7/dist-packages/oslo/concurrency/loc2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher Traceback (most recent call last):
  2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher   File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 134, in _dispatch_and_reply
  2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher     incoming.message))
  2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher   File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 177, in _dispatch
  2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher     return self._do_dispatch(endpoint, method, ctxt, args)
  2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher   File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 123, in _do_dispatch
  2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher     result = getattr(endpoint, method)(ctxt, **new_args)
  2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/nova/nova/exception.py", line 88, in wrapped
  2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher     payload)
  2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher   File "/usr/local/lib/python2.7/dist-packages/oslo/utils/excutils.py", line 82, in __exit__
  2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
  2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/nova/nova/exception.py", line 71, in wrapped
  2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher     return f(self, context, *args, **kw)
  2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/nova/nova/compute/manager.py", line 294, in decorated_function
  2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher     pass
  2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher   File "/usr/local/lib/python2.7/dist-packages/oslo/utils/excutils.py", line 82, in __exit__
  2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
  2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/nova/nova/compute/manager.py", line 279, in decorated_function
  2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher     return function(self, context, *args, **kwargs)
  2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/nova/nova/compute/manager.py", line 344, in decorated_function
  2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher     return function(self, context, *args, **kwargs)
  2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/nova/nova/compute/manager.py", line 322, in decorated_function
  2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher     kwargs['instance'], e, sys.exc_info())
  2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher   File "/usr/local/lib/python2.7/dist-packages/oslo/utils/excutils.py", line 82, in __exit__
  2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
  2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/nova/nova/compute/manager.py", line 310, in decorated_function
  2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher     return function(self, context, *args, **kwargs)
  2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/nova/nova/compute/manager.py", line 3572, in finish_revert_resize
  2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher     block_device_info, power_on)
  2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 6197, in finish_revert_migration
  2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher     block_device_info, power_on)
  2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 4521, in _create_domain_and_network
  2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher     raise exception.VirtualInterfaceCreateException()
  2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher VirtualInterfaceCreateException: Virtual Interface creation failed
  2014-11-26 02:51:31.517 TRACE oslo.messaging.rpc.dispatcher

  
  Test log:
  2014-11-26 02:51:31,536 28307 DEBUG    [tempest.common.rest_client] Request (ServerActionsTestJSON:tearDown): 200 GET http://192.168.75.2:8774/v2/35285e9b7d3a40c2856ae872a4843663/servers/1de4f75b-9a92-42a7-b7f5-f3d79d062ac7 0.170s
      Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
          Body: None
      Response - Headers: {'status': '200', 'content-length': '1687', 'content-location': 'http://192.168.75.2:8774/v2/35285e9b7d3a40c2856ae872a4843663/servers/1de4f75b-9a92-42a7-b7f5-f3d79d062ac7', 'x-compute-request-id': 'req-f363ab22-3bc8-4c4d-a2dc-f65c58206be9', 'connection': 'close', 'date': 'Wed, 26 Nov 2014 02:51:31 GMT', 'content-type': 'application/json'}
          Body: {"server": {"status": "ERROR", "updated": "2014-11-26T02:51:31Z", "hostId": "68c6f0346242954c65f893a4fff3fe6afda7a3327ada98b8716d6d02", "addresses": {"ServerActionsTestJSON-413601392-network": [{"OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:83:8e:fb", "version": 4, "addr": "10.100.0.2", "OS-EXT-IPS:type": "fixed"}]}, "links": [{"href": "http://192.168.75.2:8774/v2/35285e9b7d3a40c2856ae872a4843663/servers/1de4f75b-9a92-42a7-b7f5-f3d79d062ac7";, "rel": "self"}, {"href": "http://192.168.75.2:8774/35285e9b7d3a40c2856ae872a4843663/servers/1de4f75b-9a92-42a7-b7f5-f3d79d062ac7";, "rel": "bookmark"}], "key_name": null, "image": {"id": "db54e8ba-c6ae-40ec-9b39-30f739fb3a90", "links": [{"href": "http://192.168.75.2:8774/35285e9b7d3a40c2856ae872a4843663/images/db54e8ba-c6ae-40ec-9b39-30f739fb3a90";, "rel": "bookmark"}]}, "OS-EXT-STS:task_state": null, "OS-EXT-STS:vm_state": "error", "OS-SRV-USG:launched_at": "2014-11-26T02:46:22.000000", "flavor": {"id": "42", "links": [{"href": "http://192.168.75.2:8774/35285e9b7d3a40c2856ae872a4843663/flavors/42";, "rel": "bookmark"}]}, "id": "1de4f75b-9a92-42a7-b7f5-f3d79d062ac7", "security_groups": [{"name": "default"}], "OS-SRV-USG:terminated_at": null, "OS-EXT-AZ:availability_zone": "nova", "user_id": "1b9dc6614af14bb4aed296643d209ace", "name": "server-310696776", "created": "2014-11-26T02:41:52Z", "tenant_id": "35285e9b7d3a40c2856ae872a4843663", "OS-DCF:diskConfig": "MANUAL", "os-extended-volumes:volumes_attached": [], "accessIPv4": "", "accessIPv6": "", "fault": {"message": "Virtual Interface creation failed", "code": 500, "created": "2014-11-26T02:51:31Z"}, "OS-EXT-STS:power_state": 1, "config_drive": "", "metadata": {"rebuild": "server"}}}
  2014-11-26 02:51:31,550 28307 INFO     [tempest.common.waiters] State transition "REVERT_RESIZE/resize_reverting" ==> "ERROR/None" after 110 second wait
  2014-11-26 02:51:31,551 28307 ERROR    [tempest.api.compute.base] Server 1de4f75b-9a92-42a7-b7f5-f3d79d062ac7 failed to build and is in ERROR status
  Details: {u'message': u'Virtual Interface creation failed', u'code': 500, u'created': u'2014-11-26T02:51:31Z'}
  2014-11-26 02:51:31.551 28307 TRACE tempest.api.compute.base Traceback (most recent call last):
  2014-11-26 02:51:31.551 28307 TRACE tempest.api.compute.base   File "tempest/api/compute/base.py", line 162, in server_check_teardown
  2014-11-26 02:51:31.551 28307 TRACE tempest.api.compute.base     'ACTIVE')
  2014-11-26 02:51:31.551 28307 TRACE tempest.api.compute.base   File "tempest/services/compute/json/servers_client.py", line 183, in wait_for_server_status
  2014-11-26 02:51:31.551 28307 TRACE tempest.api.compute.base     ready_wait=ready_wait)
  2014-11-26 02:51:31.551 28307 TRACE tempest.api.compute.base   File "tempest/common/waiters.py", line 77, in wait_for_server_status
  2014-11-26 02:51:31.551 28307 TRACE tempest.api.compute.base     server_id=server_id)
  2014-11-26 02:51:31.551 28307 TRACE tempest.api.compute.base BuildErrorException: Server 1de4f75b-9a92-42a7-b7f5-f3d79d062ac7 failed to build and is in ERROR status
  2014-11-26 02:51:31.551 28307 TRACE tempest.api.compute.base Details: {u'message': u'Virtual Interface creation failed', u'code': 500, u'created': u'2014-11-26T02:51:31Z'}
  2014-11-26 02:51:31.551 28307 TRACE tempest.api.compute.base 
  2014-11-26 02:51:31,843 28307 DEBUG    [tempest.common.rest_client] Request (ServerActionsTestJSON:tearDown): 204 DELETE http://192.168.75.2:8774/v2/35285e9b7d3a40c2856ae872a4843663/servers/1de4f75b-9a92-42a7-b7f5-f3d79d062ac7 0.290s
      Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
          Body: None
      Response - Headers: {'status': '204', 'content-length': '0', 'x-compute-request-id': 'req-5381e365-594e-42e7-84e1-0807206822b7', 'connection': 'close', 'date': 'Wed, 26 Nov 2014 02:51:31 GMT', 'content-type': 'application/json'}
          Body: 
  2014-11-26 02:51:31,970 28307 DEBUG    [tempest.common.rest_client] Request (ServerActionsTestJSON:tearDown): 200 GET http://192.168.75.2:8774/v2/35285e9b7d3a40c2856ae872a4843663/servers/1de4f75b-9a92-42a7-b7f5-f3d79d062ac7 0.126s
      Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
          Body: None
      Response - Headers: {'status': '200', 'content-length': '1693', 'content-location': 'http://192.168.75.2:8774/v2/35285e9b7d3a40c2856ae872a4843663/servers/1de4f75b-9a92-42a7-b7f5-f3d79d062ac7', 'x-compute-request-id': 'req-d2468758-929a-4b3c-9b6c-58c45c9f50d6', 'connection': 'close', 'date': 'Wed, 26 Nov 2014 02:51:31 GMT', 'content-type': 'application/json'}
          Body: {"server": {"status": "ERROR", "updated": "2014-11-26T02:51:31Z", "hostId": "68c6f0346242954c65f893a4fff3fe6afda7a3327ada98b8716d6d02", "addresses": {"ServerActionsTestJSON-413601392-network": [{"OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:83:8e:fb", "version": 4, "addr": "10.100.0.2", "OS-EXT-IPS:type": "fixed"}]}, "links": [{"href": "http://192.168.75.2:8774/v2/35285e9b7d3a40c2856ae872a4843663/servers/1de4f75b-9a92-42a7-b7f5-f3d79d062ac7";, "rel": "self"}, {"href": "http://192.168.75.2:8774/35285e9b7d3a40c2856ae872a4843663/servers/1de4f75b-9a92-42a7-b7f5-f3d79d062ac7";, "rel": "bookmark"}], "key_name": null, "image": {"id": "db54e8ba-c6ae-40ec-9b39-30f739fb3a90", "links": [{"href": "http://192.168.75.2:8774/35285e9b7d3a40c2856ae872a4843663/images/db54e8ba-c6ae-40ec-9b39-30f739fb3a90";, "rel": "bookmark"}]}, "OS-EXT-STS:task_state": "deleting", "OS-EXT-STS:vm_state": "error", "OS-SRV-USG:launched_at": "2014-11-26T02:46:22.000000", "flavor": {"id": "42", "links": [{"href": "http://192.168.75.2:8774/35285e9b7d3a40c2856ae872a4843663/flavors/42";, "rel": "bookmark"}]}, "id": "1de4f75b-9a92-42a7-b7f5-f3d79d062ac7", "security_groups": [{"name": "default"}], "OS-SRV-USG:terminated_at": null, "OS-EXT-AZ:availability_zone": "nova", "user_id": "1b9dc6614af14bb4aed296643d209ace", "name": "server-310696776", "created": "2014-11-26T02:41:52Z", "tenant_id": "35285e9b7d3a40c2856ae872a4843663", "OS-DCF:diskConfig": "MANUAL", "os-extended-volumes:volumes_attached": [], "accessIPv4": "", "accessIPv6": "", "fault": {"message": "Virtual Interface creation failed", "code": 500, "created": "2014-11-26T02:51:31Z"}, "OS-EXT-STS:power_state": 1, "config_drive": "", "metadata": {"rebuild": "server"}}}
  }}}

  traceback-1: {{{
  Traceback (most recent call last):
    File "tempest/api/compute/servers/test_server_actions.py", line 51, in tearDown
      self.server_check_teardown()
    File "tempest/api/compute/base.py", line 166, in server_check_teardown
      cls.servers_client.wait_for_server_termination(cls.server_id)
    File "tempest/services/compute/json/servers_client.py", line 196, in wait_for_server_termination
      raise exceptions.BuildErrorException(server_id=server_id)
  BuildErrorException: Server 1de4f75b-9a92-42a7-b7f5-f3d79d062ac7 failed to build and is in ERROR status
  }}}

  Traceback (most recent call last):
    File "tempest/api/compute/servers/test_server_actions.py", line 240, in test_resize_server_revert
      self.client.wait_for_server_status(self.server_id, 'ACTIVE')
    File "tempest/services/compute/json/servers_client.py", line 183, in wait_for_server_status
      ready_wait=ready_wait)
    File "tempest/common/waiters.py", line 97, in wait_for_server_status
      raise exceptions.TimeoutException(message)
  TimeoutException: Request timed out
  Details: (ServerActionsTestJSON:test_resize_server_revert) Server 1de4f75b-9a92-42a7-b7f5-f3d79d062ac7 failed to reach ACTIVE status and task state "None" within the required time (196 s). Current status: REVERT_RESIZE. Current task state: resize_reverting.




  Also looks like it's same problem
  https://bugs.launchpad.net/nova/+bug/1337860.

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1396561/+subscriptions
Follow ups

[Bug 1396561] Re: Thrown VirtualInterfaceCreateException in state transition "REVERT_RESIZE/resize_reverting"
From: Joe Gordon, 2015-01-22
[Bug 1396561] [NEW] Thrown VirtualInterfaceCreateException in state transition "REVERT_RESIZE/resize_reverting"
From: Andrey Alekov, 2014-11-26
References

[Bug 1396561] [NEW] Thrown VirtualInterfaceCreateException in state transition "REVERT_RESIZE/resize_reverting"
From: Andrey Alekov, 2014-11-26