Strange behavior when launching vanilla centos:7 image
lulingar opened this issue · 3 comments
lulingar commented
As a warm up, I test the centos:7 image by running
docker run --rm -it centos:7
This fails after a few minutes, with the message:
docker: Error response from daemon: failed to create shim: OCI runtime create failed: container_linux.go:380: starting container process caused: process_linux.go:385: applying cgroup configuration for process caused: error while starting unit "docker-083f8964d47e92b66cb585a62e829bfc079928ba88b39fb6ccc4e0426e4a464f.scope" with properties [{Name:Description Value:"libcontainer container 083f8964d47e92b66cb585a62e829bfc079928ba88b39fb6ccc4e0426e4a464f"} {Name:Slice Value:"system.slice"} {Name:PIDs Value:@au [301562]} {Name:Delegate Value:true} {Name:MemoryAccounting Value:true} {Name:CPUAccounting Value:true} {Name:IOAccounting Value:true} {Name:TasksAccounting Value:true} {Name:DefaultDependencies Value:false}]: Failed to activate service 'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms): unknown.
I have debugging enabled in the docker daemon. The relevant log segment that shows events for this attempt with the centos image is:
$ journalctl -u docker.service -f -n0
-- Journal begins at Sun 2020-10-25 22:15:14 CET. --
jul 27 21:04:47 machine dockerd[1188]: time="2021-07-27T21:04:47.265561314+02:00" level=debug msg="Calling GET /containers/json?all=1"
jul 27 21:05:01 machine dockerd[1188]: time="2021-07-27T21:05:01.327947124+02:00" level=debug msg="Calling HEAD /_ping"
jul 27 21:05:01 machine dockerd[1188]: time="2021-07-27T21:05:01.329035163+02:00" level=debug msg="Calling POST /v1.41/containers/create"
jul 27 21:05:01 machine dockerd[1188]: time="2021-07-27T21:05:01.329300183+02:00" level=debug msg="form data: {\"AttachStderr\":true,\"AttachStdin\":true,\"AttachStdout\":true,\"Cmd\":null,\"Domainname\":\"\",\"Entrypoint\":null,\"Env\":null,\"HostConfig\":{\"AutoRemove\":true,\"Binds\":null,\"BlkioDeviceReadBps\":null,\"BlkioDeviceReadIOps\":null,\"BlkioDeviceWriteBps\":null,\"BlkioDeviceWriteIOps\":null,\"BlkioWeight\":0,\"BlkioWeightDevice\":[],\"CapAdd\":null,\"CapDrop\":null,\"Cgroup\":\"\",\"CgroupParent\":\"\",\"CgroupnsMode\":\"\",\"ConsoleSize\":[0,0],\"ContainerIDFile\":\"\",\"CpuCount\":0,\"CpuPercent\":0,\"CpuPeriod\":0,\"CpuQuota\":0,\"CpuRealtimePeriod\":0,\"CpuRealtimeRuntime\":0,\"CpuShares\":0,\"CpusetCpus\":\"\",\"CpusetMems\":\"\",\"DeviceCgroupRules\":null,\"DeviceRequests\":null,\"Devices\":[],\"Dns\":[],\"DnsOptions\":[],\"DnsSearch\":[],\"ExtraHosts\":null,\"GroupAdd\":null,\"IOMaximumBandwidth\":0,\"IOMaximumIOps\":0,\"IpcMode\":\"\",\"Isolation\":\"\",\"KernelMemory\":0,\"KernelMemoryTCP\":0,\"Links\":null,\"LogConfig\":{\"Config\":{},\"Type\":\"\"},\"MaskedPaths\":null,\"Memory\":0,\"MemoryReservation\":0,\"MemorySwap\":0,\"MemorySwappiness\":-1,\"NanoCpus\":0,\"NetworkMode\":\"default\",\"OomKillDisable\":false,\"OomScoreAdj\":0,\"PidMode\":\"\",\"PidsLimit\":0,\"PortBindings\":{},\"Privileged\":false,\"PublishAllPorts\":false,\"ReadonlyPaths\":null,\"ReadonlyRootfs\":false,\"RestartPolicy\":{\"MaximumRetryCount\":0,\"Name\":\"no\"},\"SecurityOpt\":null,\"ShmSize\":0,\"UTSMode\":\"\",\"Ulimits\":null,\"UsernsMode\":\"\",\"VolumeDriver\":\"\",\"VolumesFrom\":null},\"Hostname\":\"\",\"Image\":\"centos:7\",\"Labels\":{},\"NetworkingConfig\":{\"EndpointsConfig\":{}},\"OnBuild\":null,\"OpenStdin\":true,\"Platform\":null,\"StdinOnce\":true,\"Tty\":true,\"User\":\"\",\"Volumes\":{},\"WorkingDir\":\"\"}"
jul 27 21:05:01 machine dockerd[1188]: time="2021-07-27T21:05:01.358519875+02:00" level=debug msg="container mounted via layerStore: &{/home/docker/overlay2/8e46cb5de3dff420b05734e709713d2ba7218778740d05f7f0e88de5d5eff51b/merged 0x56127f493f60 0x56127f493f60}" container=083f8964d47e92b66cb585a62e829bfc079928ba88b39fb6ccc4e0426e4a464f
jul 27 21:05:01 machine dockerd[1188]: time="2021-07-27T21:05:01.372715572+02:00" level=debug msg="Calling POST /v1.41/containers/083f8964d47e92b66cb585a62e829bfc079928ba88b39fb6ccc4e0426e4a464f/attach?stderr=1&stdin=1&stdout=1&stream=1"
jul 27 21:05:01 machine dockerd[1188]: time="2021-07-27T21:05:01.372849891+02:00" level=debug msg="attach: stderr: begin"
jul 27 21:05:01 machine dockerd[1188]: time="2021-07-27T21:05:01.372850259+02:00" level=debug msg="attach: stdout: begin"
jul 27 21:05:01 machine dockerd[1188]: time="2021-07-27T21:05:01.372855917+02:00" level=debug msg="attach: stdin: begin"
jul 27 21:05:01 machine dockerd[1188]: time="2021-07-27T21:05:01.373008150+02:00" level=debug msg="Calling POST /v1.41/containers/083f8964d47e92b66cb585a62e829bfc079928ba88b39fb6ccc4e0426e4a464f/wait?condition=removed"
jul 27 21:05:01 machine dockerd[1188]: time="2021-07-27T21:05:01.373312264+02:00" level=debug msg="Calling POST /v1.41/containers/083f8964d47e92b66cb585a62e829bfc079928ba88b39fb6ccc4e0426e4a464f/start"
jul 27 21:05:01 machine dockerd[1188]: time="2021-07-27T21:05:01.373834499+02:00" level=debug msg="container mounted via layerStore: &{/home/docker/overlay2/8e46cb5de3dff420b05734e709713d2ba7218778740d05f7f0e88de5d5eff51b/merged 0x56127f493f60 0x56127f493f60}" container=083f8964d47e92b66cb585a62e829bfc079928ba88b39fb6ccc4e0426e4a464f
jul 27 21:05:01 machine dockerd[1188]: time="2021-07-27T21:05:01.374156803+02:00" level=debug msg="Assigning addresses for endpoint cool_bassi's interface on network bridge"
jul 27 21:05:01 machine dockerd[1188]: time="2021-07-27T21:05:01.374174940+02:00" level=debug msg="RequestAddress(LocalDefault/172.17.0.0/16, <nil>, map[])"
jul 27 21:05:01 machine dockerd[1188]: time="2021-07-27T21:05:01.374193982+02:00" level=debug msg="Request address PoolID:172.17.0.0/16 App: ipam/default/data, ID: LocalDefault/172.17.0.0/16, DBIndex: 0x0, Bits: 65536, Unselected: 65533, Sequence: (0xc0000000, 1)->(0x0, 2046)->(0x1, 1)->end Curr:3 Serial:false PrefAddress:<nil> "
jul 27 21:05:01 machine dockerd[1188]: time="2021-07-27T21:05:01.379009407+02:00" level=debug msg="Assigning addresses for endpoint cool_bassi's interface on network bridge"
jul 27 21:05:01 machine dockerd[1188]: time="2021-07-27T21:05:01.385486470+02:00" level=debug msg="Programming external connectivity on endpoint cool_bassi (4dfa3910cfc0360771bd0623118bb969397786fdd77f1e71349384c210d05d9a)"
jul 27 21:05:01 machine dockerd[1188]: time="2021-07-27T21:05:01.387324085+02:00" level=debug msg="EnableService 083f8964d47e92b66cb585a62e829bfc079928ba88b39fb6ccc4e0426e4a464f START"
jul 27 21:05:01 machine dockerd[1188]: time="2021-07-27T21:05:01.387345473+02:00" level=debug msg="EnableService 083f8964d47e92b66cb585a62e829bfc079928ba88b39fb6ccc4e0426e4a464f DONE"
jul 27 21:05:01 machine dockerd[1188]: time="2021-07-27T21:05:01.391094545+02:00" level=debug msg="createSpec: cgroupsPath: system.slice:docker:083f8964d47e92b66cb585a62e829bfc079928ba88b39fb6ccc4e0426e4a464f"
jul 27 21:05:01 machine dockerd[1188]: time="2021-07-27T21:05:01.391465256+02:00" level=debug msg="bundle dir created" bundle=/var/run/docker/containerd/083f8964d47e92b66cb585a62e829bfc079928ba88b39fb6ccc4e0426e4a464f module=libcontainerd namespace=moby root=/home/docker/overlay2/8e46cb5de3dff420b05734e709713d2ba7218778740d05f7f0e88de5d5eff51b/merged
jul 27 21:05:01 machine dockerd[1199]: time="2021-07-27T21:05:01.395637578+02:00" level=debug msg="event published" ns=moby topic=/containers/create type=containerd.events.ContainerCreate
jul 27 21:05:01 machine dockerd[1199]: time="2021-07-27T21:05:01.401311544+02:00" level=debug msg="garbage collected" d=1.829001ms
jul 27 21:05:01 machine dockerd[1199]: time="2021-07-27T21:05:01.403881731+02:00" level=info msg="starting signal loop" namespace=moby path=/run/docker/containerd/daemon/io.containerd.runtime.v2.task/moby/083f8964d47e92b66cb585a62e829bfc079928ba88b39fb6ccc4e0426e4a464f pid=301538
jul 27 21:05:02 machine dockerd[1188]: time="2021-07-27T21:05:02.273276492+02:00" level=debug msg="Calling GET /containers/json?all=1"
jul 27 21:05:17 machine dockerd[1188]: time="2021-07-27T21:05:17.281821470+02:00" level=debug msg="Calling GET /containers/json?all=1"
jul 27 21:05:32 machine dockerd[1188]: time="2021-07-27T21:05:32.290710214+02:00" level=debug msg="Calling GET /containers/json?all=1"
jul 27 21:05:47 machine dockerd[1188]: time="2021-07-27T21:05:47.299170746+02:00" level=debug msg="Calling GET /containers/json?all=1"
jul 27 21:06:02 machine dockerd[1188]: time="2021-07-27T21:06:02.308474934+02:00" level=debug msg="Calling GET /containers/json?all=1"
jul 27 21:06:16 machine dockerd[1199]: time="2021-07-27T21:06:16.502170116+02:00" level=debug msg="failed to delete task" error="rpc error: code = NotFound desc = container not created: not found" id=083f8964d47e92b66cb585a62e829bfc079928ba88b39fb6ccc4e0426e4a464f
jul 27 21:06:16 machine dockerd[1199]: time="2021-07-27T21:06:16.502448167+02:00" level=info msg="shim disconnected" id=083f8964d47e92b66cb585a62e829bfc079928ba88b39fb6ccc4e0426e4a464f
jul 27 21:06:16 machine dockerd[1199]: time="2021-07-27T21:06:16.502503144+02:00" level=warning msg="cleaning up after shim disconnected" id=083f8964d47e92b66cb585a62e829bfc079928ba88b39fb6ccc4e0426e4a464f namespace=moby
jul 27 21:06:16 machine dockerd[1199]: time="2021-07-27T21:06:16.502515922+02:00" level=info msg="cleaning up dead shim"
jul 27 21:06:16 machine dockerd[1199]: time="2021-07-27T21:06:16.524534870+02:00" level=warning msg="cleanup warnings time=\"2021-07-27T21:06:16+02:00\" level=info msg=\"starting signal loop\" namespace=moby pid=301742\n"
jul 27 21:06:16 machine dockerd[1199]: time="2021-07-27T21:06:16.524703958+02:00" level=error msg="copy shim log" error="read /proc/self/fd/29: file already closed"
jul 27 21:06:16 machine dockerd[1188]: time="2021-07-27T21:06:16.525020660+02:00" level=error msg="stream copy error: reading from a closed fifo"
jul 27 21:06:16 machine dockerd[1188]: time="2021-07-27T21:06:16.525040583+02:00" level=debug msg="attach: stdout: end"
jul 27 21:06:16 machine dockerd[1188]: time="2021-07-27T21:06:16.525083581+02:00" level=debug msg="attach: stderr: end"
jul 27 21:06:16 machine dockerd[1188]: time="2021-07-27T21:06:16.525044899+02:00" level=debug msg="attach: stdin: end"
jul 27 21:06:16 machine dockerd[1188]: time="2021-07-27T21:06:16.525132894+02:00" level=debug msg="attach done"
jul 27 21:06:16 machine dockerd[1199]: time="2021-07-27T21:06:16.534758412+02:00" level=debug msg="event published" ns=moby topic=/containers/delete type=containerd.events.ContainerDelete
jul 27 21:06:16 machine dockerd[1188]: time="2021-07-27T21:06:16.541410419+02:00" level=debug msg="Revoking external connectivity on endpoint cool_bassi (4dfa3910cfc0360771bd0623118bb969397786fdd77f1e71349384c210d05d9a)"
jul 27 21:06:16 machine dockerd[1188]: time="2021-07-27T21:06:16.542501936+02:00" level=debug msg="DeleteConntrackEntries purged ipv4:0, ipv6:0"
jul 27 21:06:16 machine dockerd[1188]: time="2021-07-27T21:06:16.584387322+02:00" level=debug msg="Releasing addresses for endpoint cool_bassi's interface on network bridge"
jul 27 21:06:16 machine dockerd[1188]: time="2021-07-27T21:06:16.584414316+02:00" level=debug msg="ReleaseAddress(LocalDefault/172.17.0.0/16, 172.17.0.2)"
jul 27 21:06:16 machine dockerd[1188]: time="2021-07-27T21:06:16.584431919+02:00" level=debug msg="Released address PoolID:LocalDefault/172.17.0.0/16, Address:172.17.0.2 Sequence:App: ipam/default/data, ID: LocalDefault/172.17.0.0/16, DBIndex: 0x0, Bits: 65536, Unselected: 65532, Sequence: (0xe0000000, 1)->(0x0, 2046)->(0x1, 1)->end Curr:3"
jul 27 21:06:16 machine dockerd[1188]: time="2021-07-27T21:06:16.595151732+02:00" level=error msg="083f8964d47e92b66cb585a62e829bfc079928ba88b39fb6ccc4e0426e4a464f cleanup: failed to delete container from containerd: no such container"
jul 27 21:06:16 machine dockerd[1188]: time="2021-07-27T21:06:16.602378735+02:00" level=error msg="Handler for POST /v1.41/containers/083f8964d47e92b66cb585a62e829bfc079928ba88b39fb6ccc4e0426e4a464f/start returned error: failed to create shim: OCI runtime create failed: container_linux.go:380: starting container process caused: process_linux.go:385: applying cgroup configuration for process caused: error while starting unit \"docker-083f8964d47e92b66cb585a62e829bfc079928ba88b39fb6ccc4e0426e4a464f.scope\" with properties [{Name:Description Value:\"libcontainer container 083f8964d47e92b66cb585a62e829bfc079928ba88b39fb6ccc4e0426e4a464f\"} {Name:Slice Value:\"system.slice\"} {Name:PIDs Value:@au [301562]} {Name:Delegate Value:true} {Name:MemoryAccounting Value:true} {Name:CPUAccounting Value:true} {Name:IOAccounting Value:true} {Name:TasksAccounting Value:true} {Name:DefaultDependencies Value:false}]: Failed to activate service 'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms): unknown"
jul 27 21:06:16 machine dockerd[1188]: time="2021-07-27T21:06:16.602662010+02:00" level=debug msg="Closing buffered stdin pipe"
jul 27 21:06:16 machine dockerd[1199]: time="2021-07-27T21:06:16.616094651+02:00" level=debug msg="garbage collected" d=1.749896ms
For reference, this is the info:
$ docker info
Client:
Context: default
Debug Mode: false
Plugins:
app: Docker App (Docker Inc., v0.9.1-beta3)
buildx: Build with BuildKit (Docker Inc., v0.5.1-tp-docker)
Server:
Containers: 8
Running: 4
Paused: 0
Stopped: 4
Images: 818
Server Version: 20.10.7
Storage Driver: overlay2
Backing Filesystem: extfs
Supports d_type: true
Native Overlay Diff: true
userxattr: false
Logging Driver: json-file
Cgroup Driver: systemd
Cgroup Version: 2
Plugins:
Volume: local
Network: bridge host ipvlan macvlan null overlay
Log: awslogs fluentd gcplogs gelf journald json-file local logentries splunk syslog
Swarm: inactive
Runtimes: io.containerd.runc.v2 io.containerd.runtime.v1.linux runc
Default Runtime: runc
Init Binary: docker-init
containerd version: 36cc874494a56a253cd181a1a685b44b58a2e34a.m
runc version: v1.0.1-0-g4144b638
init version: de40ad0
Security Options:
apparmor
seccomp
Profile: default
cgroupns
Kernel Version: 5.12.19-1-MANJARO
Operating System: Manjaro Linux
OSType: linux
Architecture: x86_64
CPUs: 8
Total Memory: 31.02GiB
Name: luis-mdk20
ID: WWML:6J7M:QOH5:C3RU:2CNQ:Y5CD:5ZUX:PU7C:LKK2:77DR:K7CI:57TZ
Docker Root Dir: /home/docker
Debug Mode: true
File Descriptors: 55
Goroutines: 62
System Time: 2021-07-27T22:02:52.461710685+02:00
EventsListeners: 0
Username: midojenkins
Registry: https://index.docker.io/v1/
Labels:
Experimental: true
Insecure Registries:
localhost:5000
127.0.0.0/8
Live Restore Enabled: false
wglambert commented
Seems like the main error is this Failed to activate service 'org.freedesktop.systemd1' but I can't find anything immediately obvious of what exactly is causing that. Do you encounter this on any other image, I'd imagine it's something related to the host environment like AppArmor or SELinux given that I'm not able to reproduce the issue
$ docker run --rm -it centos:7
Unable to find image 'centos:7' locally
7: Pulling from library/centos
2d473b07cdd5: Pull complete
Digest: sha256:0f4ec88e21daf75124b8a9e5ca03c37a5e937e0e108a255d890492430789b60e
Status: Downloaded newer image for centos:7
[root@5e863fbe4cbd /]#yosifkit commented
A shot in the dark but perhaps related to docker/for-linux#747 (and moby/moby#28705). TLDR: try adding vsyscall=emulate to your kernel cmdline.
tianon commented
In the future, these sorts of questions/requests would be more appropriately posted to a dedicated support forum, such as the Docker Community Forums, the Docker Community Slack, or Stack Overflow.