Revision history [back]

click to hide/show revision 1
initial version

Certain VMs fail to migrate

Hi All,

Got a sore head after banging it against the wall for over a week. I've seen many similar posts, but none of them are helpful.

I'm using Pike with Ceph Luminous as the back end storage, all on CentOS 7.5. Everything is at the latest patch level.

I have 3 compute hosts. Some of my VMs migrate between them all just fine. Others won't migrate at all. It may be the larger ones that won't migrate, but at only 2GB RAM and 16GB disk one of them isn't large at all.

After I initiate the migration, I see a message in the nova-compute.log on the target node (called Krypton) that lists the CPU capabilities. After one minute I see the error "Initialize connection failed for volume ..." and HTTP 500 error. That's followed by a few more messages, then a mile-long stack trace from oslo_messaging.rpc.server.

At that same second, log messages start appearing in the nova-compute.log on the source node (called Xenon), starting with "Pre live migration failed at krypton.example.com: MessagingTimeout: Timed out waiting for a reply to message ID ..." Then a stack trace from nova.compute.manager appears. Lastly I see an INFO message saying "No calling threads waiting for msg_id ..."

Any ideas what's causing this? Are there settings I need to adjust? Any suggestions on how to further debug this?

Thanks!

Command:

openstack server migrate --live krypton.example.com b5f912f5-3c49-466b-ad43-525c0476dbf9

Krypton:/var/log/nova/nova-compute.log (target node):

2018-09-14 11:31:39.939 169568 INFO nova.virt.libvirt.driver [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] Instance launched has CPU info: {"vendor": "Intel", "model": "Broadwell-IBRS", "arch": "x86_64", "features": ["pge", "avx", "xsaveopt", "clflush", "sep", "rtm", "tsc_adjust", "tsc-deadline", "dtes64", "stibp", "invpcid", "tsc", "fsgsbase", "xsave", "smap", "vmx", "erms", "xtpr", "cmov", "hle", "smep", "ssse3", "est", "pat", "monitor", "smx", "pbe", "lm", "msr", "adx", "3dnowprefetch", "nx", "fxsr", "syscall", "tm", "sse4.1", "pae", "sse4.2", "pclmuldq", "cx16", "pcid", "fma", "vme", "popcnt", "mmx", "osxsave", "cx8", "mce", "de", "rdtscp", "ht", "dca", "lahf_lm", "abm", "rdseed", "pdcm", "mca", "pdpe1gb", "apic", "sse", "f16c", "pse", "ds", "invtsc", "pni", "tm2", "avx2", "aes", "sse2", "ss", "ds_cpl", "arat", "bmi1", "bmi2", "acpi", "spec-ctrl", "fpu", "ssbd", "pse36", "mtrr", "movbe", "rdrand", "x2apic"], "topology": {"cores": 8, "cells": 2, "threads": 2, "sockets": 1}}
2018-09-14 11:32:23.276 169568 WARNING nova.compute.resource_tracker [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] Instance b5f912f5-3c49-466b-ad43-525c0476dbf9 has been moved to another host xenon.example.com(xenon.example.com). There are allocations remaining against the source host that might need to be removed: {u'resources': {u'VCPU': 4, u'MEMORY_MB': 8192, u'DISK_GB': 40}}.
2018-09-14 11:32:23.301 169568 INFO nova.compute.resource_tracker [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] Final resource view: name=krypton.example.com phys_ram=196510MB used_ram=14848MB phys_disk=18602GB used_disk=88GB total_vcpus=32 used_vcpus=9 pci_stats=[]
2018-09-14 11:32:40.954 169568 ERROR nova.volume.cinder [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] Initialize connection failed for volume e4e411d7-59e7-463b-8598-54a4838aa898 on host krypton.example.com. Error: The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-fdf84a9b-60d6-496e-a710-7265dce7c79d) Code: 500. Attempting to terminate connection.: ClientException: The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-fdf84a9b-60d6-496e-a710-7265dce7c79d)
2018-09-14 11:32:41.618 169568 INFO nova.virt.block_device [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9] Attempting to driver detach volume e4e411d7-59e7-463b-8598-54a4838aa898 from mountpoint /dev/vda
2018-09-14 11:32:41.621 169568 WARNING nova.virt.block_device [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9] Detaching volume from unknown instance
2018-09-14 11:32:41.623 169568 WARNING nova.virt.libvirt.driver [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9] During detach_volume, instance disappeared.: InstanceNotFound: Instance b5f912f5-3c49-466b-ad43-525c0476dbf9 could not be found.
2018-09-14 11:33:25.208 169568 INFO nova.compute.resource_tracker [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] Final resource view: name=krypton.example.com phys_ram=196510MB used_ram=14848MB phys_disk=18602GB used_disk=88GB total_vcpus=32 used_vcpus=9 pci_stats=[]
2018-09-14 11:33:41.024 169568 ERROR nova.volume.cinder [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] Connection between volume e4e411d7-59e7-463b-8598-54a4838aa898 and host krypton.example.com might have succeeded, but attempt to terminate connection has failed. Validate the connection and determine if manual cleanup is needed. Error: The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-7889b8a1-1c81-427c-9b86-9ba1d13d1f95) Code: 500.: ClientException: The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-7889b8a1-1c81-427c-9b86-9ba1d13d1f95)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] Exception during message handling: ClientException: The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-fdf84a9b-60d6-496e-a710-7265dce7c79d)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server Traceback (most recent call last):
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/server.py", line 160, in _process_incoming
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     res = self.dispatcher.dispatch(message)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 213, in dispatch
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     return self._do_dispatch(endpoint, method, ctxt, args)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 183, in _do_dispatch
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     result = func(ctxt, **new_args)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/exception_wrapper.py", line 76, in wrapped
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     function_name, call_dict, binary)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     self.force_reraise()
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     six.reraise(self.type_, self.value, self.tb)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/exception_wrapper.py", line 67, in wrapped
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     return f(self, context, *args, **kw)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/compute/utils.py", line 880, in decorated_function
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     return function(self, context, *args, **kwargs)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 218, in decorated_function
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     kwargs['instance'], e, sys.exc_info())
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     self.force_reraise()
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     six.reraise(self.type_, self.value, self.tb)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 206, in decorated_function
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     return function(self, context, *args, **kwargs)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 5507, in pre_live_migration
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     context, instance, refresh_conn_info=True)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 1706, in _get_instance_block_device_info
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     context, instance, self.volume_api, self.driver)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/virt/block_device.py", line 638, in refresh_conn_infos
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     device.refresh_connection_info(*refresh_args, **refresh_kwargs)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/virt/block_device.py", line 45, in wrapped
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     ret_val = method(obj, context, *args, **kwargs)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/virt/block_device.py", line 451, in refresh_connection_info
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     connector)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/volume/cinder.py", line 235, in wrapper
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     res = method(self, ctx, *args, **kwargs)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/volume/cinder.py", line 257, in wrapper
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     res = method(self, ctx, volume_id, *args, **kwargs)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/volume/cinder.py", line 436, in initialize_connection
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     exc.code if hasattr(exc, 'code') else None)})
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     self.force_reraise()
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     six.reraise(self.type_, self.value, self.tb)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/volume/cinder.py", line 410, in initialize_connection
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     context).volumes.initialize_connection(volume_id, connector)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/cinderclient/v2/volumes.py", line 425, in initialize_connection
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     {'connector': connector})
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/cinderclient/v2/volumes.py", line 355, in _action
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     resp, body = self.api.client.post(url, body=body)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/cinderclient/client.py", line 180, in post
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     return self._cs_request(url, 'POST', **kwargs)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/cinderclient/client.py", line 168, in _cs_request
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     return self.request(url, method, **kwargs)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/cinderclient/client.py", line 154, in request
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     raise exceptions.from_response(resp, body)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server ClientException: The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-fdf84a9b-60d6-496e-a710-7265dce7c79d)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] Exception during message handling: ClientException: The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-0df9f50f-8167-4a3c-9fa0-46ec817126c4)
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server Traceback (most recent call last):
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/server.py", line 160, in _process_incoming
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server     res = self.dispatcher.dispatch(message)
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 213, in dispatch
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server     return self._do_dispatch(endpoint, method, ctxt, args)
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 183, in _do_dispatch
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server     result = func(ctxt, **new_args)
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/exception_wrapper.py", line 76, in wrapped
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server     function_name, call_dict, binary)
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server     self.force_reraise()
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server     six.reraise(self.type_, self.value, self.tb)
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/exception_wrapper.py", line 67, in wrapped
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server     return f(self, context, *args, **kw)
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 5308, in remove_volume_connection
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server     self.volume_api.terminate_connection(context, volume_id, connector)
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/volume/cinder.py", line 235, in wrapper
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server     res = method(self, ctx, *args, **kwargs)
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/volume/cinder.py", line 257, in wrapper
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server     res = method(self, ctx, volume_id, *args, **kwargs)
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/volume/cinder.py", line 441, in terminate_connection
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server     connector)
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/cinderclient/v2/volumes.py", line 435, in terminate_connection
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server     {'connector': connector})
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/cinderclient/v2/volumes.py", line 355, in _action
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server     resp, body = self.api.client.post(url, body=body)
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/cinderclient/client.py", line 180, in post
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server     return self._cs_request(url, 'POST', **kwargs)
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/cinderclient/client.py", line 168, in _cs_request
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server     return self.request(url, method, **kwargs)
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/cinderclient/client.py", line 154, in request
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server     raise exceptions.from_response(resp, body)
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server ClientException: The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-0df9f50f-8167-4a3c-9fa0-46ec817126c4)
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server
2018-09-14 11:34:27.087 169568 INFO nova.compute.resource_tracker [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] Final resource view: name=krypton.example.com phys_ram=196510MB used_ram=14848MB phys_disk=18602GB used_disk=88GB total_vcpus=32 used_vcpus=9 pci_stats=[]
2018-09-14 11:35:27.107 169568 INFO nova.compute.resource_tracker [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] Final resource view: name=krypton.example.com phys_ram=196510MB used_ram=14848MB phys_disk=18602GB used_disk=88GB total_vcpus=32 used_vcpus=9 pci_stats=[]

Xenon:/var/log/nova/nova-compute.log (source node):

2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9] Pre live migration failed at krypton.example.com: MessagingTimeout: Timed out waiting for a reply to message ID 64c9e80538e341c5b000edc3f4d7a8a5
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9] Traceback (most recent call last):
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9]   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 5574, in _do_live_migration
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9]     block_migration, disk, dest, migrate_data)
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9]   File "/usr/lib/python2.7/site-packages/nova/compute/rpcapi.py", line 745, in pre_live_migration
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9]     disk=disk, migrate_data=migrate_data)
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9]   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/client.py", line 169, in call
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9]     retry=self.retry)
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9]   File "/usr/lib/python2.7/site-packages/oslo_messaging/transport.py", line 123, in _send
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9]     timeout=timeout, retry=retry)
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9]   File "/usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 566, in send
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9]     retry=retry)
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9]   File "/usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 555, in _send
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9]     result = self._waiter.wait(msg_id, timeout)
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9]   File "/usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 447, in wait
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9]     message = self.waiters.get(msg_id, timeout=timeout)
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9]   File "/usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 335, in get
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9]     'to message ID %s' % msg_id)
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9] MessagingTimeout: Timed out waiting for a reply to message ID 64c9e80538e341c5b000edc3f4d7a8a5
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9]
2018-09-14 11:33:14.697 4937 INFO nova.compute.resource_tracker [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] Final resource view: name=xenon.example.com phys_ram=196510MB used_ram=13824MB phys_disk=18602GB used_disk=82GB total_vcpus=32 used_vcpus=6 pci_stats=[]
2018-09-14 11:33:41.094 4937 INFO oslo_messaging._drivers.amqpdriver [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] No calling threads waiting for msg_id : 64c9e80538e341c5b000edc3f4d7a8a5
2018-09-14 11:33:41.620 4937 ERROR root [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] Original exception being dropped: ['Traceback (most recent call last):\n', '  File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 5574, in _do_live_migration\n    block_migration, disk, dest, migrate_data)\n', '  File "/usr/lib/python2.7/site-packages/nova/compute/rpcapi.py", line 745, in pre_live_migration\n    disk=disk, migrate_data=migrate_data)\n', '  File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/client.py", line 169, in call\n    retry=self.retry)\n', '  File "/usr/lib/python2.7/site-packages/oslo_messaging/transport.py", line 123, in _send\n    timeout=timeout, retry=retry)\n', '  File "/usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 566, in send\n    retry=retry)\n', '  File "/usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 555, in _send\n    result = self._waiter.wait(msg_id, timeout)\n', '  File "/usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 447, in wait\n    message = self.waiters.get(msg_id, timeout=timeout)\n', '  File "/usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 335, in get\n    \'to message ID %s\' % msg_id)\n', 'MessagingTimeout: Timed out waiting for a reply to message ID 64c9e80538e341c5b000edc3f4d7a8a5\n']: MessagingTimeout: Timed out waiting for a reply to message ID 7158c7c11c9d4cce8bb54aefcadb560a
2018-09-14 11:33:41.714 4937 INFO oslo_messaging._drivers.amqpdriver [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] No calling threads waiting for msg_id : 7158c7c11c9d4cce8bb54aefcadb560a

Certain VMs fail to migrate

Hi All,

Got a sore head after banging it against the wall for over a week. I've seen many similar posts, but none of them are helpful.

I'm using Pike with Ceph Luminous as the back end storage, all on CentOS 7.5. Everything is at the latest patch level.

I have 3 compute hosts. Some of my VMs migrate between them all just fine. Others won't migrate at all. It may be the larger ones that won't migrate, but at only 2GB RAM and 16GB disk one of them isn't large at all.

After I initiate the migration, I see a message in the nova-compute.log on the target node (called Krypton) that lists the CPU capabilities. After one minute I see the error "Initialize connection failed for volume ..." and HTTP 500 error. That's followed by a few more messages, then a mile-long stack trace from oslo_messaging.rpc.server.

At that same second, log messages start appearing in the nova-compute.log on the source node (called Xenon), starting with "Pre live migration failed at krypton.example.com: ...: MessagingTimeout: Timed out waiting for a reply to message ID ..." Then a stack trace from nova.compute.manager appears. Lastly I see an INFO message saying "No calling threads waiting for msg_id ..."

Any ideas what's causing this? Are there settings I need to adjust? Any suggestions on how to further debug this?

Thanks!

Command:

openstack server migrate --live krypton.example.com b5f912f5-3c49-466b-ad43-525c0476dbf9

Krypton:/var/log/nova/nova-compute.log (target node):

2018-09-14 11:31:39.939 169568 INFO nova.virt.libvirt.driver [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] Instance launched has CPU info: {"vendor": "Intel", "model": "Broadwell-IBRS", "arch": "x86_64", "features": ["pge", "avx", "xsaveopt", "clflush", "sep", "rtm", "tsc_adjust", "tsc-deadline", "dtes64", "stibp", "invpcid", "tsc", "fsgsbase", "xsave", "smap", "vmx", "erms", "xtpr", "cmov", "hle", "smep", "ssse3", "est", "pat", "monitor", "smx", "pbe", "lm", "msr", "adx", "3dnowprefetch", "nx", "fxsr", "syscall", "tm", "sse4.1", "pae", "sse4.2", "pclmuldq", "cx16", "pcid", "fma", "vme", "popcnt", "mmx", "osxsave", "cx8", "mce", "de", "rdtscp", "ht", "dca", "lahf_lm", "abm", "rdseed", "pdcm", "mca", "pdpe1gb", "apic", "sse", "f16c", "pse", "ds", "invtsc", "pni", "tm2", "avx2", "aes", "sse2", "ss", "ds_cpl", "arat", "bmi1", "bmi2", "acpi", "spec-ctrl", "fpu", "ssbd", "pse36", "mtrr", "movbe", "rdrand", "x2apic"], "topology": {"cores": 8, "cells": 2, "threads": 2, "sockets": 1}}
2018-09-14 11:32:23.276 169568 WARNING nova.compute.resource_tracker [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] Instance b5f912f5-3c49-466b-ad43-525c0476dbf9 has been moved to another host xenon.example.com(xenon.example.com). There are allocations remaining against the source host that might need to be removed: {u'resources': {u'VCPU': 4, u'MEMORY_MB': 8192, u'DISK_GB': 40}}.
2018-09-14 11:32:23.301 169568 INFO nova.compute.resource_tracker [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] Final resource view: name=krypton.example.com phys_ram=196510MB used_ram=14848MB phys_disk=18602GB used_disk=88GB total_vcpus=32 used_vcpus=9 pci_stats=[]
2018-09-14 11:32:40.954 169568 ERROR nova.volume.cinder [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] Initialize connection failed for volume e4e411d7-59e7-463b-8598-54a4838aa898 on host krypton.example.com. Error: The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-fdf84a9b-60d6-496e-a710-7265dce7c79d) Code: 500. Attempting to terminate connection.: ClientException: The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-fdf84a9b-60d6-496e-a710-7265dce7c79d)
2018-09-14 11:32:41.618 169568 INFO nova.virt.block_device [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9] Attempting to driver detach volume e4e411d7-59e7-463b-8598-54a4838aa898 from mountpoint /dev/vda
2018-09-14 11:32:41.621 169568 WARNING nova.virt.block_device [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9] Detaching volume from unknown instance
2018-09-14 11:32:41.623 169568 WARNING nova.virt.libvirt.driver [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9] During detach_volume, instance disappeared.: InstanceNotFound: Instance b5f912f5-3c49-466b-ad43-525c0476dbf9 could not be found.
2018-09-14 11:33:25.208 169568 INFO nova.compute.resource_tracker [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] Final resource view: name=krypton.example.com phys_ram=196510MB used_ram=14848MB phys_disk=18602GB used_disk=88GB total_vcpus=32 used_vcpus=9 pci_stats=[]
2018-09-14 11:33:41.024 169568 ERROR nova.volume.cinder [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] Connection between volume e4e411d7-59e7-463b-8598-54a4838aa898 and host krypton.example.com might have succeeded, but attempt to terminate connection has failed. Validate the connection and determine if manual cleanup is needed. Error: The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-7889b8a1-1c81-427c-9b86-9ba1d13d1f95) Code: 500.: ClientException: The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-7889b8a1-1c81-427c-9b86-9ba1d13d1f95)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] Exception during message handling: ClientException: The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-fdf84a9b-60d6-496e-a710-7265dce7c79d)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server Traceback (most recent call last):
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/server.py", line 160, in _process_incoming
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     res = self.dispatcher.dispatch(message)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 213, in dispatch
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     return self._do_dispatch(endpoint, method, ctxt, args)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 183, in _do_dispatch
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     result = func(ctxt, **new_args)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/exception_wrapper.py", line 76, in wrapped
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     function_name, call_dict, binary)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     self.force_reraise()
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     six.reraise(self.type_, self.value, self.tb)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/exception_wrapper.py", line 67, in wrapped
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     return f(self, context, *args, **kw)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/compute/utils.py", line 880, in decorated_function
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     return function(self, context, *args, **kwargs)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 218, in decorated_function
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     kwargs['instance'], e, sys.exc_info())
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     self.force_reraise()
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     six.reraise(self.type_, self.value, self.tb)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 206, in decorated_function
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     return function(self, context, *args, **kwargs)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 5507, in pre_live_migration
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     context, instance, refresh_conn_info=True)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 1706, in _get_instance_block_device_info
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     context, instance, self.volume_api, self.driver)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/virt/block_device.py", line 638, in refresh_conn_infos
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     device.refresh_connection_info(*refresh_args, **refresh_kwargs)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/virt/block_device.py", line 45, in wrapped
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     ret_val = method(obj, context, *args, **kwargs)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/virt/block_device.py", line 451, in refresh_connection_info
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     connector)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/volume/cinder.py", line 235, in wrapper
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     res = method(self, ctx, *args, **kwargs)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/volume/cinder.py", line 257, in wrapper
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     res = method(self, ctx, volume_id, *args, **kwargs)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/volume/cinder.py", line 436, in initialize_connection
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     exc.code if hasattr(exc, 'code') else None)})
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     self.force_reraise()
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     six.reraise(self.type_, self.value, self.tb)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/volume/cinder.py", line 410, in initialize_connection
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     context).volumes.initialize_connection(volume_id, connector)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/cinderclient/v2/volumes.py", line 425, in initialize_connection
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     {'connector': connector})
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/cinderclient/v2/volumes.py", line 355, in _action
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     resp, body = self.api.client.post(url, body=body)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/cinderclient/client.py", line 180, in post
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     return self._cs_request(url, 'POST', **kwargs)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/cinderclient/client.py", line 168, in _cs_request
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     return self.request(url, method, **kwargs)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/cinderclient/client.py", line 154, in request
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server     raise exceptions.from_response(resp, body)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server ClientException: The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-fdf84a9b-60d6-496e-a710-7265dce7c79d)
2018-09-14 11:33:41.087 169568 ERROR oslo_messaging.rpc.server
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] Exception during message handling: ClientException: The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-0df9f50f-8167-4a3c-9fa0-46ec817126c4)
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server Traceback (most recent call last):
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/server.py", line 160, in _process_incoming
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server     res = self.dispatcher.dispatch(message)
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 213, in dispatch
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server     return self._do_dispatch(endpoint, method, ctxt, args)
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 183, in _do_dispatch
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server     result = func(ctxt, **new_args)
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/exception_wrapper.py", line 76, in wrapped
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server     function_name, call_dict, binary)
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server     self.force_reraise()
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server     six.reraise(self.type_, self.value, self.tb)
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/exception_wrapper.py", line 67, in wrapped
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server     return f(self, context, *args, **kw)
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 5308, in remove_volume_connection
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server     self.volume_api.terminate_connection(context, volume_id, connector)
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/volume/cinder.py", line 235, in wrapper
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server     res = method(self, ctx, *args, **kwargs)
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/volume/cinder.py", line 257, in wrapper
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server     res = method(self, ctx, volume_id, *args, **kwargs)
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/volume/cinder.py", line 441, in terminate_connection
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server     connector)
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/cinderclient/v2/volumes.py", line 435, in terminate_connection
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server     {'connector': connector})
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/cinderclient/v2/volumes.py", line 355, in _action
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server     resp, body = self.api.client.post(url, body=body)
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/cinderclient/client.py", line 180, in post
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server     return self._cs_request(url, 'POST', **kwargs)
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/cinderclient/client.py", line 168, in _cs_request
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server     return self.request(url, method, **kwargs)
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/cinderclient/client.py", line 154, in request
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server     raise exceptions.from_response(resp, body)
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server ClientException: The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-0df9f50f-8167-4a3c-9fa0-46ec817126c4)
2018-09-14 11:33:41.708 169568 ERROR oslo_messaging.rpc.server
2018-09-14 11:34:27.087 169568 INFO nova.compute.resource_tracker [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] Final resource view: name=krypton.example.com phys_ram=196510MB used_ram=14848MB phys_disk=18602GB used_disk=88GB total_vcpus=32 used_vcpus=9 pci_stats=[]
2018-09-14 11:35:27.107 169568 INFO nova.compute.resource_tracker [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] Final resource view: name=krypton.example.com phys_ram=196510MB used_ram=14848MB phys_disk=18602GB used_disk=88GB total_vcpus=32 used_vcpus=9 pci_stats=[]

Xenon:/var/log/nova/nova-compute.log (source node):

2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9] Pre live migration failed at krypton.example.com: MessagingTimeout: Timed out waiting for a reply to message ID 64c9e80538e341c5b000edc3f4d7a8a5
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9] Traceback (most recent call last):
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9]   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 5574, in _do_live_migration
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9]     block_migration, disk, dest, migrate_data)
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9]   File "/usr/lib/python2.7/site-packages/nova/compute/rpcapi.py", line 745, in pre_live_migration
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9]     disk=disk, migrate_data=migrate_data)
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9]   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/client.py", line 169, in call
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9]     retry=self.retry)
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9]   File "/usr/lib/python2.7/site-packages/oslo_messaging/transport.py", line 123, in _send
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9]     timeout=timeout, retry=retry)
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9]   File "/usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 566, in send
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9]     retry=retry)
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9]   File "/usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 555, in _send
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9]     result = self._waiter.wait(msg_id, timeout)
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9]   File "/usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 447, in wait
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9]     message = self.waiters.get(msg_id, timeout=timeout)
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9]   File "/usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 335, in get
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9]     'to message ID %s' % msg_id)
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9] MessagingTimeout: Timed out waiting for a reply to message ID 64c9e80538e341c5b000edc3f4d7a8a5
2018-09-14 11:32:40.836 4937 ERROR nova.compute.manager [instance: b5f912f5-3c49-466b-ad43-525c0476dbf9]
2018-09-14 11:33:14.697 4937 INFO nova.compute.resource_tracker [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] Final resource view: name=xenon.example.com phys_ram=196510MB used_ram=13824MB phys_disk=18602GB used_disk=82GB total_vcpus=32 used_vcpus=6 pci_stats=[]
2018-09-14 11:33:41.094 4937 INFO oslo_messaging._drivers.amqpdriver [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] No calling threads waiting for msg_id : 64c9e80538e341c5b000edc3f4d7a8a5
2018-09-14 11:33:41.620 4937 ERROR root [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] Original exception being dropped: ['Traceback (most recent call last):\n', '  File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 5574, in _do_live_migration\n    block_migration, disk, dest, migrate_data)\n', '  File "/usr/lib/python2.7/site-packages/nova/compute/rpcapi.py", line 745, in pre_live_migration\n    disk=disk, migrate_data=migrate_data)\n', '  File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/client.py", line 169, in call\n    retry=self.retry)\n', '  File "/usr/lib/python2.7/site-packages/oslo_messaging/transport.py", line 123, in _send\n    timeout=timeout, retry=retry)\n', '  File "/usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 566, in send\n    retry=retry)\n', '  File "/usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 555, in _send\n    result = self._waiter.wait(msg_id, timeout)\n', '  File "/usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 447, in wait\n    message = self.waiters.get(msg_id, timeout=timeout)\n', '  File "/usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 335, in get\n    \'to message ID %s\' % msg_id)\n', 'MessagingTimeout: Timed out waiting for a reply to message ID 64c9e80538e341c5b000edc3f4d7a8a5\n']: MessagingTimeout: Timed out waiting for a reply to message ID 7158c7c11c9d4cce8bb54aefcadb560a
2018-09-14 11:33:41.714 4937 INFO oslo_messaging._drivers.amqpdriver [req-6c25aada-06e2-4ab7-bd67-e8e2cf49cf29 b4d3c8b03a8d432c999e101f22f8e19e c17f7f6ae0f44372a25439fe22357500 - default default] No calling threads waiting for msg_id : 7158c7c11c9d4cce8bb54aefcadb560a