Deployment failed because "nova_wait_for_api_service" container failed to start (nova_api_wsgi_error - ModuleNotFoundError: No module named 'dataclasses')

[Sandeep Yadav]

Description:-
============

Compute Component pipeline[1] - standalone jobs is failing during deployment because nova_wait_for_api_service container failed to start.

[1] http://dashboard-ci.tripleo.org/d/FE8Hf29Wz/component-pipeline?orgId=1

Error Snippet
=============

https://logserver.rdoproject.org/openstack-component-compute/opendev.org/openstack/tripleo-ci/master/periodic-tripleo-ci-centos-8-standalone-full-tempest-scenario-compute-master/b952891/job-output.txt
~~~
2020-04-12 08:56:08.172835 | primary | TASK [tripleo_deploy : Standalone deploy] **************************************
2020-04-12 08:56:08.172988 | primary | Sunday 12 April 2020 08:56:08 +0000 (0:00:00.038) 0:05:56.618 **********
2020-04-12 09:40:46.931226 | primary | fatal: [undercloud]: FAILED! => {
2020-04-12 09:40:46.931323 | primary | "ansible_job_id": "20702334658.13401",
2020-04-12 09:40:46.931346 | primary | "changed": false,
2020-04-12 09:40:46.931363 | primary | "cmd": "openstack tripleo deploy --templates $DEPLOY_TEMPLATES --standalone --yes --output-dir $DEPLOY_OUTPUT_DIR --stack $DEPLOY_STACK --standalone-role $DEPLOY_STANDALONE_ROLE --timeout $DEPLOY_TIMEOUT_ARG -e /usr/share/openstack-tripleo-heat-templates/environments/standalone/standalone-tripleo.yaml -e /home/zuul/containers-prepare-parameters.yaml -e /home/zuul/standalone_parameters.yaml -e /usr/share/openstack-tripleo-heat-templates/environments/low-memory-usage.yaml -r $DEPLOY_ROLES_FILE --deployment-user $DEPLOY_DEPLOYMENT_USER --local-ip $DEPLOY_LOCAL_IP >/home/zuul/standalone_deploy.log 2>&1",
2020-04-12 09:40:46.931378 | primary | "delta": "0:44:26.857745",
2020-04-12 09:40:46.931419 | primary | "end": "2020-04-12 09:40:36.728046",
2020-04-12 09:40:46.931439 | primary | "finished": 1,
2020-04-12 09:40:46.931456 | primary | "rc": 1,
2020-04-12 09:40:46.931471 | primary | "start": "2020-04-12 08:56:09.870301"
2020-04-12 09:40:46.931479 | primary | }
2020-04-12 09:40:46.931486 | primary |
2020-04-12 09:40:46.931493 | primary | MSG:
2020-04-12 09:40:46.931500 | primary |
2020-04-12 09:40:46.931509 | primary | non-zero return code
2020-04-12 09:40:46.938472 | primary |
2020-04-12 09:40:46.938541 | primary | PLAY RECAP *********************************************************************
2020-04-12 09:40:46.938570 | primary | undercloud : ok=82 changed=35 unreachable=0 failed=1 skipped=87 rescued=0 ignored=0
~~~

https://logserver.rdoproject.org/openstack-component-compute/opendev.org/openstack/tripleo-ci/master/periodic-tripleo-ci-centos-8-standalone-full-tempest-scenario-compute-master/b952891/logs/undercloud/home/zuul/standalone_deploy.log.txt.gz

~~~
TASK [tripleo_container_manage : Check podman create status] *******************
Sunday 12 April 2020 09:35:21 +0000 (0:00:00.486) 0:34:00.684 **********
FAILED - RETRYING: Check podman create status (60 retries left).
.
.
FAILED - RETRYING: Check podman create status (1 retries left).
ok: [standalone] => (item=None)
ok: [standalone]

TASK [tripleo_container_manage : Print the containers that failed to start] ****
Sunday 12 April 2020 09:40:34 +0000 (0:00:00.207) 0:39:13.523 **********
fatal: [standalone]: FAILED! => changed=false
  msg: '[''nova_wait_for_api_service''] failed to start, check logs in /var/log/containers/stdouts/'

NO MORE HOSTS LEFT *************************************************************

PLAY RECAP *********************************************************************
standalone : ok=938 changed=457 unreachable=0 failed=1 skipped=657 rescued=0 ignored=0
~~~

https://logserver.rdoproject.org/openstack-component-compute/opendev.org/openstack/tripleo-ci/master/periodic-tripleo-ci-centos-8-standalone-full-tempest-scenario-compute-master/b952891/logs/undercloud/var/log/containers/stdouts/nova_wait_for_api_service.log.txt.gz

~~~
2020-04-12T09:35:24.323446648+00:00 stdout F DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): 192.168.24.1:8774
2020-04-12T09:35:27.218690625+00:00 stdout F DEBUG:urllib3.connectionpool:http://192.168.24.1:8774 "GET / HTTP/1.1" 500 531
2020-04-12T09:35:27.219942369+00:00 stdout F DEBUG:keystoneauth.session:RESP: [500] Connection: close Content-Length: 531 Content-Type: text/html; charset=iso-8859-1 Date: Sun, 12 Apr 2020 09:35:24 GMT Server: Apache
2020-04-12T09:35:27.219990956+00:00 stdout F DEBUG:keystoneauth.session:RESP BODY: Omitted, Content-Type is set to text/html; charset=iso-8859-1. Only application/json responses have their bodies logged.
2020-04-12T09:35:27.220253158+00:00 stdout F INFO:nova_wait_for_api_service:Waiting for nova-api service
2020-04-12T09:35:37.237495916+00:00 stdout F DEBUG:keystoneauth.session:REQ: curl -g -i -X GET http://192.168.24.1:8774 -H "Accept: application/json" -H "User-Agent: python-novaclient" -H "X-Auth-Token: {SHA256}6797e09a04499fdf85ad2caa71b34d174f1fbfe2dca1883bdc0ef20cc0f1c5e8" -H "X-OpenStack-Nova-API-Version: 2.11"
2020-04-12T09:35:37.240204660+00:00 stdout F DEBUG:urllib3.connectionpool:Resetting dropped connection: 192.168.24.1
2020-04-12T09:35:37.249796241+00:00 stdout F DEBUG:urllib3.connectionpool:http://192.168.24.1:8774 "GET / HTTP/1.1" 500 531
2020-04-12T09:35:37.250845874+00:00 stdout F DEBUG:keystoneauth.session:RESP: [500] Connection: close Content-Length: 531 Content-Type: text/html; charset=iso-8859-1 Date: Sun, 12 Apr 2020 09:35:37 GMT Server: Apache
2020-04-12T09:35:37.250929726+00:00 stdout F DEBUG:keystoneauth.session:RESP BODY: Omitted, Content-Type is set to text/html; charset=iso-8859-1. Only application/json responses have their bodies logged.
2020-04-12T09:35:37.251308182+00:00 stdout F INFO:nova_wait_for_api_service:Waiting for nova-api service
~~~

Current Behavior
================

500 error and awaiting for nova-api to come up.
~~~
2020-04-12T09:35:37.249796241+00:00 stdout F DEBUG:urllib3.connectionpool:http://192.168.24.1:8774 "GET / HTTP/1.1" 500 531
2020-04-12T09:35:37.250845874+00:00 stdout F DEBUG:keystoneauth.session:RESP: [500] Connection: close Content-Length: 531 Content-Type: text/html; charset=iso-8859-1 Date: Sun, 12 Apr 2020 09:35:37 GMT Server: Apache
2020-04-12T09:35:37.250929726+00:00 stdout F DEBUG:keystoneauth.session:RESP BODY: Omitted, Content-Type is set to text/html; charset=iso-8859-1. Only application/json responses have their bodies logged.
2020-04-12T09:35:37.251308182+00:00 stdout F INFO:nova_wait_for_api_service:Waiting for nova-api service
~~~

Expected behavior:-
=================

Good example - From 07th April:-

https://logserver.rdoproject.org/openstack-component-compute/opendev.org/openstack/tripleo-ci/master/periodic-tripleo-ci-centos-8-standalone-full-tempest-scenario-compute-master/4ec30d8/logs/undercloud/var/log/containers/stdouts/nova_wait_for_api_service.log.txt.gz

~~
2020-04-07T08:18:37.239408061+00:00 stdout F DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): 192.168.24.1:8774
2020-04-07T08:18:41.383153403+00:00 stdout F DEBUG:urllib3.connectionpool:http://192.168.24.1:8774 "GET / HTTP/1.1" 200 None
2020-04-07T08:18:41.384520749+00:00 stdout F DEBUG:keystoneauth.session:RESP: [200] Connection: Keep-Alive Content-Encoding: gzip Content-Type: application/json Date: Tue, 07 Apr 2020 08:18:37 GMT Keep-Alive: timeout=15, max=100 Server: Apache Transfer-Encoding: chunked Vary: Accept-Encoding
2020-04-07T08:18:41.384587373+00:00 stdout F DEBUG:keystoneauth.session:RESP BODY: {"versions": [{"id": "v2.0", "status": "SUPPORTED", "version": "", "min_version": "", "updated": "2011-01-21T11:33:21Z", "links": [{"rel": "self", "href": "http://192.168.24.1:8774/v2/"}]}, {"id": "v2.1", "status": "CURRENT", "version": "2.85", "min_version": "2.1", "updated": "2013-07-23T11:33:21Z", "links": [{"rel": "self", "href": "http://192.168.24.1:8774/v2.1/"}]}]}
2020-04-07T08:18:41.387128150+00:00 stdout F INFO:nova_wait_for_api_service:Nova-api service active
~~~

[Sandeep Yadav (sandeepyadav93)]

Main error snippet:-

https://logserver.rdoproject.org/openstack-component-compute/opendev.org/openstack/tripleo-ci/master/periodic-tripleo-ci-centos-8-standalone-full-tempest-scenario-compute-master/b952891/logs/undercloud/var/log/containers/httpd/nova-api/nova_api_wsgi_error.log.txt.gz

~~~
[Sun Apr 12 09:35:27.215667 2020] [wsgi:error] [pid 25] [remote 192.168.24.1:41778] mod_wsgi (pid=25): Failed to exec Python script file '/var/www/cgi-bin/nova/nova-api'.
[Sun Apr 12 09:35:27.215757 2020] [wsgi:error] [pid 25] [remote 192.168.24.1:41778] mod_wsgi (pid=25): Exception occurred processing WSGI script '/var/www/cgi-bin/nova/nova-api'.
[Sun Apr 12 09:35:27.216907 2020] [wsgi:error] [pid 25] [remote 192.168.24.1:41778] Traceback (most recent call last):
[Sun Apr 12 09:35:27.216963 2020] [wsgi:error] [pid 25] [remote 192.168.24.1:41778] File "/var/www/cgi-bin/nova/nova-api", line 6, in <module>
[Sun Apr 12 09:35:27.216970 2020] [wsgi:error] [pid 25] [remote 192.168.24.1:41778] from nova.api.openstack.compute.wsgi import init_application
[Sun Apr 12 09:35:27.216978 2020] [wsgi:error] [pid 25] [remote 192.168.24.1:41778] File "/usr/lib/python3.6/site-packages/nova/api/openstack/compute/__init__.py", line 21, in <module>
[Sun Apr 12 09:35:27.216982 2020] [wsgi:error] [pid 25] [remote 192.168.24.1:41778] from nova.api.openstack.compute.routes import APIRouterV21 # noqa
[Sun Apr 12 09:35:27.216988 2020] [wsgi:error] [pid 25] [remote 192.168.24.1:41778] File "/usr/lib/python3.6/site-packages/nova/api/openstack/compute/routes.py", line 43, in <module>
[Sun Apr 12 09:35:27.216992 2020] [wsgi:error] [pid 25] [remote 192.168.24.1:41778] from nova.api.openstack.compute import flavors_extraspecs
[Sun Apr 12 09:35:27.216998 2020] [wsgi:error] [pid 25] [remote 192.168.24.1:41778] File "/usr/lib/python3.6/site-packages/nova/api/openstack/compute/flavors_extraspecs.py", line 24, in <module>
[Sun Apr 12 09:35:27.217002 2020] [wsgi:error] [pid 25] [remote 192.168.24.1:41778] from nova.api.validation.extra_specs import validators
[Sun Apr 12 09:35:27.217008 2020] [wsgi:error] [pid 25] [remote 192.168.24.1:41778] File "/usr/lib/python3.6/site-packages/nova/api/validation/extra_specs/validators.py", line 23, in <module>
[Sun Apr 12 09:35:27.217012 2020] [wsgi:error] [pid 25] [remote 192.168.24.1:41778] from nova.api.validation.extra_specs import base
[Sun Apr 12 09:35:27.217018 2020] [wsgi:error] [pid 25] [remote 192.168.24.1:41778] File "/usr/lib/python3.6/site-packages/nova/api/validation/extra_specs/base.py", line 15, in <module>
[Sun Apr 12 09:35:27.217022 2020] [wsgi:error] [pid 25] [remote 192.168.24.1:41778] import dataclasses
[Sun Apr 12 09:35:27.217038 2020] [wsgi:error] [pid 25] [remote 192.168.24.1:41778] ModuleNotFoundError: No module named 'dataclasses'
~~~

[Sandeep Yadav (sandeepyadav93)]

The dataclasses library was recently added as requirements [1] and nova is it's first user[2] - so now this new dep needs to be added in RDO, once added it needs to be added in nova rpm spec file(Workflow details here[3]).

But we cannot direct patch it as this is special case(only needed for python3.6, The dataclasses library has been added to the standard library in Python 3.7 ) so need to handle differently. we will need some suggestion/discussion with rdo experts and nova team on how to handle it.

[1] https://github.com/openstack/requirements/commit/e7c7dbfc8e09f07ba19cb4474b13f98470ae16b7
[2] https://review.opendev.org/#/c/704643
[3] https://www.rdoproject.org/documentation/requirements/#adding-a-new-requirement-to-rdo

[yatin (yatinkarel)]

Proposed https://review.rdoproject.org/r/#/c/26402/ to add python-dataclasses to Ussuri CentOS8 repo. Once the patch merges and package is available in ussuri deps repo http://trunk.rdoproject.org/centos8-master/deps/latest/ it can be added to nova spec file https://github.com/rdo-packages/nova-distgit/blob/rpm-master/openstack-nova.spec.

[yatin (yatinkarel)]

Added dataclasses to nova rpm https://review.rdoproject.org/r/#/c/26411/, jobs should not see this issue in next run of openstack-component-compute pipeline.

[yatin (yatinkarel)]

Jobs started passing in the pipeline:- https://review.rdoproject.org/zuul/builds?pipeline=openstack-component-compute, one job failed there but it's seperate issue.