Hide Forgot
Created attachment 1142238 [details] complete /var/log/message from the moment docker run is executed Description of problem: Docker 1.10.3 cannot run containers Version-Release: docker-1.10.3-4.gitf8a9a2a.fc24.x86_64 docker-selinux-1.10.3-4.gitf8a9a2a.fc24.x86_64 docker-v1.10-migrator-1.10.3-4.gitf8a9a2a.fc24.x86_64 How reproducible: Always Steps to Reproduce: 1. Stop Docker 2. rm -rf /var/lib/docker /etc/sysconfig/docker* /etc/docker /var/run/docker 3. dnf reinstall docker 4. systemctl start docker 5. docker run -ti centos /bin/bash Actual results: Docker fails with the following error: # docker run -ti centos /bin/bash Unable to find image 'centos:latest' locally Trying to pull repository docker.io/library/centos ... latest: Pulling from docker.io/library/centos a3ed95caeb02: Pull complete 196355c4b639: Pull complete Digest: sha256:381f21e4c7b3724c6f420b2bcfa6e13e47ed155192869a2a04fa10f944c78476 Status: Downloaded newer image for docker.io/centos:latest docker: Error response from daemon: Cannot start container 2bec99afcc117e3176c4d355dee260586023491ee0d2d0419b93b14733eb5010: [9] System error: exit status 1. Expected results: Container is started Additional info: Kernel: kernel-4.5.0-0.rc7.git0.2.fc24.x86_64 SELinux: permissive /var/log/messages Mar 31 11:15:21 yubi docker: time="2016-03-31T11:15:21.746477509-03:00" level=info msg="{Action=create, Username=gtirloni, LoginUID=1000, PID=11064}" Mar 31 11:15:21 yubi docker: time="2016-03-31T11:15:21.951673269-03:00" level=info msg="{Action=attach, ID=4df38bbdb6fef1623710680ce2e4db285c32ad1f5823c447a1e61c19fd351e10, Username=gtirloni, LoginUID=1000, PID=11064}" Mar 31 11:15:21 yubi docker: time="2016-03-31T11:15:21.952466193-03:00" level=info msg="{Action=start, ID=4df38bbdb6fef1623710680ce2e4db285c32ad1f5823c447a1e61c19fd351e10, Username=gtirloni, LoginUID=1000, PID=11064, Config={Hostname=4df38bbdb6fe, AttachStdin=true, AttachStdout=true, AttachStderr=true, Tty=true, OpenStdin=true, StdinOnce=true, Cmd={parts:[/bin/bash]}, ArgsEscaped=false, Image=centos, NetworkDisabled=false, Labels=map[build-date:2016-03-04 license:GPLv2 name:CentOS Base Image vendor:CentOS], StopSignal=SIGTERM}, HostConfig={LogConfig={Type:journald Config:map[]}, NetworkMode=default, PortBindings=map[], RestartPolicy={Name:no MaximumRetryCount:0}, DNS=[], DNSOptions=[], DNSSearch=[], Privileged=false, PublishAllPorts=false, ReadonlyRootfs=false, ShmSize=67108864, Resources={CPUShares:0 CgroupParent: BlkioWeight:0 BlkioWeightDevice:[] BlkioDeviceReadBps:[] BlkioDeviceWriteBps:[] BlkioDeviceReadIOps:[] BlkioDeviceWriteIOps:[] CPUPeriod:0 CPUQuota:0 CpusetCpus: CpusetMems: Devices:[] KernelMemory:0 Memory:0 MemoryReservation:0 MemorySwap:0 MemorySwappiness:0xc820720480 OomKillDisable:0xc82072048a PidsLimit:0 Ulimits:[]}}}" Mar 31 11:15:21 yubi docker: time="2016-03-31T11:15:21.992887887-03:00" level=info msg="Config: &{CommonCommand:{ContainerPid:0 ID:4df38bbdb6fef1623710680ce2e4db285c32ad1f5823c447a1e61c19fd351e10 InitPath:/.dockerinit MountLabel:system_u:object_r:svirt_sandbox_file_t:s0:c968,c973 Mounts:[{Source:/var/lib/docker/containers/4df38bbdb6fef1623710680ce2e4db285c32ad1f5823c447a1e61c19fd351e10/secrets Destination:/run/secrets Writable:true Data: Propagation:} {Source:/var/lib/docker/containers/4df38bbdb6fef1623710680ce2e4db285c32ad1f5823c447a1e61c19fd351e10/resolv.conf Destination:/etc/resolv.conf Writable:true Data: Propagation:rprivate} {Source:/var/lib/docker/containers/4df38bbdb6fef1623710680ce2e4db285c32ad1f5823c447a1e61c19fd351e10/hostname Destination:/etc/hostname Writable:true Data: Propagation:rprivate} {Source:/var/lib/docker/containers/4df38bbdb6fef1623710680ce2e4db285c32ad1f5823c447a1e61c19fd351e10/hosts Destination:/etc/hosts Writable:true Data: Propagation:rprivate} {Source:/var/lib/docker/containers/4df38bbdb6fef1623710680ce2e4db285c32ad1f5823c447a1e61c19fd351e10/shm Destination:/dev/shm Writable:true Data: Propagation:rprivate}] Network:0xc8213ed830 ProcessConfig:{CommonProcessConfig:{Cmd:{Path: Args:[] Env:[PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin HOSTNAME=4df38bbdb6fe TERM=xterm] Dir: Stdin:<nil> Stdout:<nil> Stderr:<nil> ExtraFiles:[] SysProcAttr:0xc8200f1580 Process:<nil> ProcessState:<nil> lookPathErr:<nil> finished:false childFiles:[] closeAfterStart:[] closeAfterWait:[] goroutine:[] errch:<nil>} Tty:true Entrypoint:/bin/bash Arguments:[] Terminal:<nil>} Privileged:false User: Console:} ProcessLabel:system_u:system_r:svirt_lxc_net_t:s0:c968,c973 Resources:0xc820a4d400 Rootfs:/var/lib/docker/devicemapper/mnt/27a4dcf2c2b8cdb4f03ef74e74aa4ee86e3323192ef56a3bdb5a20541791f067/rootfs WorkingDir: TmpDir:/var/lib/docker/tmp/4df38bbdb6fef1623710680ce2e4db285c32ad1f5823c447a1e61c19fd351e10108355879 ContainerJSONPath:/var/lib/docker/containers/4df38bbdb6fef1623710680ce2e4db285c32ad1f5823c447a1e61c19fd351e10/config Mar 31 11:15:21 yubi docker: .v2.json} AllowedDevices:[0xc820076a50 0xc820076aa0 0xc820076af0 0xc820076b40 0xc820076b90 0xc820076be0 0xc820076c30 0xc820076c80 0x214aea0 0x214af00 0x214af60 0x214afc0 0x214b020 0x214b080] AppArmorProfile: AutoCreatedDevices:[0xc820076cd0 0x214aea0 0x214af00 0x214af60 0x214afc0 0x214b020 0x214b080] CapAdd:[] CapDrop:[] CgroupParent:system.slice GIDMapping:[] GroupAdd:[] Ipc:0xc820e35c80 OomScoreAdj:0 Pid:0xc820e2b319 ReadonlyRootfs:false RemappedRoot:0xc820e2b320 SeccompProfile: UIDMapping:[] UTS:0xc820e2b31a}" Mar 31 11:15:22 yubi docker: time="2016-03-31T11:15:22.094914722-03:00" level=warning msg="signal: killed" Mar 31 11:15:22 yubi docker: time="2016-03-31T11:15:22.201612835-03:00" level=error msg="error locating sandbox id 7a932c6b9cc1e8e48aed25f134e2af6b52bb4d61b8a75dc4b818ada055d621b6: sandbox 7a932c6b9cc1e8e48aed25f134e2af6b52bb4d61b8a75dc4b818ada055d621b6 not found" Mar 31 11:15:22 yubi docker: time="2016-03-31T11:15:22.201657199-03:00" level=warning msg="failed to cleanup ipc mounts:\nfailed to umount /var/lib/docker/containers/4df38bbdb6fef1623710680ce2e4db285c32ad1f5823c447a1e61c19fd351e10/shm: invalid argument" Mar 31 11:15:22 yubi docker: time="2016-03-31T11:15:22.201676781-03:00" level=error msg="Error unmounting container 4df38bbdb6fef1623710680ce2e4db285c32ad1f5823c447a1e61c19fd351e10: not mounted" Mar 31 11:15:22 yubi docker: time="2016-03-31T11:15:22.201792841-03:00" level=error msg="Handler for POST /v1.22/containers/4df38bbdb6fef1623710680ce2e4db285c32ad1f5823c447a1e61c19fd351e10/start returned error: Cannot start container 4df38bbdb6fef1623710680ce2e4db285c32ad1f5823c447a1e61c19fd351e10: [9] System error: exit status 1"
How are you running your docker daemon. What does the docker daemon CLI look like?
# systemctl stop docker # systemctl status docker ● docker.service - Docker Application Container Engine Loaded: loaded (/usr/lib/systemd/system/docker.service; enabled; vendor preset: disabled) Active: inactive (dead) since Thu 2016-03-31 13:07:11 BRT; 7s ago Docs: http://docs.docker.com Process: 1352 ExecStart=/usr/bin/docker daemon --exec-opt native.cgroupdriver=systemd $OPTIONS $DOCKER_STORAGE_OPTIONS $DOCKER_NETWORK_OPTIONS $INSECURE_REGISTRY (code=exited, status=0/SUCCESS) Main PID: 1352 (code=exited, status=0/SUCCESS) Mar 31 11:36:51 yubi docker[1352]: time="2016-03-31T11:36:51.147789955-03:00" level=info msg="Loading containers: start." Mar 31 11:36:51 yubi docker[1352]: .... Mar 31 11:36:51 yubi docker[1352]: time="2016-03-31T11:36:51.154899118-03:00" level=info msg="Loading containers: done." Mar 31 11:36:51 yubi docker[1352]: time="2016-03-31T11:36:51.154926145-03:00" level=info msg="Daemon has completed initialization" Mar 31 11:36:51 yubi docker[1352]: time="2016-03-31T11:36:51.154948896-03:00" level=info msg="Docker daemon" commit="f8a9a2a/1.10.3" execdriver=native-0.2 graphdriver=devicemapper version=1.10.3 Mar 31 11:36:51 yubi systemd[1]: Started Docker Application Container Engine. Mar 31 11:36:51 yubi docker[1352]: time="2016-03-31T11:36:51.162834561-03:00" level=info msg="API listen on /var/run/docker.sock" Mar 31 13:07:11 yubi systemd[1]: Stopping Docker Application Container Engine... Mar 31 13:07:11 yubi docker[1352]: time="2016-03-31T13:07:11.351793814-03:00" level=info msg="Processing signal 'terminated'" Mar 31 13:07:11 yubi systemd[1]: Stopped Docker Application Container Engine. # systemctl start docker # systemctl status docker ● docker.service - Docker Application Container Engine Loaded: loaded (/usr/lib/systemd/system/docker.service; enabled; vendor preset: disabled) Active: active (running) since Thu 2016-03-31 13:07:27 BRT; 1s ago Docs: http://docs.docker.com Main PID: 5578 (docker) Tasks: 10 (limit: 512) CGroup: /system.slice/docker.service └─5578 /usr/bin/docker daemon --exec-opt native.cgroupdriver=systemd --selinux-enabled --log-driver=journald Mar 31 13:07:26 yubi docker[5578]: time="2016-03-31T13:07:26.884341751-03:00" level=info msg="Graph migration to content-addressability took 0.00 seconds" Mar 31 13:07:26 yubi docker[5578]: time="2016-03-31T13:07:26.892924433-03:00" level=info msg="Firewalld running: true" Mar 31 13:07:26 yubi docker[5578]: time="2016-03-31T13:07:26.973609255-03:00" level=info msg="Default bridge (docker0) is assigned with an IP address 172.17.0.0/16. Daemon option --bip can be used to set a preferred IP address" Mar 31 13:07:27 yubi docker[5578]: time="2016-03-31T13:07:27.064291995-03:00" level=info msg="Loading containers: start." Mar 31 13:07:27 yubi docker[5578]: .... Mar 31 13:07:27 yubi docker[5578]: time="2016-03-31T13:07:27.065781819-03:00" level=info msg="Loading containers: done." Mar 31 13:07:27 yubi docker[5578]: time="2016-03-31T13:07:27.065803349-03:00" level=info msg="Daemon has completed initialization" Mar 31 13:07:27 yubi docker[5578]: time="2016-03-31T13:07:27.065816320-03:00" level=info msg="Docker daemon" commit="f8a9a2a/1.10.3" execdriver=native-0.2 graphdriver=devicemapper version=1.10.3 Mar 31 13:07:27 yubi systemd[1]: Started Docker Application Container Engine. Mar 31 13:07:27 yubi docker[5578]: time="2016-03-31T13:07:27.071047939-03:00" level=info msg="API listen on /var/run/docker.sock" # ps auxf | grep docker root 5662 0.0 0.0 117188 884 pts/1 S+ 13:07 0:00 | | \_ grep --color=auto docker root 5578 0.3 0.1 492924 32556 ? Ssl 13:07 0:00 /usr/bin/docker daemon --exec-opt native.cgroupdriver=systemd --selinux-enabled --log-driver=journald # cat /etc/sysconfig/docker | egrep -v '^#' | uniq OPTIONS='--selinux-enabled --log-driver=journald' DOCKER_CERT_PATH=/etc/docker # getenforce Permissive # docker info Containers: 5 Running: 0 Paused: 0 Stopped: 5 Images: 1 Server Version: 1.10.3 Storage Driver: devicemapper Pool Name: docker-253:0-1179774-pool Pool Blocksize: 65.54 kB Base Device Size: 10.74 GB Backing Filesystem: xfs Data file: /dev/loop0 Metadata file: /dev/loop1 Data Space Used: 272.7 MB Data Space Total: 107.4 GB Data Space Available: 68.17 GB Metadata Space Used: 913.4 kB Metadata Space Total: 2.147 GB Metadata Space Available: 2.147 GB Udev Sync Supported: true Deferred Removal Enabled: false Deferred Deletion Enabled: false Deferred Deleted Device Count: 0 Data loop file: /var/lib/docker/devicemapper/devicemapper/data WARNING: Usage of loopback devices is strongly discouraged for production use. Either use `--storage-opt dm.thinpooldev` or use `--storage-opt dm.no_warn_on_loop_devices=true` to suppress this warning. Metadata loop file: /var/lib/docker/devicemapper/devicemapper/metadata Library Version: 1.02.117 (2016-02-21) Execution Driver: native-0.2 Logging Driver: journald Plugins: Volume: local Network: bridge null host Kernel Version: 4.5.0-0.rc7.git0.2.fc24.x86_64 Operating System: Fedora 24 (Twenty Four) OSType: linux Architecture: x86_64 Number of Docker Hooks: 1 CPUs: 4 Total Memory: 15.59 GiB Name: yubi ID: 2QAH:A3X4:O2II:CSVY:ZIJU:4GBL:3IJI:V7DG:CWRP:H3TA:F5NW:32U2 Registries: docker.io (secure)
Created attachment 1142297 [details] `strace -ff -p $daemon_pid` followed by `docker run`
Installed F24 Alpha on a VirtualBox VM running on the same host and I cannot reproduce it. This machine was installed from F23 and upgraded a few weeks ago to F24 after it was branched. It's a pretty boring setup so I'm wondering if other users will have issues upgrading. I thought cleaning all of Docker's config and state directories should help but no luck. So it may not be an issue for fresh installs but for upgrades. Please let me know what other information would be useful to capture.
Vivek do you see anything obvious? Giovani, if you just run docker daemon --selinux-enabled --log-driver=journald Can you start a container?
Created attachment 1142315 [details] output from running `docker daemon` and trying to start container
It has got to be something in your configuration. You have tried other containers, and you attempted to rm -rf /var/lib/docker?
Fortunately, that seems true. I installed F23, upgraded to F24 alpha using DNF (got Docker 1.10.2), containers worked. Upgraded to Docker 1.10.3, containers worked. I'll keep digging and hopefully find out what's happening here, although I have nothing special in my configuration (I did erase all of /etc/docker, /etc/sysconfig/docker*, /var/lib/docker, /var/run/docker and reinstalled the packages many times). Thank you!
Also try to run a --privileged container.
Privileged containers are working fine on the F24 VM. I remember when using 1.10.2 on the host, that I had removed Docker, cleared all directories, rebooted, reinstalled 1.10.2 and everything worked again. The first time I saw the issue while running 1.10.3, I tried just the reboot alone without success. I also removed Docker and the directories (but without rebooting), no success either. Just now, I noticed /sys still had a bunch of cgroup files with "docker" in their names... although Docker was not installed and no containers were running. I removed everything again, rebooted (so the entries in /sys were gone), installed Docker 1.10.3, started the daemon and everything is working fine now! Although I would automatically blame it on 'zombie' state in /sys, rebooting before didn't fix the issue. It seems as if the Docker files got in a situation where they were creating cgroups that were broken/bad (and would recreate them after reboots)... but this is just speculation on my part. I'll keep an eye for this issue and let anyone known if I hit it again. Thanks again for all the help. I think this BZ could be closed as NOTABUG.
That is wierd. Stuff in /sys should not persist across a reboot. Something in systemd might have been recreating them?
Hit the same bug after upgrading F23 to F24. I had to manually remove docker-engine and install the package docker and docker-selinux . I haven't deleted any directories yet. Privileged containers work fine. But underprivileged containers don't. ~ ❯❯❯ docker run -it ubuntu bash permission denied docker: Error response from daemon: Container command could not be invoked.. journalctl says: Jul 04 11:30:35 lenovo docker[5541]: time="2016-07-04T11:30:35.916252143+05:30" level=error msg="error locating sandbox id c57bda4ad7f0349767a64d4f26cc10fc83c261ae25662473b1f9e582c80bab2f: sandbox c57bda4ad7f0349767a64d4f26cc10fc83c261ae25662473b1f9e582c80bab2f not found" Jul 04 11:30:35 lenovo docker[5541]: time="2016-07-04T11:30:35.916315973+05:30" level=warning msg="failed to cleanup ipc mounts:\nfailed to umount /var/lib/docker/containers/4e8d1fbfecf9e97220294aa58cc1d07e197859be12af0f67097c49003c4a316f/shm: invalid argument" Jul 04 11:30:35 lenovo docker[5541]: time="2016-07-04T11:30:35.916344607+05:30" level=error msg="Error unmounting container 4e8d1fbfecf9e97220294aa58cc1d07e197859be12af0f67097c49003c4a316f: not mounted" Jul 04 11:30:35 lenovo docker[5541]: time="2016-07-04T11:30:35.916540317+05:30" level=error msg="Handler for POST /v1.22/containers/4e8d1fbfecf9e97220294aa58cc1d07e197859be12af0f67097c49003c4a316f/start returned error: Container command could not be invoked."
Setting SELinux to permissive mode let's me launch the underprivileged container.
Okay, so I reinstalled docker-selinux package, restarted docker daemon and now everything works as expected. Initially, I had installed docker-selinux and then installed docker 1.10.3. Perhaps the package docker-1.10.3-21.git19b5791.fc24.x86_64 should have been a dependency of docker-selinux-1.10.3-21.git19b5791.fc24.x86_64 ?