Functional tests are timing out

[Slawek Kaplonski]

Probably due to very large number of logs it's timeouting at some point. We had similar issues in the past and we limited some WARNING messages to not be logged to workaround the issue.

Example of job's logs: https://storage.bhs.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_117/734304/9/check/neutron-functional/11781bb/job-output.txt

Most likely problem is caused by logs like below. And those tests are passing.

2020-07-29 21:56:37.633888 | controller | The above exception was the direct cause of the following exception:
2020-07-29 21:56:37.633897 | controller |
2020-07-29 21:56:37.633909 | controller | Traceback (most recent call last):
2020-07-29 21:56:37.633918 | controller | File "/usr/lib/python3.8/contextlib.py", line 131, in __exit__
2020-07-29 21:56:37.633927 | controller | self.gen.throw(type, value, traceback)
2020-07-29 21:56:37.633936 | controller | File "/home/zuul/src/opendev.org/openstack/neutron/.tox/dsvm-functional/lib/python3.8/site-packages/oslo_db/sqlalchemy/enginefacade.py", line 1064, in _transaction_scope
2020-07-29 21:56:37.633946 | controller | yield resource
2020-07-29 21:56:37.633956 | controller | File "/home/zuul/src/opendev.org/openstack/neutron/neutron/db/ovn_hash_ring_db.py", line 42, in remove_nodes_from_host
2020-07-29 21:56:37.633965 | controller | context.session.query(ovn_models.OVNHashRing).filter(
2020-07-29 21:56:37.633974 | controller | File "/home/zuul/src/opendev.org/openstack/neutron/.tox/dsvm-functional/lib/python3.8/site-packages/sqlalchemy/orm/query.py", line 3894, in delete
2020-07-29 21:56:37.633984 | controller | delete_op.exec_()
2020-07-29 21:56:37.633994 | controller | File "/home/zuul/src/opendev.org/openstack/neutron/.tox/dsvm-functional/lib/python3.8/site-packages/sqlalchemy/orm/persistence.py", line 1697, in exec_
2020-07-29 21:56:37.634004 | controller | self._do_exec()
2020-07-29 21:56:37.634013 | controller | File "/home/zuul/src/opendev.org/openstack/neutron/.tox/dsvm-functional/lib/python3.8/site-packages/sqlalchemy/orm/persistence.py", line 1928, in _do_exec
2020-07-29 21:56:37.634023 | controller | self._execute_stmt(delete_stmt)
2020-07-29 21:56:37.634032 | controller | File "/home/zuul/src/opendev.org/openstack/neutron/.tox/dsvm-functional/lib/python3.8/site-packages/sqlalchemy/orm/persistence.py", line 1702, in _execute_stmt
2020-07-29 21:56:37.634042 | controller | self.result = self.query._execute_crud(stmt, self.mapper)
2020-07-29 21:56:37.634050 | controller | File "/home/zuul/src/opendev.org/openstack/neutron/.tox/dsvm-functional/lib/python3.8/site-packages/sqlalchemy/orm/query.py", line 3536, in _execute_crud
2020-07-29 21:56:37.634059 | controller | return conn.execute(stmt, self._params)
2020-07-29 21:56:37.634069 | controller | File "/home/zuul/src/opendev.org/openstack/neutron/.tox/dsvm-functional/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1014, in execute
2020-07-29 21:56:37.634079 | controller | return meth(self, multiparams, params)
2020-07-29 21:56:37.634088 | controller | File "/home/zuul/src/opendev.org/openstack/neutron/.tox/dsvm-functional/lib/python3.8/site-packages/sqlalchemy/sql/elements.py", line 298, in _execute_on_connection
2020-07-29 21:56:37.634098 | controller | return connection._execute_clauseelement(self, multiparams, params)
2020-07-29 21:56:37.634121 | controller | File "/home/zuul/src/opendev.org/openstack/neutron/.tox/dsvm-functional/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1127, in _execute_clauseelement
2020-07-29 21:56:37.634132 | controller | ret = self._execute_context(
2020-07-29 21:56:37.634142 | controller | File "/home/zuul/src/opendev.org/openstack/neutron/.tox/dsvm-functional/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1317, in _execute_context
2020-07-29 21:56:37.634150 | controller | self._handle_dbapi_exception(
2020-07-29 21:56:37.634163 | controller | File "/home/zuul/src/opendev.org/openstack/neutron/.tox/dsvm-functional/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1509, in _handle_dbapi_exception
2020-07-29 21:56:37.634172 | controller | util.raise_(newraise, with_traceback=exc_info[2], from_=e)
2020-07-29 21:56:37.634187 | controller | File "/home/zuul/src/opendev.org/openstack/neutron/.tox/dsvm-functional/lib/python3.8/site-packages/sqlalchemy/util/compat.py", line 178, in raise_
2020-07-29 21:56:37.634196 | controller | raise exception
2020-07-29 21:56:37.634205 | controller | File "/home/zuul/src/opendev.org/openstack/neutron/.tox/dsvm-functional/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1277, in _execute_context
2020-07-29 21:56:37.634214 | controller | self.dialect.do_execute(
2020-07-29 21:56:37.634223 | controller | File "/home/zuul/src/opendev.org/openstack/neutron/.tox/dsvm-functional/lib/python3.8/site-packages/sqlalchemy/engine/default.py", line 593, in do_execute
2020-07-29 21:56:37.634232 | controller | cursor.execute(statement, parameters)
2020-07-29 21:56:37.634241 | controller | oslo_db.exception.DBNonExistentTable: (sqlite3.OperationalError) no such table: ovn_hash_ring
2020-07-29 21:56:37.634251 | controller | [SQL: DELETE FROM ovn_hash_ring WHERE ovn_hash_ring.hostname = ? AND ovn_hash_ring.group_name = ?]
2020-07-29 21:56:37.634260 | controller | [parameters: ('ubuntu-focal-ovh-gra1-0018961947', 'mechanism_driver')]
2020-07-29 21:56:37.634269 | controller | (Background on this error at: http://sqlalche.me/e/13/e3q8)

[Slawek Kaplonski (slaweq)]

Looks that after fixing other issues this isn't a problem anymore. So I'm closing it, at least for now.

[Slawek Kaplonski (slaweq)]

I see now that it happens also in our current functional tests jobs, which are run on Ubuntu 18.04, like e.g. https://1ecd386c312cee0f5e31-dcaa487a47c3d7a82f096f3792363793.ssl.cf1.rackcdn.com/745641/2/check/neutron-functional-with-uwsgi/8401f85/job-output.txt

[Slawek Kaplonski (slaweq)]

It happened again recently https://storage.gra.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_6dc/755752/3/check/neutron-functional-with-uwsgi/6dcca4f/job-output.txt

[Slawek Kaplonski (slaweq)]

New logs with such timeout https://zuul.opendev.org/t/openstack/build/8248ee500c344c0396bd46271f8ee201

[Slawek Kaplonski (slaweq)]

It still happens pretty often: https://zuul.opendev.org/t/openstack/builds?job_name=neutron-functional-with-uwsgi&result=TIMED_OUT

In most cases there is huge "gap" in the logs at the end, like:

2021-05-15 09:03:38.066452 | controller | {2} neutron.tests.functional.tests.common.test_net_helpers.NetcatTesterTestCase.test_stop_process_no_process_skip_no_process_exception [2.384257s] ... ok
2021-05-15 09:03:38.090009 | controller | Stopping rootwrap daemon process with pid=67346
2021-05-15 10:42:26.262192 | RUN END RESULT_TIMED_OUT: [untrusted : opendev.org/openstack/neutron/playbooks/run_functional_job.yaml@master]

or

2021-05-13 10:25:17.427785 | controller | {1} neutron.tests.functional.agent.ovn.metadata.test_metadata_agent.TestMetadataAgent.test_agent_delete_bound_nonexternal_port [2.128591s] ... ok
2021-05-13 11:51:34.275468 | RUN END RESULT_TIMED_OUT: [untrusted : opendev.org/openstack/neutron/playbooks/run_functional_job.yaml@master]
2021-05-13 11:51:34.276828 | POST-RUN START: [untrusted : opendev.org/openstack/neutron/playbooks/post_functional_job.yaml@master]

[Slawek Kaplonski (slaweq)]

We don't see this issue anymore, I'm closing that bug.