nova reschedule instance while updating instance task state

[Dongcan Ye]

While booting an instance, if save expected task_state is "block_device_mapping", but it conflicts with actual task_state "spawning". Then nova will raise RescheduledException and reschedule to another host.

original node nova-compute log:
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac] Traceback (most recent call last):
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac]
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac] File "/usr/lib/python2.7/site-packages/nova/conductor/manager.py", line 86, in _object_dispatch
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac] return getattr(target, method)(*args, **kwargs)
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac]
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac] File "/usr/lib/python2.7/site-packages/oslo_versionedobjects/base.py", line 223, in wrapper
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac] return fn(self, *args, **kwargs)
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac]
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac] File "/usr/lib/python2.7/site-packages/nova/objects/instance.py", line 701, in save
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac] columns_to_join=_expected_cols(expected_attrs))
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac]
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac] File "/usr/lib/python2.7/site-packages/nova/db/api.py", line 809, in instance_update_and_get_original
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac] expected=expected)
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac]
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac] File "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 229, in wrapper
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac] return f(*args, **kwargs)
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac]
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac] File "/usr/lib/python2.7/site-packages/oslo_db/api.py", line 148, in wrapper
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac] ectxt.value = e.inner_exc
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac]
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac] File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac] self.force_reraise()
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac]
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac] File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac] six.reraise(self.type_, self.value, self.tb)
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac]
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac] File "/usr/lib/python2.7/site-packages/oslo_db/api.py", line 138, in wrapper
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac] return f(*args, **kwargs)
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac]
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac] File "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 300, in wrapped
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac] return f(context, *args, **kwargs)
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac]
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac] File "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 2723, in instance_update_and_get_original
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac] context, instance_uuid, values, expected, original=instance_ref))
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac]
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac] File "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 2859, in _instance_update
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac] raise exc(**exc_props)
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac]
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac] UnexpectedTaskStateError: Conflict updating instance 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac. Expected: {'task_state': [u'block_device_mapping']}. Actual: {'task_state': u'spawning'}
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac]
localhost nova-compute:2019-01-24 16:38:52.882 2427 ERROR nova.compute.manager [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac]
localhost nova-compute:2019-01-24 16:38:53.500 2427 INFO nova.compute.manager [req-2b6ee2e1-6f8e-4bc0-80d7-62e41ce02619 28be004cfb19402597149e00a9b4d813 ab9ba89406a64c76b8240da11f4b52d3 - - -] [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac] Terminating instance
localhost nova-compute:2019-01-24 16:38:53.500 2427 INFO nova.compute.manager [req-2b6ee2e1-6f8e-4bc0-80d7-62e41ce02619 28be004cfb19402597149e00a9b4d813 ab9ba89406a64c76b8240da11f4b52d3 - - -] [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac] Terminating instance

reschedule node nova-compute log:
localhost nova-compute:2019-01-24 16:39:19.466 28548 INFO nova.virt.libvirt.driver [-] [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac] Instance spawned successfully.
localhost nova-compute:2019-01-24 16:39:19.466 28548 INFO nova.virt.libvirt.driver [-] [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac] Instance spawned successfully.
localhost nova-compute:2019-01-24 16:39:19.467 28548 INFO nova.compute.manager [req-2b6ee2e1-6f8e-4bc0-80d7-62e41ce02619 28be004cfb19402597149e00a9b4d813 ab9ba89406a64c76b8240da11f4b52d3 - - -] [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac] Took 6.32 seconds to spawn the instance on the hypervisor.
localhost nova-compute:2019-01-24 16:39:19.467 28548 INFO nova.compute.manager [req-2b6ee2e1-6f8e-4bc0-80d7-62e41ce02619 28be004cfb19402597149e00a9b4d813 ab9ba89406a64c76b8240da11f4b52d3 - - -] [instance: 0b6fddfa-27e1-4e71-83dd-c5cd9035dbac] Took 6.32 seconds to spawn the instance on the hypervisor.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/633160

[Alex Xu (xuhj)]

>Yea, this is really strange. @DongCan, What is your Env looks like,
>like all-in-one one node setup, or you have multiple node?Each building request only can be >accepted by one compute node, I
>don't understand why there is conflict happened.

@Alex, yes, we run multiple node, both compute node can be controller node.

[OpenStack Infra (hudson-openstack)]

Change abandoned by Balazs Gibizer (<email address hidden>) on branch: master
Review: https://review.opendev.org/633160
Reason: This is an old patch with negative review. So I'm abandoning it. If you would like to continue working on it then please answer the question from Matt.

[Balazs Gibizer (balazs-gibizer)]

Please provide a reproduction steps for the bug or a functional test the reproduce the bug as Matt requested it in the code review https://review.opendev.org/633160 .

I mark this bug Incomplete until reproduction steps are provided. Please set it back to New when you provide the requested information.