ERROR: test_launch_small_instance (zaza.openstack.charm_tests.nova.tests.CirrosGuestCreateTest)

[freyes]

the function resource_reaches_status() should accept a parameter to indicate what state(s) are considered final states and non-desired states so it can short-circuit earlier.

For example in this case launching a cirros instance, it failed 3 seconds after it was launched, but we stayed waiting for ACTIVE state for 18 minutes, and this specific operation is retried 3 times, so we have a delay of almost an hour for the ci results.

Issue seen at https://openstack-ci-reports.ubuntu.com/artifacts/634/841977/3/check/focal-xena/6344234/

2022-05-23 17:29:43 [INFO] Launching instance zaza-nova-cirros
2022-05-23 17:29:44 [INFO] Checking instance is active
2022-05-23 17:29:44 [INFO] resource: resource d4e9d939-1e1a-44da-a694-5b839856c654 in BUILD state, waiting for ACTIVE
2022-05-23 17:29:45 [INFO] resource: resource d4e9d939-1e1a-44da-a694-5b839856c654 in BUILD state, waiting for ACTIVE
2022-05-23 17:29:48 [INFO] resource: resource d4e9d939-1e1a-44da-a694-5b839856c654 in ERROR state, waiting for ACTIVE
2022-05-23 17:29:52 [INFO] resource: resource d4e9d939-1e1a-44da-a694-5b839856c654 in ERROR state, waiting for ACTIVE
2022-05-23 17:30:00 [INFO] resource: resource d4e9d939-1e1a-44da-a694-5b839856c654 in ERROR state, waiting for ACTIVE
2022-05-23 17:30:16 [INFO] resource: resource d4e9d939-1e1a-44da-a694-5b839856c654 in ERROR state, waiting for ACTIVE
2022-05-23 17:30:48 [INFO] resource: resource d4e9d939-1e1a-44da-a694-5b839856c654 in ERROR state, waiting for ACTIVE
2022-05-23 17:31:53 [INFO] resource: resource d4e9d939-1e1a-44da-a694-5b839856c654 in ERROR state, waiting for ACTIVE
2022-05-23 17:33:53 [INFO] resource: resource d4e9d939-1e1a-44da-a694-5b839856c654 in ERROR state, waiting for ACTIVE
2022-05-23 17:35:54 [INFO] resource: resource d4e9d939-1e1a-44da-a694-5b839856c654 in ERROR state, waiting for ACTIVE
2022-05-23 17:37:54 [INFO] resource: resource d4e9d939-1e1a-44da-a694-5b839856c654 in ERROR state, waiting for ACTIVE
2022-05-23 17:39:54 [INFO] resource: resource d4e9d939-1e1a-44da-a694-5b839856c654 in ERROR state, waiting for ACTIVE
2022-05-23 17:41:55 [INFO] resource: resource d4e9d939-1e1a-44da-a694-5b839856c654 in ERROR state, waiting for ACTIVE
2022-05-23 17:43:55 [INFO] resource: resource d4e9d939-1e1a-44da-a694-5b839856c654 in ERROR state, waiting for ACTIVE
2022-05-23 17:45:56 [INFO] resource: resource d4e9d939-1e1a-44da-a694-5b839856c654 in ERROR state, waiting for ACTIVE
2022-05-23 17:47:56 [INFO] resource: resource d4e9d939-1e1a-44da-a694-5b839856c654 in ERROR state, waiting for ACTIVE
2022-05-23 17:47:59 [INFO] Removing already existing instance (d4e9d939-1e1a-44da-a694-5b839856c654) with requested name (zaza-nova-cirros)
2022-05-23 17:48:10 [INFO] looking at application: {'name': 'keystone', 'type': {'pkg': 'keystone', 'origin_setting': 'openstack-origin'}}
2022-05-23 17:48:14 [INFO] Using keystone API V3 (or later) for overcloud auth
scp: /usr/local/share/ca-certificates/keystone_juju_ca_cert.crt: No such file or directory
2022-05-23 17:48:19 [INFO] looking at application: {'name': 'keystone', 'type': {'pkg': 'keystone', 'origin_setting': 'openstack-origin'}}
2022-05-23 17:48:23 [INFO] Launching instance zaza-nova-cirros
2022-05-23 17:48:24 [INFO] Checking instance is active
2022-05-23 17:48:24 [INFO] resource: resource e58fdc44-b5ed-43ee-b0d1-0d6ecfbc1296 in BUILD state, waiting for ACTIVE
2022-05-23 17:48:25 [INFO] resource: resource e58fdc44-b5ed-43ee-b0d1-0d6ecfbc1296 in ERROR state, waiting for ACTIVE
2022-05-23 17:48:27 [INFO] resource: resource e58fdc44-b5ed-43ee-b0d1-0d6ecfbc1296 in ERROR state, waiting for ACTIVE
2022-05-23 17:48:31 [INFO] resource: resource e58fdc44-b5ed-43ee-b0d1-0d6ecfbc1296 in ERROR state, waiting for ACTIVE
2022-05-23 17:48:40 [INFO] resource: resource e58fdc44-b5ed-43ee-b0d1-0d6ecfbc1296 in ERROR state, waiting for ACTIVE
2022-05-23 17:48:56 [INFO] resource: resource e58fdc44-b5ed-43ee-b0d1-0d6ecfbc1296 in ERROR state, waiting for ACTIVE
2022-05-23 17:49:28 [INFO] resource: resource e58fdc44-b5ed-43ee-b0d1-0d6ecfbc1296 in ERROR state, waiting for ACTIVE
2022-05-23 17:50:32 [INFO] resource: resource e58fdc44-b5ed-43ee-b0d1-0d6ecfbc1296 in ERROR state, waiting for ACTIVE
2022-05-23 17:52:33 [INFO] resource: resource e58fdc44-b5ed-43ee-b0d1-0d6ecfbc1296 in ERROR state, waiting for ACTIVE
2022-05-23 17:54:33 [INFO] resource: resource e58fdc44-b5ed-43ee-b0d1-0d6ecfbc1296 in ERROR state, waiting for ACTIVE
2022-05-23 17:56:34 [INFO] resource: resource e58fdc44-b5ed-43ee-b0d1-0d6ecfbc1296 in ERROR state, waiting for ACTIVE
2022-05-23 17:58:34 [INFO] resource: resource e58fdc44-b5ed-43ee-b0d1-0d6ecfbc1296 in ERROR state, waiting for ACTIVE
2022-05-23 18:00:35 [INFO] resource: resource e58fdc44-b5ed-43ee-b0d1-0d6ecfbc1296 in ERROR state, waiting for ACTIVE
2022-05-23 18:02:35 [INFO] resource: resource e58fdc44-b5ed-43ee-b0d1-0d6ecfbc1296 in ERROR state, waiting for ACTIVE
2022-05-23 18:04:35 [INFO] resource: resource e58fdc44-b5ed-43ee-b0d1-0d6ecfbc1296 in ERROR state, waiting for ACTIVE
2022-05-23 18:06:36 [INFO] resource: resource e58fdc44-b5ed-43ee-b0d1-0d6ecfbc1296 in ERROR state, waiting for ACTIVE
2022-05-23 18:06:39 [INFO] Removing already existing instance (e58fdc44-b5ed-43ee-b0d1-0d6ecfbc1296) with requested name (zaza-nova-cirros)
2022-05-23 18:06:49 [INFO] looking at application: {'name': 'keystone', 'type': {'pkg': 'keystone', 'origin_setting': 'openstack-origin'}}
2022-05-23 18:06:53 [INFO] Using keystone API V3 (or later) for overcloud auth
scp: /usr/local/share/ca-certificates/keystone_juju_ca_cert.crt: No such file or directory
2022-05-23 18:06:58 [INFO] looking at application: {'name': 'keystone', 'type': {'pkg': 'keystone', 'origin_setting': 'openstack-origin'}}
2022-05-23 18:07:02 [INFO] Launching instance zaza-nova-cirros
2022-05-23 18:07:03 [INFO] Checking instance is active
2022-05-23 18:07:03 [INFO] resource: resource 01a82755-4e0b-46d7-9ec2-2acc7f2b67e3 in BUILD state, waiting for ACTIVE
2022-05-23 18:07:04 [INFO] resource: resource 01a82755-4e0b-46d7-9ec2-2acc7f2b67e3 in ERROR state, waiting for ACTIVE
2022-05-23 18:07:07 [INFO] resource: resource 01a82755-4e0b-46d7-9ec2-2acc7f2b67e3 in ERROR state, waiting for ACTIVE
2022-05-23 18:07:11 [INFO] resource: resource 01a82755-4e0b-46d7-9ec2-2acc7f2b67e3 in ERROR state, waiting for ACTIVE
2022-05-23 18:07:19 [INFO] resource: resource 01a82755-4e0b-46d7-9ec2-2acc7f2b67e3 in ERROR state, waiting for ACTIVE
2022-05-23 18:07:35 [INFO] resource: resource 01a82755-4e0b-46d7-9ec2-2acc7f2b67e3 in ERROR state, waiting for ACTIVE
2022-05-23 18:08:08 [INFO] resource: resource 01a82755-4e0b-46d7-9ec2-2acc7f2b67e3 in ERROR state, waiting for ACTIVE
2022-05-23 18:09:12 [INFO] resource: resource 01a82755-4e0b-46d7-9ec2-2acc7f2b67e3 in ERROR state, waiting for ACTIVE
2022-05-23 18:11:12 [INFO] resource: resource 01a82755-4e0b-46d7-9ec2-2acc7f2b67e3 in ERROR state, waiting for ACTIVE
2022-05-23 18:13:13 [INFO] resource: resource 01a82755-4e0b-46d7-9ec2-2acc7f2b67e3 in ERROR state, waiting for ACTIVE
2022-05-23 18:15:13 [INFO] resource: resource 01a82755-4e0b-46d7-9ec2-2acc7f2b67e3 in ERROR state, waiting for ACTIVE
2022-05-23 18:17:13 [INFO] resource: resource 01a82755-4e0b-46d7-9ec2-2acc7f2b67e3 in ERROR state, waiting for ACTIVE
2022-05-23 18:19:14 [INFO] resource: resource 01a82755-4e0b-46d7-9ec2-2acc7f2b67e3 in ERROR state, waiting for ACTIVE
2022-05-23 18:21:15 [INFO] resource: resource 01a82755-4e0b-46d7-9ec2-2acc7f2b67e3 in ERROR state, waiting for ACTIVE
2022-05-23 18:23:15 [INFO] resource: resource 01a82755-4e0b-46d7-9ec2-2acc7f2b67e3 in ERROR state, waiting for ACTIVE
2022-05-23 18:25:16 [INFO] resource: resource 01a82755-4e0b-46d7-9ec2-2acc7f2b67e3 in ERROR state, waiting for ACTIVE
2022-05-23 18:25:16 [INFO] Removing instances launched by test (zaza-nova*)
2022-05-23 18:25:17 [INFO] ERROR
2022-05-23 18:25:17 [INFO] ======================================================================
2022-05-23 18:25:17 [INFO] ERROR: test_launch_small_instance (zaza.openstack.charm_tests.nova.tests.CirrosGuestCreateTest)
2022-05-23 18:25:17 [INFO] Launch a cirros instance and test connectivity.
2022-05-23 18:25:17 [INFO] ----------------------------------------------------------------------
2022-05-23 18:25:17 [INFO] Traceback (most recent call last):
2022-05-23 18:25:17 [INFO]   File "/home/ubuntu/src/review.opendev.org/openstack/charm-nova-cell-controller/src/.tox/func-target/lib/python3.8/site-packages/zaza/openstack/charm_tests/test_utils.py", line 677, in launch_guest
2022-05-23 18:25:17 [INFO]     return configure_guest.launch_instance(
2022-05-23 18:25:17 [INFO]   File "/home/ubuntu/src/review.opendev.org/openstack/charm-nova-cell-controller/src/.tox/func-target/lib/python3.8/site-packages/zaza/openstack/configure/guest.py", line 124, in launch_instance
2022-05-23 18:25:17 [INFO]     openstack_utils.resource_reaches_status(
2022-05-23 18:25:17 [INFO]   File "/home/ubuntu/src/review.opendev.org/openstack/charm-nova-cell-controller/src/.tox/func-target/lib/python3.8/site-packages/zaza/openstack/utilities/openstack.py", line 2340, in resource_reaches_status
2022-05-23 18:25:17 [INFO]     retryer(
2022-05-23 18:25:17 [INFO]   File "/home/ubuntu/src/review.opendev.org/openstack/charm-nova-cell-controller/src/.tox/func-target/lib/python3.8/site-packages/tenacity/__init__.py", line 404, in __call__
2022-05-23 18:25:17 [INFO]     do = self.iter(retry_state=retry_state)
2022-05-23 18:25:17 [INFO]   File "/home/ubuntu/src/review.opendev.org/openstack/charm-nova-cell-controller/src/.tox/func-target/lib/python3.8/site-packages/tenacity/__init__.py", line 360, in iter
2022-05-23 18:25:17 [INFO]     raise retry_exc.reraise()
2022-05-23 18:25:17 [INFO]   File "/home/ubuntu/src/review.opendev.org/openstack/charm-nova-cell-controller/src/.tox/func-target/lib/python3.8/site-packages/tenacity/__init__.py", line 193, in reraise
2022-05-23 18:25:17 [INFO]     raise self.last_attempt.result()
2022-05-23 18:25:17 [INFO]   File "/usr/lib/python3.8/concurrent/futures/_base.py", line 437, in result
2022-05-23 18:25:17 [INFO]     return self.__get_result()
2022-05-23 18:25:17 [INFO]   File "/usr/lib/python3.8/concurrent/futures/_base.py", line 389, in __get_result
2022-05-23 18:25:17 [INFO]     raise self._exception
2022-05-23 18:25:17 [INFO]   File "/home/ubuntu/src/review.opendev.org/openstack/charm-nova-cell-controller/src/.tox/func-target/lib/python3.8/site-packages/tenacity/__init__.py", line 407, in __call__
2022-05-23 18:25:17 [INFO]     result = fn(*args, **kwargs)
2022-05-23 18:25:17 [INFO]   File "/home/ubuntu/src/review.opendev.org/openstack/charm-nova-cell-controller/src/.tox/func-target/lib/python3.8/site-packages/zaza/openstack/utilities/openstack.py", line 2295, in _resource_reaches_status
2022-05-23 18:25:17 [INFO]     assert resource_status == expected_status
2022-05-23 18:25:17 [INFO] AssertionError
2022-05-23 18:25:17 [INFO] The above exception was the direct cause of the following exception:
2022-05-23 18:25:17 [INFO] Traceback (most recent call last):
2022-05-23 18:25:17 [INFO]   File "/home/ubuntu/src/review.opendev.org/openstack/charm-nova-cell-controller/src/.tox/func-target/lib/python3.8/site-packages/zaza/openstack/charm_tests/nova/tests.py", line 49, in test_launch_small_instance
2022-05-23 18:25:17 [INFO]     self.launch_guest(
2022-05-23 18:25:17 [INFO]   File "/home/ubuntu/src/review.opendev.org/openstack/charm-nova-cell-controller/src/.tox/func-target/lib/python3.8/site-packages/zaza/openstack/charm_tests/test_utils.py", line 660, in launch_guest
2022-05-23 18:25:17 [INFO]     for attempt in tenacity.Retrying(
2022-05-23 18:25:17 [INFO]   File "/home/ubuntu/src/review.opendev.org/openstack/charm-nova-cell-controller/src/.tox/func-target/lib/python3.8/site-packages/tenacity/__init__.py", line 382, in __iter__
2022-05-23 18:25:17 [INFO]     do = self.iter(retry_state=retry_state)
2022-05-23 18:25:17 [INFO]   File "/home/ubuntu/src/review.opendev.org/openstack/charm-nova-cell-controller/src/.tox/func-target/lib/python3.8/site-packages/tenacity/__init__.py", line 361, in iter
2022-05-23 18:25:17 [INFO]     raise retry_exc from fut.exception()
2022-05-23 18:25:17 [INFO] tenacity.RetryError: RetryError[<Future at 0x7f18fe602730 state=finished raised AssertionError>]
2022-05-23 18:25:17 [INFO] ----------------------------------------------------------------------
2022-05-23 18:25:17 [INFO] Ran 1 test in 3388.128s