TestInstanceNotificationSampleWithMultipleCompute.test_multiple_compute_actions intermittently failing since Sept 10, 2019

Seen here:

https://openstack.fortnebula.com:13808/v1/AUTH_e8fd161dc34c421a979a9e6421f823e9/zuul_opendev_logs_c4c/671072/18/gate/nova-tox-functional/c4ca604/job-output.txt

2019-09-11 16:01:31.460243 | ubuntu-bionic | {3} nova.tests.functional.notification_sample_tests.test_instance.TestInstanceNotificationSampleWithMultipleCompute.test_multiple_compute_actions [15.126947s] ... FAILED
2019-09-11 16:01:31.460323 | ubuntu-bionic |
2019-09-11 16:01:31.460383 | ubuntu-bionic | Captured traceback:
2019-09-11 16:01:31.460442 | ubuntu-bionic | ~~~~~~~~~~~~~~~~~~~
2019-09-11 16:01:31.460525 | ubuntu-bionic | Traceback (most recent call last):
2019-09-11 16:01:31.460714 | ubuntu-bionic | File "nova/tests/functional/notification_sample_tests/test_instance.py", line 61, in test_multiple_compute_actions
2019-09-11 16:01:31.460775 | ubuntu-bionic | action(server)
2019-09-11 16:01:31.460975 | ubuntu-bionic | File "nova/tests/functional/notification_sample_tests/test_instance.py", line 306, in _test_live_migration_force_complete
2019-09-11 16:01:31.461065 | ubuntu-bionic | fake_notifier.VERSIONED_NOTIFICATIONS)
2019-09-11 16:01:31.461297 | ubuntu-bionic | File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional/local/lib/python2.7/site-packages/testtools/testcase.py", line 411, in assertEqual
2019-09-11 16:01:31.461394 | ubuntu-bionic | self.assertThat(observed, matcher, message)
2019-09-11 16:01:31.461628 | ubuntu-bionic | File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional/local/lib/python2.7/site-packages/testtools/testcase.py", line 498, in assertThat
2019-09-11 16:01:31.461695 | ubuntu-bionic | raise mismatch_error
2019-09-11 16:01:31.484778 | ubuntu-bionic | testtools.matchers._impl.MismatchError: 6 != 7: [{'priority': 'INFO', 'payload': {'nova_object.namespace': 'nova', 'nova_object.name': 'RequestSpecPayload', 'nova_object.version': '1.1', 'nova_object.data': {'flavor': {'nova_object.namespace': 'nova', 'nova_object.name': 'FlavorPayload', 'nova_object.version': '1.4', 'nova_object.data': {'flavorid': u'a22d5517-147c-4147-a0d1-e698df5cd4e3', 'is_public': True, 'ephemeral_gb': 0, 'vcpus': 1, 'root_gb': 1, 'disabled': False, 'description': None, 'projects': None, 'vcpu_weight': 0, 'memory_mb': 512, 'name': u'test_flavor', 'rxtx_factor': 1.0, 'extra_specs': {'trait:COMPUTE_STATUS_DISABLED': u'forbidden', u'hw:watchdog_action': u'disabled'}, 'swap': 0}}, 'image': {'nova_object.namespace': 'nova', 'nova_object.name': 'ImageMetaPayload', 'nova_object.version': '1.0', 'nova_object.data': {'direct_url': None, 'container_format': u'raw', 'visibility': u'public', 'size': 25165824, 'disk_format': u'raw', 'virtual_size': None, 'protected': False, 'status': u'active', 'updated_at': '2011-01-01T01:02:03Z', 'tags': [u'tag1', u'tag2'], 'name': u'fakeimage123456', 'created_at': '2011-01-01T01:02:03Z', 'min_disk': 0, 'checksum': None, 'owner': None, 'id': u'155d900f-4e14-4e4c-a73d-069cbf4541e6', 'properties': {'nova_object.namespace': 'nova', 'nova_object.name': 'ImageMetaPropsPayload', 'nova_object.version': '1.1', 'nova_object.data': {'hw_architecture': u'x86_64'}}, 'min_ram': 0}}, 'requested_destination': {'nova_object.namespace': 'nova', 'nova_object.name': 'DestinationPayload', 'nova_object.version': '1.0', 'nova_object.data': {'host': u'host2', 'aggregates': None, 'node': u'host2', 'cell': {'nova_object.namespace': 'nova', 'nova_object.name': 'CellMappingPayload', 'nova_object.version': '2.0', 'nova_object.data': {'disabled': False, 'uuid': u'49bb4305-6acb-4b60-abff-382e2e85108a', 'name': u'cell1'}}}}, 'security_groups': [u'default'], 'scheduler_hints': {}, 'project_id': u'6f70656e737461636b20342065766572', 'retry': None, 'num_instances': 1, 'instance_group': None, 'force_nodes': None, 'ignore_hosts': [u'compute'], 'force_hosts': None, 'numa_topology': None, 'instance_uuid': u'8d65a36d-36e8-4994-9bdd-89a455166ab9', 'availability_zone': None, 'user_id': u'fake', 'pci_requests': {'nova_object.namespace': 'nova', 'nova_object.name': 'InstancePCIRequestsPayload', 'nova_object.version': '1.0', 'nova_object.data': {'requests': [], 'instance_uuid': u'8d65a36d-36e8-4994-9bdd-89a455166ab9'}}}}, 'publisher_id': u'nova-scheduler:host2', 'event_type': u'scheduler.select_destinations.start'}, {'priority': 'INFO', 'payload': {'nova_object.namespace': 'nova', 'nova_object.name': 'RequestSpecPayload', 'nova_object.version': '1.1', 'nova_object.data': {'flavor': {'nova_object.namespace': 'nova', 'nova_object.name': 'FlavorPayload', 'nova_object.version': '1.4', 'nova_object.data': {'flavorid': u'a22d5517-147c-4147-a0d1-e698df5cd4e3', 'is_public': True, 'ephemeral_gb': 0, 'vcpus': 1, 'root_gb': 1, 'disabled': False, 'description': None, 'projects': None, 'vcpu_weight': 0, 'memory_mb': 512, 'name': u'test_flavor', 'rxtx_factor': 1.0, 'extra_specs': {'trait:COMPUTE_STATUS_DISABLED': u'forbidden', u'hw:watchdog_action': u'disabled'}, 'swap': 0}}, 'image': {'nova_object.namespace': 'nova', 'nova_object.name': 'ImageMetaPayload', 'nova_object.version': '1.0', 'nova_object.data': {'direct_url': None, 'container_format': u'raw', 'visibility': u'public', 'size': 25165824, 'disk_format': u'raw', 'virtual_size': None, 'protected': False, 'status': u'active', 'updated_at': '2011-01-01T01:02:03Z', 'tags': [u'tag1', u'tag2'], 'name': u'fakeimage123456', 'created_at': '2011-01-01T01:02:03Z', 'min_disk': 0, 'checksum': None, 'owner': None, 'id': u'155d900f-4e14-4e4c-a73d-069cbf4541e6', 'properties': {'nova_object.namespace': 'nova', 'nova_object.name': 'ImageMetaPropsPayload', 'nova_object.version': '1.1', 'nova_object.data': {'hw_architecture': u'x86_64'}}, 'min_ram': 0}}, 'requested_destination': {'nova_object.namespace': 'nova', 'nova_object.name': 'DestinationPayload', 'nova_object.version': '1.0', 'nova_object.data': {'host': u'host2', 'aggregates': None, 'node': u'host2', 'cell': {'nova_object.namespace': 'nova', 'nova_object.name': 'CellMappingPayload', 'nova_object.version': '2.0', 'nova_object.data': {'disabled': False, 'uuid': u'49bb4305-6acb-4b60-abff-382e2e85108a', 'name': u'cell1'}}}}, 'security_groups': [u'default'], 'scheduler_hints': {}, 'project_id': u'6f70656e737461636b20342065766572', 'retry': None, 'num_instances': 1, 'instance_group': None, 'force_nodes': None, 'ignore_hosts': [u'compute'], 'force_hosts': None, 'numa_topology': None, 'instance_uuid': u'8d65a36d-36e8-4994-9bdd-89a455166ab9', 'availability_zone': None, 'user_id': u'fake', 'pci_requests': {'nova_object.namespace': 'nova', 'nova_object.name': 'InstancePCIRequestsPayload', 'nova_object.version': '1.0', 'nova_object.data': {'requests': [], 'instance_uuid': u'8d65a36d-36e8-4994-9bdd-89a455166ab9'}}}}, 'publisher_id': u'nova-scheduler:host2', 'event_type': u'scheduler.select_destinations.end'}, {'priority': 'INFO', 'payload': {'nova_object.namespace': 'nova', 'nova_object.name': 'InstanceActionPayload', 'nova_object.version': '1.8', 'nova_object.data': {'os_type': None, 'flavor': {'nova_object.namespace': 'nova', 'nova_object.name': 'FlavorPayload', 'nova_object.version': '1.4', 'nova_object.data': {'flavorid': u'a22d5517-147c-4147-a0d1-e698df5cd4e3', 'is_public': True, 'ephemeral_gb': 0, 'vcpus': 1, 'root_gb': 1, 'disabled': False, 'description': None, 'projects': None, 'vcpu_weight': 0, 'memory_mb': 512, 'name': u'test_flavor', 'rxtx_factor': 1.0, 'extra_specs': {u'hw:watchdog_action': u'disabled'}, 'swap': 0}}, 'display_description': u'some-server', 'action_initiator_user': u'admin', 'kernel_id': u'', 'host_name': u'some-server', 'created_at': '2012-10-29T13:42:11Z', 'ramdisk_id': u'', 'key_name': u'my-key', 'fault': None, 'progress': 0, 'reservation_id': u'r-7gm79j0r', 'launched_at': '2012-10-29T13:42:11Z', 'state': u'active', 'action_initiator_project': u'6f70656e737461636b20342065766572', 'architecture': u'x86_64', 'deleted_at': None, 'host': u'compute', 'availability_zone': u'nova', 'locked': False, 'ip_addresses': [{'nova_object.namespace': 'nova', 'nova_object.name': 'IpPayload', 'nova_object.version': '1.0', 'nova_object.data': {'label': u'private-network', 'meta': {}, 'address': '192.168.1.3', 'device_name': u'tapce531f90-19', 'mac': u'fa:16:3e:4c:2c:30', 'version': 4, 'port_uuid': u'ce531f90-199f-48c0-816c-13e38010b442'}}], 'auto_disk_config': u'MANUAL', 'block_devices': [{'nova_object.namespace': 'nova', 'nova_object.name': 'BlockDevicePayload', 'nova_object.version': '1.0', 'nova_object.data': {'boot_index': None, 'device_name': u'/dev/sdb', 'delete_on_termination': False, 'volume_id': u'a07f71dc-8151-4e7d-a0cc-cd24a3f11113', 'tag': None}}], 'node': u'fake-mini', 'request_id': u'req-5b6c791d-5709-4f36-8fbe-c3e02869e35d', 'locked_reason': None, 'tenant_id': u'6f70656e737461636b20342065766572', 'metadata': {}, 'task_state': u'migrating', 'terminated_at': None, 'image_uuid': u'155d900f-4e14-4e4c-a73d-069cbf4541e6', 'display_name': u'some-server', 'updated_at': '2012-10-29T13:42:11Z', 'power_state': u'running', 'user_id': u'fake', 'uuid': u'8d65a36d-36e8-4994-9bdd-89a455166ab9'}}, 'publisher_id': u'nova-compute:host2', 'event_type': u'instance.live_migration_pre.start'}, {'priority': 'INFO', 'payload': {'nova_object.namespace': 'nova', 'nova_object.name': 'InstanceActionPayload', 'nova_object.version': '1.8', 'nova_object.data': {'os_type': None, 'flavor': {'nova_object.namespace': 'nova', 'nova_object.name': 'FlavorPayload', 'nova_object.version': '1.4', 'nova_object.data': {'flavorid': u'a22d5517-147c-4147-a0d1-e698df5cd4e3', 'is_public': True, 'ephemeral_gb': 0, 'vcpus': 1, 'root_gb': 1, 'disabled': False, 'description': None, 'projects': None, 'vcpu_weight': 0, 'memory_mb': 512, 'name': u'test_flavor', 'rxtx_factor': 1.0, 'extra_specs': {u'hw:watchdog_action': u'disabled'}, 'swap': 0}}, 'display_description': u'some-server', 'action_initiator_user': u'admin', 'kernel_id': u'', 'host_name': u'some-server', 'created_at': '2012-10-29T13:42:11Z', 'ramdisk_id': u'', 'key_name': u'my-key', 'fault': None, 'progress': 0, 'reservation_id': u'r-7gm79j0r', 'launched_at': '2012-10-29T13:42:11Z', 'state': u'active', 'action_initiator_project': u'6f70656e737461636b20342065766572', 'architecture': u'x86_64', 'deleted_at': None, 'host': u'compute', 'availability_zone': u'nova', 'locked': False, 'ip_addresses': [{'nova_object.namespace': 'nova', 'nova_object.name': 'IpPayload', 'nova_object.version': '1.0', 'nova_object.data': {'label': u'private-network', 'meta': {}, 'address': '192.168.1.3', 'device_name': u'tapce531f90-19', 'mac': u'fa:16:3e:4c:2c:30', 'version': 4, 'port_uuid': u'ce531f90-199f-48c0-816c-13e38010b442'}}], 'auto_disk_config': u'MANUAL', 'block_devices': [{'nova_object.namespace': 'nova', 'nova_object.name': 'BlockDevicePayload', 'nova_object.version': '1.0', 'nova_object.data': {'boot_index': None, 'device_name': u'/dev/sdb', 'delete_on_termination': False, 'volume_id': u'a07f71dc-8151-4e7d-a0cc-cd24a3f11113', 'tag': None}}], 'node': u'fake-mini', 'request_id': u'req-5b6c791d-5709-4f36-8fbe-c3e02869e35d', 'locked_reason': None, 'tenant_id': u'6f70656e737461636b20342065766572', 'metadata': {}, 'task_state': u'migrating', 'terminated_at': None, 'image_uuid': u'155d900f-4e14-4e4c-a73d-069cbf4541e6', 'display_name': u'some-server', 'updated_at': '2012-10-29T13:42:11Z', 'power_state': u'running', 'user_id': u'fake', 'uuid': u'8d65a36d-36e8-4994-9bdd-89a455166ab9'}}, 'publisher_id': u'nova-compute:host2', 'event_type': u'instance.live_migration_pre.end'}, {'priority': 'INFO', 'payload': {'nova_object.namespace': 'nova', 'nova_object.name': 'InstanceActionPayload', 'nova_object.version': '1.8', 'nova_object.data': {'os_type': None, 'flavor': {'nova_object.namespace': 'nova', 'nova_object.name': 'FlavorPayload', 'nova_object.version': '1.4', 'nova_object.data': {'flavorid': u'a22d5517-147c-4147-a0d1-e698df5cd4e3', 'is_public': True, 'ephemeral_gb': 0, 'vcpus': 1, 'root_gb': 1, 'disabled': False, 'description': None, 'projects': None, 'vcpu_weight': 0, 'memory_mb': 512, 'name': u'test_flavor', 'rxtx_factor': 1.0, 'extra_specs': {u'hw:watchdog_action': u'disabled'}, 'swap': 0}}, 'display_description': u'some-server', 'action_initiator_user': u'admin', 'kernel_id': u'', 'host_name': u'some-server', 'created_at': '2012-10-29T13:42:11Z', 'ramdisk_id': u'', 'key_name': u'my-key', 'fault': None, 'progress': 0, 'reservation_id': u'r-7gm79j0r', 'launched_at': '2012-10-29T13:42:11Z', 'state': u'active', 'action_initiator_project': u'6f70656e737461636b20342065766572', 'architecture': u'x86_64', 'deleted_at': None, 'host': u'compute', 'availability_zone': u'nova', 'locked': False, 'ip_addresses': [{'nova_object.namespace': 'nova', 'nova_object.name': 'IpPayload', 'nova_object.version': '1.0', 'nova_object.data': {'label': u'private-network', 'meta': {}, 'address': '192.168.1.3', 'device_name': u'tapce531f90-19', 'mac': u'fa:16:3e:4c:2c:30', 'version': 4, 'port_uuid': u'ce531f90-199f-48c0-816c-13e38010b442'}}], 'auto_disk_config': u'MANUAL', 'block_devices': [{'nova_object.namespace': 'nova', 'nova_object.name': 'BlockDevicePayload', 'nova_object.version': '1.0', 'nova_object.data': {'boot_index': None, 'device_name': u'/dev/sdb', 'delete_on_termination': False, 'volume_id': u'a07f71dc-8151-4e7d-a0cc-cd24a3f11113', 'tag': None}}], 'node': u'fake-mini', 'request_id': u'req-5b6c791d-5709-4f36-8fbe-c3e02869e35d', 'locked_reason': None, 'tenant_id': u'6f70656e737461636b20342065766572', 'metadata': {}, 'task_state': u'migrating', 'terminated_at': None, 'image_uuid': u'155d900f-4e14-4e4c-a73d-069cbf4541e6', 'display_name': u'some-server', 'updated_at': '2012-10-29T13:42:11Z', 'power_state': u'running', 'user_id': u'fake', 'uuid': u'8d65a36d-36e8-4994-9bdd-89a455166ab9'}}, 'publisher_id': u'nova-compute:compute', 'event_type': u'instance.live_migration_force_complete.start'}, {'priority': 'INFO', 'payload': {'nova_object.namespace': 'nova', 'nova_object.name': 'InstanceActionPayload', 'nova_object.version': '1.8', 'nova_object.data': {'os_type': None, 'flavor': {'nova_object.namespace': 'nova', 'nova_object.name': 'FlavorPayload', 'nova_object.version': '1.4', 'nova_object.data': {'flavorid': u'a22d5517-147c-4147-a0d1-e698df5cd4e3', 'is_public': True, 'ephemeral_gb': 0, 'vcpus': 1, 'root_gb': 1, 'disabled': False, 'description': None, 'projects': None, 'vcpu_weight': 0, 'memory_mb': 512, 'name': u'test_flavor', 'rxtx_factor': 1.0, 'extra_specs': {u'hw:watchdog_action': u'disabled'}, 'swap': 0}}, 'display_description': u'some-server', 'action_initiator_user': u'admin', 'kernel_id': u'', 'host_name': u'some-server', 'created_at': '2012-10-29T13:42:11Z', 'ramdisk_id': u'', 'key_name': u'my-key', 'fault': None, 'progress': 0, 'reservation_id': u'r-7gm79j0r', 'launched_at': '2012-10-29T13:42:11Z', 'state': u'active', 'action_initiator_project': u'6f70656e737461636b20342065766572', 'architecture': u'x86_64', 'deleted_at': None, 'host': u'compute', 'availability_zone': u'nova', 'locked': False, 'ip_addresses': [{'nova_object.namespace': 'nova', 'nova_object.name': 'IpPayload', 'nova_object.version': '1.0', 'nova_object.data': {'label': u'private-network', 'meta': {}, 'address': '192.168.1.3', 'device_name': u'tapce531f90-19', 'mac': u'fa:16:3e:4c:2c:30', 'version': 4, 'port_uuid': u'ce531f90-199f-48c0-816c-13e38010b442'}}], 'auto_disk_config': u'MANUAL', 'block_devices': [{'nova_object.namespace': 'nova', 'nova_object.name': 'BlockDevicePayload', 'nova_object.version': '1.0', 'nova_object.data': {'boot_index': None, 'device_name': u'/dev/sdb', 'delete_on_termination': False, 'volume_id': u'a07f71dc-8151-4e7d-a0cc-cd24a3f11113', 'tag': None}}], 'node': u'fake-mini', 'request_id': u'req-5b6c791d-5709-4f36-8fbe-c3e02869e35d', 'locked_reason': None, 'tenant_id': u'6f70656e737461636b20342065766572', 'metadata': {}, 'task_state': u'migrating', 'terminated_at': None, 'image_uuid': u'155d900f-4e14-4e4c-a73d-069cbf4541e6', 'display_name': u'some-server', 'updated_at': '2012-10-29T13:42:11Z', 'power_state': u'running', 'user_id': u'fake', 'uuid': u'8d65a36d-36e8-4994-9bdd-89a455166ab9'}}, 'publisher_id': u'nova-compute:compute', 'event_type': u'instance.live_migration_force_complete.end'}, {'priority': 'INFO', 'payload': {'nova_object.namespace': 'nova', 'nova_object.name': 'InstanceActionPayload', 'nova_object.version': '1.8', 'nova_object.data': {'os_type': None, 'flavor': {'nova_object.namespace': 'nova', 'nova_object.name': 'FlavorPayload', 'nova_object.version': '1.4', 'nova_object.data': {'flavorid': u'a22d5517-147c-4147-a0d1-e698df5cd4e3', 'is_public': True, 'ephemeral_gb': 0, 'vcpus': 1, 'root_gb': 1, 'disabled': False, 'description': None, 'projects': None, 'vcpu_weight': 0, 'memory_mb': 512, 'name': u'test_flavor', 'rxtx_factor': 1.0, 'extra_specs': {u'hw:watchdog_action': u'disabled'}, 'swap': 0}}, 'display_description': u'some-server', 'action_initiator_user': u'admin', 'kernel_id': u'', 'host_name': u'some-server', 'created_at': '2012-10-29T13:42:11Z', 'ramdisk_id': u'', 'key_name': u'my-key', 'fault': None, 'progress': 0, 'reservation_id': u'r-7gm79j0r', 'launched_at': '2012-10-29T13:42:11Z', 'state': u'active', 'action_initiator_project': u'6f70656e737461636b20342065766572', 'architecture': u'x86_64', 'deleted_at': None, 'host': u'compute', 'availability_zone': u'nova', 'locked': False, 'ip_addresses': [{'nova_object.namespace': 'nova', 'nova_object.name': 'IpPayload', 'nova_object.version': '1.0', 'nova_object.data': {'label': u'private-network', 'meta': {}, 'address': '192.168.1.3', 'device_name': u'tapce531f90-19', 'mac': u'fa:16:3e:4c:2c:30', 'version': 4, 'port_uuid': u'ce531f90-199f-48c0-816c-13e38010b442'}}], 'auto_disk_config': u'MANUAL', 'block_devices': [{'nova_object.namespace': 'nova', 'nova_object.name': 'BlockDevicePayload', 'nova_object.version': '1.0', 'nova_object.data': {'boot_index': None, 'device_name': u'/dev/sdb', 'delete_on_termination': False, 'volume_id': u'a07f71dc-8151-4e7d-a0cc-cd24a3f11113', 'tag': None}}], 'node': u'fake-mini', 'request_id': u'req-5b6c791d-5709-4f36-8fbe-c3e02869e35d', 'locked_reason': None, 'tenant_id': u'6f70656e737461636b20342065766572', 'metadata': {}, 'task_state': u'migrating', 'terminated_at': None, 'image_uuid': u'155d900f-4e14-4e4c-a73d-069cbf4541e6', 'display_name': u'some-server', 'updated_at': '2012-10-29T13:42:11Z', 'power_state': u'running', 'user_id': u'fake', 'uuid': u'8d65a36d-36e8-4994-9bdd-89a455166ab9'}}, 'publisher_id': u'nova-compute:compute', 'event_type': u'instance.live_migration_post.start'}]

The test code is expecting 6 notifications but got 7:

self._wait_for_notification(
            'instance.live_migration_force_complete.end')

        # 0. scheduler.select_destinations.start
        # 1. scheduler.select_destinations.end
        # 2. instance.live_migration_pre.start
        # 3. instance.live_migration_pre.end
        # 4. instance.live_migration_force_complete.start
        # 5. instance.live_migration_force_complete.end
        self.assertEqual(6, len(fake_notifier.VERSIONED_NOTIFICATIONS),
                         fake_notifier.VERSIONED_NOTIFICATIONS)

The 7th is instance.live_migration_post.start:

http://paste.openstack.org/show/775148/

so it appears something has changed when that is sent or we're losing a race with when force complete is triggered? Meaning maybe we don't catch the force complete in time before post live migration starts.