[victoria] fs001 and fs035 failing due to tempest.lib.exceptions.TimeoutException: Request timed out

[Bhagyashri Shewale]

Test:
tempest.scenario.test_network_basic_ops.TestNetworkBasicOps.test_hotplug_nic

Error logs:
2022-04-27 21:30:52,410 382630 INFO [tempest.lib.common.rest_client] Request (TestNetworkBasicOps:_run_cleanups): 204 DELETE https://10.0.0.5:13696/v2.0/networks/432b4038-581b-44c2-a0cf-10f8c2367699 1.779s
2022-04-27 21:30:52,411 382630 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: None
    Response - Headers: {'content-length': '0', 'x-openstack-request-id': 'req-b719f76f-6e4f-4b09-9f16-8b127f51be10', 'date': 'Wed, 27 Apr 2022 21:30:52 GMT', 'connection': 'close', 'status': '204', 'content-location': 'https://10.0.0.5:13696/v2.0/networks/432b4038-581b-44c2-a0cf-10f8c2367699'}
        Body: b''
}}}

Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/tempest/common/utils/__init__.py", line 70, in wrapper
    return f(*func_args, **func_kwargs)
  File "/usr/lib/python3.6/site-packages/tempest/scenario/test_network_basic_ops.py", line 531, in test_hotplug_nic
    self._setup_network_and_servers()
  File "/usr/lib/python3.6/site-packages/tempest/scenario/test_network_basic_ops.py", line 120, in _setup_network_and_servers
    server = self._create_server(self.network, port_id)
  File "/usr/lib/python3.6/site-packages/tempest/scenario/test_network_basic_ops.py", line 172, in _create_server
    security_groups=security_groups)
  File "/usr/lib/python3.6/site-packages/tempest/scenario/manager.py", line 317, in create_server
    image_id=image_id, **kwargs)
  File "/usr/lib/python3.6/site-packages/tempest/common/compute.py", line 266, in create_test_server
    server['id'])
  File "/usr/lib/python3.6/site-packages/oslo_utils/excutils.py", line 220, in __exit__
    self.force_reraise()
  File "/usr/lib/python3.6/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
    six.reraise(self.type_, self.value, self.tb)
  File "/usr/local/lib/python3.6/site-packages/six.py", line 719, in reraise
    raise value
  File "/usr/lib/python3.6/site-packages/tempest/common/compute.py", line 237, in create_test_server
    clients.servers_client, server['id'], wait_until)
  File "/usr/lib/python3.6/site-packages/tempest/common/waiters.py", line 96, in wait_for_server_status
    raise lib_exc.TimeoutException(message)
tempest.lib.exceptions.TimeoutException: Request timed out
Details: (TestNetworkBasicOps:test_hotplug_nic) Server e7dd89ea-c6bb-4ad0-8bd5-867c959e96d4 failed to reach ACTIVE status and task state "None" within the required time (300 s). Current status: BUILD. Current task state: spawning.

Affected jobs:

fs001 and fs035

[1]: https://logserver.rdoproject.org/35/35235/10/check/periodic-tripleo-ci-centos-8-ovb-3ctlr_1comp-featureset001-victoria/702f76d/logs/undercloud/var/log/tempest/stestr_results.html.gz
[2]: https://logserver.rdoproject.org/35/35235/11/check/periodic-tripleo-ci-centos-8-ovb-3ctlr_1comp-featureset001-victoria/81608da/logs/undercloud/var/log/tempest/stestr_results.html.gz

[Bhagyashri Shewale (bhagyashri-shewale)]

skiplist patch : https://review.opendev.org/c/openstack/openstack-tempest-skiplist/+/839721

[Douglas Viroel (dviroel)]

Error on compute node:

2022-04-27 21:30:42.601 7 ERROR nova.compute.manager [req-5eff7201-c298-4b5b-8e93-0505ca4348e2 aae01b89eddb4ed2b13c227e40e69072 a217a9ea4d9942cc8749a5c561199933 - default default] [instance: e7dd89ea-c6bb-4ad0-8bd5-867c959e96d4] Instance failed to spawn: nova.exception.VirtualInterfaceCreateException: Virtual Interface creation failed

[1] https://logserver.rdoproject.org/35/35235/10/check/periodic-tripleo-ci-centos-8-ovb-3ctlr_1comp-featureset001-victoria/702f76d/logs/overcloud-novacompute-0/var/log/containers/nova/nova-compute.log.txt.gz

[Marios Andreou (marios-b)]

not sure about the skiplist @ [1] yet - this bug and the skip list are based on the testproject runs from [2]

looking at the job history [3] i cant find an example of this from the periodic runs - the latest 2 have one deployment failure @ [4] and another tempest failure at [5] but with much more tests than just that one

[1] https://review.opendev.org/c/openstack/openstack-tempest-skiplist/+/839721
[2] https://review.rdoproject.org/r/c/testproject/+/35235
[3] https://review.rdoproject.org/zuul/builds?job_name=periodic-tripleo-ci-centos-8-ovb-3ctlr_1comp-featureset001-victoria
[4] https://logserver.rdoproject.org/openstack-periodic-integration-stable2/opendev.org/openstack/tripleo-ci/master/periodic-tripleo-ci-centos-8-ovb-3ctlr_1comp-featureset001-victoria/8518b79/logs/undercloud/home/zuul/overcloud_deploy.log.txt.gz
[5] https://logserver.rdoproject.org/openstack-periodic-integration-stable2/opendev.org/openstack/tripleo-ci/master/periodic-tripleo-ci-centos-8-ovb-3ctlr_1comp-featureset001-victoria/016b699/logs/undercloud/var/log/tempest/stestr_results.html.gz

[Marios Andreou (marios-b)]

situation is *really* unstable and unclear right now. I checked the last 3 runs of each fs1 and fs35 and we basically have 6 different things (and not one of this bug):

-----FS1----

        * https://review.rdoproject.org/zuul/builds?job_name=periodic-tripleo-ci-centos-8-ovb-3ctlr_1comp-featureset001-victoria

        * https://logserver.rdoproject.org/openstack-periodic-integration-stable2/opendev.org/openstack/tripleo-ci/master/periodic-tripleo-ci-centos-8-ovb-3ctlr_1comp-featureset001-victoria/2fec62f/job-output.txt
        * 2022-05-01 07:57:51.576153 | primary | FAILED - RETRYING: Ensure private network exists (5 retries left).
        * 2022-05-01 08:00:59.615332 | primary | fatal: [undercloud -> undercloud]: FAILED! => {"attempts": 5, "changed": false, "extra_data": {"data": null, "details": "None", "response": "None"}, "msg": "Multiple matches found for private"}

        * https://logserver.rdoproject.org/openstack-periodic-integration-stable2/opendev.org/openstack/tripleo-ci/master/periodic-tripleo-ci-centos-8-ovb-3ctlr_1comp-featureset001-victoria/3bfd1c9/job-output.txt
        * 2022-04-30 06:35:18.730319 | primary | fatal: [undercloud]: FAILED! => {"changed": true, "cmd": " openstack overcloud node introspect --all-manageable --provide >/home/zuul/overcloud_introspect.log 2>&1", "delta": "0:20:28.207084", "end": "2022-04-30 06:35:18.476489", "msg": "non-zero return code", "rc": 1, "start": "2022-04-30 06:14:50.269405", "stderr": "", "stderr_lines": [], "stdout": "", "stdout_lines": []}

        * https://logserver.rdoproject.org/openstack-periodic-integration-stable2/opendev.org/openstack/tripleo-ci/master/periodic-tripleo-ci-centos-8-ovb-3ctlr_1comp-featureset001-victoria/8518b79/job-output.txt
        * 2022-04-29 07:58:15.569434 | primary | "overcloud_deploy_result": "failed"

-----FS35----

        * https://review.rdoproject.org/zuul/builds?job_name=periodic-tripleo-ci-centos-8-ovb-3ctlr_1comp-featureset035-victoria

        * https://logserver.rdoproject.org/openstack-periodic-integration-stable2/opendev.org/openstack/tripleo-ci/master/periodic-tripleo-ci-centos-8-ovb-3ctlr_1comp-featureset035-victoria/55a12de/logs/undercloud/var/log/tempest/stestr_results.html.gz

        * https://logserver.rdoproject.org/openstack-periodic-integration-stable2/opendev.org/openstack/tripleo-ci/master/periodic-tripleo-ci-centos-8-ovb-3ctlr_1comp-featureset035-victoria/286a7d4/job-output.txt
        * 2022-04-30 08:08:54.503695 | primary | "overcloud_deploy_result": "failed"

        * https://logserver.rdoproject.org/openstack-periodic-integration-stable2/opendev.org/openstack/tripleo-ci/master/periodic-tripleo-ci-centos-8-ovb-3ctlr_1comp-featureset035-victoria/0b810b7/job-output.txt
        * 2022-04-29 06:39:40.391327 | primary | fatal: [undercloud]: FAILED! => {"changed": false, "module_stderr": "Warning: Permanently added '127.0.0.2' (ECDSA) to the list of known hosts.\r\nConnection to 127.0.0.2 closed.\r\n", "module_stdout": "error: rpmdb: BDB0113 Thread/process 162763/139914106981248 failed: BDB1507 Thread died in Berkeley DB library\r\nerror: db5 error(-30973) from dbenv->failchk: BDB0087 DB_RUNRECOVERY: Fatal error...

[Marios Andreou (marios-b)]

as commented above - closing this out for now as we (still) don't have consistent fails on this in order to investigate.

If you see more examples please re-open the bug and add the relevant info