OS_CTRL ubuntu@ubuntu:~$ pushd /opt/stack/nova; git branch; git log --format="%ci %h %s" -n 5; popd /opt/stack/nova ~ * master 2017-10-05 11:30:31 +0000 e4f89ed Merge "Add instance.interface_detach notification" 2017-10-05 11:29:53 +0000 b3c7652 Merge "Add instance.interface_attach notification" 2017-10-05 10:03:23 +0000 a6eadd8 Merge "doc: Add documentation for cpu_realtime, cpu_realtime_mask" 2017-10-05 02:09:17 +0000 22c9f43 Merge "Fix CellDatabases fixture swallowing exceptions" 2017-10-05 01:15:52 +0000 6e57fd8 Merge "Make allocation cleanup honor new by-migration rules" OS_CTRL ubuntu@ubuntu:~$ instance_id=`nova boot cirros --poll --image=cirros-0.3.5-x86_64-disk --nic net-name=private --flavor=1 --availability-zone=nova:ubuntu --block-device source=blank,dest=volume,type=disk,size=1 | grep -w "id" | cut -d '|' -f 3` OS_CTRL ubuntu@ubuntu:~$ nova show $instance_id +--------------------------------------+----------------------------------------------------------------------------------+ | Property | Value | +--------------------------------------+----------------------------------------------------------------------------------+ | OS-DCF:diskConfig | MANUAL | | OS-EXT-AZ:availability_zone | nova | | OS-EXT-SRV-ATTR:host | ubuntu | | OS-EXT-SRV-ATTR:hostname | cirros | | OS-EXT-SRV-ATTR:hypervisor_hostname | ubuntu | | OS-EXT-SRV-ATTR:instance_name | instance-0000003f | | OS-EXT-SRV-ATTR:kernel_id | | | OS-EXT-SRV-ATTR:launch_index | 0 | | OS-EXT-SRV-ATTR:ramdisk_id | | | OS-EXT-SRV-ATTR:reservation_id | r-u0lj0iy2 | | OS-EXT-SRV-ATTR:root_device_name | /dev/vda | | OS-EXT-SRV-ATTR:user_data | - | | OS-EXT-STS:power_state | 1 | | OS-EXT-STS:task_state | - | | OS-EXT-STS:vm_state | active | | OS-SRV-USG:launched_at | 2017-10-12T07:29:02.000000 | | OS-SRV-USG:terminated_at | - | | accessIPv4 | | | accessIPv6 | | | config_drive | | | created | 2017-10-12T07:28:46Z | | description | - | | flavor:disk | 1 | | flavor:ephemeral | 0 | | flavor:extra_specs | {} | | flavor:original_name | m1.tiny | | flavor:ram | 512 | | flavor:swap | 0 | | flavor:vcpus | 1 | | hostId | b391bb9adbe8e4923a2011b6b08a2efc34b6028ac46134cc7eae9218 | | host_status | UP | | id | 1f190aab-b701-48ab-96c9-82758af2a75f | | image | cirros-0.3.5-x86_64-disk (a0911993-01de-4644-9db4-aea2c53919a9) | | key_name | mykey | | locked | False | | metadata | {} | | name | cirros | | os-extended-volumes:volumes_attached | [{"id": "d758e962-2741-406e-940b-ec65e5d346c3", "delete_on_termination": false}] | | private network | 10.0.0.8 | | progress | 0 | | security_groups | default | | status | ACTIVE | | tags | [] | | tenant_id | 68957b950e984ce3a7521d9f942b2953 | | updated | 2017-10-12T07:29:03Z | | user_id | f1112ac130c74eadb9f313e05483e315 | +--------------------------------------+----------------------------------------------------------------------------------+ OS_CTRL ubuntu@ubuntu:~$ private_ip=`nova show $instance_id | grep "private network" | cut -d "|" -f 3` OS_CTRL ubuntu@ubuntu:~$ neutron port-list | grep $private_ip | cut -d '|' -f 2 OS_CTRL ubuntu@ubuntu:~$ port_id=`neutron port-list | grep $private_ip | cut -d '|' -f 2` OS_CTRL ubuntu@ubuntu:~$ echo $port_id 5043444c-d951-4583-98e9-233627d6822a OS_CTRL ubuntu@ubuntu:~$ sudo ovs-vsctl list-ifaces br-int | grep `echo $port_id | cut -d '-' -f 1` qvo5043444c-d9 OS_CTRL ubuntu@ubuntu:~$ cinder list | grep $instance_id | d758e962-2741-406e-940b-ec65e5d346c3 | in-use | 1f190aab-b701-48ab-96c9-82758af2a75f-blank-vol | 1 | lvmdriver-1 | false | 1f190aab-b701-48ab-96c9-82758af2a75f | OS_CTRL ubuntu@ubuntu:~$ vol_id=`cinder list | grep $instance_id | cut -d '|' -f 2` OS_CTRL ubuntu@ubuntu:~$ iscsiadm -m session | grep $vol_id tcp: [1] 192.168.42.110:3260,1 iqn.2010-10.org.openstack:volume-d758e962-2741-406e-940b-ec65e5d346c3 (non-flash) OS_CTRL ubuntu@ubuntu:~$ instance_name=`nova show $instance_id | grep instance_name | cut -d '|' -f 3` OS_CTRL ubuntu@ubuntu:~$ echo $instance_name instance-0000003f OS_CTRL ubuntu@ubuntu:~$ hostname=`nova show $instance_id | grep hypervisor_hostname | cut -d '|' -f 3` OS_CTRL ubuntu@ubuntu:~$ nova hypervisor-list | grep -w $hostname | 164b8e65-f062-46a1-a9e7-ff1175f8d6e7 | ubuntu | up | enabled | # We're stopping the n-cpu service and waiting for the status to be updated. OS_CTRL ubuntu@ubuntu:~$ sudo systemctl stop devstack@n-cpu OS_CTRL ubuntu@ubuntu:~$ while [[ ! -z `nova hypervisor-list | grep -w $hostname | grep up` ]]; do sleep 10; done OS_CTRL ubuntu@ubuntu:~$ nova hypervisor-list | grep -w $hostname | 164b8e65-f062-46a1-a9e7-ff1175f8d6e7 | ubuntu | down | enabled | # This is an AIO environment. The nova compute service is currently down, the instance is still there, as expected. # Will be cleaned up when the agent starts. OS_CTRL ubuntu@ubuntu:~$ virsh list | grep $instance_name 50 instance-0000003f running OS_CTRL ubuntu@ubuntu:~$ sudo systemctl start devstack@n-cpu # For testing purposes, I've set a small polling value here. OS_CTRL ubuntu@ubuntu:~$ grep running_deleted_instance_poll_interval /etc/nova/nova-cpu.conf running_deleted_instance_poll_interval = 20 # We'll wait for the polling interval plus an extra 180 seconds, giving the compute service # time to perform the cleanups OS_CTRL ubuntu@ubuntu:~$ cleanup_interval=`grep running_deleted_instance_poll_interval /etc/nova/nova-cpu.conf | cut -d '=' -f 2` OS_CTRL ubuntu@ubuntu:~$ sleep $(( $cleanup_interval + 180 )) # The VM was deleted, as expected. OS_CTRL ubuntu@ubuntu:~$ virsh list Id Name State ---------------------------------------------------- # The OVS port is still there while it shouldn't. OS_CTRL ubuntu@ubuntu:~$ sudo ovs-vsctl list-ifaces br-int | grep `echo $port_id | cut -d '-' -f 1` qvo5043444c-d9 # The volume export was terminated on the Cinder backend side by the Nova API while n-cpu was down. OS_CTRL ubuntu@ubuntu:~$ cinder list | grep $vol_id | d758e962-2741-406e-940b-ec65e5d346c3 | available | 1f190aab-b701-48ab-96c9-82758af2a75f-blank-vol | 1 | lvmdriver-1 | false | | # The volume connection hasn't been terminated on the initiator side though. OS_CTRL ubuntu@ubuntu:~$ ls -l /dev/disk/by-path | grep $vol_id lrwxrwxrwx 1 root root 9 Oct 12 11:35 ip-192.168.42.110:3260-iscsi-iqn.2010-10.org.openstack:volume-d758e962-2741-406e-940b-ec65e5d346c3-lun-1 -> ../../sdb OS_CTRL ubuntu@ubuntu:~$ iscsiadm -m session | grep $vol_id tcp: [1] 192.168.42.110:3260,1 iqn.2010-10.org.openstack:volume-d758e962-2741-406e-940b-ec65e5d346c3 (non-flash) # looking for the expected flush error OS_CTRL ubuntu@ubuntu:~$ journalctl -u devstack@n-cpu --no-pager | grep -A 10 -B 40 "Flushing /dev/sdb failed" Oct 12 11:35:27 ubuntu nova-compute[26756]: DEBUG nova.virt.driver [None req-c65b6229-ee10-4f7f-8279-134404698a90 None None] Emitting event Stopped> {{(pid=26756) emit_event /opt/stack/nova/nova/virt/driver.py:1430}} Oct 12 11:35:27 ubuntu nova-compute[26756]: INFO nova.compute.manager [None req-c65b6229-ee10-4f7f-8279-134404698a90 None None] [instance: 1f190aab-b701-48ab-96c9-82758af2a75f] VM Stopped (Lifecycle Event) Oct 12 11:35:28 ubuntu nova-compute[26756]: DEBUG nova.compute.manager [None req-c65b6229-ee10-4f7f-8279-134404698a90 None None] [instance: 1f190aab-b701-48ab-96c9-82758af2a75f] Checking state {{(pid=26756) _get_power_state /opt/stack/nova/nova/compute/manager.py:1157}} Oct 12 11:35:28 ubuntu nova-compute[26756]: DEBUG nova.compute.manager [None req-c65b6229-ee10-4f7f-8279-134404698a90 None None] [instance: 1f190aab-b701-48ab-96c9-82758af2a75f] Synchronizing instance power state after lifecycle event "Stopped"; current vm_state: deleted, current task_state: None, current DB power_state: 1, VM power_state: 4 {{(pid=26756) handle_lifecycle_event /opt/stack/nova/nova/compute/manager.py:1061}} Oct 12 11:35:28 ubuntu nova-compute[26756]: INFO nova.compute.manager [None req-c65b6229-ee10-4f7f-8279-134404698a90 None None] [instance: 1f190aab-b701-48ab-96c9-82758af2a75f] During _sync_instance_power_state the DB power_state (1) does not match the vm_power_state from the hypervisor (4). Updating power_state in the DB to match the hypervisor. Oct 12 11:35:34 ubuntu nova-compute[26756]: DEBUG oslo_concurrency.processutils [None req-c65b6229-ee10-4f7f-8279-134404698a90 None None] CMD "blockdev --flushbufs /dev/sdb" returned: 1 in 20.014s {{(pid=26958) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:404}} Oct 12 11:35:34 ubuntu nova-compute[26756]: DEBUG oslo_concurrency.processutils [None req-c65b6229-ee10-4f7f-8279-134404698a90 None None] u'blockdev --flushbufs /dev/sdb' failed. Retrying. {{(pid=26958) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:456}} Oct 12 11:35:34 ubuntu nova-compute[26756]: DEBUG oslo_concurrency.processutils [None req-c65b6229-ee10-4f7f-8279-134404698a90 None None] Running cmd (subprocess): blockdev --flushbufs /dev/sdb {{(pid=26958) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:367}} Oct 12 11:35:34 ubuntu nova-compute[26756]: DEBUG os_brick.privileged.rootwrap [None req-c65b6229-ee10-4f7f-8279-134404698a90 None None] Sleeping for 40 seconds {{(pid=26958) on_execute /usr/local/lib/python2.7/dist-packages/os_brick/privileged/rootwrap.py:107}} Oct 12 11:36:14 ubuntu nova-compute[26756]: DEBUG oslo_concurrency.processutils [None req-c65b6229-ee10-4f7f-8279-134404698a90 None None] CMD "blockdev --flushbufs /dev/sdb" returned: 1 in 40.047s {{(pid=26958) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:404}} Oct 12 11:36:14 ubuntu nova-compute[26756]: DEBUG oslo_concurrency.processutils [None req-c65b6229-ee10-4f7f-8279-134404698a90 None None] u'blockdev --flushbufs /dev/sdb' failed. Not Retrying. {{(pid=26958) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:452}} Oct 12 11:36:14 ubuntu nova-compute[26756]: DEBUG oslo.privsep.daemon [None req-c65b6229-ee10-4f7f-8279-134404698a90 None None] privsep: Exception during request[140009364036496]: Unexpected error while running command. Oct 12 11:36:14 ubuntu nova-compute[26756]: Command: blockdev --flushbufs /dev/sdb Oct 12 11:36:14 ubuntu nova-compute[26756]: Exit code: 1 Oct 12 11:36:14 ubuntu nova-compute[26756]: Stdout: u'' Oct 12 11:36:14 ubuntu nova-compute[26756]: Stderr: u'blockdev: cannot open /dev/sdb: No such device or address\n' {{(pid=26958) loop /usr/local/lib/python2.7/dist-packages/oslo_privsep/daemon.py:449}} Oct 12 11:36:14 ubuntu nova-compute[26756]: Traceback (most recent call last): Oct 12 11:36:14 ubuntu nova-compute[26756]: File "/usr/local/lib/python2.7/dist-packages/oslo_privsep/daemon.py", line 445, in loop Oct 12 11:36:14 ubuntu nova-compute[26756]: reply = self._process_cmd(*msg) Oct 12 11:36:14 ubuntu nova-compute[26756]: File "/usr/local/lib/python2.7/dist-packages/oslo_privsep/daemon.py", line 428, in _process_cmd Oct 12 11:36:14 ubuntu nova-compute[26756]: ret = func(*f_args, **f_kwargs) Oct 12 11:36:14 ubuntu nova-compute[26756]: File "/usr/local/lib/python2.7/dist-packages/oslo_privsep/priv_context.py", line 207, in _wrap Oct 12 11:36:14 ubuntu nova-compute[26756]: return func(*args, **kwargs) Oct 12 11:36:14 ubuntu nova-compute[26756]: File "/usr/local/lib/python2.7/dist-packages/os_brick/privileged/rootwrap.py", line 194, in execute_root Oct 12 11:36:14 ubuntu nova-compute[26756]: return custom_execute(*cmd, shell=False, run_as_root=False, **kwargs) Oct 12 11:36:14 ubuntu nova-compute[26756]: File "/usr/local/lib/python2.7/dist-packages/os_brick/privileged/rootwrap.py", line 143, in custom_execute Oct 12 11:36:14 ubuntu nova-compute[26756]: on_completion=on_completion, *cmd, **kwargs) Oct 12 11:36:14 ubuntu nova-compute[26756]: File "/usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py", line 419, in execute Oct 12 11:36:14 ubuntu nova-compute[26756]: cmd=sanitized_cmd) Oct 12 11:36:14 ubuntu nova-compute[26756]: ProcessExecutionError: Unexpected error while running command. Oct 12 11:36:14 ubuntu nova-compute[26756]: Command: blockdev --flushbufs /dev/sdb Oct 12 11:36:14 ubuntu nova-compute[26756]: Exit code: 1 Oct 12 11:36:14 ubuntu nova-compute[26756]: Stdout: u'' Oct 12 11:36:14 ubuntu nova-compute[26756]: Stderr: u'blockdev: cannot open /dev/sdb: No such device or address\n' Oct 12 11:36:14 ubuntu nova-compute[26756]: DEBUG oslo.privsep.daemon [None req-c65b6229-ee10-4f7f-8279-134404698a90 None None] privsep: reply[140009364036496]: (5, 'oslo_concurrency.processutils.ProcessExecutionError', (u'', u'blockdev: cannot open /dev/sdb: No such device or address\n', 1, u'blockdev --flushbufs /dev/sdb', None)) {{(pid=26958) loop /usr/local/lib/python2.7/dist-packages/oslo_privsep/daemon.py:456}} Oct 12 11:36:14 ubuntu nova-compute[26756]: WARNING os_brick.initiator.linuxscsi [None req-c65b6229-ee10-4f7f-8279-134404698a90 None None] Failed to flush IO buffers prior to removing device: 1: ProcessExecutionError: Unexpected error while running command. Oct 12 11:36:14 ubuntu nova-compute[26756]: Command: blockdev --flushbufs /dev/sdb Oct 12 11:36:14 ubuntu nova-compute[26756]: Exit code: 1 Oct 12 11:36:14 ubuntu nova-compute[26756]: Stdout: u'' Oct 12 11:36:14 ubuntu nova-compute[26756]: Stderr: u'blockdev: cannot open /dev/sdb: No such device or address\n' Oct 12 11:36:14 ubuntu nova-compute[26756]: WARNING os_brick.exception [None req-c65b6229-ee10-4f7f-8279-134404698a90 None None] Flushing /dev/sdb failed: ProcessExecutionError: Unexpected error while running command. Oct 12 11:36:14 ubuntu nova-compute[26756]: Command: blockdev --flushbufs /dev/sdb Oct 12 11:36:14 ubuntu nova-compute[26756]: Exit code: 1 Oct 12 11:36:14 ubuntu nova-compute[26756]: Stdout: u'' Oct 12 11:36:14 ubuntu nova-compute[26756]: Stderr: u'blockdev: cannot open /dev/sdb: No such device or address\n' Oct 12 11:36:14 ubuntu nova-compute[26756]: DEBUG oslo_concurrency.lockutils [None req-c65b6229-ee10-4f7f-8279-134404698a90 None None] Lock "connect_volume" released by "os_brick.initiator.connectors.iscsi.disconnect_volume" :: held 61.121s {{(pid=26756) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:285}} Oct 12 11:36:14 ubuntu nova-compute[26756]: DEBUG os_brick.initiator.connectors.iscsi [None req-c65b6229-ee10-4f7f-8279-134404698a90 None None] <== disconnect_volume: exception (61123ms) ProcessExecutionError(u'', u'blockdev: cannot open /dev/sdb: No such device or address\n', 1, u'blockdev --flushbufs /dev/sdb', None) {{(pid=26756) trace_logging_wrapper /usr/local/lib/python2.7/dist-packages/os_brick/utils.py:156}} Oct 12 11:36:14 ubuntu nova-compute[26756]: WARNING nova.virt.libvirt.driver [None req-c65b6229-ee10-4f7f-8279-134404698a90 None None] [instance: 1f190aab-b701-48ab-96c9-82758af2a75f] Ignoring Volume Error on vol None during delete Unexpected error while running command. Oct 12 11:36:14 ubuntu nova-compute[26756]: Command: blockdev --flushbufs /dev/sdb Oct 12 11:36:14 ubuntu nova-compute[26756]: Exit code: 1 Oct 12 11:36:14 ubuntu nova-compute[26756]: Stdout: u''