Bug 1378929

Created attachment 1204192 [details]
Logs from fresh recreate at Fri Sep 23 10:25:29 EDT 2016

Added logs from all masters for fresh recreate.   Restart occurred at Fri Sep 23 10:25:29 EDT 2016



There are several recreates in there.   The first encounter was Sep 22 around 19:30.   At Sep 22 19:37 you can see the cluster go into a really bad state as all the lists started failing and nodes realized the cluster was hosed.

systemd was updated earlier.   The problem occurs on every restart of systemd, not just for the original update.

root@ip-172-31-51-247: ~ # systemctl status atomic-openshift-master-controllers                                                                                                                                                                                     [1/1860]
● atomic-openshift-master-controllers.service - Atomic OpenShift Master Controllers
   Loaded: loaded (/usr/lib/systemd/system/atomic-openshift-master-controllers.service; enabled; vendor preset: disabled)
   Active: inactive (dead) since Fri 2016-09-23 10:56:21 EDT; 26s ago
     Docs: https://github.com/openshift/origin
  Process: 94375 ExecStart=/usr/bin/openshift start master controllers --config=${CONFIG_FILE} $OPTIONS (code=killed, signal=PIPE)
 Main PID: 94375 (code=killed, signal=PIPE)

Systemd is 219-30.el7 

To be clear,  even though systemd-journald was restarted everywhere, this problem can be reproduced by just restarting it on the combined master/etcd.

So logs don't show the window which appears @10:56 for a Controllers event.?.? and no OOM-ing either.  It looks like the api-sever is still executing after the event. 

$ grep Started messages.master1 | grep systemd
Sep 23 10:20:26 ip-172-31-51-245 systemd: Started Atomic OpenShift Master Controllers.
Sep 23 10:25:28 ip-172-31-51-245 systemd: Started Session 224 of user root.
Sep 23 10:25:28 ip-172-31-51-245 systemd: Started Flush Journal to Persistent Storage.
Sep 23 10:26:28 ip-172-31-51-245 systemd: Started Atomic OpenShift Node.
Sep 23 10:26:51 ip-172-31-51-245 systemd: Started Session 225 of user root.

$ grep systemd messages.master1 | grep -i Openshift
Sep 23 10:20:26 ip-172-31-51-245 systemd: Starting Atomic OpenShift Master Controllers...
Sep 23 10:20:26 ip-172-31-51-245 systemd: Started Atomic OpenShift Master Controllers.
Sep 23 10:26:27 ip-172-31-51-245 systemd: atomic-openshift-node.service holdoff time over, scheduling restart.
Sep 23 10:26:27 ip-172-31-51-245 systemd: Starting Atomic OpenShift Node...
Sep 23 10:26:28 ip-172-31-51-245 atomic-openshift-node: I0923 10:26:28.451318   87612 factory.go:54] Registering systemd factory
Sep 23 10:26:28 ip-172-31-51-245 atomic-openshift-node: I0923 10:26:28.453859   87612 oomparser.go:185] oomparser using systemd
Sep 23 10:26:28 ip-172-31-51-245 systemd: Started Atomic OpenShift Node.

I was able to recreate once with a "systemctl daemon-reexec".  This is what the %post in systemd RPM does.

Let me first say that I don't think this is new.

https://bugzilla.redhat.com/show_bug.cgi?id=1317031#c20

I think that systemd upgrades have, at least in recent history, always taken out the master-controller.

It appears that the master-controller has a pipe open and a daemon-rexec or systemd-journald restart breaks it.  At some point in the future, the master-controller tries to access the pipe and gets a SIGPIPE.

The service unit does have:

Restart=on-failure
RestartSec=5s

However, SIGPIPE is considered a "clean" exit signal so it does not restart (search for SIGPIPE) here
https://www.freedesktop.org/software/systemd/man/systemd.service.html

So the process is not restarted by systemd.

systemd v219 and later has a mechanism to maintain file descriptors across daemon restart (thanks to Derek for finding this):
https://github.com/systemd/systemd/blob/master/NEWS#L2016

However, the service file must set FileDescriptorStoreMax to use it.

While it is included in the journald service file upstream for v219:
https://github.com/systemd/systemd/blob/v219/units/systemd-journald.service.in

It is not in the RHEL 7.2 service file.  It is patched in our rpm:

SOURCES]$ grep FileDescriptorStoreMax *
0125-Revert-journald-allow-restarting-journald-without-lo.patch:-FileDescriptorStoreMax=1024

Including that is likely the fix for this.

Installed 3.2 on an identical cluster config and ran the same scenario.   The problem was not reproducible.

Mike has since confirmed that it was reproduced on 3.2 using an identical cluster configuration, but it took time for the problem to manifest.

I am lowering the priority and moving this to UPCOMING_RELEASE.

The proper fix is to leverage the FileDescriptorStoreMax features introduced in systemd 219 but disabled.  I am moving this bug to the productization team to evaluate the risk of enabling the systemd feature so this problem does not occur.

See https://bugzilla.redhat.com/show_bug.cgi?id=1378929#c6 on the host change needed to prevent this from occurring.

Confirming comment 9.   The cluster mentioned in comment 7 did reproduce this issue when it was put under load during the restart of systemd.

Can you increase the severity to high? It normally happens that the customer tuned /etc/systemd/journald.conf and restart the journald services in production environment. (One of the customer hit this issue, actually.)

Also, I appreciate it if you could add this issue to the Known-issue list in documentation - https://docs.openshift.com/container-platform/3.3/release_notes/ocp_3_3_release_notes.html#ocp-33-known-issues

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

Setup a multi-master ocp-3.3 cluster with openshift-ansible-3.3.44-1.git.0.48e34f6.el7.noarch.rpm, check the atomic-openshift-master-controllers.service configuration file, the service is using Restart=always now.

Run a script to restart systemd-journald on combined master/etcd continuously, after a while, atomic-openshift-master-controllers.service on the masters are all running well.

[root@ip-172-18-15-196 ~]# systemctl status atomic-openshift-master-controllers
● atomic-openshift-master-controllers.service - Atomic OpenShift Master Controllers
   Loaded: loaded (/usr/lib/systemd/system/atomic-openshift-master-controllers.service; enabled; vendor preset: disabled)
   Active: active (running) since Thu 2016-11-03 05:24:12 EDT; 30min ago
     Docs: https://github.com/openshift/origin
 Main PID: 41694 (openshift)
   Memory: 50.3M
   CGroup: /system.slice/atomic-openshift-master-controllers.service
           └─41694 /usr/bin/openshift start master controllers --config=/etc/origin/master/master-config.yaml --loglevel=5 --listen=https://0.0.0.0:8444

I think we need to verify the status of atomic-openshift-master-api as well because in the duplicate bug BZ1380570 and customer support case, -api also stopped unexpectedly due to this issue.

Also verified the status of atomic-openshift-master-api service on all masters were running. When systemd-journald restart on master, atomic-openshift-master-api also got restart, after that, the service would always be running.

@Mike, so is this working well for you now?

The api service has Restart=always for containerized deployments, but *not* for rpm deployments. I suspect this means it could happen there as well, this one is a bit hard to reproduce reliably as I think it requires logging messages to be sent at the right times.

I have applied the same fix for API service in this PR:

https://github.com/openshift/openshift-ansible/pull/2718

Verified on container install (3.3.1.4) that restarting systemd-journald caused both master-api and master-controllers containers to exit and both were immediately restarted.

Still have to check master-api on rpm install.   Moving back to ON_QA temporarily.

BTW, do we also need this fix for 3.4?

On 3.3.1.4, verified 

rpm:  atomic-openshift-master-controllers and atomic-openshift-master-api are restarted by systemd.

containerized:  atomic-openshift-master-controllers and atomic-openshift-master-api are restarted by systemd.

Commands do fail during the restart interval, but the services restart.

Re: comment 36 the change seems to be on openshift-ansible master.   Is there anyplace it is missing?

For comment 36, I was using an older playbook to install my env. Sorry for my fault. Pls ignore it.



According to comment 37, move this bug to "verified".

Since this fix will be provided ansible, current userss will not get this fix. They need manual change by themselves, don't they?
On top of that, even if users got this fix, when they restart systemd-journald, OpenShift (master) services always restart.
I still think that this issue should be listed in known issue, but it is not necessary?

It's probably a good idea to recommend it, however journald restarts should be relatively rare (I think?) and personally I'd be rebooting that host after one.

OK, I see. I may be worrying too much. If Engineering team says so, it is no problem for me.

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/RHSA-2016:2778