podman hangs with deadlock

[rhjhunt]

Is this a BUG REPORT or FEATURE REQUEST?:

[//]: # Uncomment only one, leave it on its own line:

kind bug

[//]: # kind feature

Description

podman deadlocks on /var/lib/containers/storage/storage.lock

-bash-4.2$ ps -ef | grep podman
username   5343 29530  0 20:23 pts/1    00:00:00 grep --color=auto podman
root     13804     1  0 Sep27 ?        00:00:08 /usr/bin/podman --root /var/lib/containers/storage --runroot /var/run/containers/storage --log-level error --cgroup-manager cgroupfs --tmpdir /var/run/libpod --storage-driver overlay container cleanup 62bedf7f6d3a55020e7f314f401769281ef5b16c222d1753b0281590b48f63bb
root     14038 13701  0 Sep27 ?        00:02:25 /usr/bin/podman wait container_1537988606812_0012_01_000005
root     15355     1  0 Sep27 ?        00:00:07 /usr/bin/podman --root /var/lib/containers/storage --runroot /var/run/containers/storage --log-level error --cgroup-manager cgroupfs --tmpdir /var/run/libpod --storage-driver overlay container cleanup cf2ac277eb9a5b85e1b78ef088a5fff8ae41ac29639d27f77ade427211378d87
root     15359     1  0 Sep27 ?        00:00:07 /usr/bin/podman --root /var/lib/containers/storage --runroot /var/run/containers/storage --log-level error --cgroup-manager cgroupfs --tmpdir /var/run/libpod --storage-driver overlay container cleanup 79181a9932ae72ae4fe7b8377ab92cc57d1651dcd7e47dca4596b29b3787e934
root     15543 15298  0 Sep27 ?        00:01:51 /usr/bin/podman wait container_1537988606812_0012_01_000011
root     15546     1  0 Sep27 ?        00:00:08 /usr/bin/podman --root /var/lib/containers/storage --runroot /var/run/containers/storage --log-level error --cgroup-manager cgroupfs --tmpdir /var/run/libpod --storage-driver overlay container cleanup eb569521b8838b1336e6a23428c3f033ee981f7113d5ccc50967f0775dfae5dc
root     15564 15297  0 Sep27 ?        00:01:56 /usr/bin/podman wait container_1537988606812_0012_01_000017
root     15769 15404  0 Sep27 ?        00:01:56 /usr/bin/podman wait container_1537988606812_0012_01_000016
root     22399  9698  0 08:01 ?        00:00:00 [podman] <defunct>

Steps to reproduce the issue:

1. Launch several containers at the same time

2. wait for pod man to hang

Output of podman info:

$ sudo podman info
host:
  Conmon:
    package: podman-0.9.4-1537914470.gitf4e2810f.el7.x86_64
    path: /usr/libexec/podman/conmon
    version: 'conmon version 1.12.0-dev, commit: 51dcc3ad101da1c64efd9d49a1a0911242beac29-dirty'
  MemFree: 9827209216
  MemTotal: 16557703168
  OCIRuntime:
    package: runc-1.0.0-37.rc5.dev.gitad0f525.el7.x86_64
    path: /usr/bin/runc
    version: 'runc version spec: 1.0.0'
  SwapFree: 0
  SwapTotal: 0
  arch: amd64
  cpus: 4
  hostname: host01.example.com
  kernel: 3.10.0-862.9.1.el7.x86_64
  os: linux
  uptime: 702h 19m 22.38s (Approximately 29.25 days)
insecure registries:
  registries: []
registries:
  registries:
  - registry.access.redhat.com
store:
  ContainerStore:
    number: 5
  GraphDriverName: overlay
  GraphOptions:
  - overlay.override_kernel_check=true
  GraphRoot: /var/lib/containers/storage
  GraphStatus:
    Backing Filesystem: xfs
    Native Overlay Diff: "true"
    Supports d_type: "true"
  ImageStore:
    number: 2
  RunRoot: /var/run/containers/storage

Attaching a file with the strace and pstack since it is large.

podman_deadlock_modified.txt

[mheon]

Can you get the output of lslocks during the deadlock?

[mheon]

Appears to be podman wait racing against podman cleanup - how exactly are you reproducing this, running a loop that makes a detached container and then waits for it?

[rhjhunt]

-bash-4.2$ lslocks
COMMAND           PID   TYPE SIZE MODE   M      START        END PATH
lvmetad           460  POSIX   0B WRITE  0          0          0 /run/netns
osqueryd         1474  POSIX   0B WRITE  0          0          0 /var/lib/containers/storage/overlay
osqueryd         1474  FLOCK   0B WRITE  0          0          0 /var/lib/containers/storage/overlay
crond            2242  FLOCK   0B WRITE  0          0          0 /run/netns
java            12368  POSIX   0B WRITE  0          0          0 /var/lib/containers/storage/overlay
nslcd            1327  POSIX   0B WRITE  0          0          0 /run/netns
dockerd-current  2330  FLOCK   0B WRITE  0          0          0 /var/lib/containers/storage/overlay
nessusd         31866  POSIX   0B READ   0 1073741826 1073742335 /var/lib/containers/storage/overlay
nessusd         31866  POSIX   0B READ   0        128        128 /var/lib/containers/storage/overlay
java            12368  POSIX   0B WRITE  0          0          0 /var/lib/containers/storage/overlay
java            12368  POSIX   0B WRITE  0          0          0 /var/lib/containers/storage/overlay
yakl-client     10832  FLOCK   0B WRITE  0          0          0 /var/lib/containers/storage/overlay
falcond           655  POSIX   0B WRITE  0          0          0 /run/netns
master           1905  FLOCK   0B WRITE  0          0          0 /var/lib/containers/storage/overlay
master           1905  FLOCK   0B WRITE  0          0          0 /var/lib/containers/storage/overlay
(unknown)          -1 OFDLCK   0B READ   0          0          0 /dev
supervise        9316  FLOCK   0B WRITE  0          0          0 /var/lib/containers/storage/overlay
ykeykeyd         9317  POSIX   0B WRITE  0          0          0 /var/lib/containers/storage/overlay
jsvc            16188  POSIX   0B WRITE  0          0          0 /var/lib/containers/storage/overlay
java            12368  POSIX   0B WRITE  0          0          0 /var/lib/containers/storage/overlay
java            12368  POSIX   0B WRITE  0          0          0 /var/lib/containers/storage/overlay
podman          32595  POSIX   0B WRITE* 0          0          0 /run/netns
podman          32736  POSIX   0B WRITE  0          0          0 /run/netns
atd              2247  POSIX   0B WRITE  0          0          0 /run/netns
supervise        9315  FLOCK   0B WRITE  0          0          0 /var/lib/containers/storage/overlay
multilog         9318  FLOCK   0B WRITE  0          0          0 /var/lib/containers/storage/overlay

[mheon]

Hm. It looks like Nessus has grabbed a POSIX lock on /var/lib/containers/storage/overlay. C/storage uses flock, but it's possible it's still interfering with Podman.

[rhjhunt]

The way I get it to deadlock quickly is by running a Hadoop job that spawns JVMs that touch a lot of memory and try to make the VM swap. This is a test that I have been running on docker to get docker to fail with the containerd vs dockerd out of sync issue.

[mheon]

I'm putting money on this being the JVM and/or Nessus POSIX locks on /var/lib/containers/storage/overlay interfering with containers/storage

@nalind Any thoughts?

[mheon]

Hm. The locks in question aren't mandatory, though.

One Podman is stuck waiting for /var/run/netns, which sounds like the CNI plugins?

[mheon]

@unxfrek Are you spawning the JVMs in containers, or are they just a way to make the host run out of memory and force swapping?

[baude]

eliminate the networking component with --network=none ?

[TomSweeneyRedHat]

@unxfrek any chance you could share the Hadoop job or otherwise provide a reproducer? It would be handy for our diagnosis and future testings.

[rhjhunt]

They've been able to turn off nessus on the VMs that are being used to test podman and rerun the tests. However, they still are able to generate a deadlock on each VM running the same test. I've attached logs for all 3 of these VMs. Two things are particularly interesting:

1. The deadlock only happens on podman ps -a. I can still run containers via podman run perfectly fine. This is an upgrade over the previous deadlocks that I was seeing where everything related to podman would hang.

2. The straces of the podman ps -a on each VM seem to stick at different points in the code. But for each VM, they always stick during those same pieces of the code across different runs of podman ps -a

I'll see about a reproducer.

• Jacob
  podman_deadlock_no_nessus_10_5.3.txt
  podman_deadlock_no_nessus_10_5.2.txt
  podman_deadlock_no_nessus_10_5.1.txt

[ericbadger]

Hey all, I'm the hadoop dev who @unxfrek is reporting this issue for. Let me give some more details and hopefully we can iterate more quickly with me responding directly here.

A little background on how I'm reproducing this; I have a VM-based Hadoop cluster with 3 worker nodes (this is where podman is run), each with 16GB of memory and all running RHEL 7.5. I've been keeping up to date with the latest podman nightly releases from RH, but I always post the version along with my outputs. Currently I'm running with podman-0.9.4-1537914470.gitf4e2810f.el7.x86_64. The output I've attached below all corresponds to the text file podman_deadlock_no_nessus_10_5.3.txt that @unxfrek attached in the previous comment. I still have this deadlock sitting, intact, so I can get whatever output you'd like from it or any of the other nodes.

Here is the specific job that I run to get podman stuck. Usually it happens on the first run, but sometimes it takes 2 or 3 times. This is running on our own custom hadoop release, so it might not reproduce with an Apache build. Podman also isn't actually supported in Apache Hadoop yet, so we've had to make some small changes to the docker code just to get this to work at all.

$HADOOP_PREFIX/bin/hadoop jar $HADOOP_PREFIX/share/hadoop/mapreduce/hadoop-mapreduce-client-jobclient-*-tests.jar sleep -Dmapreduce.map.java.opts="-Xms3500M -Xmx3500M -XX:+AlwaysPreTouch" -Dmapreduce.map.memory.mb=4000 -m 200 -r 1 -mt 1 -rt 1

I think your early assertion is correct that this is a deadlock between podman container cleanup and podman wait. Giving a root output from lslocks, it shows that podman wait is holding the write lock on /run/libpod/lock/039c73bae701c7fc6ecd3dfe2b52175f5c4e1406dc1b98677078e2a0218e5fe4 and podman container cleanup is trying to acquire that same lock. The interesting part to me is that it looks like /usr/bin/runc state is deadlocked under the hood. It looks like there's even some runc commands that were never cleaned up from the last few times I produced this deadlock scenario. In the output below, you can see that the runc state process 5784 has 5046 as its parent, which is the podman wait command. However, when I run the exact same /usr/bin/runc state command now it completes successfully and doesn't hang at all. Not sure why it wouldn't get stuck on the same lock.

[root@hostname1 overlay-containers]# lslocks
COMMAND           PID   TYPE SIZE MODE   M START END PATH
lvmetad           460  POSIX   4B WRITE  0     0   0 /run/lvmetad.pid
osqueryd         1474  POSIX   0B WRITE  0     0   0 /var/osquery/osquery.db/LOCK
osqueryd         1474  FLOCK   0B WRITE  0     0   0 /var/osquery/syslog_pipe
crond            2242  FLOCK   5B WRITE  0     0   0 /run/crond.pid
java            12368  POSIX   0B WRITE  0     0   0 /home/gs/var/run/mapredqa/yarn-nodemanager/nm-aux-services/spark_shuffle/sparkShuffleRecovery.ldb/LOCK
nslcd            1327  POSIX   5B WRITE  0     0   0 /run/nslcd/nslcd.pid
dockerd-current  2330  FLOCK  32K WRITE  0     0   0 /home/gs/var/docker/volumes/metadata.db
java            12368  POSIX   0B WRITE  0     0   0 /home/gs/var/run/mapredqa/yarn-nodemanager/nm-aux-services/mapreduce_shuffle/mapreduce_shuffle_state/LOCK
java            12368  POSIX   0B WRITE  0     0   0 /home/gs/var/run/mapredqa/yarn-nodemanager/nm-aux-services/tez_shuffle/tez_shuffle_state/LOCK
podman           6143  POSIX   0B WRITE* 0     0   0 /run/libpod/lock/1b62a8299325a002b51c3d081f9d7daa3c23526837b8cfa9f2f4d08f70639e1f
podman           6275  POSIX   0B WRITE  0     0   0 /run/libpod/lock/1b62a8299325a002b51c3d081f9d7daa3c23526837b8cfa9f2f4d08f70639e1f
foobar           655  POSIX   4B WRITE  0     0   0 /run/foobar.pid
master           1905  FLOCK  33B WRITE  0     0   0 /var/spool/postfix/pid/master.pid
master           1905  FLOCK  33B WRITE  0     0   0 /var/lib/postfix/master.lock
(unknown)          -1 OFDLCK   0B READ   0     0   0 /dev
supervise        9316  FLOCK   0B WRITE  0     0   0 /home/y/var/daemontools/keymanager/log/supervise/lock
keymanager         9317  POSIX   0B WRITE  0     0   0 /home/y/var/run/keymanager.lock
jsvc            16188  POSIX  42B WRITE  0     0   0 /grid/0/tmp/hadoop-hdfsqa/dfs/data/in_use.lock
java            12368  POSIX   0B WRITE  0     0   0 /home/gs/var/run/mapredqa/yarn-nodemanager/yarn-nm-state/LOCK
java            12368  POSIX   0B WRITE  0     0   0 /home/gs/var/run/mapredqa/yarn-nodemanager/nm-aux-services/spark_shuffle/registeredExecutors.ldb/LOCK
atd              2247  POSIX   5B WRITE  0     0   0 /run/atd.pid
supervise        9315  FLOCK   0B WRITE  0     0   0 /home/y/var/daemontools/keymanager/supervise/lock
multilog         9318  FLOCK   0B WRITE  0     0   0 /home/y/logs/keymanager/lock
podman           4904  POSIX   0B WRITE* 0     0   0 /run/libpod/lock/039c73bae701c7fc6ecd3dfe2b52175f5c4e1406dc1b98677078e2a0218e5fe4
podman           5046  POSIX   0B WRITE  0     0   0 /run/libpod/lock/039c73bae701c7fc6ecd3dfe2b52175f5c4e1406dc1b98677078e2a0218e5fe4
acldaemon     17817  FLOCK   0B WRITE  0     0   0 /opt/acldaemon/var/uniqlock

[root@hostname1 overlay-containers]# ps -ef | grep runc
root      1135     1  0 Oct01 ?        00:00:00 /usr/bin/runc state 823c299634ab27b42936a5edc84ec7cba084924f98c0ff69c26a9d0a26738041
root      1752     1  0 Oct01 ?        00:00:00 /usr/bin/runc state d292af5d6733789beb8ea50a49ba6fb2bea74667071cd920f2459710c506bd17
root      2330     1  0 Aug30 ?        01:41:40 /usr/bin/dockerd-current --add-runtime docker-runc=/usr/libexec/docker/docker-runc-current --default-runtime=docker-runc --authorization-plugin=rhel-push-plugin --exec-opt native.cgroupdriver=cgroupfs --userland-proxy-path=/usr/libexec/docker/docker-proxy-current --selinux-enabled -g /home/gs/var/docker --add-registry docker-registry.ops.yahoo.com:4443 --add-registry registry.access.redhat.com
root      2517  2330  0 Aug30 ?        01:02:01 /usr/bin/docker-containerd-current -l unix:///var/run/docker/libcontainerd/docker-containerd.sock --metrics-interval=0 --start-timeout 2m --state-dir /var/run/docker/libcontainerd/containerd --shim docker-containerd-shim --runtime docker-runc
root      5784  5046  0 Oct05 ?        00:00:00 /usr/bin/runc state 039c73bae701c7fc6ecd3dfe2b52175f5c4e1406dc1b98677078e2a0218e5fe4
root      6648  6275  0 Oct05 ?        00:00:00 /usr/bin/runc state 1b62a8299325a002b51c3d081f9d7daa3c23526837b8cfa9f2f4d08f70639e1f
root     15957     1  0 Sep27 ?        00:00:00 /usr/bin/runc state 62bedf7f6d3a55020e7f314f401769281ef5b16c222d1753b0281590b48f63bb
root     15970     1  0 Sep27 ?        00:00:00 /usr/bin/runc state cf2ac277eb9a5b85e1b78ef088a5fff8ae41ac29639d27f77ade427211378d87
root     15971     1  0 Sep27 ?        00:00:00 /usr/bin/runc state 79181a9932ae72ae4fe7b8377ab92cc57d1651dcd7e47dca4596b29b3787e934
root     15973     1  0 Sep27 ?        00:00:00 /usr/bin/runc state eb569521b8838b1336e6a23428c3f033ee981f7113d5ccc50967f0775dfae5dc
root     20297 19560  0 16:00 pts/0    00:00:00 grep --color=auto runc
root     23669     1  0 Oct03 ?        00:00:00 /usr/bin/runc state b82400095591ef20172eab9d5842de881b0798aa5c9bc8c84338779e8a0d4c5f

[root@hostname1 overlay-containers]# /usr/bin/runc state 039c73bae701c7fc6ecd3dfe2b52175f5c4e1406dc1b98677078e2a0218e5fe4
{
  "ociVersion": "1.0.0",
  "id": "039c73bae701c7fc6ecd3dfe2b52175f5c4e1406dc1b98677078e2a0218e5fe4",
  "pid": 0,
  "status": "stopped",
  "bundle": "/var/lib/containers/storage/overlay-containers/039c73bae701c7fc6ecd3dfe2b52175f5c4e1406dc1b98677078e2a0218e5fe4/userdata",
  "rootfs": "/var/lib/containers/storage/overlay/e90e740c8a5d214f2336fb452beef3e48a493fe618b2e1afff2f552ebe55fdd8/merged",
  "created": "2018-10-05T19:48:13.066628449Z",
  "annotations": {
    "io.kubernetes.cri-o.ContainerType": "sandbox",
    "io.kubernetes.cri-o.Created": "2018-10-05T19:48:12.833107532Z",
    "io.kubernetes.cri-o.TTY": "false",
    "org.opencontainers.image.stopSignal": "15"
  },
  "owner": ""
}

[mheon]

@ericbadger Thanks - that's very thorough!

This is seeming like runc state getting stuck somewhere and not returning, causing us to get caught in a critical section.

We can fix this locally by adding a timeout on our call to runc - 10 seconds, maybe? - after which we kill runc and abandon the operation.

That's just treating the symptoms, though. I'm betting the root cause here is a runc bug causing it to occasionally hang when doing runc status calls. Can you get a more detailed ps of the runc processes (something that shows process state, ps aux should be fine) and maybe try and strace, see if it's trying to grab a lock or similar?

[ericbadger]

@mheon sorry for not including the strace/pstack in the last comment. I had the output, just forgot to include it in the comment. Anyway, it's stuck waiting on some futex. Not sure where to go from there on the debugging front.

[root@hostname1 overlay-containers]# ps aux | grep runc
root      1135  0.0  0.0  83936  2404 ?        S    Oct01   0:00 /usr/bin/runc state 823c299634ab27b42936a5edc84ec7cba084924f98c0ff69c26a9d0a26738041
root      1752  0.0  0.0  83936  2404 ?        S    Oct01   0:00 /usr/bin/runc state d292af5d6733789beb8ea50a49ba6fb2bea74667071cd920f2459710c506bd17
root      2330  0.1  0.1 1007288 26992 ?       Ssl  Aug30 102:05 /usr/bin/dockerd-current --add-runtime docker-runc=/usr/libexec/docker/docker-runc-current --default-runtime=docker-runc --authorization-plugin=rhel-push-plugin --exec-opt native.cgroupdriver=cgroupfs --userland-proxy-path=/usr/libexec/docker/docker-proxy-current --selinux-enabled -g /home/gs/var/docker --add-registry docker-registry.ops.yahoo.com:4443 --add-registry registry.access.redhat.com
root      2517  0.1  0.0 769096  8328 ?        Ssl  Aug30  62:17 /usr/bin/docker-containerd-current -l unix:///var/run/docker/libcontainerd/docker-containerd.sock --metrics-interval=0 --start-timeout 2m --state-dir /var/run/docker/libcontainerd/containerd --shim docker-containerd-shim --runtime docker-runc
root      5784  0.0  0.0  83936  2408 ?        S    Oct05   0:00 /usr/bin/runc state 039c73bae701c7fc6ecd3dfe2b52175f5c4e1406dc1b98677078e2a0218e5fe4
root      6648  0.0  0.0  83936  2408 ?        S    Oct05   0:00 /usr/bin/runc state 1b62a8299325a002b51c3d081f9d7daa3c23526837b8cfa9f2f4d08f70639e1f
root      7808  0.0  0.0 112708   980 pts/0    S+   19:58   0:00 grep --color=auto runc
root     15957  0.0  0.0  83936  2404 ?        S    Sep27   0:00 /usr/bin/runc state 62bedf7f6d3a55020e7f314f401769281ef5b16c222d1753b0281590b48f63bb
root     15970  0.0  0.0  83936  2404 ?        S    Sep27   0:00 /usr/bin/runc state cf2ac277eb9a5b85e1b78ef088a5fff8ae41ac29639d27f77ade427211378d87
root     15971  0.0  0.0  83936  2404 ?        S    Sep27   0:00 /usr/bin/runc state 79181a9932ae72ae4fe7b8377ab92cc57d1651dcd7e47dca4596b29b3787e934
root     15973  0.0  0.0  83936  2404 ?        S    Sep27   0:00 /usr/bin/runc state eb569521b8838b1336e6a23428c3f033ee981f7113d5ccc50967f0775dfae5dc
root     23669  0.0  0.0  83936  2408 ?        S    Oct03   0:00 /usr/bin/runc state b82400095591ef20172eab9d5842de881b0798aa5c9bc8c84338779e8a0d4c5f

[root@hostname1 overlay-containers]# strace -fp 5784
strace: Process 5784 attached
futex(0x562902da4360, FUTEX_WAIT, 2, NULL^Cstrace: Process 5784 detached
 <detached ...>

[root@hostname1 overlay-containers]# pstack 5784
#0  0x000056290261e1c3 in runtime.futex ()
#1  0x00005629025eb842 in runtime.futexsleep ()
#2  0x0000562902da4360 in __bss_start ()
#3  0x0000000200000000 in ?? ()
#4  0x0000000000000000 in ?? ()