moby / moby

The Moby Project - a collaborative project for the container ecosystem to assemble container-based systems
https://mobyproject.org/
Apache License 2.0
68.54k stars 18.64k forks source link

OCI runtime exec failed: exec failed: container_linux.go:346: starting container process caused "process_linux.go:101: executing setns process caused \"exit status 1\"": unknown #40399

Closed yuklia closed 1 year ago

yuklia commented 4 years ago

BUG REPORT INFORMATION

Description

Service worked OK and suddenly turned Unhealthy

FailingStreak 3
2
End 2020-01-21T15:06:18.1439409Z
ExitCode -1
Output OCI runtime exec failed: exec failed: container_linux.go:346: starting container process caused "process_linux.go:101: executing setns process caused \"exit status 1\"": unknown
Start 2020-01-21T15:06:18.007996483Z
3
End 2020-01-21T15:06:28.33604261Z
ExitCode -1
Output OCI runtime exec failed: exec failed: container_linux.go:346: starting container process caused "process_linux.go:101: executing setns process caused \"exit status 1\"": unknown
Start 2020-01-21T15:06:28.157518263Z
4
End 2020-01-21T15:06:38.703726179Z
ExitCode -1
Output OCI runtime exec failed: exec failed: container_linux.go:346: starting container process caused "read init-p: connection reset by peer": unknown
Start 2020-01-21T15:06:38.350317727Z

Steps to reproduce the issue: don't know yet what causes:

Output OCI runtime exec failed: exec failed: container_linux.go:346: starting container process caused "read init-p: connection reset by peer": unknown

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

Output of docker version:

Client: Docker Engine - Community
 Version:           19.03.5
 API version:       1.40
 Go version:        go1.12.12
 Git commit:        633a0ea838
 Built:             Wed Nov 13 07:29:52 2019
 OS/Arch:           linux/amd64
 Experimental:      false

Server: Docker Engine - Community
 Engine:
  Version:          19.03.1
  API version:      1.40 (minimum version 1.12)
  Go version:       go1.12.5
  Git commit:       74b1e89
  Built:            Thu Jul 25 21:19:41 2019
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          1.2.10
  GitCommit:        b34a5c8af56e510852c35414db4c1f4fa6172339
 runc:
  Version:          1.0.0-rc8+dev
  GitCommit:        3e425f80a8c931f88e6d94a8c831b9d5aa481657
 docker-init:
  Version:          0.18.0
  GitCommit:        fec3683

Output of docker info:

Client:
 Debug Mode: false

Server:
 Containers: 33
  Running: 21
  Paused: 0
  Stopped: 12
 Images: 16
 Server Version: 19.03.1
 Storage Driver: overlay2
  Backing Filesystem: extfs
  Supports d_type: true
  Native Overlay Diff: true
 Logging Driver: awslogs
 Cgroup Driver: cgroupfs
 Plugins:
  Volume: local
  Network: bridge host ipvlan macvlan null overlay
  Log: awslogs fluentd gcplogs gelf journald json-file local logentries splunk syslog
 Swarm: active
  NodeID: zuvtge6vhow5s6fdi84m52bgh
  Is Manager: true
  ClusterID: f8x0rci4oq57u8elufoqnsv9m
  Managers: 1
  Nodes: 1
  Default Address Pool: 10.0.0.0/8  
  SubnetSize: 24
  Data Path Port: 4789
  Orchestration:
   Task History Retention Limit: 5
  Raft:
   Snapshot Interval: 10000
   Number of Old Snapshots to Retain: 0
   Heartbeat Tick: 1
   Election Tick: 10
  Dispatcher:
   Heartbeat Period: 5 seconds
  CA Configuration:
   Expiry Duration: 3 months
   Force Rotate: 0
  Autolock Managers: false
  Root Rotation In Progress: false
  Node Address: 172.0.11.33
  Manager Addresses:
   172.0.11.33:2377
 Runtimes: runc
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: b34a5c8af56e510852c35414db4c1f4fa6172339
 runc version: 3e425f80a8c931f88e6d94a8c831b9d5aa481657
 init version: fec3683
 Security Options:
  apparmor
  seccomp
   Profile: default
 Kernel Version: 4.15.0-1057-aws
 Operating System: Ubuntu 18.04.2 LTS
 OSType: linux
 Architecture: x86_64
 CPUs: 4
 Total Memory: 15.66GiB
 Name: devnode1
 ID: JQGY:G3FF:GLYN:23JZ:5GEI:76GY:HULG:YH4I:ZOG2:LVXD:7AWM:P2NM
 Docker Root Dir: /var/lib/docker
 Debug Mode: false
 Registry: https://index.docker.io/v1/
 Labels:
 Experimental: false
 Insecure Registries:
  127.0.0.0/8
 Live Restore Enabled: false

WARNING: API is accessible on http://0.0.0.0:2376 without encryption.
         Access to the remote API is equivalent to root access on the host. Refer
         to the 'Docker daemon attack surface' section in the documentation for
         more information: https://docs.docker.com/engine/security/security/#docker-daemon-attack-surface
WARNING: No swap limit support

Additional environment details (AWS, VirtualBox, physical, etc.): Hosted on AWS, EC2 instance Docker Swarm 1-node cluster, overlay network Distributor ID: Ubuntu Description: Ubuntu 18.04.2 LTS Release: 18.04 Codename: bionic

CPU and RAM, Disk were not overloaded inodes OK image

looking forward to your suggestions about what may cause an issue! Thanks in advance

cpuguy83 commented 4 years ago

Usually you'd see something like this because the runc was oom killed. Do you have a memory limit applied to the container?

thaJeztah commented 4 years ago

(not related to the issue, but I noticed the warning)

WARNING: API is accessible on http://0.0.0.0:2376 without encryption.
         Access to the remote API is equivalent to root access on the host. Refer
         to the 'Docker daemon attack surface' section in the documentation for
         more information: https://docs.docker.com/engine/security/security/#docker-daemon-attack-surface

Make sure that host is not publicly accessible. If you need to access a remote daemon without publicly exposing its API, you might be interested in the option to use an ssh connection for that, which is supported by Docker 18.09 and up (see https://github.com/docker/cli/pull/1014)

darkl0rd commented 4 years ago

I just had the exact same thing happen to me across a bunch of nodes in my swarm cluster. Cluster consists of 3 workers and 3 managers, running 19.03.4.

On two out of 3 nodes, 4 services were killed with this error (2 on each).

Docker inspect on the container on each respective node shows that their health-check failed with:

....
 "Health": {
                "Status": "unhealthy",
                "FailingStreak": 13,
                "Log": [
                    {
                        "Start": "2020-04-09T16:23:40.682408992Z",
                        "End": "2020-04-09T16:23:40.823917177Z",
                        "ExitCode": -1,
                        "Output": "OCI runtime exec failed: exec failed: container_linux.go:346: starting container process caused \"process_linux.go:101: executing setns process ca
used \\\"exit status 1\\\"\": unknown"
                    },
...
...

Containers have memory and CPU limits defined. None of the containers were anywhere near the limits imposed. When a container is killed by the oom-killer a message is also left in 'dmesg', this is not the case, and the actual error on the container is different (the error code is 137, but there is no mention of '"executing setns process caused ..."'.

-- OS & Package Information:

DISTRIB_ID=Ubuntu DISTRIB_RELEASE=18.04 DISTRIB_CODENAME=bionic DISTRIB_DESCRIPTION="Ubuntu 18.04.4 LTS"

docker-ce 5:19.03.4~3-0~ubuntu-bionic
containerd.io 1.2.10-3 docker-ce-cli 5:19.03.4~3-0~ubuntu-bionic

output of docker info:

Client: Debug Mode: false

Server: Containers: 90 Running: 76 Paused: 0 Stopped: 14 Images: 51 Server Version: 19.03.4 Storage Driver: overlay2 Backing Filesystem: xfs Supports d_type: true Native Overlay Diff: true Logging Driver: json-file Cgroup Driver: cgroupfs Plugins: Volume: local Network: bridge host ipvlan macvlan null overlay Log: awslogs fluentd gcplogs gelf journald json-file local logentries splunk syslog Swarm: active NodeID: obfuscated Is Manager: false Node Address: obfuscated Manager Addresses: obfuscated Runtimes: runc Default Runtime: runc Init Binary: docker-init containerd version: b34a5c8af56e510852c35414db4c1f4fa6172339 runc version: 3e425f80a8c931f88e6d94a8c831b9d5aa481657 init version: fec3683 Security Options: apparmor seccomp Profile: default Kernel Version: 4.15.0-1058-aws Operating System: Ubuntu 18.04.4 LTS OSType: linux Architecture: x86_64 CPUs: 8 Total Memory: 31.41GiB Name: obfuscated ID: obfuscated Docker Root Dir: /var/lib/docker Debug Mode: false Registry: https://index.docker.io/v1/ Labels: obfuscated Experimental: true Insecure Registries: 127.0.0.0/8 Live Restore Enabled: false

output of docker version:

Client: Docker Engine - Community Version: 19.03.4 API version: 1.40 Go version: go1.12.10 Git commit: 9013bf583a Built: Fri Oct 18 15:54:09 2019 OS/Arch: linux/amd64 Experimental: false

Server: Docker Engine - Community Engine: Version: 19.03.4 API version: 1.40 (minimum version 1.12) Go version: go1.12.10 Git commit: 9013bf583a Built: Fri Oct 18 15:52:40 2019 OS/Arch: linux/amd64 Experimental: true containerd: Version: 1.2.10 GitCommit: b34a5c8af56e510852c35414db4c1f4fa6172339 runc: Version: 1.0.0-rc8+dev GitCommit: 3e425f80a8c931f88e6d94a8c831b9d5aa481657 docker-init: Version: 0.18.0 GitCommit: fec3683

No errors in dmesg, syslog etc. Prometheus monitoring data shows container usage was at around 8% CPU for all containers killed and at around 15% memory usage.

MNCODE commented 4 years ago

same error and same symptoms... hoping for a solution

G-Rath commented 4 years ago

I've got a very similar error happening when I do npm ci - cross-posting in case they're related :)

f4810 commented 3 years ago

Hi all. I've the same problems with 19.03.13 on Mac os 10.15.7 in swarm mode. Even if I use docker every day, this error occur from 1-2 weeks after some upgrade (may be Docker Desktop Community 2.5.0.0???) .

In my case it seems to occur when I come back from sleep mode. I've a vpn that provides the dns (...default gateway is the one of vpn...), but I can't replicate the problem turning it on/off. It's only after a "long-time" sleep mode that problem occur.

more info: I'm using swarm, with one stack, a private network (yejfgncrg9v7 my_network overlay swarm), some image from debian, others from alpine. (...and they are all in error except the one with powerdns...)

I hope this can help for more debug info...

[edit] with swarm stucked in such manner, I've tried this: docker run -it --privileged --pid=host debian nsenter -t 1 -m -u -n -i sh but this never return. After downloading image I can only see this with a system ps: 0 47450 47447 0 10:46am ttys008 0:00.04 /usr/local/bin/com.docker.cli run -it --privileged --pid=host debian nsenter -t 1 -m -u -n -i sh

rootwyrm commented 3 years ago

This is most definitely a bug, and still not fixed. I have a 100% reproducible failure test case using TaleCaster created at this point. ALL docker exec calls fail, without exception. This is not the /proc issue; this is an issue where /sys is missing resulting in runc panic. The issue appears to be that BuildKit does not create /sys for some reason. Which is why reproduction is spotty; docker build will not reproduce, and buildkit will only reproduce under certain conditions. Here is the related upstream issue at runc

@thaJeztah, is this something that should be moved over to https://github.com/moby/buildkit instead, or would it be more of a parallel issue since the actual 'bug' is both in runc and buildkit?

Failure

Failure occurs with 100% consistency when docker-compose is used to stand up the containers in any configuration whatsoever. Details on the containers can be found at TaleCaster. In the example here, only tc_nzbget is used for simplicity, but all images behave identically. If you want to simplify further, it also reproduces with tc_docker as well, but tc_nzbget demonstrates more clearly that the application is running and perfectly healthy.

Sample Compose:

version: "3.7"
services:
  nntp:
    container_name: nntp
    image: docker.io/rootwyrm/tc_${NNTP_PROVIDER:-nzbget}:${RELEASE:-latest}
    restart: on-failure
    env_file:
      - /opt/talecaster/docker.env
    cap_add:
      - NET_ADMIN
    devices:
      - "/dev/net/tun:/dev/net/tun"
    tmpfs:
      - /run
      - /tmp
    ports:
      - "${NNTP_PORT:-6789}:6789"
    volumes:
      - /opt/talecaster/blackhole:/talecaster/blackhole
      - /opt/talecaster/downloads:/talecaster/downloads
      - /opt/talecaster/config/nntp:/talecaster/config
      - /etc/localtime:/etc/localtime:ro

This container will compose, start, and run successfully but all attempts to run exec result in the error.

Working - the issue is a missing /sys

Digging into runc when I found errors related to it in the strace pointed me at the solution. And it also clearly points to the bug.

version: "3.7"
services:
  nntp:
    container_name: nntp
    image: docker.io/rootwyrm/tc_${NNTP_PROVIDER:-nzbget}:${RELEASE:-latest}
    restart: on-failure
    env_file:
      - /opt/talecaster/docker.env
    cap_add:
      - NET_ADMIN
    devices:
      - "/dev/net/tun:/dev/net/tun"
    tmpfs:
      - /run
      - /tmp
    ports:
      - "${NNTP_PORT:-6789}:6789"
    volumes:
      - /opt/talecaster/blackhole:/talecaster/blackhole
      - /opt/talecaster/downloads:/talecaster/downloads
      - /opt/talecaster/config/nntp:/talecaster/config
      - /etc/localtime:/etc/localtime:ro
      - /sys:/sys

Now we test:

# docker-compose up --no-start
Building with native build. Learn about native build in Compose here: https://docs.docker.com/go/compose-native-build/
Recreating nntp ... done
# docker start nntp
nntp
# docker logs nntp

   OpenRC 0.42.1.788529e388 is starting up Linux 3.10.0-1127.el7.x86_64 (x86_64) [DOCKER]

 * /proc is already mounted
 * /run/openrc: creating directory
 * /run/lock: creating directory
 * /run/lock: correcting owner
 * Caching service dependencies ... [ ok ]
 * Starting dcron ... [ ok ]
 * Starting haveged ... [ ok ]
 * Starting talecaster ...
TaleCaster user is talecaster[30000]:media[30000]
Adding media as gid 30000
Adding talecaster as uid 30000
 * TaleCaster: found /firstboot, running initial setup
 [ ok ]
 * Starting nzbget ... [ ok ]
# docker exec -it nntp /bin/bash
(talecaster:latest) / # ^D
#

Well crap. It really was that simple? Crap.

Preliminary Root Cause Analysis

In the case of tc_docker, having a VOLUME [ "/sys" ] statement in the Dockerfile seems to have prevented buildkit from creating /sys correctly, which it should not have. (This was a dangling fix for an unrelated issue with buildx.)

This also clearly points to a behavioral divergence between docker build and buildkit; as stated previously, the VOLUME statement in the Dockerfile did NOT cause problems. Namely because this forced a /sys volume to always be created, including on platforms where that wasn't working as expected. However, buildkit appears to handle it differently and ultimately incorrectly by assuming a VOLUME statement to mean it should not create a corresponding /sys for some reason. The absence of /sys will then cause runc to panic when trying to do any sort of operations against the container, because it lacks cgroup data and cannot retrieve the cgroup data. The runc panic is the ultimate root cause of the error message, but the cause of the runc panic is the missing functional /sys volume. It is certain that other build scenarios can and do cause the problem as well, however, a comprehensive analysis to identify all of these is well beyond my means and free time.

Possible Solutions

This part is tricky. It can be summed up in a very simple statement: "/sys must always exist, unless on upstream runc 1.0.0-rc93 or above." See https://github.com/opencontainers/runc/pull/2634 - this changes runc to mount /sys itself, if it is missing. (So Docker doesn't have to care if it's there or not.) The problem is: what is the correct direction for the fix? Should this be fixed in BuildKit to match docker build behavior (which admittedly I haven't looked at in depth.) Should runc be updated to incorporate the upstream fix? Or should a third path be looked at, such as runtime always instituting a /sys volume?

Build details

2021-02-14T16:50:36.3038112Z ##[group]Run docker/setup-buildx-action@v1
2021-02-14T16:50:36.3038624Z with:
2021-02-14T16:50:36.3039010Z   driver: docker-container
2021-02-14T16:50:36.3040022Z   buildkitd-flags: --allow-insecure-entitlement security.insecure --allow-insecure-entitlement network.host
2021-02-14T16:50:36.3040954Z   install: false
2021-02-14T16:50:36.3041281Z   use: true
2021-02-14T16:50:36.3041592Z env:
2021-02-14T16:50:36.3041927Z   CONTAINER: tc_nzbget
2021-02-14T16:50:36.3042305Z ##[endgroup]
2021-02-14T16:50:37.8258008Z 📣 Buildx version: 0.5.1
2021-02-14T16:50:37.8268643Z ##[group]🔨 Creating a new builder instance
2021-02-14T16:50:37.8325892Z [command]/usr/bin/docker buildx create --name builder-854d3a16-2a9d-438c-a024-872f73ece881 --driver docker-container --buildkitd-flags --allow-insecure-entitlement security.insecure --allow-insecure-entitlement network.host --use
2021-02-14T16:50:37.9385812Z builder-854d3a16-2a9d-438c-a024-872f73ece881
2021-02-14T16:50:37.9425695Z ##[endgroup]
2021-02-14T16:50:37.9426888Z ##[group]🏃 Booting builder
2021-02-14T16:50:37.9444871Z [command]/usr/bin/docker buildx inspect --bootstrap --builder builder-854d3a16-2a9d-438c-a024-872f73ece881
2021-02-14T16:50:38.1042043Z #1 [internal] booting buildkit
2021-02-14T16:50:38.1105181Z #1 sha256:4f4f2fb07173e9934b42eec44bf5e51e95f256d5e5f67eb9ffda12b6a2463e1d
2021-02-14T16:50:38.2607104Z #1 pulling image moby/buildkit:buildx-stable-1
2021-02-14T16:50:40.1720980Z #1 pulling image moby/buildkit:buildx-stable-1 2.1s done
2021-02-14T16:50:40.3220419Z #1 creating container buildx_buildkit_builder-854d3a16-2a9d-438c-a024-872f73ece8810
2021-02-14T16:50:43.0403973Z #1 creating container buildx_buildkit_builder-854d3a16-2a9d-438c-a024-872f73ece8810 2.9s done
2021-02-14T16:50:43.0405308Z #1 DONE 4.9s
2021-02-14T16:50:43.1585375Z Name:   builder-854d3a16-2a9d-438c-a024-872f73ece881
2021-02-14T16:50:43.1614417Z Driver: docker-container
2021-02-14T16:50:43.1614899Z 
2021-02-14T16:50:43.1615368Z Nodes:
2021-02-14T16:50:43.1616458Z Name:      builder-854d3a16-2a9d-438c-a024-872f73ece8810
2021-02-14T16:50:43.1617379Z Endpoint:  unix:///var/run/docker.sock
2021-02-14T16:50:43.1618105Z Status:    running
2021-02-14T16:50:43.1619337Z Flags:     --allow-insecure-entitlement security.insecure --allow-insecure-entitlement network.host
2021-02-14T16:50:43.1620339Z Platforms: linux/amd64, linux/386
2021-02-14T16:50:43.1734938Z ##[endgroup]

/usr/bin/docker buildx build --tag ***/tc_nzbget:latest --platform linux/amd64 --iidfile /tmp/docker-build-push-kunWaL/iidfile --pull --push container/tc_nzbget
dennisvanderpool commented 3 years ago

Maybe unrelated, but I got the same error and it might help you?

I got the issue when using device mappings to container and not properly unmounting them before trying to end the container. I needed to reboot my docker host for it to properly get fixed. I got this error while trying my container out whilst building it.

Since I now properly unmount my device I don't have the issue anymore.

Dockerfile

FROM ubuntu

RUN apt -y update && apt -y upgrade

RUN DEBIAN_FRONTEND="noninteractive" apt -y install exfat-fuse exfat-utils mc ncdu rsync tmux vim

COPY run_backup /root

RUN bash

Script to run container

docker run -it \
        --rm \
        --name backup_monika \
        --device=/dev/sdb1 \
        --device=/dev/sdc1 \
        --device /dev/fuse \
        --privileged \
        dennisvanderpool/rsync

Backup script

#!/bin/bash
echo "Starting backup process..."

echo "Creating mount points..."
mkdir /mnt/monika
mkdir /mnt/backup

echo "Mounting backup drives..."
mount -U "F205-4050" /mnt/monika
mount -U "173cb3c6-569d-4193-bc2a-92c76654b3c8" /mnt/backup

echo "Checking if backup drives are mounted..."
BACKUP_DIR=/mnt/backup/monika/backup_hdd/
if grep -qs '/mnt/monika ' /proc/mounts; then
  if grep -qs '/mnt/backup ' /proc/mounts; then
    echo "Backup drives mounted, starting sync"

    mkdir -p $BACKUP_DIR
    rsync -avX /mnt/monika/ --delete --inplace $BACKUP_DIR
    echo "Sync completed"

    echo "Unmounting backup drives..."
    umount /mnt/monika
    umount /mnt/backup
    echo "Backup drives unmounted"

    echo "Backup process completed"
  fi
else
  echo "ONE OR MORE BACKUP DRIVES ARE NOT MOUNTED!"
fi
jpetazzo commented 2 years ago

I landed on this issue because I was seeing something similar when trying to run a post-start hook in a Kubernetes Pod. Specifically, I was seeing the read init-p: connection reset by peer message, and the Pod was crashing. It turns out that the container in the Pod was exiting (because the command was set to "sh" but there was nothing attached to stdin), and I suppose that this confused the container engine as it tried to exec an extra process in the container while the container was being torn down since PID 1 was exiting. Even though the root cause is super obvious once you know it, these messages really confused me. Leaving that information just in case you land on that issue after copy-pasting a similar error message :)

sam-thibault commented 1 year ago

It appears there are some varying issues, maybe a work-around, but generally this issue is stale. If you encounter this in the current release of Moby please open a new issue.