Migration/Resize fails with Unexpected exception in API method: Circular reference detected

[Eric Miller]

Description
===========

Cold migration of a VM failed, so I tried resizing, and the same error occurred.

Previous to this, I had disabled the compute service on one node, to see if cold migrating VMs would avoid scheduling the VMs on the disabled node. This succeeded a few times, but then this error occurred and now it happens on the two test VMs that I have running in this environment (there are only two VMs total).

Steps to reproduce
==================

Run as "admin" on a test server created by a domain user in its respective domain project:
openstack server migrate <uuid>

It continues to be 100% repeatable. VMs are still operational and can be shut down and powered on without issue.

Expected result
===============

As with previous migrations, a graceful shut down, cold migrate, and power on of the VM.

Actual result
=============

This is returned (note that this is from a different migration attempt than the logs included below):

Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
<type 'exceptions.ValueError'> (HTTP 500) (Request-ID: req-46ce0fd3-5579-48be-9486-499fdea085a1)

Environment
===========

stable/rocky deployed with Kolla-Ansible 7.0.0.0rc3devXX (as of October 15, 2018) with respective Kolla images

Hypervisor: Libvirt + KVM
Storage: iSCSI attached (Blockbridge)
Networking: DVR

Logs & Configs
==============

This is a filtered list of nova files from all nova containers running on all controllers, concatenated and sorted, filtered by the request ID.

/var/lib/docker/volumes/kolla_logs/_data/nova/nova-api.log:2018-10-22 16:05:07.105 26 DEBUG nova.api.openstack.wsgi [req-8a41af8d-23ea-491e-be0a-b0fbe98dd6a7 ebdf7b1025a6464ba150b8ea63bfacb5 a87099d25afd4c599d34b2fae7689dec - default default] Action: 'action', calling method: <bound method MigrateServerController._migrate of <nova.api.openstack.compute.migrate_server.MigrateServerController object at 0x7f46647a4590>>, body: {"migrate": null} _process_stack /var/lib/kolla/venv/lib/python2.7/site-packages/nova/api/openstack/wsgi.py:615

/var/lib/docker/volumes/kolla_logs/_data/nova/nova-api.log:2018-10-22 16:05:07.106 26 DEBUG nova.compute.api [req-8a41af8d-23ea-491e-be0a-b0fbe98dd6a7 ebdf7b1025a6464ba150b8ea63bfacb5 a87099d25afd4c599d34b2fae7689dec - default default] [instance: 2fd8ff29-f64a-4e5b-bfcd-97c52cf6d66d] Fetching instance by UUID get /var/lib/kolla/venv/lib/python2.7/site-packages/nova/compute/api.py:2402

/var/lib/docker/volumes/kolla_logs/_data/nova/nova-api.log:2018-10-22 16:05:07.117 26 DEBUG oslo_concurrency.lockutils [req-8a41af8d-23ea-491e-be0a-b0fbe98dd6a7 ebdf7b1025a6464ba150b8ea63bfacb5 a87099d25afd4c599d34b2fae7689dec - default default] Lock "43894fde-4653-4499-9c83-0e963c974fae" acquired by "nova.context.get_or_set_cached_cell_and_set_connections" :: waited 0.000s inner /var/lib/kolla/venv/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:273

/var/lib/docker/volumes/kolla_logs/_data/nova/nova-api.log:2018-10-22 16:05:07.118 26 DEBUG oslo_concurrency.lockutils [req-8a41af8d-23ea-491e-be0a-b0fbe98dd6a7 ebdf7b1025a6464ba150b8ea63bfacb5 a87099d25afd4c599d34b2fae7689dec - default default] Lock "43894fde-4653-4499-9c83-0e963c974fae" released by "nova.context.get_or_set_cached_cell_and_set_connections" :: held 0.000s inner /var/lib/kolla/venv/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:285

/var/lib/docker/volumes/kolla_logs/_data/nova/nova-api.log:2018-10-22 16:05:07.174 26 DEBUG nova.objects.instance [req-8a41af8d-23ea-491e-be0a-b0fbe98dd6a7 ebdf7b1025a6464ba150b8ea63bfacb5 a87099d25afd4c599d34b2fae7689dec - default default] Lazy-loading 'flavor' on Instance uuid 2fd8ff29-f64a-4e5b-bfcd-97c52cf6d66d obj_load_attr /var/lib/kolla/venv/lib/python2.7/site-packages/nova/objects/instance.py:1109

/var/lib/docker/volumes/kolla_logs/_data/nova/nova-api.log:2018-10-22 16:05:07.212 26 DEBUG nova.compute.api [req-8a41af8d-23ea-491e-be0a-b0fbe98dd6a7 ebdf7b1025a6464ba150b8ea63bfacb5 a87099d25afd4c599d34b2fae7689dec - default default] [instance: 2fd8ff29-f64a-4e5b-bfcd-97c52cf6d66d] flavor_id is None. Assuming migration. resize /var/lib/kolla/venv/lib/python2.7/site-packages/nova/compute/api.py:3448

/var/lib/docker/volumes/kolla_logs/_data/nova/nova-api.log:2018-10-22 16:05:07.213 26 DEBUG nova.compute.api [req-8a41af8d-23ea-491e-be0a-b0fbe98dd6a7 ebdf7b1025a6464ba150b8ea63bfacb5 a87099d25afd4c599d34b2fae7689dec - default default] [instance: 2fd8ff29-f64a-4e5b-bfcd-97c52cf6d66d] Old instance type c5.4xlarge, new instance type c5.4xlarge resize /var/lib/kolla/venv/lib/python2.7/site-packages/nova/compute/api.py:3469

/var/lib/docker/volumes/kolla_logs/_data/nova/nova-api.log:2018-10-22 16:05:09.999 26 ERROR nova.api.openstack.wsgi [req-8a41af8d-23ea-491e-be0a-b0fbe98dd6a7 ebdf7b1025a6464ba150b8ea63bfacb5 a87099d25afd4c599d34b2fae7689dec - default default] Unexpected exception in API method: ValueError: Circular reference detected

/var/lib/docker/volumes/kolla_logs/_data/nova/nova-api.log:2018-10-22 16:05:10.005 26 INFO nova.api.openstack.wsgi [req-8a41af8d-23ea-491e-be0a-b0fbe98dd6a7 ebdf7b1025a6464ba150b8ea63bfacb5 a87099d25afd4c599d34b2fae7689dec - default default] HTTP exception thrown: Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.

/var/lib/docker/volumes/kolla_logs/_data/nova/nova-api.log:2018-10-22 16:05:10.006 26 DEBUG nova.api.openstack.wsgi [req-8a41af8d-23ea-491e-be0a-b0fbe98dd6a7 ebdf7b1025a6464ba150b8ea63bfacb5 a87099d25afd4c599d34b2fae7689dec - default default] Returning 500 to user: Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.

/var/lib/docker/volumes/kolla_logs/_data/nova/nova-api.log:2018-10-22 16:05:10.007 26 INFO nova.osapi_compute.wsgi.server [req-8a41af8d-23ea-491e-be0a-b0fbe98dd6a7 ebdf7b1025a6464ba150b8ea63bfacb5 a87099d25afd4c599d34b2fae7689dec - default default] 104.36.108.132,192.168.4.1 "POST /v2.1/a87099d25afd4c599d34b2fae7689dec/servers/2fd8ff29-f64a-4e5b-bfcd-97c52cf6d66d/action HTTP/1.1" status: 500 len: 603 time: 2.9094801

[Matt Riedemann (mriedem)]

Can you attach the nova-api logs? Kind of need a stacktrace to see where the ValueError is coming from.

[Eric Miller (erickmiller)]

Sorry for the delay - the nova-api log Traceback (as requested in a DM) is below.

Eric

2018-10-22 16:05:09.999 26 ERROR nova.api.openstack.wsgi call_monitor_timeout, retry=retry)
2018-10-22 16:05:09.999 26 ERROR nova.api.openstack.wsgi chunks = self.iterencode(o, _one_shot=True)
2018-10-22 16:05:09.999 26 ERROR nova.api.openstack.wsgi File "/usr/lib64/python2.7/json/encoder.py", line 207, in encode
2018-10-22 16:05:09.999 26 ERROR nova.api.openstack.wsgi File "/usr/lib64/python2.7/json/encoder.py", line 270, in iterencode
2018-10-22 16:05:09.999 26 ERROR nova.api.openstack.wsgi File "/usr/lib64/python2.7/json/__init__.py", line 250, in dumps
2018-10-22 16:05:09.999 26 ERROR nova.api.openstack.wsgi File "/var/lib/kolla/venv/lib/python2.7/site-packages/nova/api/openstack/compute/migrate_server.py", line 56, in _migrate
2018-10-22 16:05:09.999 26 ERROR nova.api.openstack.wsgi File "/var/lib/kolla/venv/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 801, in wrapped
2018-10-22 16:05:09.999 26 ERROR nova.api.openstack.wsgi File "/var/lib/kolla/venv/lib/python2.7/site-packages/nova/api/validation/__init__.py", line 110, in wrapper
2018-10-22 16:05:09.999 26 ERROR nova.api.openstack.wsgi File "/var/lib/kolla/venv/lib/python2.7/site-packages/nova/compute/api.py", line 153, in inner
2018-10-22 16:05:09.999 26 ERROR nova.api.openstack.wsgi File "/var/lib/kolla/venv/lib/python2.7/site-packages/nova/compute/api.py", line 205, in inner
2018-10-22 16:05:09.999 26 ERROR nova.api.openstack.wsgi File "/var/lib/kolla/venv/lib/python2.7/site-packages/nova/compute/api.py", line 213, in _wrapped
2018-10-22 16:05:09.999 26 ERROR nova.api.openstack.wsgi File "/var/lib/kolla/venv/lib/python2.7/site-packages/nova/compute/api.py", line 3553, in resize
2018-10-22 16:05:09.999 26 ERROR nova.api.openstack.wsgi File "/var/lib/kolla/venv/lib/python2.7/site-packages/nova/compute/utils.py", line 1141, in decorated_function
2018-10-22 16:05:09.999 26 ERROR nova.api.openstack.wsgi File "/var/lib/kolla/venv/lib/python2.7/site-packages/nova/conductor/api.py", line 98, in resize_instance
2018-10-22 16:05:09.999 26 ERROR nova.api.openstack.wsgi File "/var/lib/kolla/venv/lib/python2.7/site-packages/nova/conductor/manager.py", line 289, in migrate_server
2018-10-22 16:05:09.999 26 ERROR nova.api.openstack.wsgi File "/var/lib/kolla/venv/lib/python2.7/site-packages/nova/conductor/manager.py", line 318, in _cold_migrate
2018-10-22 16:05:09.999 26 ERROR nova.api.openstack.wsgi File "/var/lib/kolla/venv/lib/python2.7/site-packages/nova/conductor/manager.py", line 349, in _cold_migrate
2018-10-22 16:05:09.999 26 ERROR nova.api.openstack.wsgi File "/var/lib/kolla/venv/lib/python2.7/site-packages/nova/conductor/manager.py", line 86, in wrapper
2018-10-22 16:05:09.999 26 ERROR nova.api.openstack.wsgi File "/var/lib/kolla/venv/lib/python2.7/site-packages/nova/conductor/rpcapi.py", line 338, in migrate_server
2018-10-22 16:05:09.999 26 ERROR nova.api.openstack.wsgi File "/var/lib/kolla/venv/lib/python2.7/site-packages/nova/conductor/tasks/base.py", line 24, in wrap
2018-10-22 16:05:09.999 26 ERROR nova.api.openstack.wsgi File "/var/l...

[Eric Miller (erickmiller)]

Please let me know if you need anything else to diagnose this issue.

It does seem to be a timing issue since I have been able to run a test script with sleep commands between stop, migrate, confirm resize, and start commands and the problem does not occur.

Eric

[Eric Miller (erickmiller)]

Just a quick note that I tested the script with delays and looped it. I ran it 576 times before stopping it - all successful "cold" migrations, whereas a cold migrate while the VM is powered on will create the error described above, which I have yet to find a way to recover from.

Eric

[Erik Olof Gunnar Andersson (eandersson)]

We are seeing the same issue in Rocky and talked to mriedem about it on IRC.
http://eavesdrop.openstack.org/irclogs/%23openstack-nova/%23openstack-nova.2019-08-02.log.html#t2019-08-02T18:37:47

[Balazs Gibizer (balazs-gibizer)]

In the IRC discussion linked in comment #5 the [1] weird piece of code was mentioned, which point to [2]. So I dig that code a bit to see why we really need that and come up with some answers see [3] and [2]. I'm not sure if this helps this bug so I left his here as a FYI.

[1]https://github.com/openstack/nova/blob/stable/rocky/nova/conductor/tasks/migrate.py#L291
[2]https://bugs.launchpad.net/oslo.messaging/+bug/1529084
[3]https://review.opendev.org/#/c/675281/

[Balazs Gibizer (balazs-gibizer)]

I believe that the fix for bug [1] in oslo is fixing you problem.

[1] https://bugs.launchpad.net/oslo.messaging/+bug/1529084

[OpenStack Infra (hudson-openstack)]

Change abandoned by norman shen (<email address hidden>) on branch: master
Review: https://review.opendev.org/732003