Bug 1730994

Summary: heat-engine services have their service status flapping in "openstack orchestration service list"
Product: Red Hat OpenStack Reporter: Takashi Kajinami <tkajinam>
Component: openstack-heatAssignee: Rabi Mishra <ramishra>
Status: CLOSED ERRATA QA Contact: Victor Voronkov <vvoronko>
Severity: low Docs Contact:
Priority: medium    
Version: 13.0 (Queens)CC: mburns, sbaker, shardy, vvoronko
Target Milestone: ---Keywords: Triaged, ZStream
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: openstack-heat-10.0.3-6.el7ost Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2019-09-03 16:53:18 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Takashi Kajinami 2019-07-18 06:15:46 UTC
Description of problem:

We observe that some of the heat-engine services has their status flapping,
which is shown in "openstack orchestration serviece list"

~~~
(overcloud) [stack@undercloud-0 ~]$ for i in `seq 1 100`; do echo "Before: $(date)"; openstack orchestration service list; echo "After: $(date)"; done
...
Before: Thu Jul 18 01:54:11 EDT 2019
+--------------+-------------+--------------------------------------+--------------+--------+----------------------------+--------+
| Hostname     | Binary      | Engine ID                            | Host         | Topic  | Updated At                 | Status |
+--------------+-------------+--------------------------------------+--------------+--------+----------------------------+--------+
| controller-0 | heat-engine | 08565a4f-3b63-46dc-9743-9a43de2a3cfa | controller-0 | engine | 2019-07-18T05:53:25.000000 | up     |
| controller-2 | heat-engine | 3233cf30-de56-4103-8f75-f4d49efa8622 | controller-2 | engine | 2019-07-18T05:54:02.000000 | up     |
| controller-2 | heat-engine | 06068351-16e6-4ce7-9396-50f54d48089a | controller-2 | engine | 2019-07-18T05:54:02.000000 | up     |
| controller-1 | heat-engine | f55b8e0b-d761-4270-8e6b-bd0677a35118 | controller-1 | engine | 2019-07-18T05:53:16.000000 | up     |
| controller-1 | heat-engine | 4b678e0e-6706-4c1a-9915-f08952c86ba7 | controller-1 | engine | 2019-07-18T05:53:16.000000 | up     |
| controller-0 | heat-engine | 766fb15f-9267-4e0c-aef2-8f2a6bca12b0 | controller-0 | engine | 2019-07-18T05:53:25.000000 | up     |
| controller-0 | heat-engine | 7620f13f-ee4f-4950-ba2a-47ece67e0322 | controller-0 | engine | 2019-07-18T05:53:25.000000 | up     |
| controller-2 | heat-engine | 262efd2c-88c9-4786-bd14-b9ab894ca12b | controller-2 | engine | 2019-07-18T05:54:02.000000 | up     |
| controller-1 | heat-engine | 26aa0386-cca0-4b5a-83bd-9e0340b71645 | controller-1 | engine | 2019-07-18T05:53:16.000000 | up     |
| controller-1 | heat-engine | c55bb4f8-6bc5-47d1-9acc-bdaa02328407 | controller-1 | engine | 2019-07-18T05:53:16.000000 | up     |
| controller-2 | heat-engine | b24c98a1-69b6-4043-ac28-6eb749743126 | controller-2 | engine | 2019-07-18T05:54:02.000000 | up     |
| controller-0 | heat-engine | 014da988-14e4-429b-980a-15c90a888ad4 | controller-0 | engine | 2019-07-18T05:53:25.000000 | up     |
+--------------+-------------+--------------------------------------+--------------+--------+----------------------------+--------+
After: Thu Jul 18 01:54:13 EDT 2019
Before: Thu Jul 18 01:54:13 EDT 2019
+--------------+-------------+--------------------------------------+--------------+--------+----------------------------+--------+
| Hostname     | Binary      | Engine ID                            | Host         | Topic  | Updated At                 | Status |
+--------------+-------------+--------------------------------------+--------------+--------+----------------------------+--------+
| controller-0 | heat-engine | 08565a4f-3b63-46dc-9743-9a43de2a3cfa | controller-0 | engine | 2019-07-18T05:53:25.000000 | up     |
| controller-2 | heat-engine | 3233cf30-de56-4103-8f75-f4d49efa8622 | controller-2 | engine | 2019-07-18T05:54:02.000000 | up     |
| controller-2 | heat-engine | 06068351-16e6-4ce7-9396-50f54d48089a | controller-2 | engine | 2019-07-18T05:54:02.000000 | up     |
| controller-1 | heat-engine | f55b8e0b-d761-4270-8e6b-bd0677a35118 | controller-1 | engine | 2019-07-18T05:53:16.000000 | down   |
| controller-1 | heat-engine | 4b678e0e-6706-4c1a-9915-f08952c86ba7 | controller-1 | engine | 2019-07-18T05:53:16.000000 | down   |
| controller-0 | heat-engine | 766fb15f-9267-4e0c-aef2-8f2a6bca12b0 | controller-0 | engine | 2019-07-18T05:53:25.000000 | up     |
| controller-0 | heat-engine | 7620f13f-ee4f-4950-ba2a-47ece67e0322 | controller-0 | engine | 2019-07-18T05:53:25.000000 | up     |
| controller-2 | heat-engine | 262efd2c-88c9-4786-bd14-b9ab894ca12b | controller-2 | engine | 2019-07-18T05:54:02.000000 | up     |
| controller-1 | heat-engine | 26aa0386-cca0-4b5a-83bd-9e0340b71645 | controller-1 | engine | 2019-07-18T05:53:16.000000 | down   |
| controller-1 | heat-engine | c55bb4f8-6bc5-47d1-9acc-bdaa02328407 | controller-1 | engine | 2019-07-18T05:53:16.000000 | down   |
| controller-2 | heat-engine | b24c98a1-69b6-4043-ac28-6eb749743126 | controller-2 | engine | 2019-07-18T05:54:02.000000 | up     |
| controller-0 | heat-engine | 014da988-14e4-429b-980a-15c90a888ad4 | controller-0 | engine | 2019-07-18T05:53:25.000000 | up     |
+--------------+-------------+--------------------------------------+--------------+--------+----------------------------+--------+
After: Thu Jul 18 01:54:16 EDT 2019
Before: Thu Jul 18 01:54:16 EDT 2019
+--------------+-------------+--------------------------------------+--------------+--------+----------------------------+--------+
| Hostname     | Binary      | Engine ID                            | Host         | Topic  | Updated At                 | Status |
+--------------+-------------+--------------------------------------+--------------+--------+----------------------------+--------+
| controller-0 | heat-engine | 08565a4f-3b63-46dc-9743-9a43de2a3cfa | controller-0 | engine | 2019-07-18T05:53:25.000000 | up     |
| controller-2 | heat-engine | 3233cf30-de56-4103-8f75-f4d49efa8622 | controller-2 | engine | 2019-07-18T05:54:02.000000 | up     |
| controller-2 | heat-engine | 06068351-16e6-4ce7-9396-50f54d48089a | controller-2 | engine | 2019-07-18T05:54:02.000000 | up     |
| controller-1 | heat-engine | f55b8e0b-d761-4270-8e6b-bd0677a35118 | controller-1 | engine | 2019-07-18T05:54:16.000000 | up     |
| controller-1 | heat-engine | 4b678e0e-6706-4c1a-9915-f08952c86ba7 | controller-1 | engine | 2019-07-18T05:54:16.000000 | up     |
| controller-0 | heat-engine | 766fb15f-9267-4e0c-aef2-8f2a6bca12b0 | controller-0 | engine | 2019-07-18T05:53:25.000000 | up     |
| controller-0 | heat-engine | 7620f13f-ee4f-4950-ba2a-47ece67e0322 | controller-0 | engine | 2019-07-18T05:53:25.000000 | up     |
| controller-2 | heat-engine | 262efd2c-88c9-4786-bd14-b9ab894ca12b | controller-2 | engine | 2019-07-18T05:54:02.000000 | up     |
| controller-1 | heat-engine | 26aa0386-cca0-4b5a-83bd-9e0340b71645 | controller-1 | engine | 2019-07-18T05:54:16.000000 | up     |
| controller-1 | heat-engine | c55bb4f8-6bc5-47d1-9acc-bdaa02328407 | controller-1 | engine | 2019-07-18T05:54:16.000000 | up     |
| controller-2 | heat-engine | b24c98a1-69b6-4043-ac28-6eb749743126 | controller-2 | engine | 2019-07-18T05:54:02.000000 | up     |
| controller-0 | heat-engine | 014da988-14e4-429b-980a-15c90a888ad4 | controller-0 | engine | 2019-07-18T05:53:25.000000 | up     |
+--------------+-------------+--------------------------------------+--------------+--------+----------------------------+--------+
After: Thu Jul 18 01:54:18 EDT 2019
~~~

This flapping status is continuously observed, even if we perform no operations to heat,
or have no heat stacks deployed.

We do not see any errors in heat-engine nor mariadb, and all of the processes are still running,
when we see some of these services has down status.

How reproducible:
Always

Steps to Reproduce:
1. Deploy overcloud via Director
2. Try "openstack orchestration service list" some time

Actual results:
Sometimes some of the services has down status

Expected results:
No services has down status

Comment 1 Takashi Kajinami 2019-07-18 06:23:38 UTC
After looking at current implementation about service status in Heat, I think this is a bug in heat,
which makes heat expect REAL ZERO TAT for status reporting.

In current code, we see that status reporting is executed repeatedly
based on the interval defined as periodic_interval. 

heat/engine/service.py
~~~
    def start(self):
        self.engine_id = service_utils.generate_engine_id()
        ...
        if self.manage_thread_grp is None:
            self.manage_thread_grp = threadgroup.ThreadGroup()
        self.manage_thread_grp.add_timer(cfg.CONF.periodic_interval,
                                         self.service_manage_report)
~~~

On the other hand, when we mark services as down, which has not reporeted
its status for service.report_interval.

heat/common/service_utils.py
~~~
def format_service(service):    
    if service is None:    
        return    
    
    status = 'down'    
    if service.updated_at is not None:    
        if ((timeutils.utcnow() - service.updated_at).total_seconds()          
                <= service.report_interval):    
            status = 'up'    
    else:    
        if ((timeutils.utcnow() - service.created_at).total_seconds()          
                <= service.report_interval):    
            status = 'up'    
~~~

And we use the same value as periodic_interval to set service.report_interval.

heat/common/service_utils.py
~~~
    def service_manage_report(self):
        cnxt = context.get_admin_context()

        if self.service_id is None:
            service_ref = service_objects.Service.create(
                cnxt,
                dict(host=self.host,
                     hostname=self.hostname,
                     binary=self.binary,
                     engine_id=self.engine_id,
                     topic=self.topic,
                     report_interval=cfg.CONF.periodic_interval)
            )
            self.service_id = service_ref['id']
            LOG.debug('Service %s is started', self.service_id)
~~~

As we use the same value for report interval and status judge, it is possible
that when it takes even a little to get status report reached from heat-engine to database,
the status of the service is judged as DOWN.

IMO, we should have some margin for the report time, when we judge status of engine services,
so that we can avoid the flapping caused by possibly very small overhead.

Comment 16 errata-xmlrpc 2019-09-03 16:53:18 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2019:2625