Intermittent "Neutron did not start" failures in the gate

[Matt Riedemann]

Seen here:

http://logs.openstack.org/68/642068/2/gate/tempest-full-py3/3648e00/controller/logs/devstacklog.txt.gz#_2019-03-13_09_43_32_198

2019-03-13 09:42:32.696 | + functions-common:test_with_retry:2261 : timeout 60 sh -c 'while ! wget --no-proxy -q -O- http://198.72.124.14:19696; do sleep 0.5; done'
2019-03-13 09:43:32.198 | + functions-common:test_with_retry:2262 : die 2262 'Neutron did not start'
2019-03-13 09:43:32.203 | + functions-common:die:195 : local exitcode=0
2019-03-13 09:43:32.207 | [Call Trace]
2019-03-13 09:43:32.207 | ./stack.sh:1303:start_neutron_service_and_check
2019-03-13 09:43:32.207 | /opt/stack/devstack/lib/neutron-legacy:504:test_with_retry
2019-03-13 09:43:32.207 | /opt/stack/devstack/functions-common:2262:die
2019-03-13 09:43:32.213 | [ERROR] /opt/stack/devstack/functions-common:2262 Neutron did not start

devstack waits up to 60 seconds to neutron API to start and looking at the API logs it took longer than 2 minutes:

http://logs.openstack.org/68/642068/2/gate/tempest-full-py3/3648e00/controller/logs/screen-q-svc.txt.gz

Starts here:

Mar 13 09:42:31.162711 ubuntu-bionic-inap-mtl01-0003755170 systemd[1]: Started Devstack <email address hidden>.

This is the last API log entry:

Mar 13 09:44:18.906122 ubuntu-bionic-inap-mtl01-0003755170 neutron-server[10000]: DEBUG oslo_service.service [-] ******************************************************************************** {{(pid=10000) log_opt_values /usr/local/lib/python3.6/dist-packages/oslo_config/cfg.py:2577}}

Looks like there is a big jump in time here:

Mar 13 09:42:35.558034 ubuntu-bionic-inap-mtl01-0003755170 neutron-server[10000]: DEBUG oslo_db.sqlalchemy.engines [None req-46b360f6-5a07-4e28-ad6d-7820e1c174b9 None None] MySQL server mode set to STRICT_TRANS_TABLES,STRICT_ALL_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,TRADITIONAL,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION {{(pid=10000) _check_effective_sql_mode /usr/local/lib/python3.6/dist-packages/oslo_db/sqlalchemy/engines.py:307}}
Mar 13 09:44:18.212177 ubuntu-bionic-inap-mtl01-0003755170 neutron-server[10000]: INFO neutron.plugins.ml2.managers [None req-46b360f6-5a07-4e28-ad6d-7820e1c174b9 None None] Initializing driver for type 'gre'

http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22%5BERROR%5D%5C%22%20AND%20message%3A%5C%22Neutron%20did%20not%20start%5C%22%20AND%20tags%3A%5C%22console%5C%22%20AND%20voting%3A1&from=7d

[Matt Riedemann (mriedem)]

frickler also pointed out these other failures that result in the same devstack timeout but have obvious failures in the neutron API logs:

http://logs.openstack.org/34/642834/1/check/tempest-full/f8a254a/controller/logs/screen-q-svc.txt.gz?level=TRACE

Mar 12 18:16:06.388244 ubuntu-bionic-ovh-bhs1-0003715080 neutron-server[3874]: ERROR neutron.service [None req-4fee45c3-a421-4505-9136-36a95fa1d327 None None] Unrecoverable error: please check log for details.: ExtensionsNotFound: Extensions not found: ['subnet-service-types'].
Mar 12 18:16:06.388244 ubuntu-bionic-ovh-bhs1-0003715080 neutron-server[3874]: ERROR neutron.service Traceback (most recent call last):
Mar 12 18:16:06.388244 ubuntu-bionic-ovh-bhs1-0003715080 neutron-server[3874]: ERROR neutron.service File "/opt/stack/neutron/neutron/service.py", line 88, in serve_wsgi
Mar 12 18:16:06.388244 ubuntu-bionic-ovh-bhs1-0003715080 neutron-server[3874]: ERROR neutron.service service.start()
Mar 12 18:16:06.388244 ubuntu-bionic-ovh-bhs1-0003715080 neutron-server[3874]: ERROR neutron.service File "/opt/stack/neutron/neutron/service.py", line 64, in start
Mar 12 18:16:06.388244 ubuntu-bionic-ovh-bhs1-0003715080 neutron-server[3874]: ERROR neutron.service self.wsgi_app = _run_wsgi(self.app_name)
Mar 12 18:16:06.388244 ubuntu-bionic-ovh-bhs1-0003715080 neutron-server[3874]: ERROR neutron.service File "/opt/stack/neutron/neutron/service.py", line 316, in _run_wsgi
Mar 12 18:16:06.388244 ubuntu-bionic-ovh-bhs1-0003715080 neutron-server[3874]: ERROR neutron.service app = config.load_paste_app(app_name)
Mar 12 18:16:06.388244 ubuntu-bionic-ovh-bhs1-0003715080 neutron-server[3874]: ERROR neutron.service File "/opt/stack/neutron/neutron/common/config.py", line 125, in load_paste_app
Mar 12 18:16:06.388244 ubuntu-bionic-ovh-bhs1-0003715080 neutron-server[3874]: ERROR neutron.service app = loader.load_app(app_name)
Mar 12 18:16:06.388244 ubuntu-bionic-ovh-bhs1-0003715080 neutron-server[3874]: ERROR neutron.service File "/usr/local/lib/python2.7/dist-packages/oslo_service/wsgi.py", line 353, in load_app
Mar 12 18:16:06.388244 ubuntu-bionic-ovh-bhs1-0003715080 neutron-server[3874]: ERROR neutron.service return deploy.loadapp("config:%s" % self.config_path, name=name)
Mar 12 18:16:06.388244 ubuntu-bionic-ovh-bhs1-0003715080 neutron-server[3874]: ERROR neutron.service File "/usr/local/lib/python2.7/dist-packages/paste/deploy/loadwsgi.py", line 253, in loadapp
Mar 12 18:16:06.388244 ubuntu-bionic-ovh-bhs1-0003715080 neutron-server[3874]: ERROR neutron.service return loadobj(APP, uri, name=name, **kw)
Mar 12 18:16:06.388244 ubuntu-bionic-ovh-bhs1-0003715080 neutron-server[3874]: ERROR neutron.service File "/usr/local/lib/python2.7/dist-packages/paste/deploy/loadwsgi.py", line 278, in loadobj
Mar 12 18:16:06.388244 ubuntu-bionic-ovh-bhs1-0003715080 neutron-server[3874]: ERROR neutron.service return context.create()
Mar 12 18:16:06.388244 ubuntu-bionic-ovh-bhs1-0003715080 neutron-server[3874]: ERROR neutron.service File "/usr/local/lib/python2.7/dist-packages/paste/deploy/loadwsgi.py", line 715, in create
Mar 12 18:16:06.388244 ubuntu-bionic-ovh-bhs1-0003715080 neutron...

[LIU Yulong (dragon889)]

This "ExtensionsNotFound: Extensions not found: ['subnet-service-types']." may only come from this refactor patch:
https://review.openstack.org/#/c/642834

[LIU Yulong (dragon889)]

And most "Neutron did not start" failures are coming from this:
https://review.openstack.org/#/c/641186
it is trying to rename the process tittle by using this:
https://review.openstack.org/#/c/637019/

This one seems still in progress:
https://review.openstack.org/#/c/639585/

[Slawek Kaplonski (slaweq)]

I'm closing this bug now as I don't think we still have such issue in the gate currently.