Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 1802573

Summary:	overcloud update prepare times out as mistral-executor and mistral-event-engine fail to be restarted during undercloud update.
Product:	Red Hat OpenStack	Reporter:	Sofer Athlan-Guyot <sathlang>
Component:	python-paunch	Assignee:	Sofer Athlan-Guyot <sathlang>
Status:	CLOSED ERRATA	QA Contact:	nlevinki <nlevinki>
Severity:	urgent	Docs Contact:
Priority:	urgent
Version:	16.0 (Train)	CC:	amcleod, bdobreli, cjeanner, elicohen, eolivare, lbezdick, michele, pbabbar, sclewis
Target Milestone:	z1	Keywords:	Regression, Triaged
Target Release:	16.0 (Train on RHEL 8.1)
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:	python-paunch-5.3.2-0.20200130065659.d56765a.el8ost	Doc Type:	Known Issue
Doc Text:	There is a known issue where Mistral containers do not restart during minor updates and the update prepare times out after 10 hours. The workaround is to restart the containers manually.	Story Points:	---
Clone Of:		Environment:
Last Closed:	2020-03-03 09:45:05 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 Sofer Athlan-Guyot 2020-02-13 12:27:17 UTC

Hi,

Description of problem:

Running an update from OSP16 GA to latest puddle.  During openstack
overcloud update prepare we fail with:

2020-02-12 20:41:33 | 2020-02-12 20:41:33.380 37919 ERROR tripleoclient.workflows.base [-] Timed out waiting for messages from Execution (ID: 3c924ee8-d664-40eb-9346-6bf19c00876d, State: RUNNING). The WebSocket timed out before the Workflow completed.: tripleoclient.exceptions.WebSocketTimeout
2020-02-12 20:41:33 | 2020-02-12 20:41:33.433 37919 ERROR openstack [-] : tripleoclient.exceptions.WebSocketTimeout
2020-02-12 20:41:33 | 2020-02-12 20:41:33.439 37919 INFO osc_lib.shell [-] END return value: 1

When we check the current podman container we can see that
mistral-executor and mistral-event-engine fail to be updated during
the previous step, undercloud update.

That previous step finish "successfully" even with those errors.

During undercloud update we can see the "real" error:

2020-02-12 20:00:22 |         "Removed /etc/systemd/system/multi-user.target.wants/tripleo_mistral_executor.service.",
2020-02-12 20:00:22 |         "Removed /etc/systemd/system/timers.target.wants/tripleo_mistral_executor_healthcheck.timer.",
2020-02-12 20:00:22 |         "Removed /etc/systemd/system/tripleo_mistral_executor.service.requires/tripleo_mistral_executor_healthcheck.timer.",
2020-02-12 20:00:22 |         "Error removing container: mistral_executor",
2020-02-12 20:00:22 |         "Error: cannot remove container 0f6959e6d306272ff8aa8e3e7ab8ade61b826de55d15f002b01705b59b4381e0 as it has active exec sessions: container state improper",
2020-02-12 20:00:22 |         "Removed /etc/systemd/system/multi-user.target.wants/tripleo_mistral_event_engine.service.",
2020-02-12 20:00:22 |         "Removed /etc/systemd/system/tripleo_mistral_event_engine.service.requires/tripleo_mistral_event_engine_healthcheck.timer.",
2020-02-12 20:00:22 |         "Removed /etc/systemd/system/timers.target.wants/tripleo_mistral_event_engine_healthcheck.timer.",
2020-02-12 20:00:22 |         "Error removing container: mistral_event_engine",
2020-02-12 20:00:22 |         "Error: cannot remove container a2c85d9377add7f73c3a732c16b02b311ebe7a6da58df540360b465173271149 as it has active exec sessions: container state improper",

This is during:

TASK [Wait for containers to start for step 4 using paunch]

in undercloud_update.log.

Note that the image were properly downloaded:

2020-02-12 19:42:01,941 390137 INFO tripleo_common.image.image_uploader [  ] [rhos-qe-mirror-tlv.usersys.redhat.com:5002/rh-osbs/rhosp16-openstack-mistral-executor:20200210.1] Completed upload for image

podman-1.6.4-2.module+el8.1.1+5363+bf8ff1af.x86_64
python3-paunch-5.3.2-0.20200130065658.d56765a.el8ost.noarch

This has been reproduced in two last OSP16 jobs.  In the composable,
only the mistral_executor failed.

2020-02-12 21:14:05 |         "Error removing container: mistral_executor",
2020-02-12 21:14:05 |         "Error: cannot remove container 49dce21b160b99aa6bffdf518279ba599b012d4ba07b790794ab44b83fc58e5e as it has active exec sessions: container state improper",

Comment 6 Sofer Athlan-Guyot 2020-02-18 10:01:26 UTC

So we had it another time here and nova_scheduler was at the party:

2020-02-14 04:59:49 |         "Error removing container: nova_scheduler",
2020-02-14 04:59:49 |         "Error: cannot remove container dfb53114b434d4320d87d4fe9525b1fa977e56cc9e722b7164a7b88a60374dd9 as it has active exec sessions: container state improper",

2020-02-14 04:59:49 |         "Error removing container: mistral_executor",
2020-02-14 04:59:49 |         "Error: cannot remove container 9d597ce48e2e8b5d5aa28e518a03f67d0a9386038d6a68dde09887775093f86f as it has active exec sessions: container state improper",

2020-02-14 04:59:49 |         "Error removing container: mistral_event_engine",
2020-02-14 04:59:49 |         "Error: cannot remove container ee949ddd4db79a0327b0c9fd3d184bd7d66db5278dbf2bc2e92109613daa25f1 as it has active exec sessions: container state improper",

Again, this is during undercloud update, but we don't raise any error, so the error is seen during overcloud update prepare as mistral is not around.

On the undercloud we end up with:

dfb53114b434  undercloud-0.ctlplane.redhat.local:8787/rh-osbs/rhosp16-openstack-nova-scheduler:20200130.1             kolla_start           4 hours ago        Created                              nova_scheduler234kB (virtual 1.15GB)
9d597ce48e2e  undercloud-0.ctlplane.redhat.local:8787/rh-osbs/rhosp16-openstack-mistral-executor:20200130.1           kolla_start           4 hours ago        Created                              mistral_executor                                            2.18MB (virtual 1.41GB)
ee949ddd4db7  undercloud-0.ctlplane.redhat.local:8787/rh-osbs/rhosp16-openstack-mistral-event-engine:20200130.1       kolla_start           4 hours ago        Created                              mistral_event_engine                                        14kB (virtual 1.03GB)

Comment 8 Sofer Athlan-Guyot 2020-02-18 10:33:05 UTC

Hi,

so I went digging a little from the logs.  Here is a successful stop
of a nova_scheduler:

2020-02-07 20:40:19.664 8 INFO oslo_service.service [req-2a8bebce-547f-41a1-a6b0-7f204660edbb - - - - -] Caught SIGTERM, stopping children
2020-02-07 20:40:19.665 8 DEBUG oslo_concurrency.lockutils [req-2a8bebce-547f-41a1-a6b0-7f204660edbb - - - - -] Acquired lock "singleton_lock" lock /usr/lib/python3.6/site-packages/oslo_concurrency/lockutils.py:265
2020-02-07 20:40:19.666 8 DEBUG oslo_concurrency.lockutils [req-2a8bebce-547f-41a1-a6b0-7f204660edbb - - - - -] Releasing lock "singleton_lock" lock /usr/lib/python3.6/site-packages/oslo_concurrency/lockutils.py:281
2020-02-07 20:40:19.666 8 DEBUG oslo_service.service [req-2a8bebce-547f-41a1-a6b0-7f204660edbb - - - - -] Stop services. stop /usr/lib/python3.6/site-packages/oslo_service/service.py:699
2020-02-07 20:40:19.667 8 DEBUG oslo_service.service [req-2a8bebce-547f-41a1-a6b0-7f204660edbb - - - - -] Killing children. stop /usr/lib/python3.6/site-packages/oslo_service/service.py:704
2020-02-07 20:40:19.667 8 INFO oslo_service.service [req-2a8bebce-547f-41a1-a6b0-7f204660edbb - - - - -] Waiting on 4 children to exit
2020-02-07 20:40:19.707 8 INFO oslo_service.service [req-2a8bebce-547f-41a1-a6b0-7f204660edbb - - - - -] Child 26 killed by signal 15
2020-02-07 20:40:19.745 8 INFO oslo_service.service [req-2a8bebce-547f-41a1-a6b0-7f204660edbb - - - - -] Child 24 killed by signal 15
2020-02-07 20:40:19.775 8 INFO oslo_service.service [req-2a8bebce-547f-41a1-a6b0-7f204660edbb - - - - -] Child 23 killed by signal 15
2020-02-07 20:40:19.805 8 INFO oslo_service.service [req-2a8bebce-547f-41a1-a6b0-7f204660edbb - - - - -] Child 25 killed by signal 15
2020-02-07 20:41:58.878 10 INFO oslo_service.periodic_task [-] Skipping periodic task _discover_hosts_in_cells because its interval is negative

Here is an unsuccessful one:

2020-02-14 04:28:42.856 7 INFO oslo_service.service [req-31a10e1f-73c4-4440-915c-cb6dc5fbea6b - - - - -] Caught SIGTERM, stopping children
2020-02-14 04:28:42.857 7 DEBUG oslo_concurrency.lockutils [req-31a10e1f-73c4-4440-915c-cb6dc5fbea6b - - - - -] Acquired lock "singleton_lock" lock /usr/lib/python3.6/site-packages/oslo_concurrency/lockutils.py:265
2020-02-14 04:28:42.858 7 DEBUG oslo_concurrency.lockutils [req-31a10e1f-73c4-4440-915c-cb6dc5fbea6b - - - - -] Releasing lock "singleton_lock" lock /usr/lib/python3.6/site-packages/oslo_concurrency/lockutils.py:281
2020-02-14 04:28:42.858 7 DEBUG oslo_service.service [req-31a10e1f-73c4-4440-915c-cb6dc5fbea6b - - - - -] Stop services. stop /usr/lib/python3.6/site-packages/oslo_service/service.py:699
2020-02-14 04:28:42.859 7 DEBUG oslo_service.service [req-31a10e1f-73c4-4440-915c-cb6dc5fbea6b - - - - -] Killing children. stop /usr/lib/python3.6/site-packages/oslo_service/service.py:704
2020-02-14 04:28:42.859 7 INFO oslo_service.service [req-31a10e1f-73c4-4440-915c-cb6dc5fbea6b - - - - -] Waiting on 4 children to exit
2020-02-14 04:28:45.690 25 DEBUG oslo_service.periodic_task [req-b6dbaa0f-7dc9-462d-a1e5-362643f49653 - - - - -] Running periodic task SchedulerManager._run_periodic_tasks run_periodic_tasks /usr/lib/python3.6/site-packages/oslo_service/periodic_task.py:217

We can see that the subprocess seems to not be killed properly.  This
might be why we fail later with "has active exec sessions"

Now, one big difference between paunch working
(python3-paunch-5.3.1-0.20191214120154.b2f3c3c.el8ost.noarch) and
paunch not working (ie cannot stop sub process) -
paunch-services-5.3.2-0.20200130065658.d56765a.el8ost.noarch) is that
patch:

https://review.opendev.org/#/c/702901/

which stop container gracefully.

Requesting blocker flag on that one as it happens now all the time during update.

I will go and try with a revert of that patch as it looks like a
promising contender for the regression.

Comment 9 Sofer Athlan-Guyot 2020-02-18 11:01:15 UTC

For completeness of hypothesis that review[1] could also explain the issue:
 - some process now execute (because before they didn't as they didn't have the right user)
 - they are not child of the main init container process 
 - they linger around preventing the container to stop.

actually that could be the conjunction of both patches.  The healthcheck should be stop before the container is stopped.


[1] https://review.opendev.org/#/q/I2e49d4dd5b385237f4f79929c70365424f6fa22d

Comment 10 Bogdan Dobrelya 2020-02-18 11:09:58 UTC

I confirm this is a podman specific behavior:

$ docker run -itd --privileged --name=foo busybox sleep 1000
$ docker exec -it foo sh -c "sleep 180"
$ kill -STOP <that process>
$ docker stop foo
$ docker rm foo

works w/o errors, while podman fails with the aforementioned error after the last step.

I think there is no need to revert it for podman, but add an rm -f fallback for such corner cases

Comment 11 Bogdan Dobrelya 2020-02-18 11:24:26 UTC

Note that both podman and docker leave the slept process behind, which is probably expected for Linux. If we resume it with CONT it continues operate. So that's up to the exec'ed process how to proceed with signals and termination. From the containers runtime and orchestration we cannot/should not control that IMHO. So I believe there is no need for extra orchestration of health-checks for that case.

Comment 12 Sofer Athlan-Guyot 2020-02-18 15:49:30 UTC

(In reply to Bogdan Dobrelya from comment #10)

> I think there is no need to revert it for podman, but add an rm -f fallback
> for such corner cases

It's not an corner case, not a single osp16 undercloud update was successful since that patch, neither is the overcloud upgrade.

So I've tested a revert and the undercloud update went fine, will post the result using the falback action ASAP.

We currently don't know the impact on the overcloud update.

Comment 13 Sofer Athlan-Guyot 2020-02-18 15:57:37 UTC

*** Bug 1804008 has been marked as a duplicate of this bug. ***

Comment 20 Bogdan Dobrelya 2020-02-24 13:58:46 UTC

*** Bug 1805986 has been marked as a duplicate of this bug. ***

Comment 24 Sofer Athlan-Guyot 2020-02-25 14:00:14 UTC

*** Bug 1797889 has been marked as a duplicate of this bug. ***

Comment 29 Sofer Athlan-Guyot 2020-02-27 14:09:20 UTC

Hi,

so manual testing was successful:

# undercloud successful:

2020-02-26 18:48:52 | The Undercloud has been successfully upgraded.

# now for the overcloud
(undercloud) [stack@undercloud-0 ~]$ grep -A1 -E 'Overcloud Deployed|Updated nodes -|Stack qe-Cloud-0.*UPDATE_COMPLETE' overcloud_update_prepare.sh.log overcloud_update_run-C*.sh.log ceph-update-run.sh.log overcloud_update_converge.sh.log


# prepare successful
overcloud_update_prepare.sh.log: Stack qe-Cloud-0/10b24d48-e731-4587-b955-2d8382c3544a UPDATE_COMPLETE
overcloud_update_prepare.sh.log-
--

# Run of update successful
overcloud_update_run-CephStorage.sh.log:Updated nodes - CephStorage
overcloud_update_run-CephStorage.sh.log-Success
--
overcloud_update_run-Compute.sh.log:Updated nodes - Compute
overcloud_update_run-Compute.sh.log-Success
--
overcloud_update_run-Controller.sh.log:Updated nodes - Controller
overcloud_update_run-Controller.sh.log-Success

# run of the ceph update (added the neccessary repo definition here with CephAnsibleRepo)
--
ceph-update-run.sh.log:Updated nodes - all
ceph-update-run.sh.log-Success
--

# run of the converge
overcloud_update_converge.sh.log: Stack qe-Cloud-0/10b24d48-e731-4587-b955-2d8382c3544a UPDATE_COMPLETE
overcloud_update_converge.sh.log-
--
overcloud_update_converge.sh.log:Overcloud Deployed
overcloud_update_converge.sh.log-2020-02-27 13:28:00.239 621994 INFO tripleoclient.v1.overcloud_update.UpdateConverge [-] Update converge on stack qe-Cloud-0 complete.

# check that we have the right paunch version:

# undercloud:
(undercloud) [stack@undercloud-0 ~]$ rpm -qa | grep paunch
paunch-services-5.3.2-0.20200130065659.d56765a.el8ost.noarch
python3-paunch-5.3.2-0.20200130065659.d56765a.el8ost.noarch

# one controller 

(undercloud) [stack@undercloud-0 ~]$ ssh heat-admin.24.13 rpm -qa | grep paunch
Warning: Permanently added '192.168.24.13' (ECDSA) to the list of known hosts.
python3-paunch-5.3.2-0.20200130065659.d56765a.el8ost.noarch
paunch-services-5.3.2-0.20200130065659.d56765a.el8ost.noarch

Pushing this to VERIFIED.

Thanks.

Comment 30 Sofer Athlan-Guyot 2020-02-27 14:30:06 UTC

Some more verification.

We can see that the mechanism in place now in paunch was triggered:

(undercloud) [stack@undercloud-0 ~]$ grep gracefully overcloud_update_run-*.sh.log
overcloud_update_run-Controller.sh.log:        "Error removing container gracefully: nova_scheduler",
overcloud_update_run-Controller.sh.log:        "Error removing container gracefully: nova_scheduler",
overcloud_update_run-Controller.sh.log:        "Error removing container gracefully: nova_scheduler",

In:

TASK [Debug output for task: Start containers for step 4]

but later on nova_scheduler was properly started, showing that it was indeed properly removed:


"Running container: nova_scheduler",
"$ podman ps -a --filter label=container_name=nova_scheduler --filter label=config_id=tripleo_step4 --format {{.Names}}",
"Did not find container with \"['podman', 'ps', '-a', '--filter', 'label=container_name=nova_scheduler', '--filter', 'label=config_id=tripleo_step4', '--format', '{{.Names}}']\" - retrying without config_id",
"$ podman ps -a --filter label=container_name=nova_scheduler --format {{.Names}}",
"Did not find container with \"['podman', 'ps', '-a', '--filter', 'label=container_name=nova_scheduler', '--format', '{{.Names}}']\"",
"Start container nova_scheduler as nova_scheduler.",
"$ podman create --name nova_scheduler --label config_id=tripleo_step4 --label container_name=nova_scheduler --label managed_by=tripleo-Controller - ....
"Completed $ podman create --name nova_scheduler --label config_id=tripleo_step4 --label container_name=nova_scheduler --label managed_by=tripleo-Controller ....

for all three controller.

And there were properly restarted with the right tag (using puddle RHOS_TRUNK-16.0-RHEL-8-20200225.n.1)

Then (undercloud) [stack@undercloud-0 ~]$ ansible -i inventory.yaml 'Controller' -m shell -a 'sudo podman ps | grep nova_scheduler'
[WARNING]: Consider using 'become', 'become_method', and 'become_user' rather than running sudo

controller-1 | CHANGED | rc=0 >>
f355b421341b  undercloud-0.ctlplane.redhat.local:8787/rh-osbs/rhosp16-openstack-nova-scheduler:20200213.1      kolla_start           4 hours ago        Up 4 hours ago               nova_scheduler


controller-0 | CHANGED | rc=0 >>
df9ce3161498  undercloud-0.ctlplane.redhat.local:8787/rh-osbs/rhosp16-openstack-nova-scheduler:20200213.1      kolla_start           5 hours ago        Up 5 hours ago               nova_scheduler

controller-2 | CHANGED | rc=0 >>
8151762542d2  undercloud-0.ctlplane.redhat.local:8787/rh-osbs/rhosp16-openstack-nova-scheduler:20200213.1      kolla_start           4 hours ago        Up 4 hours ago               nova_scheduler

Comment 32 errata-xmlrpc 2020-03-03 09:45:05 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-2020:0655