Bug 1901754

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

I confirmed that the containers paunch failed to stop (nova_libvirt on compute-4 and nova_virlogd on compute-5)
has TRIPLEO_CONFIG_HASH different from the one in container-startup-config json.
This shows that paunch didn't run steps to create containers with new config hash...


compute-4

$ sudo podman inspect nova_libvirt | jq .[0].Config.Env
[
  ...
  "TRIPLEO_CONFIG_HASH=625b1a9cec416ffb7510a575bb82a938",
  ...
]

/var/lib/tripleo-config/container-startup-config/step_3/hashed-nova_libvirt.json
~~~
{
  "cpuset_cpus": "all",
  "depends_on": [
    "tripleo_nova_virtlogd.service"
  ],
  "environment": {
    "KOLLA_CONFIG_STRATEGY": "COPY_ALWAYS",
    "TRIPLEO_CONFIG_HASH": "a7a350bde34fee59724c7cf52366877d"
  },
  ...
~~~


$ sudo podman inspect nova_virtlogd | jq .[0].Config.Env
[
  ...
  "TRIPLEO_CONFIG_HASH=a7a350bde34fee59724c7cf52366877d",
  ...
]

/var/lib/tripleo-config/container-startup-config/step_3/hashed-nova_virtlogd.json
~~~
{
  "environment": {
    "KOLLA_CONFIG_STRATEGY": "COPY_ALWAYS",
    "TRIPLEO_CONFIG_HASH": "a7a350bde34fee59724c7cf52366877d"
  },
  ...
~~~


compute-5


$ sudo podman inspect nova_libvirt | jq .[0].Config.Env
[
  ...
  "TRIPLEO_CONFIG_HASH=c2021708da4df13f562f4ae13a4c9fc4",
  ...
]

/var/lib/tripleo-config/container-startup-config/step_3/hashed-nova_libvirt.json
~~~
{
  "cpuset_cpus": "all",
  "depends_on": [
    "tripleo_nova_virtlogd.service"
  ],
  "environment": {
    "KOLLA_CONFIG_STRATEGY": "COPY_ALWAYS",
    "TRIPLEO_CONFIG_HASH": "c2021708da4df13f562f4ae13a4c9fc4"
  },
  ...
~~~


$ sudo podman inspect nova_virtlogd | jq .[0].Config.Env
[
  ...
  "TRIPLEO_CONFIG_HASH=b30b8d8e81bf50209db634e0bed48c55",
  ...
]

/var/lib/tripleo-config/container-startup-config/step_3/hashed-nova_virtlogd.json
~~~
{
  "environment": {
    "KOLLA_CONFIG_STRATEGY": "COPY_ALWAYS",
    "TRIPLEO_CONFIG_HASH": "c2021708da4df13f562f4ae13a4c9fc4"
  },
  ...
~~~

So according to my observation so far, it seems that the "systemctl stop <service" command doesn't fail even when "podman stop" fails because of timeout, and it can cause failures in subsequent podman commands.
This causes only systemd service file deleted, while the container is still left without getting stopped...

I have replaced ExecStop command by dummy script which returns 125.

~~~
[root@compute-1 ~]# cat /root/test.sh 
#!/bin/bash

exit 125
[root@compute-1 ~]# cat /etc/systemd/system/tripleo_logrotate_crond.service
[Unit]
Description=logrotate_crond container
After=paunch-container-shutdown.service
Wants=
[Service]
Restart=always
ExecStart=/usr/bin/podman start logrotate_crond
ExecReload=/usr/bin/podman kill --signal HUP logrotate_crond
ExecStop=/bin/bash /root/test.sh
KillMode=none
Type=forking
PIDFile=/var/run/logrotate_crond.pid

[Install]
WantedBy=multi-user.target
[root@compute-1 ~]#
~~~

However systemctl stop doesn't return error code.
~~~
[root@compute-1 ~]# sudo systemctl daemon-reload
[root@compute-1 ~]# sudo systemctl status tripleo_logrotate_crond.service
● tripleo_logrotate_crond.service - logrotate_crond container
   Loaded: loaded (/etc/systemd/system/tripleo_logrotate_crond.service; enabled; vendor preset: disabled)
   Active: active (running) since Wed 2020-12-09 04:10:00 UTC; 23h ago
 Main PID: 2671 (conmon)
    Tasks: 0 (limit: 101106)
   Memory: 1.7M
   CGroup: /system.slice/tripleo_logrotate_crond.service
           ‣ 2671 /usr/bin/conmon --api-version 1 -s -c e683b161a92beef0b1a66bebb01fdf99989893f904233a1d8701567547bab6f7 -u e683b161a92beef0b1a66bebb01fdf99989893f904233a1d8701567547bab6f7 -r /usr/bin/runc -b /var/lib/containers/storage/>

Dec 09 04:09:58 compute-1 systemd[1]: Starting logrotate_crond container...
Dec 09 04:10:00 compute-1 podman[2462]: 2020-12-09 04:10:00.305730294 +0000 UTC m=+1.282243334 container init e683b161a92beef0b1a66bebb01fdf99989893f904233a1d8701567547bab6f7 (image=undercloud-0.ctlplane.redhat.local:8787/rh-osbs/rhosp16>
Dec 09 04:10:00 compute-1 podman[2462]: 2020-12-09 04:10:00.334236854 +0000 UTC m=+1.310749885 container start e683b161a92beef0b1a66bebb01fdf99989893f904233a1d8701567547bab6f7 (image=undercloud-0.ctlplane.redhat.local:8787/rh-osbs/rhosp1>
Dec 09 04:10:00 compute-1 podman[2462]: logrotate_crond
Dec 09 04:10:00 compute-1 systemd[1]: Started logrotate_crond container.
[root@compute-1 ~]# sudo systemctl stop tripleo_logrotate_crond.service
[root@compute-1 ~]# echo $?
0
[root@compute-1 ~]# sudo systemctl status tripleo_logrotate_crond.service
● tripleo_logrotate_crond.service - logrotate_crond container
   Loaded: loaded (/etc/systemd/system/tripleo_logrotate_crond.service; enabled; vendor preset: disabled)
   Active: failed (Result: exit-code) since Thu 2020-12-10 03:20:54 UTC; 14s ago
  Process: 252506 ExecStop=/bin/bash /root/test.sh (code=exited, status=125)
 Main PID: 2671

Dec 09 04:09:58 compute-1 systemd[1]: Starting logrotate_crond container...
Dec 09 04:10:00 compute-1 podman[2462]: 2020-12-09 04:10:00.305730294 +0000 UTC m=+1.282243334 container init e683b161a92beef0b1a66bebb01fdf99989893f904233a1d8701567547bab6f7 (image=undercloud-0.ctlplane.redhat.local:8787/rh-osbs/rhosp16>
Dec 09 04:10:00 compute-1 podman[2462]: 2020-12-09 04:10:00.334236854 +0000 UTC m=+1.310749885 container start e683b161a92beef0b1a66bebb01fdf99989893f904233a1d8701567547bab6f7 (image=undercloud-0.ctlplane.redhat.local:8787/rh-osbs/rhosp1>
Dec 09 04:10:00 compute-1 podman[2462]: logrotate_crond
Dec 09 04:10:00 compute-1 systemd[1]: Started logrotate_crond container.
Dec 10 03:20:54 compute-1 systemd[1]: Stopping logrotate_crond container...
Dec 10 03:20:54 compute-1 systemd[1]: tripleo_logrotate_crond.service: Control process exited, code=exited status=125
Dec 10 03:20:54 compute-1 systemd[1]: tripleo_logrotate_crond.service: Failed with result 'exit-code'.
Dec 10 03:20:54 compute-1 systemd[1]: Stopped logrotate_crond container.
[root@compute-1 ~]# sudo podman ps | grep logrotate
e683b161a92b  undercloud-0.ctlplane.redhat.local:8787/rh-osbs/rhosp16-openstack-cron:16.1_20201020.1                        kolla_start  2 weeks ago  Up 23 hours ago         logrotate_crond
~~~

Even if I add ExecStopPost to simulate the content of service files generated by paunch, systemctl stop returns 0.

~~~
[root@compute-1 ~]# cat tripleo_logrotate_crond.service 
[Unit]
Description=logrotate_crond container
After=paunch-container-shutdown.service
Wants=
[Service]
Restart=always
ExecStart=/usr/bin/podman start logrotate_crond
ExecReload=/usr/bin/podman kill --signal HUP logrotate_crond
ExecStop=/usr/bin/podman stop -t 10 logrotate_crond
ExecStopPost=/usr/bin/podman stop -t 10 logrotate_crond
KillMode=none
Type=forking
PIDFile=/var/run/logrotate_crond.pid

[Install]
[root@compute-1 ~]# sudo systemctl daemon-reload
[root@compute-1 ~]# sudo systemctl status tripleo_logrotate_crond.service
● tripleo_logrotate_crond.service - logrotate_crond container
   Loaded: loaded (/etc/systemd/system/tripleo_logrotate_crond.service; enabled; vendor preset: disabled)
   Active: active (running) since Thu 2020-12-10 03:24:49 UTC; 37s ago
 Main PID: 253292 (conmon)
    Tasks: 0 (limit: 101106)
   Memory: 1.6M
   CGroup: /system.slice/tripleo_logrotate_crond.service
           ‣ 253292 /usr/bin/conmon --api-version 1 -s -c e683b161a92beef0b1a66bebb01fdf99989893f904233a1d8701567547bab6f7 -u e683b161a92beef0b1a66bebb01fdf99989893f904233a1d8701567547bab6f7 -r /usr/bin/runc -b /var/lib/containers/storag>

Dec 10 03:24:48 compute-1 systemd[1]: Starting logrotate_crond container...
Dec 10 03:24:49 compute-1 podman[253247]: 2020-12-10 03:24:49.203373271 +0000 UTC m=+0.227471808 container init e683b161a92beef0b1a66bebb01fdf99989893f904233a1d8701567547bab6f7 (image=undercloud-0.ctlplane.redhat.local:8787/rh-osbs/rhosp>
Dec 10 03:24:49 compute-1 podman[253247]: 2020-12-10 03:24:49.218287972 +0000 UTC m=+0.242386484 container start e683b161a92beef0b1a66bebb01fdf99989893f904233a1d8701567547bab6f7 (image=undercloud-0.ctlplane.redhat.local:8787/rh-osbs/rhos>
Dec 10 03:24:49 compute-1 podman[253247]: logrotate_crond
Dec 10 03:24:49 compute-1 systemd[1]: Started logrotate_crond container.
[root@compute-1 ~]# systemctl stop tripleo_logrotate_crond.service
[root@compute-1 ~]# echo $?
0
[root@compute-1 ~]# systemctl status tripleo_logrotate_crond.service
● tripleo_logrotate_crond.service - logrotate_crond container
   Loaded: loaded (/etc/systemd/system/tripleo_logrotate_crond.service; enabled; vendor preset: disabled)
   Active: failed (Result: exit-code) since Thu 2020-12-10 03:27:06 UTC; 24s ago
  Process: 253453 ExecStopPost=/bin/bash /root/test.sh (code=exited, status=125)
  Process: 253451 ExecStop=/bin/bash /root/test.sh (code=exited, status=125)
 Main PID: 253292

Dec 10 03:24:49 compute-1 podman[253247]: 2020-12-10 03:24:49.203373271 +0000 UTC m=+0.227471808 container init e683b161a92beef0b1a66bebb01fdf99989893f904233a1d8701567547bab6f7 (image=undercloud-0.ctlplane.redhat.local:8787/rh-osbs/rhosp>
Dec 10 03:24:49 compute-1 podman[253247]: 2020-12-10 03:24:49.218287972 +0000 UTC m=+0.242386484 container start e683b161a92beef0b1a66bebb01fdf99989893f904233a1d8701567547bab6f7 (image=undercloud-0.ctlplane.redhat.local:8787/rh-osbs/rhos>
Dec 10 03:24:49 compute-1 podman[253247]: logrotate_crond
Dec 10 03:24:49 compute-1 systemd[1]: Started logrotate_crond container.
Dec 10 03:25:36 compute-1 systemd[1]: Stopping logrotate_crond container...
Dec 10 03:25:36 compute-1 systemd[1]: tripleo_logrotate_crond.service: Control process exited, code=exited status=125
Dec 10 03:25:36 compute-1 systemd[1]: tripleo_logrotate_crond.service: Control process exited, code=exited status=125
Dec 10 03:27:06 compute-1 systemd[1]: tripleo_logrotate_crond.service: State 'stop-post' timed out. Terminating.
Dec 10 03:27:06 compute-1 systemd[1]: tripleo_logrotate_crond.service: Failed with result 'exit-code'.
Dec 10 03:27:06 compute-1 systemd[1]: Stopped logrotate_crond container.
[root@compute-1 ~]# sudo podman ps | grep logrotate
e683b161a92b  undercloud-0.ctlplane.redhat.local:8787/rh-osbs/rhosp16-openstack-cron:16.1_20201020.1                        kolla_start  2 weeks ago  Up 2 minutes ago         logrotate_crond
~~~

So this is the scenarion which results in the problem.

 - For some reason a container doesn't stop within the specified timeout (10 seconds)
 - podman stop fails with 125 return code, but it doesn't forcefully stop the container
 - systemd doesn't detect the failure in stop the container, and it doesn't stop the remaining container
 - the subsequent steps performs podman stop/rm/rm -f but it doesn't check whether these steps are done successfully


I confirmed that changing kill mode from none to control-group makes systemd forcefully stop the remaining container
(maybe by SITERM or SIGKILL ?), but I'm not sure whether this is the right thing to do.

Hello Takashi,

it would be interesting to understand why those two containers aren't stopping as they should. My best guess here is: there are a lot of VMs running on the node, and nova_libvirt is just unable to stop in the delay - this is also the same reason nova_virtlogd isn't stopped and ends in the same weird black hole.

I think we should first check with Compute for this case, then we should be able to find a better way within paunch. Maybe the way VMs are managed within nova_libvirt is the issue? For instance, Neutron isn't doing the same thing, they start dedicated containers when a new network action is done (i.e. new dhcp/subnet). Might be a path to explore so that all the VMs don't depend on one unique container?

Fact is, if we kill the container it might lead to data corruption within the VMs... Not sure this is something we actually want to see, do we?

Cheers,

C.

Hi Cédric,


> it would be interesting to understand why those two containers aren't stopping as they should. My best guess here is: there are a lot of VMs running on the node, and nova_libvirt is just unable to stop in the delay - this is also the same reason nova_virtlogd isn't stopped and ends in the same weird black hole.

I checked the log of libvirt and messages around the time when podman couldn't stop these containers, but I didn't see any errors or interesting logs so far.
All I could have confirmed so far is podman failed to stop these container retuning 125(I guess it's timeout) and these containers are left running, without having processes inside receive any stop signals.
A customer stopped these containers manually later, but they didn't see any issues at that time, so that "hung" seems to be something temproral.

Also, this problem happened not only with these libvirt containers, but also with the neutron-ovs-agent container, so I'm afraid this is not very specific to Compute.

Hello Takashi,

humpf. "great"..... seems to point to yet another podman thing. IIRC there were others issues with the timeout, and we already had to raise it a bit. Maybe that's "just" it - but I really doubt this is a way we want to follow...

I'll call for help within DF then (thank you needinfo()) - on my side I don't really see what we can really do without any risk :/. But seeing the whole thing, there might be an issue with the way systemd catches that 125 code, preventing paunch to actually get it and retry... Probably a thing to dig in.

@Alex, @Kevin, any thoughts or ideas?

Cheers,

C.

We'll have to look further into the error handling.  We likely don't want to just fail the entire paunch execution because we want to manage whatever we can in a given step. That being said, this should have been a deploy failure so this will likely need more code/testing. I thought we had a different patch to bump timeouts or make them configurable to address this kind of problem however.

So we specifically set KillMode to none due to race conditions. See https://review.opendev.org/c/openstack/paunch/+/645550  I'm not certain if switching to control-group has the same problem as process.

So I don't think we address the podman failure itself for timeout.  The timeout value is configurable at a service level but I don't think it's tuneable by the end user at this time. I checked and KillGroup=control-group has the race condition as process so we cannot switch to it. I think the solution here would be to catch this failure better and not remove the systemd unit if the service is still running. Additionally we should ensure that we do fail when this condition occurs.

They have the wrong version of podman installed so the containers are not able to be managed/renamed/etc.  They should have 1.6.4 but they have 1.9.3


podman-1.9.3-2.module+el8.2.1+6867+366c07d6.x86_64          Sun Aug  2 15:15:23 2020
podman-docker-1.9.3-2.module+el8.2.1+6867+366c07d6.noarch   Sun Aug  2 15:15:26 2020

The rename is occurring because the container cannot be removed. But the container has an improper state so it never works.

2020-12-01 18:11:31.413 410894 ERROR paunch [  ] Error: cannot remove container f5a01ec7b2ee86c53f2d89d76a926b06ee9b93643e63ee8a778e2357c95c60d9 as it is running - running or paused containers cannot be removed without force: container state improper

Thanks Alex, for pointing the wrong podman version. Sorry I missed that in my analysis...
I'll ask the customer to downgrade the podman package to have the correct version.

> The rename is occurring because the container cannot be removed. But the container has an improper state so it never works.

IIUC paunch is not renaming the container but removing it to replace it by the newly created one.
What I've observed so far is that container is still running and doesn't accept stop operation via systemd or directly,
and still running when paunch tries to remove it by "podman rm" or "podman rm -f"

Yea I looked at the paunch code and we actually remove the systemd unit prior to stopping it because they'll conflicit when trying to operate on the container.  The bit of code from the log is actually from the rename functions and not part of the actual service management. I've got some additional patches to improve error handling when these conditions occur but it's likely that manual intervention will be needed if this condition occurs. If systemctl doesn't return an error, there's not much we can do to detect this state.

set qe_test_coverage to - because the root cause of the problem was using an incorrect podman version. That should not be automated. A commit was made to handle a corner case error condition. A way to force creation of that error manually or through automation hasn't been found.

Paused nova_libvirt container, redeployed OC and verified tripleo_nova_libvirt.service exists
Removed nova_libvirt container, redeployed OC and verified tripleo_nova_libvirt.service exists

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 (Red Hat OpenStack Platform 16.1.6 bug fix and enhancement 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-2021:2097