send signal to pidfd: Permission denied

[bicca23]

Is this a BUG REPORT or FEATURE REQUEST? (leave only one on its own line)

/kind bug

Description
We use AWS SSM to run/restart podman container. This execution is done using root account. The first time shell script is executed, podman containers are started properly. Next time, when we send AWS SSM command to restart containers (podman stop, podman rm, podman run) we get issue with podman stop. Below is a bash snippet that we use to stop running containers

   podman ps -q | xargs -r podman stop

   sleep 10

   podman ps -a -q | xargs -r podman rm -f

Steps to reproduce the issue:

1. Using AWS SSM command, start one or more containers with podman run

2. Using AWS SSM command, stop containers, remove them, and start them again

Describe the results you received:

time="2022-02-23T23:36:28Z" level=info msg="podman filtering at log level debug"

time="2022-02-23T23:36:28Z" level=debug msg="Called stop.PersistentPreRunE(podman stop --log-level=DEBUG 50cbc4d68f59 9842b4dbbd11)"

time="2022-02-23T23:36:28Z" level=debug msg="Merged system config \"/usr/share/containers/containers.conf\""

time="2022-02-23T23:36:28Z" level=debug msg="Using conmon: \"/usr/libexec/podman/conmon\""

time="2022-02-23T23:36:28Z" level=debug msg="Initializing boltdb state at /var/lib/containers/storage/libpod/bolt_state.db"

time="2022-02-23T23:36:28Z" level=debug msg="Using graph driver overlay"

time="2022-02-23T23:36:28Z" level=debug msg="Using graph root /var/lib/containers/storage"

time="2022-02-23T23:36:28Z" level=debug msg="Using run root /run/containers/storage"

time="2022-02-23T23:36:28Z" level=debug msg="Using static dir /var/lib/containers/storage/libpod"

time="2022-02-23T23:36:28Z" level=debug msg="Using tmp dir /run/libpod"

time="2022-02-23T23:36:28Z" level=debug msg="Using volume path /var/lib/containers/storage/volumes"

time="2022-02-23T23:36:28Z" level=debug msg="Set libpod namespace to \"\""

time="2022-02-23T23:36:28Z" level=debug msg="[graphdriver] trying provided driver \"overlay\""

time="2022-02-23T23:36:28Z" level=debug msg="cached value indicated that overlay is supported"

time="2022-02-23T23:36:28Z" level=debug msg="cached value indicated that metacopy is being used"

time="2022-02-23T23:36:28Z" level=debug msg="cached value indicated that native-diff is not being used"

time="2022-02-23T23:36:28Z" level=info msg="Not using native diff for overlay, this may cause degraded performance for building images: kernel has CONFIG_OVERLAY_FS_REDIRECT_DIR enabled"

time="2022-02-23T23:36:28Z" level=debug msg="backingFs=extfs, projectQuotaSupported=false, useNativeDiff=false, usingMetacopy=true"

time="2022-02-23T23:36:28Z" level=debug msg="Initializing event backend journald"

time="2022-02-23T23:36:28Z" level=debug msg="configured OCI runtime runc initialization failed: no valid executable found for OCI runtime runc: invalid argument"

time="2022-02-23T23:36:28Z" level=debug msg="configured OCI runtime kata initialization failed: no valid executable found for OCI runtime kata: invalid argument"

time="2022-02-23T23:36:28Z" level=debug msg="configured OCI runtime runsc initialization failed: no valid executable found for OCI runtime runsc: invalid argument"

time="2022-02-23T23:36:28Z" level=debug msg="Using OCI runtime \"/usr/bin/crun\""

time="2022-02-23T23:36:28Z" level=info msg="Found CNI network podman (type=bridge) at /etc/cni/net.d/87-podman.conflist"

time="2022-02-23T23:36:28Z" level=debug msg="Default CNI network name podman is unchangeable"

time="2022-02-23T23:36:28Z" level=info msg="Setting parallel job count to 7"

time="2022-02-23T23:36:28Z" level=debug msg="Starting parallel job on container 50cbc4d68f5907d613481b9b1ab5b8b5315bd2ea505178e6f2ff39caeb9a74af"

time="2022-02-23T23:36:28Z" level=debug msg="Starting parallel job on container 9842b4dbbd1118fc4910a29a8ff7d38e97ca91839ac807669af7c399c0fe52a5"

time="2022-02-23T23:36:28Z" level=debug msg="Stopping ctr 9842b4dbbd1118fc4910a29a8ff7d38e97ca91839ac807669af7c399c0fe52a5 (timeout 10)"

time="2022-02-23T23:36:28Z" level=debug msg="Stopping ctr 50cbc4d68f5907d613481b9b1ab5b8b5315bd2ea505178e6f2ff39caeb9a74af (timeout 10)"

time="2022-02-23T23:36:28Z" level=debug msg="Stopping container 50cbc4d68f5907d613481b9b1ab5b8b5315bd2ea505178e6f2ff39caeb9a74af (PID 209395)"

time="2022-02-23T23:36:28Z" level=debug msg="Sending signal 15 to container 50cbc4d68f5907d613481b9b1ab5b8b5315bd2ea505178e6f2ff39caeb9a74af"

send signal to pidfd: Permission denied

time="2022-02-23T23:36:28Z" level=debug msg="Stopping container 9842b4dbbd1118fc4910a29a8ff7d38e97ca91839ac807669af7c399c0fe52a5 (PID 210028)"

time="2022-02-23T23:36:28Z" level=debug msg="Sending signal 15 to container 9842b4dbbd1118fc4910a29a8ff7d38e97ca91839ac807669af7c399c0fe52a5"

send signal to pidfd: Permission denied

Error: timed out waiting for file /run/libpod/exits/9842b4dbbd1118fc4910a29a8ff7d38e97ca91839ac807669af7c399c0fe52a5: internal libpod error

Error: timed out waiting for file /run/libpod/exits/50cbc4d68f5907d613481b9b1ab5b8b5315bd2ea505178e6f2ff39caeb9a74af: internal libpod error

failed to run commands: exit status 123

Describe the results you expected:
Containers to stop properly.

Additional information you deem important (e.g. issue happens only occasionally):

Output of podman version:

Version:      3.4.2
API Version:  3.4.2
Go Version:   go1.16.6
Built:        Thu Jan  1 00:00:00 1970
OS/Arch:      linux/amd64

Output of podman info --debug:

host:
  arch: amd64
  buildahVersion: 1.23.1
  cgroupControllers:
  - cpuset
  - cpu
  - cpuacct
  - blkio
  - memory
  - devices
  - freezer
  - net_cls
  - perf_event
  - net_prio
  - hugetlb
  - pids
  - rdma
  cgroupManager: systemd
  cgroupVersion: v1
  conmon:
    package: 'conmon: /usr/libexec/podman/conmon'
    path: /usr/libexec/podman/conmon
    version: 'conmon version 2.0.30, commit: '
  cpus: 2
  distribution:
    codename: focal
    distribution: ubuntu
    version: "20.04"
  eventLogger: journald
  hostname: ip-10-60-2-134
  idMappings:
    gidmap: null
    uidmap: null
  kernel: 5.11.0-1022-aws
  linkmode: dynamic
  logDriver: journald
  memFree: 174895104
  memTotal: 4054708224
  ociRuntime:
    name: crun
    package: 'crun: /usr/bin/crun'
    path: /usr/bin/crun
    version: |-
      crun version UNKNOWN
      commit: ea1fe3938eefa14eb707f1d22adff4db670645d6
      spec: 1.0.0
      +SYSTEMD +SELINUX +APPARMOR +CAP +SECCOMP +EBPF +CRIU +YAJL
  os: linux
  remoteSocket:
    path: /run/podman/podman.sock
  security:
    apparmorEnabled: true
    capabilities: CAP_CHOWN,CAP_DAC_OVERRIDE,CAP_FOWNER,CAP_FSETID,CAP_KILL,CAP_NET_BIND_SERVICE,CAP_SETFCAP,CAP_SETGID,CAP_SETPCAP,CAP_SETUID,CAP_SYS_CHROOT
    rootless: false
    seccompEnabled: true
    seccompProfilePath: /usr/share/containers/seccomp.json
    selinuxEnabled: false
  serviceIsRemote: false
  slirp4netns:
    executable: /usr/bin/slirp4netns
    package: 'slirp4netns: /usr/bin/slirp4netns'
    version: |-
      slirp4netns version 1.1.8
      commit: unknown
      libslirp: 4.3.1-git
      SLIRP_CONFIG_VERSION_MAX: 3
      libseccomp: 2.4.3
  swapFree: 0
  swapTotal: 0
  uptime: 30h 35m 14.23s (Approximately 1.25 days)
plugins:
  log:
  - k8s-file
  - none
  - journald
  network:
  - bridge
  - macvlan
  volume:
  - local
registries:
  search:
  - docker.io
  - quay.io
store:
  configFile: /etc/containers/storage.conf
  containerStore:
    number: 74
    paused: 0
    running: 2
    stopped: 72
  graphDriverName: overlay
  graphOptions:
    overlay.mountopt: nodev,metacopy=on
  graphRoot: /var/lib/containers/storage
  graphStatus:
    Backing Filesystem: extfs
    Native Overlay Diff: "false"
    Supports d_type: "true"
    Using metacopy: "true"
  imageStore:
    number: 3
  runRoot: /run/containers/storage
  volumePath: /var/lib/containers/storage/volumes
version:
  APIVersion: 3.4.2
  Built: 0
  BuiltTime: Thu Jan  1 00:00:00 1970
  GitCommit: ""
  GoVersion: go1.16.6
  OsArch: linux/amd64
  Version: 3.4.2

Package info (e.g. output of rpm -q podman or apt list podman):

Listing... Done
podman/unknown,now 100:3.4.2-1 amd64 [installed]
podman/unknown 100:3.4.2-1 arm64
podman/unknown 100:3.4.2-1 armhf
podman/unknown 100:3.4.2-1 s390x

Have you tested with the latest version of Podman and have you checked the Podman Troubleshooting Guide? (https://github.com/containers/podman/blob/main/troubleshooting.md)

Yes

Additional environment details (AWS, VirtualBox, physical, etc.):
AWS EC2 instance with Ubuntu: Linux ip-10-60-2-134 5.11.0-1022-aws #23~20.04.1-Ubuntu SMP Mon Nov 15 14:03:19 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux

I cannot reproduce the issue when I use my own Ubuntu VM on VMware.

[mheon]

Why are you using separate podman stop and podman rm commands? podman rm -af should suffice to get rid of every container on the system, running or not running, in a single command.

[bicca23]

Why are you using separate podman stop and podman rm commands? podman rm -af should suffice to get rid of every container on the system, running or not running, in a single command.

I didn't paste full command:

  podman ps 'label=<something>' -q | xargs -r podman stop

   sleep 10

   podman ps  'label=<something>'  -a -q | xargs -r podman rm -f

Also, same shell script is used for docker which doesn't seem to support -a for rm

[bicca23]

Even using one command triggered issue:

time="2022-02-24T17:08:28Z" level=info msg="podman filtering at log level debug"

time="2022-02-24T17:08:28Z" level=debug msg="Called rm.PersistentPreRunE(podman rm -af --log-level=DEBUG)"

time="2022-02-24T17:08:28Z" level=debug msg="Merged system config \"/usr/share/containers/containers.conf\""

time="2022-02-24T17:08:28Z" level=debug msg="Using conmon: \"/usr/libexec/podman/conmon\""

time="2022-02-24T17:08:28Z" level=debug msg="Initializing boltdb state at /var/lib/containers/storage/libpod/bolt_state.db"

time="2022-02-24T17:08:28Z" level=debug msg="Using graph driver overlay"

time="2022-02-24T17:08:28Z" level=debug msg="Using graph root /var/lib/containers/storage"

time="2022-02-24T17:08:28Z" level=debug msg="Using run root /run/containers/storage"

time="2022-02-24T17:08:28Z" level=debug msg="Using static dir /var/lib/containers/storage/libpod"

time="2022-02-24T17:08:28Z" level=debug msg="Using tmp dir /run/libpod"

time="2022-02-24T17:08:28Z" level=debug msg="Using volume path /var/lib/containers/storage/volumes"

time="2022-02-24T17:08:28Z" level=debug msg="Set libpod namespace to \"\""

time="2022-02-24T17:08:28Z" level=debug msg="[graphdriver] trying provided driver \"overlay\""

time="2022-02-24T17:08:28Z" level=debug msg="cached value indicated that overlay is supported"

time="2022-02-24T17:08:28Z" level=debug msg="cached value indicated that metacopy is being used"

time="2022-02-24T17:08:28Z" level=debug msg="cached value indicated that native-diff is not being used"

time="2022-02-24T17:08:28Z" level=info msg="Not using native diff for overlay, this may cause degraded performance for building images: kernel has CONFIG_OVERLAY_FS_REDIRECT_DIR enabled"

time="2022-02-24T17:08:28Z" level=debug msg="backingFs=extfs, projectQuotaSupported=false, useNativeDiff=false, usingMetacopy=true"

time="2022-02-24T17:08:28Z" level=debug msg="Initializing event backend journald"

time="2022-02-24T17:08:28Z" level=debug msg="configured OCI runtime kata initialization failed: no valid executable found for OCI runtime kata: invalid argument"

time="2022-02-24T17:08:28Z" level=debug msg="configured OCI runtime runsc initialization failed: no valid executable found for OCI runtime runsc: invalid argument"

time="2022-02-24T17:08:28Z" level=debug msg="configured OCI runtime runc initialization failed: no valid executable found for OCI runtime runc: invalid argument"

time="2022-02-24T17:08:28Z" level=debug msg="Using OCI runtime \"/usr/bin/crun\""

time="2022-02-24T17:08:28Z" level=info msg="Found CNI network podman (type=bridge) at /etc/cni/net.d/87-podman.conflist"

time="2022-02-24T17:08:28Z" level=debug msg="Default CNI network name podman is unchangeable"

time="2022-02-24T17:08:28Z" level=info msg="Setting parallel job count to 7"

time="2022-02-24T17:08:28Z" level=debug msg="Starting parallel job on container 2a5197be109e3e4da7568f38ec28fe4a191bb01111333397272bb687d176283d"

time="2022-02-24T17:08:28Z" level=debug msg="Starting parallel job on container 30b3f3e823df1341b471a69423a5f752d8da3d00f7973e24b3512610abc5aa55"

time="2022-02-24T17:08:28Z" level=debug msg="Starting parallel job on container 6b5b2e606b1f520f11e8b82498229b96ca8fc3ba4a9c0b1ce4d1c8ee6a873b1f"

time="2022-02-24T17:08:28Z" level=debug msg="Starting parallel job on container d2124f93a7431847e1c56f7cf190430efdfe85185392e558731597e502c9f04f"

time="2022-02-24T17:08:28Z" level=debug msg="Removing container 6b5b2e606b1f520f11e8b82498229b96ca8fc3ba4a9c0b1ce4d1c8ee6a873b1f"

time="2022-02-24T17:08:28Z" level=debug msg="Stopping ctr 6b5b2e606b1f520f11e8b82498229b96ca8fc3ba4a9c0b1ce4d1c8ee6a873b1f (timeout 10)"

time="2022-02-24T17:08:28Z" level=debug msg="Stopping container 6b5b2e606b1f520f11e8b82498229b96ca8fc3ba4a9c0b1ce4d1c8ee6a873b1f (PID 275090)"

time="2022-02-24T17:08:28Z" level=debug msg="Sending signal 15 to container 6b5b2e606b1f520f11e8b82498229b96ca8fc3ba4a9c0b1ce4d1c8ee6a873b1f"

send signal to pidfd: Permission denied

time="2022-02-24T17:08:33Z" level=debug msg="Failed to remove container 6b5b2e606b1f520f11e8b82498229b96ca8fc3ba4a9c0b1ce4d1c8ee6a873b1f: cannot remove container 6b5b2e606b1f520f11e8b82498229b96ca8fc3ba4a9c0b1ce4d1c8ee6a873b1f as it could not be stopped: timed out waiting for file /run/libpod/exits/6b5b2e606b1f520f11e8b82498229b96ca8fc3ba4a9c0b1ce4d1c8ee6a873b1f: internal libpod error"

time="2022-02-24T17:08:33Z" level=debug msg="Removing container 2a5197be109e3e4da7568f38ec28fe4a191bb01111333397272bb687d176283d"

time="2022-02-24T17:08:33Z" level=debug msg="Stopping ctr 2a5197be109e3e4da7568f38ec28fe4a191bb01111333397272bb687d176283d (timeout 10)"

time="2022-02-24T17:08:33Z" level=debug msg="Stopping container 2a5197be109e3e4da7568f38ec28fe4a191bb01111333397272bb687d176283d (PID 274901)"

time="2022-02-24T17:08:33Z" level=debug msg="Sending signal 15 to container 2a5197be109e3e4da7568f38ec28fe4a191bb01111333397272bb687d176283d"

send signal to pidfd: Permission denied

time="2022-02-24T17:08:38Z" level=debug msg="Failed to remove container 2a5197be109e3e4da7568f38ec28fe4a191bb01111333397272bb687d176283d: cannot remove container 2a5197be109e3e4da7568f38ec28fe4a191bb01111333397272bb687d176283d as it could not be stopped: timed out waiting for file /run/libpod/exits/2a5197be109e3e4da7568f38ec28fe4a191bb01111333397272bb687d176283d: internal libpod error"

time="2022-02-24T17:08:38Z" level=debug msg="Removing container 30b3f3e823df1341b471a69423a5f752d8da3d00f7973e24b3512610abc5aa55"

time="2022-02-24T17:08:38Z" level=debug msg="Stopping ctr 30b3f3e823df1341b471a69423a5f752d8da3d00f7973e24b3512610abc5aa55 (timeout 10)"

time="2022-02-24T17:08:38Z" level=debug msg="Stopping container 30b3f3e823df1341b471a69423a5f752d8da3d00f7973e24b3512610abc5aa55 (PID 275310)"

time="2022-02-24T17:08:38Z" level=debug msg="Sending signal 15 to container 30b3f3e823df1341b471a69423a5f752d8da3d00f7973e24b3512610abc5aa55"

send signal to pidfd: Permission denied

time="2022-02-24T17:08:43Z" level=debug msg="Failed to remove container 30b3f3e823df1341b471a69423a5f752d8da3d00f7973e24b3512610abc5aa55: cannot remove container 30b3f3e823df1341b471a69423a5f752d8da3d00f7973e24b3512610abc5aa55 as it could not be stopped: timed out waiting for file /run/libpod/exits/30b3f3e823df1341b471a69423a5f752d8da3d00f7973e24b3512610abc5aa55: internal libpod error"

time="2022-02-24T17:08:43Z" level=debug msg="Removing container d2124f93a7431847e1c56f7cf190430efdfe85185392e558731597e502c9f04f"

time="2022-02-24T17:08:43Z" level=debug msg="Stopping ctr d2124f93a7431847e1c56f7cf190430efdfe85185392e558731597e502c9f04f (timeout 10)"

time="2022-02-24T17:08:43Z" level=debug msg="Stopping container d2124f93a7431847e1c56f7cf190430efdfe85185392e558731597e502c9f04f (PID 275498)"

time="2022-02-24T17:08:43Z" level=debug msg="Sending signal 15 to container d2124f93a7431847e1c56f7cf190430efdfe85185392e558731597e502c9f04f"

send signal to pidfd: Permission denied

time="2022-02-24T17:08:48Z" level=debug msg="Failed to remove container d2124f93a7431847e1c56f7cf190430efdfe85185392e558731597e502c9f04f: cannot remove container d2124f93a7431847e1c56f7cf190430efdfe85185392e558731597e502c9f04f as it could not be stopped: timed out waiting for file /run/libpod/exits/d2124f93a7431847e1c56f7cf190430efdfe85185392e558731597e502c9f04f: internal libpod error"

Error: cannot remove container 2a5197be109e3e4da7568f38ec28fe4a191bb01111333397272bb687d176283d as it could not be stopped: timed out waiting for file /run/libpod/exits/2a5197be109e3e4da7568f38ec28fe4a191bb01111333397272bb687d176283d: internal libpod error

Error: cannot remove container 30b3f3e823df1341b471a69423a5f752d8da3d00f7973e24b3512610abc5aa55 as it could not be stopped: timed out waiting for file /run/libpod/exits/30b3f3e823df1341b471a69423a5f752d8da3d00f7973e24b3512610abc5aa55: internal libpod error

Error: cannot remove container 6b5b2e606b1f520f11e8b82498229b96ca8fc3ba4a9c0b1ce4d1c8ee6a873b1f as it could not be stopped: timed out waiting for file /run/libpod/exits/6b5b2e606b1f520f11e8b82498229b96ca8fc3ba4a9c0b1ce4d1c8ee6a873b1f: internal libpod error

Error: cannot remove container d2124f93a7431847e1c56f7cf190430efdfe85185392e558731597e502c9f04f as it could not be stopped: timed out waiting for file /run/libpod/exits/d2124f93a7431847e1c56f7cf190430efdfe85185392e558731597e502c9f04f: internal libpod error

failed to run commands: exit status 125

[bduffany]

I am running into the same issue on Ubuntu 20.04, podman version 3.4.2:

sudo podman run --rm -it --name=sleep --detach ubuntu:20.04 sleep 1000
sudo podman kill --signal=KILL sleep

# output:
# 2022-03-22T01:43:27.000294649Z: send signal to pidfd: Permission denied
# Error: error sending signal to container b273117b259da38007effcbafcb9c7544d54fbf454a62c8a2bf86c044f498dfd: `/usr/bin/crun kill b273117b259da38007effcbafcb9c7544d54fbf454a62c8a2bf86c044f498dfd 9` failed: exit status 1

The same issue happens whether I use sudo podman kill --signal=KILL or sudo podman rm -f.

Running the output crun command directly (with sudo) also doesn't work:

sudo /usr/bin/crun kill b273117b259da38007effcbafcb9c7544d54fbf454a62c8a2bf86c044f498dfd 9
# output:
# 2022-03-22T01:43:34.000939261Z: send signal to pidfd: Permission denied

[bduffany]

I ran into this gist which suggested it might be related to apparmor, and indeed it looks related to apparmor. I ran the following:

sudo systemctl disable apparmor.service --now
sudo aa-teardown

sudo podman run --rm -it --name=sleep --detach ubuntu:20.04 sleep 1000
sudo podman kill --signal=KILL sleep

And it works now.

I don't know why disabling apparmor fixes the problem though, and I would like to help figure out how to fix this without disabling apparmor. Happy to share more info about my system and/or try out various debugging commands if it would help at all.

[baude]

we dont currently have any apparmor experts on the team. where did you get podman from? if it was from ubuntu, can you create a launchpad with them and perhaps get some help?

[giuseppe]

this doesn't look like a podman issue, AppArmor should not block the pidfd_send_signal call