yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1813255] [NEW] nova reschedule instance while updating instance task state

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Dongcan Ye <yedongcan@xxxxxxxx>
Date: Fri, 25 Jan 2019 07:45:11 -0000
Reply-to: Bug 1813255 <1813255@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

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.

** Affects: nova
     Importance: Undecided
     Assignee: Dongcan Ye (hellochosen)
         Status: New

** Changed in: nova
     Assignee: (unassigned) => Dongcan Ye (hellochosen)

-- 
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/1813255

Title:
  nova reschedule instance while updating instance task state

Status in OpenStack Compute (nova):
  New

Bug description:
  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.

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