search

containers / podman

Podman: A tool for managing OCI containers and pods.
https://podman.io
Apache License 2.0
23.64k stars 2.41k forks source link

rootless: `--rm` doesn't seem to remove containers after execution #2647

Closed dustymabe closed 5 years ago

dustymabe commented 5 years ago

/kind bug

Description

--rm doesn't seem to remove containers after execution:

[dustymabe@media sync2jira (dusty *%)]$ podman rm --all
a22b31c5a594be90005a7932ead2707af6672c9a9da8b4f74762a725fe59531f
[dustymabe@media sync2jira (dusty *%)]$ 
[dustymabe@media sync2jira (dusty *%)]$ podman run -it --rm registry.fedoraproject.org/fedora:29 
[root@62f6d33070e0 /]# 
[root@62f6d33070e0 /]# exit
exit
[dustymabe@media sync2jira (dusty *%)]$ podman ps -a
CONTAINER ID  IMAGE                                 COMMAND    CREATED        STATUS                    PORTS  NAMES
62f6d33070e0  registry.fedoraproject.org/fedora:29  /bin/bash  6 seconds ago  Exited (0) 4 seconds ago         festive_davinci

Output of podman version:

[dustymabe@media sync2jira (dusty *%)]$ rpm -q podman
podman-1.1.2-1.git0ad9b6b.fc29.x86_64
[dustymabe@media sync2jira (dusty *%)]$ podman version
Version:            1.1.2
RemoteAPI Version:  1
Go Version:         go1.11.5
Git Commit:         a95a49d3038462d033f84ac314ec8a3064a99cff
Built:              Tue Mar  5 13:10:31 2019
OS/Arch:            linux/amd64

Output of podman info --debug:

[dustymabe@media sync2jira (dusty *%)]$ podman info --debug
debug:
  compiler: gc
  git commit: a95a49d3038462d033f84ac314ec8a3064a99cff
  go version: go1.11.5
  podman version: 1.1.2
host:
  BuildahVersion: 1.7.1
  Conmon:
    package: podman-1.1.2-1.git0ad9b6b.fc29.x86_64
    path: /usr/libexec/podman/conmon
    version: 'conmon version 1.12.0-dev, commit: a95a49d3038462d033f84ac314ec8a3064a99cff'
  Distribution:
    distribution: fedora
    version: "29"
  MemFree: 3664621568
  MemTotal: 20999905280
  OCIRuntime:
    package: runc-1.0.0-68.dev.git6635b4f.fc29.x86_64
    path: /usr/bin/runc
    version: |-
      runc version 1.0.0-rc6+dev
      commit: ef9132178ccc3d2775d4fb51f1e431f30cac1398-dirty
      spec: 1.0.1-dev
  SwapFree: 4287623168
  SwapTotal: 4294963200
  arch: amd64
  cpus: 8
  hostname: media
  kernel: 4.20.14-200.fc29.x86_64
  os: linux
  rootless: true
  uptime: 25h 34m 53.69s (Approximately 1.04 days)
insecure registries:
  registries: []
registries:
  registries:
  - docker.io
  - registry.fedoraproject.org
  - quay.io
  - registry.access.redhat.com
  - registry.centos.org
store:
  ConfigFile: /home/dustymabe/.config/containers/storage.conf
  ContainerStore:
    number: 9
  GraphDriverName: overlay
  GraphOptions:
  - overlay.mount_program=/usr/bin/fuse-overlayfs
  GraphRoot: /var/b/dustymabe-config-containers/storage
  GraphStatus:
    Backing Filesystem: extfs
    Native Overlay Diff: "false"
    Supports d_type: "true"
    Using metacopy: "false"
  ImageStore:
    number: 32
  RunRoot: /run/user/1001
  VolumePath: /home/dustymabe/.local/share/containers/storage/volumes
neVERberleRfellerER commented 5 years ago

I can't reproduce this on podman 1.0.0 on Fedora Atomic Host and podman 1.1.2 on Fedora Silverblue 29 and on podman 1.1.2 on Arch Linux.

dustymabe commented 5 years ago

Any chance you are running as root? I'm running rootless.

rhatdan commented 5 years ago 
$ podman run -it --rm registry.fedoraproject.org/fedora:29 
Trying to pull registry.fedoraproject.org/fedora:29...
Getting image source signatures
Copying blob 8dba660c242f [======================================] 92.5MiB / 92.5MiB
Copying config 81174df11a [======================================] 1.3KiB / 1.3KiB
Writing manifest to image destination
Storing signatures
[root@62f6d33070e0 /]# 
[root@8f825a2f1462 /]# [root@62f6d33070e0 /]# 
bash: [root@62f6d33070e0: command not found
[root@8f825a2f1462 /]# exit
exit
$ podman ps -a
CONTAINER ID  IMAGE  COMMAND  CREATED  STATUS  PORTS  NAMES

$ rpm -q podman podman-1.1.2-1.git0ad9b6b.fc29.x86_64

rhatdan commented 5 years ago

Does not look like an issue in podman 1.2

neVERberleRfellerER commented 5 years ago

My tests were also rootless. Can you actually remove that container manually (right after it was not autoremoved)?

dustymabe commented 5 years ago

anything you all would like me to do to give you debug information?

dustymabe commented 5 years ago

Can you actually remove that container manually (right after it was not autoremoved)?

yes. I don't have any problems removing it. It just doesn't get cleaned up like it should

mheon commented 5 years ago

@dustymabe There was a potential race condition we fixed recently where containers were not removed by the time the podman run command completed, but shortly afterwards. Is there any significant delay between run and ps when you test this? If you wait a few seconds before running ps has the container been removed?

dustymabe commented 5 years ago

Nope. They stay around for a long time it seems. All of these were created with --rm: 

[dustymabe@media sync2jira (dusty *%)]$ podman ps -a
CONTAINER ID  IMAGE                                 COMMAND    CREATED      STATUS                     PORTS  NAMES
dd0a59d67e88  localhost/sync2jira:latest            bash       2 hours ago  Exited (0) 11 seconds ago         xenodochial_ptolemy
ab290c106a67  localhost/sync2jira:latest            bash       2 hours ago  Exited (1) 2 hours ago            tender_stonebraker
edbca2f8c36e  localhost/sync2jira:latest            bash       2 hours ago  Exited (1) 2 hours ago            inspiring_bardeen
62f6d33070e0  registry.fedoraproject.org/fedora:29  /bin/bash  3 hours ago  Exited (0) 3 hours ago            festive_davinci
mheon commented 5 years ago

Alright. Can you run a container with --syslog and --log-level=debug both set, and paste anything that pops in in journalctl after the container exits?

dustymabe commented 5 years ago

Here is the output from podman run -it --rm --syslog --log-level=debug registry.fedoraproject.org/fedora:29 echo hello &> /tmp/output.txt:

``` time="2019-03-14T15:41:29-04:00" level=info msg="running as rootless" time="2019-03-14T15:41:29-04:00" level=debug msg="Initializing boltdb state at /var/b/dustymabe-config-containers/storage/libpod/bolt_state.db" time="2019-03-14T15:41:29-04:00" level=debug msg="Using graph driver overlay" time="2019-03-14T15:41:29-04:00" level=debug msg="Using graph root /var/b/dustymabe-config-containers/storage" time="2019-03-14T15:41:29-04:00" level=debug msg="Using run root /run/user/1001" time="2019-03-14T15:41:29-04:00" level=debug msg="Using static dir /var/b/dustymabe-config-containers/storage/libpod" time="2019-03-14T15:41:29-04:00" level=debug msg="Using tmp dir /run/user/1001/libpod/tmp" time="2019-03-14T15:41:29-04:00" level=debug msg="Using volume path /home/dustymabe/.local/share/containers/storage/volumes" time="2019-03-14T15:41:30-04:00" level=debug msg="Set libpod namespace to """ time="2019-03-14T15:41:30-04:00" level=debug msg="Not configuring container store" time="2019-03-14T15:41:30-04:00" level=debug msg="Using slirp4netns netmode" time="2019-03-14T15:41:30-04:00" level=info msg="running as rootless" time="2019-03-14T15:41:30-04:00" level=warning msg="The configuration is using `runtime_path`, which is deprecated and will be removed in future. Please use `runtimes` and `runtime`" time="2019-03-14T15:41:30-04:00" level=warning msg="If you are using both `runtime_path` and `runtime`, the configuration from `runtime_path` is used" time="2019-03-14T15:41:30-04:00" level=debug msg="Initializing boltdb state at /var/b/dustymabe-config-containers/storage/libpod/bolt_state.db" time="2019-03-14T15:41:30-04:00" level=debug msg="Using graph driver overlay" time="2019-03-14T15:41:30-04:00" level=debug msg="Using graph root /var/b/dustymabe-config-containers/storage" time="2019-03-14T15:41:30-04:00" level=debug msg="Using run root /run/user/1001" time="2019-03-14T15:41:30-04:00" level=debug msg="Using static dir /var/b/dustymabe-config-containers/storage/libpod" time="2019-03-14T15:41:30-04:00" level=debug msg="Using tmp dir /run/user/1001/libpod/tmp" time="2019-03-14T15:41:30-04:00" level=debug msg="Using volume path /home/dustymabe/.local/share/containers/storage/volumes" time="2019-03-14T15:41:30-04:00" level=debug msg="Set libpod namespace to """ time="2019-03-14T15:41:30-04:00" level=debug msg="[graphdriver] trying provided driver "overlay"" time="2019-03-14T15:41:30-04:00" level=debug msg="overlay: mount_program=/usr/bin/fuse-overlayfs" time="2019-03-14T15:41:30-04:00" level=debug msg="backingFs=extfs, projectQuotaSupported=false, useNativeDiff=false, usingMetacopy=false" time="2019-03-14T15:41:30-04:00" level=debug msg="parsed reference into "[overlay@/var/b/dustymabe-config-containers/storage+/run/user/1001:overlay.mount_program=/usr/bin/fuse-overlayfs]registry.fedoraproject.org/fedora:29"" time="2019-03-14T15:41:30-04:00" level=debug msg="parsed reference into "[overlay@/var/b/dustymabe-config-containers/storage+/run/user/1001:overlay.mount_program=/usr/bin/fuse-overlayfs]@69c5db8b64a76b5f0b3ac812f317f828d3d4d8e7b399ea196de6de659c225b96"" time="2019-03-14T15:41:30-04:00" level=debug msg="exporting opaque data as blob "sha256:69c5db8b64a76b5f0b3ac812f317f828d3d4d8e7b399ea196de6de659c225b96"" time="2019-03-14T15:41:30-04:00" level=debug msg="parsed reference into "[overlay@/var/b/dustymabe-config-containers/storage+/run/user/1001:overlay.mount_program=/usr/bin/fuse-overlayfs]@69c5db8b64a76b5f0b3ac812f317f828d3d4d8e7b399ea196de6de659c225b96"" time="2019-03-14T15:41:30-04:00" level=debug msg="exporting opaque data as blob "sha256:69c5db8b64a76b5f0b3ac812f317f828d3d4d8e7b399ea196de6de659c225b96"" time="2019-03-14T15:41:30-04:00" level=debug msg="parsed reference into "[overlay@/var/b/dustymabe-config-containers/storage+/run/user/1001:overlay.mount_program=/usr/bin/fuse-overlayfs]@69c5db8b64a76b5f0b3ac812f317f828d3d4d8e7b399ea196de6de659c225b96"" time="2019-03-14T15:41:30-04:00" level=debug msg="Using slirp4netns netmode" time="2019-03-14T15:41:30-04:00" level=debug msg="Allocated lock 0 for container f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca" time="2019-03-14T15:41:30-04:00" level=debug msg="parsed reference into "[overlay@/var/b/dustymabe-config-containers/storage+/run/user/1001:overlay.mount_program=/usr/bin/fuse-overlayfs]@69c5db8b64a76b5f0b3ac812f317f828d3d4d8e7b399ea196de6de659c225b96"" time="2019-03-14T15:41:30-04:00" level=debug msg="exporting opaque data as blob "sha256:69c5db8b64a76b5f0b3ac812f317f828d3d4d8e7b399ea196de6de659c225b96"" time="2019-03-14T15:41:30-04:00" level=debug msg="created container "f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca"" time="2019-03-14T15:41:30-04:00" level=debug msg="container "f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca" has work directory "/var/b/dustymabe-config-containers/storage/overlay-containers/f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca/userdata"" time="2019-03-14T15:41:30-04:00" level=debug msg="container "f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca" has run directory "/run/user/1001/overlay-containers/f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca/userdata"" time="2019-03-14T15:41:30-04:00" level=debug msg="New container created "f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca"" time="2019-03-14T15:41:30-04:00" level=debug msg="container "f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca" has CgroupParent "/libpod_parent/libpod-f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca"" time="2019-03-14T15:41:30-04:00" level=debug msg="Handling terminal attach" time="2019-03-14T15:41:30-04:00" level=debug msg="overlay: mount_data=lowerdir=/var/b/dustymabe-config-containers/storage/overlay/l/FPHCR6IKM6WTB7AQ2OQREDT62W,upperdir=/var/b/dustymabe-config-containers/storage/overlay/20c9d5bc0401f643090304cc5301ff2432c5983f95bf92d258a1d861106404a4/diff,workdir=/var/b/dustymabe-config-containers/storage/overlay/20c9d5bc0401f643090304cc5301ff2432c5983f95bf92d258a1d861106404a4/work,context="system_u:object_r:container_file_t:s0:c375,c821"" time="2019-03-14T15:41:30-04:00" level=debug msg="mounted container "f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca" at "/var/b/dustymabe-config-containers/storage/overlay/20c9d5bc0401f643090304cc5301ff2432c5983f95bf92d258a1d861106404a4/merged"" time="2019-03-14T15:41:30-04:00" level=debug msg="Created root filesystem for container f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca at /var/b/dustymabe-config-containers/storage/overlay/20c9d5bc0401f643090304cc5301ff2432c5983f95bf92d258a1d861106404a4/merged" time="2019-03-14T15:41:30-04:00" level=debug msg="/etc/system-fips does not exist on host, not mounting FIPS mode secret" time="2019-03-14T15:41:30-04:00" level=warning msg="failed to parse language "en_US.UTF-8": language: tag is not well-formed" time="2019-03-14T15:41:30-04:00" level=debug msg="Created OCI spec for container f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca at /var/b/dustymabe-config-containers/storage/overlay-containers/f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca/userdata/config.json" time="2019-03-14T15:41:30-04:00" level=debug msg="/usr/libexec/podman/conmon messages will be logged to syslog" time="2019-03-14T15:41:30-04:00" level=debug msg="running conmon: /usr/libexec/podman/conmon" args=[-c f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca -u f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca -r /usr/bin/runc -b /var/b/dustymabe-config-containers/storage/overlay-containers/f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca/userdata -p /run/user/1001/overlay-containers/f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca/userdata/pidfile -l /var/b/dustymabe-config-containers/storage/overlay-containers/f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca/userdata/ctr.log --exit-dir /run/user/1001/libpod/tmp/exits --conmon-pidfile /run/user/1001/overlay-containers/f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca/userdata/conmon.pid --exit-command /usr/bin/podman --exit-command-arg --root --exit-command-arg /var/b/dustymabe-config-containers/storage --exit-command-arg --runroot --exit-command-arg /run/user/1001 --exit-command-arg --log-level --exit-command-arg debug --exit-command-arg --cgroup-manager --exit-command-arg cgroupfs --exit-command-arg --tmpdir --exit-command-arg /run/user/1001/libpod/tmp --exit-command-arg --runtime --exit-command-arg runc --exit-command-arg --storage-driver --exit-command-arg overlay --exit-command-arg --syslog --exit-command-arg container --exit-command-arg cleanup --exit-command-arg --rm --exit-command-arg f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca --socket-dir-path /run/user/1001/libpod/tmp/socket -t --log-level debug --syslog] time="2019-03-14T15:41:30-04:00" level=warning msg="Failed to add conmon to cgroupfs sandbox cgroup: mkdir /sys/fs/cgroup/systemd/libpod_parent: permission denied" time="2019-03-14T15:41:30-04:00" level=debug msg="Received container pid: 22556" time="2019-03-14T15:41:30-04:00" level=debug msg="Created container f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca in OCI runtime" time="2019-03-14T15:41:30-04:00" level=debug msg="Attaching to container f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca" time="2019-03-14T15:41:30-04:00" level=debug msg="connecting to socket /run/user/1001/libpod/tmp/socket/f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca/attach" time="2019-03-14T15:41:30-04:00" level=debug msg="Starting container f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca with command [echo hello]" time="2019-03-14T15:41:30-04:00" level=debug msg="Received a resize event: {Width:281 Height:17}" time="2019-03-14T15:41:30-04:00" level=debug msg="Enabling signal proxying" time="2019-03-14T15:41:30-04:00" level=debug msg="Started container f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca" hello time="2019-03-14T15:41:30-04:00" level=debug msg="Checking container f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca status..." ```

Here is my journal from the time period of the run:

``` Mar 14 15:41:28 media NetworkManager[1407]: [1552592488.4142] device (wlp3s0): set-hw-addr: set MAC address to 86:9F:57:6E:AF:BF (scanning) Mar 14 15:41:28 media kernel: IPv6: ADDRCONF(NETDEV_UP): wlp3s0: link is not ready Mar 14 15:41:28 media NetworkManager[1407]: [1552592488.4465] device (wlp3s0): supplicant interface state: inactive -> disabled Mar 14 15:41:28 media NetworkManager[1407]: [1552592488.4590] device (wlp3s0): supplicant interface state: disabled -> inactive Mar 14 15:41:28 media wpa_supplicant[1546]: wlp3s0: Reject scan trigger since one is already pending Mar 14 15:41:29 media podman[22516]: time="2019-03-14T15:41:29-04:00" level=info msg="running as rootless" Mar 14 15:41:29 media podman[22516]: time="2019-03-14T15:41:29-04:00" level=debug msg="Initializing boltdb state at /var/b/dustymabe-config-containers/storage/libpod/bolt_state.db" Mar 14 15:41:29 media podman[22516]: time="2019-03-14T15:41:29-04:00" level=debug msg="Using graph driver overlay" Mar 14 15:41:29 media podman[22516]: time="2019-03-14T15:41:29-04:00" level=debug msg="Using graph root /var/b/dustymabe-config-containers/storage" Mar 14 15:41:29 media podman[22516]: time="2019-03-14T15:41:29-04:00" level=debug msg="Using run root /run/user/1001" Mar 14 15:41:29 media podman[22516]: time="2019-03-14T15:41:29-04:00" level=debug msg="Using static dir /var/b/dustymabe-config-containers/storage/libpod" Mar 14 15:41:29 media podman[22516]: time="2019-03-14T15:41:29-04:00" level=debug msg="Using tmp dir /run/user/1001/libpod/tmp" Mar 14 15:41:29 media podman[22516]: time="2019-03-14T15:41:29-04:00" level=debug msg="Using volume path /home/dustymabe/.local/share/containers/storage/volumes" Mar 14 15:41:30 media podman[22516]: time="2019-03-14T15:41:30-04:00" level=debug msg="Set libpod namespace to """ Mar 14 15:41:30 media podman[22516]: time="2019-03-14T15:41:30-04:00" level=debug msg="Not configuring container store" Mar 14 15:41:30 media podman[22516]: time="2019-03-14T15:41:30-04:00" level=debug msg="Using slirp4netns netmode" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=info msg="running as rootless" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=warning msg="The configuration is using `runtime_path`, which is deprecated and will be removed in future. Please use `runtimes` and `runtime`" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=warning msg="If you are using both `runtime_path` and `runtime`, the configuration from `runtime_path` is used" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="Initializing boltdb state at /var/b/dustymabe-config-containers/storage/libpod/bolt_state.db" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="Using graph driver overlay" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="Using graph root /var/b/dustymabe-config-containers/storage" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="Using run root /run/user/1001" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="Using static dir /var/b/dustymabe-config-containers/storage/libpod" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="Using tmp dir /run/user/1001/libpod/tmp" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="Using volume path /home/dustymabe/.local/share/containers/storage/volumes" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="Set libpod namespace to """ Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="[graphdriver] trying provided driver "overlay"" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="overlay: mount_program=/usr/bin/fuse-overlayfs" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="backingFs=extfs, projectQuotaSupported=false, useNativeDiff=false, usingMetacopy=false" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="parsed reference into "[overlay@/var/b/dustymabe-config-containers/storage+/run/user/1001:overlay.mount_program=/usr/bin/fuse-overlayfs]registry.fedoraproject.org/fedora:29"" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="parsed reference into "[overlay@/var/b/dustymabe-config-containers/storage+/run/user/1001:overlay.mount_program=/usr/bin/fuse-overlayfs]@69c5db8b64a76b5f0b3ac812f317f828d3d4d8e7b399ea196de6de659c225b96"" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="exporting opaque data as blob "sha256:69c5db8b64a76b5f0b3ac812f317f828d3d4d8e7b399ea196de6de659c225b96"" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="parsed reference into "[overlay@/var/b/dustymabe-config-containers/storage+/run/user/1001:overlay.mount_program=/usr/bin/fuse-overlayfs]@69c5db8b64a76b5f0b3ac812f317f828d3d4d8e7b399ea196de6de659c225b96"" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="exporting opaque data as blob "sha256:69c5db8b64a76b5f0b3ac812f317f828d3d4d8e7b399ea196de6de659c225b96"" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="parsed reference into "[overlay@/var/b/dustymabe-config-containers/storage+/run/user/1001:overlay.mount_program=/usr/bin/fuse-overlayfs]@69c5db8b64a76b5f0b3ac812f317f828d3d4d8e7b399ea196de6de659c225b96"" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="Using slirp4netns netmode" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="Allocated lock 0 for container f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="parsed reference into "[overlay@/var/b/dustymabe-config-containers/storage+/run/user/1001:overlay.mount_program=/usr/bin/fuse-overlayfs]@69c5db8b64a76b5f0b3ac812f317f828d3d4d8e7b399ea196de6de659c225b96"" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="exporting opaque data as blob "sha256:69c5db8b64a76b5f0b3ac812f317f828d3d4d8e7b399ea196de6de659c225b96"" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="created container "f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca"" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="container "f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca" has work directory "/var/b/dustymabe-config-containers/storage/overlay-containers/f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca/userdata"" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="container "f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca" has run directory "/run/user/1001/overlay-containers/f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca/userdata"" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="New container created "f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca"" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="container "f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca" has CgroupParent "/libpod_parent/libpod-f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca"" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="Handling terminal attach" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="overlay: mount_data=lowerdir=/var/b/dustymabe-config-containers/storage/overlay/l/FPHCR6IKM6WTB7AQ2OQREDT62W,upperdir=/var/b/dustymabe-config-containers/storage/overlay/20c9d5bc0401f643090304cc5301ff2432c5983f95bf92d258a1d861106404a4/diff,workdir=/var/b/dustymabe-config-containers/storage/overlay/20c9d5bc0401f643090304cc5301ff2432c5983f95bf92d258a1d861106404a4/work,context="system_u:object_r:container_file_t:s0:c375,c821"" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="mounted container "f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca" at "/var/b/dustymabe-config-containers/storage/overlay/20c9d5bc0401f643090304cc5301ff2432c5983f95bf92d258a1d861106404a4/merged"" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="Created root filesystem for container f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca at /var/b/dustymabe-config-containers/storage/overlay/20c9d5bc0401f643090304cc5301ff2432c5983f95bf92d258a1d861106404a4/merged" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="/etc/system-fips does not exist on host, not mounting FIPS mode secret" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=warning msg="failed to parse language "en_US.UTF-8": language: tag is not well-formed" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="Created OCI spec for container f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca at /var/b/dustymabe-config-containers/storage/overlay-containers/f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca/userdata/config.json" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="/usr/libexec/podman/conmon messages will be logged to syslog" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="running conmon: /usr/libexec/podman/conmon" args=[-c f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca -u f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca -r /usr/bin/runc -b /var/b/dustymabe-config-containers/storage/overlay-containers/f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca/userdata -p /run/user/1001/overlay-containers/f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca/userdata/pidfile -l /var/b/dustymabe-config-containers/storage/overlay-containers/f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca/userdata/ctr.log --exit-dir /run/user/1001/libpod/tmp/exits --conmon-pidfile /run/user/1001/overlay-containers/f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca/userdata/conmon.pid --exit-command /usr/bin/podman --exit-command-arg --root --exit-command-arg /var/b/dustymabe-config-containers/storage --exit-command-arg --runroot --exit-command-arg /run/user/1001 --exit-command-arg --log-level --exit-command-arg debug --exit-command-arg --cgroup-manager --exit-command-arg cgroupfs --exit-command-arg --tmpdir --exit-command-arg /run/user/1001/libpod/tmp --exit-command-arg --runtime --exit-command-arg runc --exit-command-arg --storage-driver --exit-command-arg overlay --exit-command-arg --syslog --exit-command-arg container --exit-command-arg cleanup --exit-command-arg --rm --exit-command-arg f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca --socket-dir-path /run/user/1001/libpod/tmp/socket -t --log-level debug --syslog] Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=warning msg="Failed to add conmon to cgroupfs sandbox cgroup: mkdir /sys/fs/cgroup/systemd/libpod_parent: permission denied" Mar 14 15:41:30 media conmon[22545]: conmon f7d2bdb1b35e0871ebd6 : addr{sun_family=AF_UNIX, sun_path=/tmp/conmon-term.W0GKYZ} Mar 14 15:41:30 media conmon[22545]: conmon f7d2bdb1b35e0871ebd6 : about to accept from console_socket_fd: 10 Mar 14 15:41:30 media conmon[22545]: conmon f7d2bdb1b35e0871ebd6 : about to recvfd from connfd: 13 Mar 14 15:41:30 media kernel: SELinux: mount invalid. Same superblock, different security settings for (dev mqueue, type mqueue) Mar 14 15:41:30 media conmon[22545]: [83B blob data] Mar 14 15:41:30 media conmon[22545]: conmon f7d2bdb1b35e0871ebd6 : container PID: 22556 Mar 14 15:41:30 media conmon[22545]: conmon f7d2bdb1b35e0871ebd6 : attach sock path: /run/user/1001/libpod/tmp/socket/f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca/attach Mar 14 15:41:30 media conmon[22545]: conmon f7d2bdb1b35e0871ebd6 : addr{sun_family=AF_UNIX, sun_path=/run/user/1001/libpod/tmp/socket/f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca/attach} Mar 14 15:41:30 media conmon[22545]: conmon f7d2bdb1b35e0871ebd6 : ctl fifo path: /var/b/dustymabe-config-containers/storage/overlay-containers/f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca/userdata/ctl Mar 14 15:41:30 media conmon[22545]: conmon f7d2bdb1b35e0871ebd6 : terminal_ctrl_fd: 14 Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="Received container pid: 22556" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="Created container f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca in OCI runtime" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="Attaching to container f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="connecting to socket /run/user/1001/libpod/tmp/socket/f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca/attach" Mar 14 15:41:30 media conmon[22545]: conmon f7d2bdb1b35e0871ebd6 : Accepted connection 11 Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="Starting container f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca with command [echo hello]" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="Received a resize event: {Width:281 Height:17}" Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="Enabling signal proxying" Mar 14 15:41:30 media conmon[22545]: conmon f7d2bdb1b35e0871ebd6 : Got ctl message: 1 17 281 Mar 14 15:41:30 media conmon[22545]: conmon f7d2bdb1b35e0871ebd6 : Message type: 1, Height: 17, Width: 281 Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="Started container f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca" Mar 14 15:41:30 media conmon[22545]: conmon f7d2bdb1b35e0871ebd6 : stdio_input read failed Input/output error Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="Checking container f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca status..." ```
mheon commented 5 years ago

Absolutely nothing after Checking container $ID status...?

It appears that cleanup processes are not running, but I'm really not sure as to what would cause that. It's added as an atexit() and Conmon doesn't seem to be exiting due to an error.

Any SELinux AVCs?

neVERberleRfellerER commented 5 years ago

It never logs after "Checking container $ID status", not even when it removes the container.

Wild guess and I could ge the whole "run" thing wrong: Cleanup starts here https://github.com/containers/libpod/blob/v1.1.2/cmd/podman/run.go#L144 it uses removeContainer to actually remove the container, but removeContainer have log-less non-error exit here: https://github.com/containers/libpod/blob/v1.1.2/libpod/runtime_ctr.go#L257 since logs show that boltdb is used, it means that this https://github.com/containers/libpod/blob/v1.1.2/libpod/boltdb_state.go#L445 is called and for some reaosn might return false. Could ~/.local/share/containers/storage/libpod/bolt_state.db be corrupted? Everything else would cause log at https://github.com/containers/libpod/blob/v1.1.2/cmd/podman/run.go#L145

mheon commented 5 years ago

BoltDB corruption would take down most all of Podman, so I doubt it's that.

Personal suspicion is that the exit command is either not running, or is running and not logging despite --syslog being specified.

dustymabe commented 5 years ago

Absolutely nothing after Checking container $ID status...?

not really:

Mar 14 15:41:30 media podman[22527]: time="2019-03-14T15:41:30-04:00" level=debug msg="Checking container f7d2bdb1b35e0871ebd694c47992974587e238af905830a7b5afe2e85f86d2ca status..."
Mar 14 15:41:35 media sudo[22428]: pam_unix(sudo:session): session closed for user root
Mar 14 15:41:35 media audit[22428]: USER_END pid=22428 uid=0 auid=1001 ses=3 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='op=PAM:session_close grantors=pam_keyinit,pam_limits,pam_keyinit,pam_limits,pam_systemd,pam_unix acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/13 res=success'
Mar 14 15:41:35 media audit[22428]: CRED_DISP pid=22428 uid=0 auid=1001 ses=3 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='op=PAM:setcred grantors=pam_unix acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/13 res=success'
Mar 14 15:46:30 media gnome-terminal-[3671]: gnome-terminal-server has no capability of surrounding-text feature

The pam_unix(sudo:session): session closed for user root was me CTRL-C out of my sudo journalctl -f and then there is a 5 minute delay until the next log message.

It appears that cleanup processes are not running, but I'm really not sure as to what would cause that. It's added as an atexit() and Conmon doesn't seem to be exiting due to an error.

Any SELinux AVCs?

Nope

rhatdan commented 5 years ago

Is this still an issue?

dustymabe commented 5 years ago

Doesn't seem like it:

[dustymabe@media ansible (master %=)]$ rpm -q podman
podman-1.2.0-2.git3bd528e.fc29.x86_64
[dustymabe@media ansible (master %=)]$ 
[dustymabe@media ansible (master %=)]$ podman run -it --rm registry.fedoraproject.org/fedora:29 
[root@867a35d00bc0 /]# exit
exit
[dustymabe@media ansible (master %=)]$ podman ps -a
CONTAINER ID  IMAGE  COMMAND  CREATED  STATUS  PORTS  NAMES
[dustymabe@media ansible (master %=)]$