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

Bug 1782601

Summary: CRI-O reporting container OOMKilled despite clean exit and no memory pressure
Product: OpenShift Container Platform Reporter: W. Trevor King <wking>
Component: NodeAssignee: Peter Hunt <pehunt>
Status: CLOSED ERRATA QA Contact: Sunil Choudhary <schoudha>
Severity: low Docs Contact:
Priority: unspecified    
Version: 4.3.0CC: aos-bugs, jokerman, pehunt, rphillips
Target Milestone: ---   
Target Release: 4.3.z   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2020-06-03 03:30:41 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:
Attachments:
Description Flags
sum (node_memory_MemFree_bytes{instance="ip-10-0-86-63.ec2.internal"}) by (instance)
none
pod:container_memory_usage_bytes:sum{pod="cloud-credential-operator-57f58db849-tl2mf"} none

Description W. Trevor King 2019-12-11 22:33:20 UTC
Created attachment 1644234 [details]
sum (node_memory_MemFree_bytes{instance="ip-10-0-86-63.ec2.internal"}) by (instance)

From a 4.3 CI job [1]:

  $ curl -s https://storage.googleapis.com/origin-ci-test/logs/release-openshift-ocp-installer-e2e-aws-upi-4.3/488/build-log.txt | grep OOMKilled
  Dec 10 19:17:40.923 E ns/openshift-cloud-credential-operator pod/cloud-credential-operator-57f58db849-tl2mf node/ip-10-0-86-63.ec2.internal container=manager container exited with code 1 (OOMKilled): ing for credentials requests targeting namespace" namespace=e2e-secrets-3498\ntime="2019-12-10T19:17:12Z" level=debug msg="checking for credentials requests targeting namespace" namespace=e2e-volume-8748\ntime="2019-12-10T19:17:17Z" level=debug msg="checking for credentials requests targeting namespace" namespace=e2e-projected-3537\ntime="2019-12-10T19:17:17Z" level=debug msg="checking for credentials requests targeting namespace" namespace=e2e-test-image-dqwks\ntime="2019-12-10T19:17:17Z" level=debug msg="checking for credentials requests targeting namespace" namespace=e2e-downward-api-4970\ntime="2019-12-10T19:17:21Z" level=debug msg="checking for credentials requests targeting namespace" namespace=e2e-provisioning-4684\ntime="2019-12-10T19:17:25Z" level=debug msg="checking for credentials requests targeting namespace" namespace=e2e-dns-7031\nE1210 19:17:38.602075       1 leaderelection.go:306] error retrieving resource lock openshift-cloud-credential-operator/cloud-credential-operator-leader: etcdserver: request timed out\nE1210 19:17:39.126290       1 event.go:247] Could not construct reference to: '&v1.ConfigMap{TypeMeta:v1.TypeMeta{Kind:"", APIVersion:""}, ObjectMeta:v1.ObjectMeta{Name:"", GenerateName:"", Namespace:"", SelfLink:"", UID:"", ResourceVersion:"", Generation:0, CreationTimestamp:v1.Time{Time:time.Time{wall:0x0, ext:0, loc:(*time.Location)(nil)}}, DeletionTimestamp:(*v1.Time)(nil), DeletionGracePeriodSeconds:(*int64)(nil), Labels:map[string]string(nil), Annotations:map[string]string(nil), OwnerReferences:[]v1.OwnerReference(nil), Initializers:(*v1.Initializers)(nil), Finalizers:[]string(nil), ClusterName:"", ManagedFields:[]v1.ManagedFieldsEntry(nil)}, Data:map[string]string(nil), BinaryData:map[string][]uint8(nil)}' due to: 'selfLink was empty, can't make reference'. Will not report event: 'Normal' 'LeaderElection' 'cloud-credential-operator-57f58db849-tl2mf_85edeaa1-1b7f-11ea-b939-0a580a800002 stopped leading'\ntime="2019-12-10T19:17:39Z" level=error msg="leader election lostunable to run the manager"\n
  ...

"unable to run the manager" means the cred operator was just about to Exit(1) [2], and indeed the logged line has "container exited with code 1".  The OOMKilled seems like a false-positive, because there was no memory pressure on node ip-10-0-86-63 at that point (node_memory_MemFree_bytes attachment), and the cred operator was at its requested ~150 MB [3].  I suspect conmon's OOM detection [4,5] (RHCOS is still running cgroups v1), but don't see anything wrong with the code (which follows the eventfd approach described in [6]).  There are some node logs under [7], but nothing interesting here from the CRI-O logs:

  $ curl -s https://storage.googleapis.com/origin-ci-test/logs/release-openshift-ocp-installer-e2e-aws-upi-4.3/488/artifacts/e2e-aws-upi/must-gather/host_service_logs/masters/crio_service.log | grep ' ip-10-0-86-63 ' | grep -A3 ' 19:17:36 '
  Dec 10 19:17:36 ip-10-0-86-63 crio[1939]: 2019-12-10T19:17:36Z [verbose] Del: e2e-svcaccounts-3767:pod-service-account-defaultsa-mountspec:openshift-sdn:eth0 {"cniVersion":"0.3.1","name":"openshift-sdn","type":"openshift-sdn"}
  Dec 10 19:17:49 ip-10-0-86-63 crio[1939]: time="2019-12-10T19:17:49Z" level=error msg="container not running"
  Dec 10 19:17:49 ip-10-0-86-63 crio[1939]: container not running
  Dec 10 19:17:49 ip-10-0-86-63 crio[1939]: 2019-12-10T19:17:49Z [error] SetNetworkStatus: failed to query the pod netserver-5 in out of cluster comm: pods "netserver-5" not found

I don't know if/how conmon logs get stored on disk.

[1]: https://prow.svc.ci.openshift.org/view/gcs/origin-ci-test/logs/release-openshift-ocp-installer-e2e-aws-upi-4.3/488
[2]: https://github.com/openshift/cloud-credential-operator/blob/3305f735726d5282251dd02d8c067a9af5908623/cmd/manager/main.go#L112-L113
[3]: https://storage.googleapis.com/origin-ci-test/logs/release-openshift-ocp-installer-e2e-aws-upi-4.3/488/artifacts/e2e-aws-upi/must-gather/namespaces/openshift-cloud-credential-operator/pods/cloud-credential-operator-57f58db849-tl2mf/cloud-credential-operator-57f58db849-tl2mf.yaml
[4]: https://github.com/containers/conmon/blob/8ba95756ee81607edc1d20704f6c86140493ece0/src/conmon.c#L1118-L1136
[5]: https://github.com/containers/conmon/blob/8ba95756ee81607edc1d20704f6c86140493ece0/src/conmon.c#L513-L542
[6]: https://git.kernel.org/pub/scm/linux/kernel/git/stable/linux.git/tree/Documentation/admin-guide/cgroup-v1/memory.rst?h=v5.4.2#n841
[7]: https://gcsweb-ci.svc.ci.openshift.org/gcs/origin-ci-test/logs/release-openshift-ocp-installer-e2e-aws-upi-4.3/488/artifacts/e2e-aws-upi/must-gather/host_service_logs/masters/

Comment 1 W. Trevor King 2019-12-11 22:35:19 UTC
Created attachment 1644235 [details]
pod:container_memory_usage_bytes:sum{pod="cloud-credential-operator-57f58db849-tl2mf"}

memory usage in the nominally-OOMKilled pod

Comment 2 Giuseppe Scrivano 2019-12-12 11:19:25 UTC
opened a PR: https://github.com/containers/conmon/pull/98

Comment 3 W. Trevor King 2019-12-18 10:28:09 UTC
Checking in on where this is in the 4.3 pipe, conmon#98 went out in 2.0.8 [1].  Latest 4.3 RHCOS is 43.81.201912171100.0 [2].  That RHCOS has conmon 2.0.7 [3].  No RHCOS with 2.0.8 means it doesn't matter which RHCOS image is currently living in machine-os-content and that we are still not ON_QE here.

[1]: https://github.com/containers/conmon/commits/v2.0.8
[2]: curl -s https://releases-rhcos-art.cloud.privileged.psi.redhat.com/storage/releases/rhcos-4.3/builds.json | jq -r '.builds[0].id'
[3]: $ curl -s https://releases-rhcos-art.cloud.privileged.psi.redhat.com/storage/releases/rhcos-4.3/43.81.201912171100.0/x86_64/commitmeta.json | jq -r '.["rpmostree.rpmdb.pkglist"][] | select(.[0] == "conmon") | .[2]'

Comment 4 Giuseppe Scrivano 2019-12-18 13:15:16 UTC
we had to revert the change as it introduced missing real OOMs: https://github.com/containers/conmon/pull/104

Comment 5 W. Trevor King 2019-12-18 13:24:46 UTC
Oh, I was getting this confused with 82ef9c7 (#97) which went out in 2.0.7 and was not reverted.  But yeah, looks like #98 actually went out 2.0.7 and was reverted in 2.0.8.

Comment 6 Peter Hunt 2020-02-24 20:12:20 UTC
I actually think this has to do with the conmon monitor incorrectly reporting. As of now, conmonmon simply checks if the conmon pid is still running, then kills the container and spoofs an oom if it's not. There exists the chance that a race could happen with kubelet, systemd and conmonmon, where:

kubelet attempts to kill a pod
when tearing down the cgroup, systemd kills conmon first (arbitrarily, the tearing down of the cgroup is not ordered AFAIK)
immediately after conmon is killed, the conmonmon loop runs, and sees that the pid is gone, kills the container and reports OOM
systemd tries to kill container pid, sees its not there and moves on silently
kubelet sees the cgroup is torn down, and also sees that an "oom" happened, and then incorrectly reports it

I am working on a fix in conmonmon that involves actually checking if an oom happened.

Comment 7 Peter Hunt 2020-02-24 20:32:52 UTC
I am now seeing this issue predates conmonmon, and is not about my comment above. Sorry for the noise

Comment 8 W. Trevor King 2020-02-25 20:35:23 UTC
Also some spurious OOMKilled discussion in bug 1800609 and bug 1801568.

Comment 9 Peter Hunt 2020-05-18 20:08:18 UTC
this should be fixed as of https://github.com/containers/conmon/releases/tag/v2.0.12, which has been in 4.3.z for a bit

Comment 15 errata-xmlrpc 2020-06-03 03:30:41 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:2256