Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

1.8.0: Systemd can't start docker on Centos 7.1 #15498

Closed
abierbaum opened this issue Aug 11, 2015 · 127 comments · Fixed by #15832
Closed

1.8.0: Systemd can't start docker on Centos 7.1 #15498

abierbaum opened this issue Aug 11, 2015 · 127 comments · Fixed by #15832
Milestone

Comments

@abierbaum
Copy link

Using the default configuration of the latest docker 1.8.0 release, systemd can't start docker.
Workaround: yum install docker-selinux

Use the commands below to provide key information from your environment:

docker version: 1.8.0-1
docker info: N/A
uname -a: Linux cent7 3.10.0-229.7.2.el7.x86_64 #1 SMP Tue Jun 23 22:06:11 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux

Provide additional environment details (AWS, VirtualBox, physical, etc.):

Reproduction:

[root@cent7 ~]# uname -a
Linux cent7 3.10.0-229.7.2.el7.x86_64 #1 SMP Tue Jun 23 22:06:11 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux
[root@cent7 ~]# rpm -qa | grep docker
[root@cent7 ~]# yum install -y http://yum.dockerproject.org/repo/main/centos/7/Packages/docker-engine-1.8.0-1.el7.centos.x86_64.rpm
Loaded plugins: fastestmirror
docker-engine-1.8.0-1.el7.centos.x86_64.rpm                                                                                            | 6.2 MB  00:00:03     
Examining /var/tmp/yum-root-ctX5iw/docker-engine-1.8.0-1.el7.centos.x86_64.rpm: docker-engine-1.8.0-1.el7.centos.x86_64
Marking /var/tmp/yum-root-ctX5iw/docker-engine-1.8.0-1.el7.centos.x86_64.rpm to be installed
Resolving Dependencies
--> Running transaction check
---> Package docker-engine.x86_64 0:1.8.0-1.el7.centos will be installed
--> Processing Dependency: libcgroup for package: docker-engine-1.8.0-1.el7.centos.x86_64
Loading mirror speeds from cached hostfile
 * base: mirror.evolvedservers.com
 * extras: centos.mbni.med.umich.edu
 * updates: mirror.cc.columbia.edu
--> Running transaction check
---> Package libcgroup.x86_64 0:0.41-8.el7 will be installed
--> Finished Dependency Resolution

Dependencies Resolved

==============================================================================================================================================================
 Package                        Arch                    Version                               Repository                                                 Size
==============================================================================================================================================================
Installing:
 docker-engine                  x86_64                  1.8.0-1.el7.centos                    /docker-engine-1.8.0-1.el7.centos.x86_64                   27 M
Installing for dependencies:
 libcgroup                      x86_64                  0.41-8.el7                            base                                                       64 k

Transaction Summary
==============================================================================================================================================================
Install  1 Package (+1 Dependent package)

Total size: 27 M
Total download size: 64 k
Installed size: 27 M
Downloading packages:
libcgroup-0.41-8.el7.x86_64.rpm                                                                                                    |  64 kB  00:00:15     
Running transaction check
Running transaction test
Transaction test succeeded
Running transaction
  Installing : libcgroup-0.41-8.el7.x86_64                                                                                                            1/2 
  Installing : docker-engine-1.8.0-1.el7.centos.x86_64                                                                                                2/2 
  Verifying  : docker-engine-1.8.0-1.el7.centos.x86_64                                                                                                1/2 
  Verifying  : libcgroup-0.41-8.el7.x86_64                                                                                                            2/2 

Installed:
  docker-engine.x86_64 0:1.8.0-1.el7.centos                                                                                                               

Dependency Installed:
  libcgroup.x86_64 0:0.41-8.el7                                                                                                                           

Complete!

[root@cent7 ~]# systemctl status docker
docker.service - Docker Application Container Engine
   Loaded: loaded (/usr/lib/systemd/system/docker.service; disabled)
   Active: inactive (dead)
     Docs: https://docs.docker.com
[root@cent7 ~]# systemctl start docker
Job for docker.service failed. See 'systemctl status docker.service' and 'journalctl -xn' for details.
[root@cent7 ~]# journalctl -xn
-- Logs begin at Sun 2015-07-12 09:27:56 EDT, end at Sun 2015-07-12 09:34:04 EDT. --
Jul 12 09:32:34 cent7 systemd[1]: Starting Docker Socket for the API.
-- Subject: Unit docker.socket has begun with start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit docker.socket has begun starting up.
Jul 12 09:32:34 cent7 systemd[1]: Listening on Docker Socket for the API.
-- Subject: Unit docker.socket has finished start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit docker.socket has finished starting up.
-- 
-- The start-up result is done.
Jul 12 09:32:34 cent7 systemd[1]: Starting Docker Application Container Engine...
-- Subject: Unit docker.service has begun with start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit docker.service has begun starting up.
Jul 12 09:32:34 cent7 kernel: loop: module loaded
Jul 12 09:32:40 cent7 docker[2603]: time="2015-07-12T09:32:40.871943813-04:00" level=info msg="Option DefaultDriver: bridge"
Jul 12 09:32:40 cent7 docker[2603]: time="2015-07-12T09:32:40.872733230-04:00" level=info msg="Option DefaultNetwork: bridge"
Jul 12 09:32:40 cent7 docker[2603]: time="2015-07-12T09:32:40.896696252-04:00" level=warning msg="Running modprobe bridge nf_nat br_netfilter failed with messag
Jul 12 09:34:04 cent7 systemd[1]: docker.service operation timed out. Terminating.
Jul 12 09:34:04 cent7 systemd[1]: Failed to start Docker Application Container Engine.
-- Subject: Unit docker.service has failed
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit docker.service has failed.
-- 
-- The result is failed.
Jul 12 09:34:04 cent7 systemd[1]: Unit docker.service entered failed state.

Expected to see docker package install correctly by default and allow using systemd to startup docker on the machine.

This is running inside a fresh install of Centos 7.1 inside virtualbox. Docker 1.7.1 works with no issue.

@thaJeztah
Copy link
Member

ping @jfrazelle

@jessfraz
Copy link
Contributor

it looks like the daemon failed to start w something about the bridge ping @mavenugo @mrjana

@jessfraz
Copy link
Contributor

did you do an yum update before

@jessfraz
Copy link
Contributor

I cant reproduce on a centos 7 machine I want to say it has something to do with kernel config

@jessfraz
Copy link
Contributor

@mrjana
Copy link
Contributor

mrjana commented Aug 12, 2015

@jfrazelle You can ignore the bridge modprobe failure message. That will be printed if the bridge module is compiled into the kernel rather than as a module. We should rather check the docker logs.

@jessfraz
Copy link
Contributor

Those were the logs :/

On Aug 11, 2015, at 17:21, Jana Radhakrishnan notifications@github.com wrote:

@jfrazelle You can ignore the bridge modprobe failure message. That will be printed if the bridge module is compiled into the kernel rather than as a module. We should rather check the docker logs.


Reply to this email directly or view it on GitHub.

@abierbaum
Copy link
Author

@jfrazelle I just ran check config and yum update.

[root@cent7 ~]# ./check-config.sh 
warning: /proc/config.gz does not exist, searching other paths for kernel config ...
info: reading kernel config from /boot/config-3.10.0-229.7.2.el7.x86_64 ...

Generally Necessary:
- cgroup hierarchy: properly mounted [/sys/fs/cgroup]
- CONFIG_NAMESPACES: enabled
- CONFIG_NET_NS: enabled
- CONFIG_PID_NS: enabled
- CONFIG_IPC_NS: enabled
- CONFIG_UTS_NS: enabled
- CONFIG_DEVPTS_MULTIPLE_INSTANCES: enabled
- CONFIG_CGROUPS: enabled
- CONFIG_CGROUP_CPUACCT: enabled
- CONFIG_CGROUP_DEVICE: enabled
- CONFIG_CGROUP_FREEZER: enabled
- CONFIG_CGROUP_SCHED: enabled
- CONFIG_CPUSETS: enabled
- CONFIG_MEMCG: enabled
- CONFIG_MACVLAN: enabled (as module)
- CONFIG_VETH: enabled (as module)
- CONFIG_BRIDGE: enabled (as module)
- CONFIG_BRIDGE_NETFILTER: enabled
- CONFIG_NF_NAT_IPV4: enabled (as module)
- CONFIG_IP_NF_FILTER: enabled (as module)
- CONFIG_IP_NF_TARGET_MASQUERADE: enabled (as module)
- CONFIG_NETFILTER_XT_MATCH_ADDRTYPE: enabled (as module)
- CONFIG_NETFILTER_XT_MATCH_CONNTRACK: enabled (as module)
- CONFIG_NF_NAT: enabled (as module)
- CONFIG_NF_NAT_NEEDED: enabled
- CONFIG_POSIX_MQUEUE: enabled

Optional Features:
- CONFIG_MEMCG_KMEM: enabled
- CONFIG_MEMCG_SWAP: enabled
- CONFIG_MEMCG_SWAP_ENABLED: enabled
- CONFIG_RESOURCE_COUNTERS: enabled
- CONFIG_BLK_CGROUP: enabled
- CONFIG_IOSCHED_CFQ: enabled
- CONFIG_CGROUP_PERF: enabled
- CONFIG_CGROUP_HUGETLB: enabled
- CONFIG_NET_CLS_CGROUP: enabled
- CONFIG_NETPRIO_CGROUP: enabled (as module)
- CONFIG_CFS_BANDWIDTH: enabled
- CONFIG_FAIR_GROUP_SCHED: enabled
- CONFIG_RT_GROUP_SCHED: enabled
- CONFIG_EXT3_FS: missing
- CONFIG_EXT3_FS_XATTR: missing
- CONFIG_EXT3_FS_POSIX_ACL: missing
- CONFIG_EXT3_FS_SECURITY: missing
    (enable these ext3 configs if you are using ext3 as backing filesystem)
- CONFIG_EXT4_FS: enabled (as module)
- CONFIG_EXT4_FS_POSIX_ACL: enabled
- CONFIG_EXT4_FS_SECURITY: enabled
- Storage Drivers:
  - "aufs":
    - CONFIG_AUFS_FS: missing
  - "btrfs":
    - CONFIG_BTRFS_FS: enabled (as module)
  - "devicemapper":
    - CONFIG_BLK_DEV_DM: enabled (as module)
    - CONFIG_DM_THIN_PROVISIONING: enabled (as module)
  - "overlay":
    - CONFIG_OVERLAY_FS: enabled (as module)
  - "zfs":
    - /dev/zfs: missing
    - zfs command: missing
    - zpool command: missing

[root@cent7 ~]# yum update
Loaded plugins: fastestmirror
Loading mirror speeds from cached hostfile
 * base: mirror.lug.udel.edu
 * extras: centos.mbni.med.umich.edu
 * updates: mirror.cc.columbia.edu
No packages marked for update
[root@cent7 ~]#  uname -a
Linux cent7 3.10.0-229.7.2.el7.x86_64 #1 SMP Tue Jun 23 22:06:11 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux
[root@cent7 ~]# cat /etc/redhat-release 
CentOS Linux release 7.1.1503 (Core) 

Anything else I can try to help collect more information to debug this? (in the morning I could try the same reproduction on a couple of cloud hosts to see how it works out)

@abierbaum
Copy link
Author

I just tried the same reproduction on a DigitalOcean RH7 droplet and docker worked fine.

Everything looks good there.

uname -a: Linux rh7test 3.10.0-123.8.1.el7.x86_64 #1 SMP Mon Sep 22 19:06:58 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux

Still trying to determine why running in centos 7 minimal with updates inside of a virtualbox is failing.

@KalleDK
Copy link

KalleDK commented Aug 12, 2015

Same problem with centos 7 inside VMware Player

Centos 7 minimal install

uname -a
Linux cento7 3.10.0-229.11.1.el7.x86_64 #1 SMP Thu Aug 6 01:06:18 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux
yum update
yum install git
curl -sSL https://get.docker.com/ -# | sh

Logs

[root@cento ~]# curl -sSL https://raw.githubusercontent.com/docker/docker/master/contrib/check-config.sh > check-config.sh
[root@cento ~]# chmod +x check-config.sh
[root@cento ~]# ./check-config.sh
warning: /proc/config.gz does not exist, searching other paths for kernel config ...
info: reading kernel config from /boot/config-3.10.0-229.11.1.el7.x86_64 ...

Generally Necessary:
- cgroup hierarchy: properly mounted [/sys/fs/cgroup]
- CONFIG_NAMESPACES: enabled
- CONFIG_NET_NS: enabled
- CONFIG_PID_NS: enabled
- CONFIG_IPC_NS: enabled
- CONFIG_UTS_NS: enabled
- CONFIG_DEVPTS_MULTIPLE_INSTANCES: enabled
- CONFIG_CGROUPS: enabled
- CONFIG_CGROUP_CPUACCT: enabled
- CONFIG_CGROUP_DEVICE: enabled
- CONFIG_CGROUP_FREEZER: enabled
- CONFIG_CGROUP_SCHED: enabled
- CONFIG_CPUSETS: enabled
- CONFIG_MEMCG: enabled
- CONFIG_MACVLAN: enabled (as module)
- CONFIG_VETH: enabled (as module)
- CONFIG_BRIDGE: enabled (as module)
- CONFIG_BRIDGE_NETFILTER: enabled
- CONFIG_NF_NAT_IPV4: enabled (as module)
- CONFIG_IP_NF_FILTER: enabled (as module)
- CONFIG_IP_NF_TARGET_MASQUERADE: enabled (as module)
- CONFIG_NETFILTER_XT_MATCH_ADDRTYPE: enabled (as module)
- CONFIG_NETFILTER_XT_MATCH_CONNTRACK: enabled (as module)
- CONFIG_NF_NAT: enabled (as module)
- CONFIG_NF_NAT_NEEDED: enabled
- CONFIG_POSIX_MQUEUE: enabled

Optional Features:
- CONFIG_MEMCG_KMEM: enabled
- CONFIG_MEMCG_SWAP: enabled
- CONFIG_MEMCG_SWAP_ENABLED: enabled
- CONFIG_RESOURCE_COUNTERS: enabled
- CONFIG_BLK_CGROUP: enabled
- CONFIG_IOSCHED_CFQ: enabled
- CONFIG_CGROUP_PERF: enabled
- CONFIG_CGROUP_HUGETLB: enabled
- CONFIG_NET_CLS_CGROUP: enabled
- CONFIG_NETPRIO_CGROUP: enabled (as module)
- CONFIG_CFS_BANDWIDTH: enabled
- CONFIG_FAIR_GROUP_SCHED: enabled
- CONFIG_RT_GROUP_SCHED: enabled
- CONFIG_EXT3_FS: missing
- CONFIG_EXT3_FS_XATTR: missing
- CONFIG_EXT3_FS_POSIX_ACL: missing
- CONFIG_EXT3_FS_SECURITY: missing
    (enable these ext3 configs if you are using ext3 as backing filesystem)
- CONFIG_EXT4_FS: enabled (as module)
- CONFIG_EXT4_FS_POSIX_ACL: enabled
- CONFIG_EXT4_FS_SECURITY: enabled
- Storage Drivers:
  - "aufs":
    - CONFIG_AUFS_FS: missing
  - "btrfs":
    - CONFIG_BTRFS_FS: enabled (as module)
  - "devicemapper":
    - CONFIG_BLK_DEV_DM: enabled (as module)
    - CONFIG_DM_THIN_PROVISIONING: enabled (as module)
  - "overlay":
    - CONFIG_OVERLAY_FS: enabled (as module)
  - "zfs":
    - /dev/zfs: missing
    - zfs command: missing
    - zpool command: missing

@abierbaum
Copy link
Author

When I run docker daemon directly from the command line I have no issue:

[root@cent7 ~]# docker daemon
INFO[0000] Listening for HTTP on unix (/var/run/docker.sock) 
INFO[0000] [graphdriver] using prior storage driver "devicemapper" 
INFO[0000] Option DefaultDriver: bridge                 
INFO[0000] Option DefaultNetwork: bridge                
WARN[0000] Running modprobe bridge nf_nat br_netfilter failed with message: modprobe: WARNING: Module br_netfilter not found.
, error: exit status 1 
INFO[0000] Firewalld running: true                      
INFO[0000] Loading containers: start.                   

INFO[0000] Loading containers: done.                    
INFO[0000] Daemon has completed initialization          
INFO[0000] Docker daemon                                 commit=0d03096 execdriver=native-0.2 graphdriver=devicemapper version=1.8.0

I added the -D debug option to the options passed through systemd, but I can't find where the additional output is going. Anyone with more experience with systemd that can point me in the right direction to provide additional details?

@KalleDK
Copy link

KalleDK commented Aug 12, 2015

My guess is firewall rules

Installed:
  docker-engine.x86_64 0:1.8.0-1.el7.centos

Complete!
[root@cento ~]# service firewalld stop
Redirecting to /bin/systemctl stop  firewalld.service
[root@cento ~]# service docker start
Starting docker (via systemctl):                           [  OK  ]
[root@cento ~]#

[root@cento log]# cat firewalld
2015-08-12 15:35:34 WARNING: iptables not usable, disabling IPv4 firewall.

@KalleDK
Copy link

KalleDK commented Aug 12, 2015

I can have firewalld running and then start the docker service one time now.. but it will fail if i restart it

[root@cento log]# service firewalld stop
Redirecting to /bin/systemctl stop  firewalld.service
[root@cento log]# systemctl daemon-reload
[root@cento log]# service firewalld start
Redirecting to /bin/systemctl start  firewalld.service
[root@cento log]# service docker start
Starting docker (via systemctl):                           [  OK  ]
[root@cento log]# service docker stop
Stopping docker (via systemctl):                           [  OK  ]
[root@cento log]# service docker start
Starting docker (via systemctl):  ^C
Fail

@abierbaum
Copy link
Author

I have verified that I can systemctl start docker on both a softlayer instance and a digitalocean instance. It will run even if firewalld is also running.

When running inside a virtualbox VM though:

  • Docker service fails to run if firewalld is running
  • Docker service runs fine if firewalld is stopped

I am still trying to collect more details and will post them here when I get them. In the meantime the only thing I can think of is that the VM I am using has multiple network interfaces configured (one bridged and one host-only), maybe that is causing some of the issue.

When running systemctl start docker with the "-D" option send to the daemon, this is the output from journalctl --unit=docker after a fresh install and start.

[root@cent7 ~]# journalctl --unit=docker
-- Logs begin at Sun 2015-07-12 09:27:56 EDT, end at Sun 2015-07-12 09:33:09 EDT. --
Jul 12 09:31:39 cent7 systemd[1]: Starting Docker Application Container Engine...
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.156651676-04:00" level=debug msg="Registering POST, /containers/{name:.*}/wait"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.157097337-04:00" level=debug msg="Registering POST, /containers/{name:.*}/attach"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.157270408-04:00" level=debug msg="Registering POST, /containers/{name:.*}/copy"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.157457427-04:00" level=debug msg="Registering POST, /containers/{name:.*}/exec"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.157650664-04:00" level=debug msg="Registering POST, /exec/{name:.*}/start"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.157832599-04:00" level=debug msg="Registering POST, /auth"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.157945893-04:00" level=debug msg="Registering POST, /build"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.158055445-04:00" level=debug msg="Registering POST, /images/load"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.158176852-04:00" level=debug msg="Registering POST, /images/{name:.*}/push"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.158390535-04:00" level=debug msg="Registering POST, /images/{name:.*}/tag"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.158554996-04:00" level=debug msg="Registering POST, /containers/{name:.*}/pause"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.158731636-04:00" level=debug msg="Registering POST, /containers/{name:.*}/rename"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.159037126-04:00" level=debug msg="Registering POST, /commit"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.160310382-04:00" level=debug msg="Registering POST, /images/create"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.160425682-04:00" level=debug msg="Registering POST, /exec/{name:.*}/resize"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.160561889-04:00" level=debug msg="Registering POST, /containers/{name:.*}/unpause"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.160819377-04:00" level=debug msg="Registering POST, /containers/{name:.*}/restart"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.161038621-04:00" level=debug msg="Registering POST, /containers/{name:.*}/start"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.161191205-04:00" level=debug msg="Registering POST, /containers/{name:.*}/stop"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.161325266-04:00" level=debug msg="Registering POST, /containers/{name:.*}/resize"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.161487803-04:00" level=debug msg="Registering POST, /containers/create"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.161611652-04:00" level=debug msg="Registering POST, /containers/{name:.*}/kill"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.161870425-04:00" level=debug msg="Registering PUT, /containers/{name:.*}/archive"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.162036512-04:00" level=debug msg="Registering DELETE, /containers/{name:.*}"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.162232696-04:00" level=debug msg="Registering DELETE, /images/{name:.*}"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.162381655-04:00" level=debug msg="Registering OPTIONS, "
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.162403718-04:00" level=debug msg="Registering HEAD, /containers/{name:.*}/archive"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.162587523-04:00" level=debug msg="Registering GET, /images/get"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.162692701-04:00" level=debug msg="Registering GET, /images/{name:.*}/get"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.162929255-04:00" level=debug msg="Registering GET, /images/{name:.*}/history"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.163080909-04:00" level=debug msg="Registering GET, /containers/json"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.163210966-04:00" level=debug msg="Registering GET, /containers/{name:.*}/export"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.163387320-04:00" level=debug msg="Registering GET, /containers/{name:.*}/json"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.163538585-04:00" level=debug msg="Registering GET, /events"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.163649548-04:00" level=debug msg="Registering GET, /images/search"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.163747586-04:00" level=debug msg="Registering GET, /containers/{name:.*}/archive"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.166128998-04:00" level=debug msg="Registering GET, /containers/{name:.*}/logs"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.166265922-04:00" level=debug msg="Registering GET, /containers/{name:.*}/stats"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.166399473-04:00" level=debug msg="Registering GET, /exec/{id:.*}/json"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.166516561-04:00" level=debug msg="Registering GET, /info"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.166597340-04:00" level=debug msg="Registering GET, /containers/{name:.*}/top"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.166917942-04:00" level=debug msg="Registering GET, /images/{name:.*}/json"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.167038751-04:00" level=debug msg="Registering GET, /containers/{name:.*}/attach/ws"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.167211266-04:00" level=debug msg="Registering GET, /_ping"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.167303479-04:00" level=debug msg="Registering GET, /images/json"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.167391986-04:00" level=debug msg="Registering GET, /containers/{name:.*}/changes"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.167546694-04:00" level=debug msg="Registering GET, /version"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.167637206-04:00" level=debug msg="Registering GET, /containers/ps"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.175458833-04:00" level=debug msg="[zfs] zfs command is not available: exec: \"zfs\": executable file not found in $PATH"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.177909273-04:00" level=debug msg="devicemapper: driver version is 4.29.0"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.178716443-04:00" level=debug msg="Generated prefix: docker-253:0-25806612"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.178849825-04:00" level=debug msg="Checking for existence of the pool 'docker-253:0-25806612-pool'"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.179127154-04:00" level=debug msg="Pool doesn't exist. Creating it."
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.179210298-04:00" level=debug msg="Creating loopback file /var/lib/docker/devicemapper/devicemapper/data for device-manage use"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.194921345-04:00" level=debug msg="Creating loopback file /var/lib/docker/devicemapper/devicemapper/metadata for device-manage use"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.284876481-04:00" level=debug msg="Initializing base device-mapper thin volume"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.287151128-04:00" level=debug msg="[devmapper] CreateDevice(poolName=/dev/mapper/docker-253:0-25806612-pool, deviceId=1)"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.297993226-04:00" level=debug msg="Registering device (id 1) with FS size 107374182400"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.298074973-04:00" level=debug msg="registerDevice(1, )"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.304941672-04:00" level=debug msg="Creating filesystem on base device-mapper thin volume"
Jul 12 09:31:39 cent7 docker[2615]: time="2015-07-12T09:31:39.305006026-04:00" level=debug msg="activateDeviceIfNeeded()"
Jul 12 09:31:45 cent7 docker[2615]: time="2015-07-12T09:31:45.241468012-04:00" level=debug msg="activateDeviceIfNeeded()"
Jul 12 09:31:45 cent7 docker[2615]: time="2015-07-12T09:31:45.282646583-04:00" level=debug msg="UUID for device: /dev/mapper/docker-253:0-25806612-base is:34c1090e-618f-4c87-aec3-538c8126cf31"
Jul 12 09:31:45 cent7 docker[2615]: time="2015-07-12T09:31:45.287904728-04:00" level=debug msg="[devmapper] deactivateDevice()"
Jul 12 09:31:45 cent7 docker[2615]: time="2015-07-12T09:31:45.291703185-04:00" level=debug msg="[devmapper] removeDevice START(docker-253:0-25806612-base)"
Jul 12 09:31:45 cent7 docker[2615]: time="2015-07-12T09:31:45.320139142-04:00" level=debug msg="[devmapper] removeDevice END(docker-253:0-25806612-base)"
Jul 12 09:31:45 cent7 docker[2615]: time="2015-07-12T09:31:45.320187455-04:00" level=debug msg="[devmapper] deactivateDevice END()"
Jul 12 09:31:45 cent7 docker[2615]: time="2015-07-12T09:31:45.325096430-04:00" level=debug msg="Using graph driver devicemapper"
Jul 12 09:31:45 cent7 docker[2615]: time="2015-07-12T09:31:45.325145999-04:00" level=debug msg="Using default logging driver json-file"
Jul 12 09:31:45 cent7 docker[2615]: time="2015-07-12T09:31:45.329322694-04:00" level=debug msg="Creating images graph"
Jul 12 09:31:45 cent7 docker[2615]: time="2015-07-12T09:31:45.332252629-04:00" level=debug msg="Restored 0 elements"
Jul 12 09:31:45 cent7 docker[2615]: time="2015-07-12T09:31:45.338474243-04:00" level=debug msg="Creating repository list"
Jul 12 09:31:45 cent7 docker[2615]: time="2015-07-12T09:31:45.338616554-04:00" level=info msg="Option DefaultDriver: bridge"
Jul 12 09:31:45 cent7 docker[2615]: time="2015-07-12T09:31:45.338650426-04:00" level=info msg="Option DefaultNetwork: bridge"
Jul 12 09:31:45 cent7 docker[2615]: time="2015-07-12T09:31:45.363185154-04:00" level=warning msg="Running modprobe bridge nf_nat br_netfilter failed with message: modprobe: WARNING: Module br_netfilter not found.\n, error: exit status 1"
Jul 12 09:33:09 cent7 systemd[1]: docker.service operation timed out. Terminating.
Jul 12 09:33:09 cent7 systemd[1]: Failed to start Docker Application Container Engine.
Jul 12 09:33:09 cent7 systemd[1]: Unit docker.service entered failed state.

If I stop firewalld, then docker can startup with no problem.

This line in the output looks suspicious to me:

Jul 12 09:31:45 cent7 docker[2615]: time="2015-07-12T09:31:45.363185154-04:00" level=warning msg="Running modprobe bridge nf_nat br_netfilter failed with message: modprobe: WARNING: Module br_netfilter not found.\n, error: exit status 1"

Is there a module or package that I need to have installed in addition to docker in order for it to work with firewalld?

@squeaky-pl
Copy link

I am also affected by this. Docker 1.7 from main repo used to function until I updated today to 1.8. I run Centos 7 minimal install inside virtualbox.

journalctl shows me this:

Aug 12 13:36:02 elena systemd[1]: Starting Docker Application Container Engine...
Aug 12 13:36:02 elena docker[3176]: time="2015-08-12T13:36:02.265776221Z" level=info msg="[graphdriver] using prior storage driver 
Aug 12 13:36:02 elena docker[3176]: time="2015-08-12T13:36:02.266449050Z" level=info msg="Option DefaultDriver: bridge"
Aug 12 13:36:02 elena docker[3176]: time="2015-08-12T13:36:02.266473946Z" level=info msg="Option DefaultNetwork: bridge"
Aug 12 13:36:02 elena docker[3176]: time="2015-08-12T13:36:02.274134316Z" level=warning msg="Running modprobe bridge nf_nat br_netf
Aug 12 13:37:32 elena systemd[1]: docker.service operation timed out. Terminating.
Aug 12 13:37:32 elena systemd[1]: Failed to start Docker Application Container Engine.
Aug 12 13:37:32 elena systemd[1]: Unit docker.service entered failed state.

however if i stop the firewall

systemctl stop firewalld

I can start Docker daemon without problems

@mavenugo
Copy link
Contributor

@abierbaum @squeaky-pl @KalleDK As a quick check, can you enable debugs (-D) and restart the docker-service ?

  1. Modify ExecStart=/usr/bin/docker daemon -D -H fd:// inside /lib/systemd/system/docker.service
  2. systemctl daemon-reload
  3. systemctl restart docker.service
  4. paste the docker related debugs from journalctl

@KalleDK
Copy link

KalleDK commented Aug 12, 2015

Aug 12 16:21:58 cento systemd: Stopping Docker Socket for the API.
Aug 12 16:21:58 cento systemd: Starting Docker Socket for the API.
Aug 12 16:21:58 cento systemd: Listening on Docker Socket for the API.
Aug 12 16:21:58 cento systemd: Starting Docker Application Container Engine...
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.389888900+02:00" level=debug msg="Registering GET, /images/{name:.*}/json"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.390234716+02:00" level=debug msg="Registering GET, /containers/{name:.*}/export"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.390385271+02:00" level=debug msg="Registering GET, /containers/{name:.*}/changes"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.390529413+02:00" level=debug msg="Registering GET, /containers/{name:.*}/top"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.390683651+02:00" level=debug msg="Registering GET, /exec/{id:.*}/json"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.390755707+02:00" level=debug msg="Registering GET, /events"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.390839491+02:00" level=debug msg="Registering GET, /version"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.390969574+02:00" level=debug msg="Registering GET, /images/json"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.391083034+02:00" level=debug msg="Registering GET, /images/search"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.391189936+02:00" level=debug msg="Registering GET, /images/{name:.*}/get"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.391382880+02:00" level=debug msg="Registering GET, /containers/{name:.*}/logs"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.391489568+02:00" level=debug msg="Registering GET, /containers/{name:.*}/stats"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.391576781+02:00" level=debug msg="Registering GET, /containers/{name:.*}/attach/ws"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.392472190+02:00" level=debug msg="Registering GET, /_ping"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.392565647+02:00" level=debug msg="Registering GET, /info"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.392610351+02:00" level=debug msg="Registering GET, /images/get"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.392659973+02:00" level=debug msg="Registering GET, /images/{name:.*}/history"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.392750797+02:00" level=debug msg="Registering GET, /containers/ps"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.392804030+02:00" level=debug msg="Registering GET, /containers/json"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.392856597+02:00" level=debug msg="Registering GET, /containers/{name:.*}/json"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.392949026+02:00" level=debug msg="Registering GET, /containers/{name:.*}/archive"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.393049305+02:00" level=debug msg="Registering POST, /containers/{name:.*}/unpause"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.393124880+02:00" level=debug msg="Registering POST, /containers/{name:.*}/start"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.393206350+02:00" level=debug msg="Registering POST, /containers/{name:.*}/wait"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.393283700+02:00" level=debug msg="Registering POST, /containers/{name:.*}/exec"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.393358247+02:00" level=debug msg="Registering POST, /images/{name:.*}/tag"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.393463681+02:00" level=debug msg="Registering POST, /images/create"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.393534118+02:00" level=debug msg="Registering POST, /containers/{name:.*}/kill"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.393613609+02:00" level=debug msg="Registering POST, /containers/{name:.*}/stop"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.393691916+02:00" level=debug msg="Registering POST, /containers/{name:.*}/copy"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.393810132+02:00" level=debug msg="Registering POST, /exec/{name:.*}/start"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.393942679+02:00" level=debug msg="Registering POST, /containers/{name:.*}/rename"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.394104129+02:00" level=debug msg="Registering POST, /build"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.394229763+02:00" level=debug msg="Registering POST, /images/load"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.394313592+02:00" level=debug msg="Registering POST, /containers/{name:.*}/restart"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.394436770+02:00" level=debug msg="Registering POST, /containers/{name:.*}/attach"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.395401475+02:00" level=debug msg="Registering POST, /exec/{name:.*}/resize"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.395479718+02:00" level=debug msg="Registering POST, /auth"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.395523706+02:00" level=debug msg="Registering POST, /images/{name:.*}/push"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.395596905+02:00" level=debug msg="Registering POST, /containers/create"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.395655780+02:00" level=debug msg="Registering POST, /containers/{name:.*}/pause"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.395767595+02:00" level=debug msg="Registering POST, /containers/{name:.*}/resize"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.395844440+02:00" level=debug msg="Registering POST, /commit"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.395889219+02:00" level=debug msg="Registering PUT, /containers/{name:.*}/archive"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.396027882+02:00" level=debug msg="Registering DELETE, /containers/{name:.*}"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.396112554+02:00" level=debug msg="Registering DELETE, /images/{name:.*}"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.396181967+02:00" level=debug msg="Registering OPTIONS, "
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.396190326+02:00" level=debug msg="Registering HEAD, /containers/{name:.*}/archive"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.409039204+02:00" level=debug msg="devicemapper: driver version is 4.29.0"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.409485273+02:00" level=debug msg="Generated prefix: docker-253:0-101523106"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.409498048+02:00" level=debug msg="Checking for existence of the pool 'docker-253:0-101523106-pool'"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.409772632+02:00" level=debug msg="[devmapper]: poolDataMajMin=7:0 poolMetaMajMin=7:1\n"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.409957897+02:00" level=debug msg="[devmapper]: Major:Minor for device: /dev/loop0 is:7:0"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.409994957+02:00" level=debug msg="[devmapper]: Major:Minor for device: /dev/loop1 is:7:1"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.415549692+02:00" level=debug msg="[deviceset] constructDeviceIdMap()"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.415597114+02:00" level=debug msg="Loading data for file /var/lib/docker/devicemapper/metadata/base"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.415675955+02:00" level=debug msg="Added deviceId=1 to DeviceIdMap"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.415690310+02:00" level=debug msg="Skipping file /var/lib/docker/devicemapper/metadata/deviceset-metadata"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.415700001+02:00" level=debug msg="Loading data for file /var/lib/docker/devicemapper/metadata/transaction-metadata"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.415725659+02:00" level=debug msg="Added deviceId=1 to DeviceIdMap"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.415732972+02:00" level=debug msg="[deviceset] constructDeviceIdMap() END"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.415795458+02:00" level=debug msg="activateDeviceIfNeeded()"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.444917456+02:00" level=debug msg="UUID for device: /dev/mapper/docker-253:0-101523106-base is:3567736f-942a-481a-b3f0-01384949b1a6"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.445206716+02:00" level=debug msg="[devmapper] deactivateDevice()"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.445269799+02:00" level=debug msg="[devmapper] removeDevice START(docker-253:0-101523106-base)"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.451747488+02:00" level=debug msg="[devmapper] removeDevice END(docker-253:0-101523106-base)"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.451778740+02:00" level=debug msg="[devmapper] deactivateDevice END()"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.452875345+02:00" level=info msg="[graphdriver] using prior storage driver \"devicemapper\""
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.452895298+02:00" level=debug msg="Using graph driver devicemapper"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.452906970+02:00" level=debug msg="Using default logging driver json-file"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.452921170+02:00" level=debug msg="Creating images graph"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.452976205+02:00" level=debug msg="Restored 0 elements"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.453188756+02:00" level=debug msg="Creating repository list"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.453263521+02:00" level=info msg="Option DefaultDriver: bridge"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.453273499+02:00" level=info msg="Option DefaultNetwork: bridge"
Aug 12 16:21:58 cento docker: time="2015-08-12T16:21:58.461557932+02:00" level=warning msg="Running modprobe bridge nf_nat br_netfilter failed with message: modprobe: WARNING: Module br_netfilter not found.\n, error: exit status 1"
Aug 12 16:21:58 cento firewalld: 2015-08-12 16:21:58 DEBUG1: getDefaultZone()
Aug 12 16:23:28 cento.k-moeller.dk systemd[1]: docker.service operation timed out. Terminating.
Aug 12 16:23:28 cento.k-moeller.dk systemd[1]: Failed to start Docker Application Container Engine.
Aug 12 16:23:28 cento.k-moeller.dk systemd[1]: Unit docker.service entered failed state.

@squeaky-pl
Copy link

@mavenugo

Aug 12 14:20:53 elena systemd[1]: Starting Docker Application Container Engine...
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.238202665Z" level=debug msg="Registering PUT, /containers/{name:.*}/archive"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.238400837Z" level=debug msg="Registering DELETE, /containers/{name:.*}"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.238499502Z" level=debug msg="Registering DELETE, /images/{name:.*}"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.239300118Z" level=debug msg="Registering OPTIONS, "
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.239315566Z" level=debug msg="Registering HEAD, /containers/{name:.*}/archive"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.239467061Z" level=debug msg="Registering GET, /containers/{name:.*}/changes"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.239561482Z" level=debug msg="Registering GET, /containers/{name:.*}/top"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.239652693Z" level=debug msg="Registering GET, /containers/{name:.*}/logs"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.239742773Z" level=debug msg="Registering GET, /containers/{name:.*}/attach/ws"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.239883187Z" level=debug msg="Registering GET, /_ping"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.239939047Z" level=debug msg="Registering GET, /info"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.240014951Z" level=debug msg="Registering GET, /images/{name:.*}/get"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.240147202Z" level=debug msg="Registering GET, /containers/json"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.240231759Z" level=debug msg="Registering GET, /images/get"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.240295673Z" level=debug msg="Registering GET, /images/{name:.*}/history"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.240393636Z" level=debug msg="Registering GET, /containers/{name:.*}/export"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.240483797Z" level=debug msg="Registering GET, /exec/{id:.*}/json"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.240565760Z" level=debug msg="Registering GET, /events"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.240628541Z" level=debug msg="Registering GET, /version"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.240683301Z" level=debug msg="Registering GET, /images/search"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.240744946Z" level=debug msg="Registering GET, /containers/{name:.*}/stats"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.240826237Z" level=debug msg="Registering GET, /containers/{name:.*}/archive"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.240977399Z" level=debug msg="Registering GET, /images/json"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.241077801Z" level=debug msg="Registering GET, /images/{name:.*}/json"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.241168034Z" level=debug msg="Registering GET, /containers/ps"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.242076700Z" level=debug msg="Registering GET, /containers/{name:.*}/json"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.242210366Z" level=debug msg="Registering POST, /auth"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.242257620Z" level=debug msg="Registering POST, /images/create"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.242359802Z" level=debug msg="Registering POST, /containers/{name:.*}/restart"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.242462211Z" level=debug msg="Registering POST, /containers/{name:.*}/wait"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.242542680Z" level=debug msg="Registering POST, /exec/{name:.*}/resize"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.242619729Z" level=debug msg="Registering POST, /containers/{name:.*}/copy"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.242706888Z" level=debug msg="Registering POST, /containers/{name:.*}/rename"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.242785009Z" level=debug msg="Registering POST, /commit"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.242831554Z" level=debug msg="Registering POST, /images/{name:.*}/tag"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.242917132Z" level=debug msg="Registering POST, /containers/{name:.*}/kill"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.242994451Z" level=debug msg="Registering POST, /containers/{name:.*}/unpause"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.243083723Z" level=debug msg="Registering POST, /containers/{name:.*}/start"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.243163418Z" level=debug msg="Registering POST, /containers/{name:.*}/attach"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.243273145Z" level=debug msg="Registering POST, /build"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.243327413Z" level=debug msg="Registering POST, /images/{name:.*}/push"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.243400941Z" level=debug msg="Registering POST, /containers/create"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.243467588Z" level=debug msg="Registering POST, /containers/{name:.*}/stop"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.243580466Z" level=debug msg="Registering POST, /containers/{name:.*}/resize"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.243667362Z" level=debug msg="Registering POST, /images/load"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.243734316Z" level=debug msg="Registering POST, /containers/{name:.*}/pause"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.243821949Z" level=debug msg="Registering POST, /containers/{name:.*}/exec"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.243917032Z" level=debug msg="Registering POST, /exec/{name:.*}/start"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.246861260Z" level=debug msg="devicemapper: driver version is 4.29.0"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.247353891Z" level=debug msg="Generated prefix: docker-253:0-9285433"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.247367961Z" level=debug msg="Checking for existence of the pool 'docker-253:0-9285433-pool'"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.247570169Z" level=debug msg="[devmapper]: poolDataMajMin=7:0 poolMetaMajMin=7:1\n"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.247671282Z" level=debug msg="[devmapper]: Major:Minor for device: /dev/loop0 is:7:0"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.247705786Z" level=debug msg="[devmapper]: Major:Minor for device: /dev/loop1 is:7:1"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.268978302Z" level=debug msg="[deviceset] constructDeviceIdMap()"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.269079906Z" level=debug msg="Loading data for file /var/lib/docker/devicemapper/metadata/base"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.269199485Z" level=debug msg="Added deviceId=1 to DeviceIdMap"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.269226777Z" level=debug msg="Skipping file /var/lib/docker/devicemapper/metadata/deviceset-metadata"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.269241623Z" level=debug msg="Loading data for file /var/lib/docker/devicemapper/metadata/transaction-metadata"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.269285283Z" level=debug msg="Added deviceId=1 to DeviceIdMap"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.269297982Z" level=debug msg="[deviceset] constructDeviceIdMap() END"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.269398283Z" level=debug msg="activateDeviceIfNeeded()"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.284238742Z" level=debug msg="UUID for device: /dev/mapper/docker-253:0-9285433-base is:9748c2b0-752e-494a-882f-28c496aeddad"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.284271956Z" level=debug msg="[devmapper] deactivateDevice()"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.284321280Z" level=debug msg="[devmapper] removeDevice START(docker-253:0-9285433-base)"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.287914769Z" level=debug msg="[devmapper] removeDevice END(docker-253:0-9285433-base)"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.287945235Z" level=debug msg="[devmapper] deactivateDevice END()"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.289065309Z" level=info msg="[graphdriver] using prior storage driver \"devicemapper\""
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.289082145Z" level=debug msg="Using graph driver devicemapper"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.289093356Z" level=debug msg="Using default logging driver json-file"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.289107819Z" level=debug msg="Creating images graph"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.289148207Z" level=debug msg="Restored 0 elements"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.289354219Z" level=debug msg="Creating repository list"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.289443222Z" level=info msg="Option DefaultDriver: bridge"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.289453261Z" level=info msg="Option DefaultNetwork: bridge"
Aug 12 14:20:53 elena docker[4602]: time="2015-08-12T14:20:53.295015440Z" level=warning msg="Running modprobe bridge nf_nat br_netfilter failed with message: modprobe: WARNING: Module br_netfilter not found.\n, error: exit status 1"
Aug 12 14:22:23 elena systemd[1]: docker.service operation timed out. Terminating.
Aug 12 14:22:23 elena systemd[1]: Failed to start Docker Application Container Engine.
Aug 12 14:22:23 elena systemd[1]: Unit docker.service entered failed state.

@mavenugo
Copy link
Contributor

@KalleDK @squeaky-pl thanks. its clear that docker daemon times out after waiting for 90 seconds on some activity that daemon is busy with. Could you get a strace output for the docker daemon during this time ? Also, as @abierbaum indicated is this seen only when started via systemd ?

I dont see this problem either in my centos7-minimal setup running in virtualbox with or without firewalld enabled. So, am guessing some specific configuration that causes the docker daemon to be busy / waiting on something.

@abierbaum
Copy link
Author

@mavenugo What is the best way to get you the strace output you need? I haven't done this before with docker so I want to make sure I get it right the first time. :)

@squeaky-pl
Copy link

@mavenugo Not sure if that helps but it seems to be stuck on this system call

systemctl start docker & sleep 1 && systemctl status docker
[1] 29211
docker.service - Docker Application Container Engine
   Loaded: loaded (/usr/lib/systemd/system/docker.service; enabled)
   Active: activating (start) since Wed 2015-08-12 16:52:38 UTC; 999ms ago
     Docs: https://docs.docker.com
 Main PID: 29215 (docker)
   CGroup: /system.slice/docker.service
           └─29215 /usr/bin/docker daemon -D -H fd://

Aug 12 16:52:38 elena docker[29215]: time="2015-08-12T16:52:38.932612200Z" level=info msg="[graphdriver] using prior storage driver \"devicemapper\""
Aug 12 16:52:38 elena docker[29215]: time="2015-08-12T16:52:38.932629346Z" level=debug msg="Using graph driver devicemapper"
Aug 12 16:52:38 elena docker[29215]: time="2015-08-12T16:52:38.932640330Z" level=debug msg="Using default logging driver json-file"
Aug 12 16:52:38 elena docker[29215]: time="2015-08-12T16:52:38.932654515Z" level=debug msg="Creating images graph"
Aug 12 16:52:38 elena docker[29215]: time="2015-08-12T16:52:38.933432273Z" level=debug msg="Restored 44 elements"
Aug 12 16:52:38 elena docker[29215]: time="2015-08-12T16:52:38.936939697Z" level=debug msg="Reloaded graph with 3 grants expiring at 2017-03-22 19:04:46.713978458 +0000 UTC"
Aug 12 16:52:38 elena docker[29215]: time="2015-08-12T16:52:38.936978164Z" level=debug msg="Creating repository list"
Aug 12 16:52:38 elena docker[29215]: time="2015-08-12T16:52:38.942812268Z" level=info msg="Option DefaultDriver: bridge"
Aug 12 16:52:38 elena docker[29215]: time="2015-08-12T16:52:38.942837485Z" level=info msg="Option DefaultNetwork: bridge"
Aug 12 16:52:38 elena docker[29215]: time="2015-08-12T16:52:38.946890017Z" level=warning msg="Running modprobe bridge nf_nat br_netfilter failed with message: modprobe: WARNING: Module br_netfilter not found.\n, error: exit status 1"

[root@elena ops]# strace -p 29215
Process 29215 attached
futex(0x17271d8, FUTEX_WAIT, 0, NULL

@mavenugo
Copy link
Contributor

@squeaky-pl thanks. but could you enable strace in ExecStart, something like ExecStart=/usr/bin/strace -o /tmp/strace-docker.log /usr/bin/docker daemon -D -H fd:// in docker.service file and capture the strace-docker.log ? Also, it would be helpful to see the /var/log/messages.

@squeaky-pl
Copy link

@mavenugo It seems that running through strace affects it somehow and causes it to fail in a different way

start docker & sleep 1 && systemctl status docker
[1] 31642
Job for docker.service failed. See 'systemctl status docker.service' and 'journalctl -xn' for details.
[1]+  Exit 1                  systemctl start docker
docker.service - Docker Application Container Engine
   Loaded: loaded (/usr/lib/systemd/system/docker.service; enabled)
   Active: failed (Result: exit-code) since Wed 2015-08-12 17:10:24 UTC; 463ms ago
     Docs: https://docs.docker.com
  Process: 31646 ExecStart=/usr/bin/strace -o /tmp/strace-docker.log /usr/bin/docker daemon -D -H fd:// (code=exited, status=1/FAILURE)
 Main PID: 31646 (code=exited, status=1/FAILURE)

Aug 12 17:10:24 elena strace[31646]: time="2015-08-12T17:10:24.486712586Z" level=debug msg="[devmapper] deactivatePool()"
Aug 12 17:10:24 elena strace[31646]: time="2015-08-12T17:10:24.486930836Z" level=debug msg="[devmapper] devicemapper.GetDeps() /dev/mapper/docker-253:0-9285433-pool: &devicemapper.Deps{Count:0x2, Filler:0x0, Device:[]uint64(nil)}"
Aug 12 17:10:24 elena systemd[1]: docker.service: Got notification message from PID 31649, but reception only permitted for PID 31646
Aug 12 17:10:24 elena strace[31646]: time="2015-08-12T17:10:24.497760737Z" level=debug msg="[devmapper] deactivatePool END"
Aug 12 17:10:24 elena strace[31646]: time="2015-08-12T17:10:24.499343539Z" level=debug msg="[deviceset docker-253:0-9285433] Shutdown() END"
Aug 12 17:10:24 elena strace[31646]: time="2015-08-12T17:10:24.500740109Z" level=debug msg="Clean shutdown succeded"
Aug 12 17:10:24 elena strace[31646]: time="2015-08-12T17:10:24.500817628Z" level=fatal msg="Shutting down due to ServeAPI error: No sockets found"
Aug 12 17:10:24 elena systemd[1]: docker.service: main process exited, code=exited, status=1/FAILURE
Aug 12 17:10:24 elena systemd[1]: Failed to start Docker Application Container Engine.
Aug 12 17:10:24 elena systemd[1]: Unit docker.service entered failed state.

here is the strace output https://gist.github.com/squeaky-pl/eb5e175f5fe6d50c42a0

@mrjana
Copy link
Contributor

mrjana commented Aug 12, 2015

@squeaky-pl One more thing that you can do is send SIGUSR1 to docker daemon and if docker daemon is anywhere near sane state it should dump the stack traces of all the go routines inside docker daemon. You have to start the daemon in debug mode though. If you can collect those traces and post it here that would be helpful.

@mrjana
Copy link
Contributor

mrjana commented Aug 12, 2015

@squeaky-pl You can send SIGUSR1 to docker daemon by doing the following

kill -SIGUSR1 <docker_daemon_pid>

@squeaky-pl
Copy link

@mrjana

docker.service - Docker Application Container Engine
   Loaded: loaded (/usr/lib/systemd/system/docker.service; enabled)
   Active: activating (start) since Wed 2015-08-12 17:20:32 UTC; 998ms ago
     Docs: https://docs.docker.com
 Main PID: 32288 (docker)
   CGroup: /system.slice/docker.service
           └─32288 /usr/bin/docker daemon -D -H fd://

Aug 12 17:20:32 elena docker[32288]: time="2015-08-12T17:20:32.157312722Z" level=info msg="[graphdriver] using prior storage driver \"devicemapper\""
Aug 12 17:20:32 elena docker[32288]: time="2015-08-12T17:20:32.157329451Z" level=debug msg="Using graph driver devicemapper"
Aug 12 17:20:32 elena docker[32288]: time="2015-08-12T17:20:32.157340322Z" level=debug msg="Using default logging driver json-file"
Aug 12 17:20:32 elena docker[32288]: time="2015-08-12T17:20:32.157355057Z" level=debug msg="Creating images graph"
Aug 12 17:20:32 elena docker[32288]: time="2015-08-12T17:20:32.158190637Z" level=debug msg="Restored 44 elements"
Aug 12 17:20:32 elena docker[32288]: time="2015-08-12T17:20:32.161390688Z" level=debug msg="Reloaded graph with 3 grants expiring at 2017-03-22 19:04:46.713978458 +0000 UTC"
Aug 12 17:20:32 elena docker[32288]: time="2015-08-12T17:20:32.161407120Z" level=debug msg="Creating repository list"
Aug 12 17:20:32 elena docker[32288]: time="2015-08-12T17:20:32.161488587Z" level=info msg="Option DefaultDriver: bridge"
Aug 12 17:20:32 elena docker[32288]: time="2015-08-12T17:20:32.161498010Z" level=info msg="Option DefaultNetwork: bridge"
Aug 12 17:20:32 elena docker[32288]: time="2015-08-12T17:20:32.166493090Z" level=warning msg="Running modprobe bridge nf_nat br_netfilter failed with message: modprobe: WARNING: Module br_netfilter not found.\n, error: exit status 1"

[root@elena tmp]# kill -SIGUSR1 32288

[root@elena tmp]# journalctl 

Aug 12 17:20:54 elena docker[32288]: time="2015-08-12T17:20:54.264610263Z" level=info msg="=== BEGIN goroutine stack dump ===\ngoroutine 11 [running]:\ngithub.com/docker/docker/pkg/signal.DumpStacks()\n\t/root/rpmbuild/BUILD/docker-engine/.gopath/src/github.com/docker/docker/pkg/signal/trap.go:60 +0x7a\ngithub.com/doc
Aug 12 17:20:54 elena docker[32288]: gopath/src/github.com/docker/docker/daemon/daemon.go:692 +0x1a3a\nmain.(*DaemonCli).CmdDaemon(0xc2080d5190, 0xc20800a020, 0x3, 0x3, 0x0, 0x0)\n\t/root/rpmbuild/BUILD/docker-engine/docker/daemon.go:256 +0xed7\nreflect.callMethod(0xc208107e90, 0xc2083f5ce0)\n\t/usr/local/go/src/refle
Aug 12 17:20:54 elena docker[32288]: /local/go/src/io/io.go:316 +0x6d\ngithub.com/godbus/dbus.(*unixTransport).ReadMessage(0xc20844f2c0, 0xc20845f350, 0x0, 0x0)\n\t/root/rpmbuild/BUILD/docker-engine/vendor/src/github.com/godbus/dbus/transport_unix.go:85 +0x1bf\ngithub.com/godbus/dbus.(*Conn).inWorker(0xc2084626c0)\n\t

@abierbaum
Copy link
Author

@mavenugo Here is my strace output: https://gist.github.com/abierbaum/6bc0bd5039559ab16828

journalctl --unit=docker

-- Logs begin at Sun 2015-07-12 09:27:56 EDT, end at Sun 2015-07-12 09:36:12 EDT. --
Jul 12 09:33:17 cent7 systemd[1]: Starting Docker Application Container Engine...
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.941513102-04:00" level=debug msg="Registering POST, /containers/{name:.*}/unpause"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.946645806-04:00" level=debug msg="Registering POST, /containers/{name:.*}/restart"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.948200227-04:00" level=debug msg="Registering POST, /exec/{name:.*}/resize"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.949683148-04:00" level=debug msg="Registering POST, /containers/create"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.951147023-04:00" level=debug msg="Registering POST, /containers/{name:.*}/kill"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.952689049-04:00" level=debug msg="Registering POST, /containers/{name:.*}/start"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.954250729-04:00" level=debug msg="Registering POST, /containers/{name:.*}/stop"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.955571461-04:00" level=debug msg="Registering POST, /containers/{name:.*}/resize"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.956972695-04:00" level=debug msg="Registering POST, /exec/{name:.*}/start"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.958251639-04:00" level=debug msg="Registering POST, /auth"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.959489517-04:00" level=debug msg="Registering POST, /build"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.960626144-04:00" level=debug msg="Registering POST, /containers/{name:.*}/wait"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.964236381-04:00" level=debug msg="Registering POST, /containers/{name:.*}/attach"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.965373495-04:00" level=debug msg="Registering POST, /containers/{name:.*}/copy"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.966950659-04:00" level=debug msg="Registering POST, /containers/{name:.*}/exec"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.968388271-04:00" level=debug msg="Registering POST, /containers/{name:.*}/rename"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.969083093-04:00" level=debug msg="Registering POST, /commit"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.969924168-04:00" level=debug msg="Registering POST, /images/create"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.971047320-04:00" level=debug msg="Registering POST, /images/load"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.971934129-04:00" level=debug msg="Registering POST, /images/{name:.*}/push"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.972913576-04:00" level=debug msg="Registering POST, /images/{name:.*}/tag"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.973635979-04:00" level=debug msg="Registering POST, /containers/{name:.*}/pause"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.974411943-04:00" level=debug msg="Registering PUT, /containers/{name:.*}/archive"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.975161539-04:00" level=debug msg="Registering DELETE, /containers/{name:.*}"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.976176420-04:00" level=debug msg="Registering DELETE, /images/{name:.*}"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.977109328-04:00" level=debug msg="Registering OPTIONS, "
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.977825733-04:00" level=debug msg="Registering HEAD, /containers/{name:.*}/archive"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.979035121-04:00" level=debug msg="Registering GET, /containers/{name:.*}/changes"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.979914978-04:00" level=debug msg="Registering GET, /containers/{name:.*}/logs"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.980663602-04:00" level=debug msg="Registering GET, /exec/{id:.*}/json"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.981389224-04:00" level=debug msg="Registering GET, /images/search"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.982211963-04:00" level=debug msg="Registering GET, /containers/json"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.983029750-04:00" level=debug msg="Registering GET, /containers/{name:.*}/export"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.983967731-04:00" level=debug msg="Registering GET, /containers/{name:.*}/json"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.984561928-04:00" level=debug msg="Registering GET, /containers/{name:.*}/attach/ws"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.988318157-04:00" level=debug msg="Registering GET, /info"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.990508855-04:00" level=debug msg="Registering GET, /version"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.990969582-04:00" level=debug msg="Registering GET, /containers/ps"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.991840728-04:00" level=debug msg="Registering GET, /containers/{name:.*}/top"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.991989074-04:00" level=debug msg="Registering GET, /containers/{name:.*}/stats"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.992130702-04:00" level=debug msg="Registering GET, /_ping"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.992217916-04:00" level=debug msg="Registering GET, /events"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.992304830-04:00" level=debug msg="Registering GET, /images/json"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.992402051-04:00" level=debug msg="Registering GET, /images/get"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.992495300-04:00" level=debug msg="Registering GET, /images/{name:.*}/get"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.992625649-04:00" level=debug msg="Registering GET, /images/{name:.*}/history"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.992825467-04:00" level=debug msg="Registering GET, /images/{name:.*}/json"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.993001256-04:00" level=debug msg="Registering GET, /containers/{name:.*}/archive"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.997014282-04:00" level=error msg="ServeAPI error: No sockets found"
Jul 12 09:33:17 cent7 strace[2640]: time="2015-07-12T09:33:17.998702985-04:00" level=debug msg="[zfs] zfs command is not available: exec: \"zfs\": executable file not found in $PATH"
Jul 12 09:33:18 cent7 strace[2640]: time="2015-07-12T09:33:18.002065877-04:00" level=debug msg="devicemapper: driver version is 4.29.0"
Jul 12 09:33:18 cent7 strace[2640]: time="2015-07-12T09:33:18.003426679-04:00" level=debug msg="Generated prefix: docker-253:0-16914458"
Jul 12 09:33:18 cent7 strace[2640]: time="2015-07-12T09:33:18.003479041-04:00" level=debug msg="Checking for existence of the pool 'docker-253:0-16914458-pool'"
Jul 12 09:33:18 cent7 strace[2640]: time="2015-07-12T09:33:18.005096111-04:00" level=debug msg="Pool doesn't exist. Creating it."
Jul 12 09:33:18 cent7 strace[2640]: time="2015-07-12T09:33:18.005170473-04:00" level=debug msg="Creating loopback file /var/lib/docker/devicemapper/devicemapper/data for device-manage use"
Jul 12 09:33:18 cent7 strace[2640]: time="2015-07-12T09:33:18.023450417-04:00" level=debug msg="Creating loopback file /var/lib/docker/devicemapper/devicemapper/metadata for device-manage use"
Jul 12 09:33:18 cent7 strace[2640]: time="2015-07-12T09:33:18.146980177-04:00" level=debug msg="Initializing base device-mapper thin volume"
Jul 12 09:33:18 cent7 strace[2640]: time="2015-07-12T09:33:18.148510662-04:00" level=debug msg="[devmapper] CreateDevice(poolName=/dev/mapper/docker-253:0-16914458-pool, deviceId=1)"
Jul 12 09:33:18 cent7 strace[2640]: time="2015-07-12T09:33:18.159877480-04:00" level=debug msg="Registering device (id 1) with FS size 107374182400"
Jul 12 09:33:18 cent7 strace[2640]: time="2015-07-12T09:33:18.159972885-04:00" level=debug msg="registerDevice(1, )"
Jul 12 09:33:18 cent7 strace[2640]: time="2015-07-12T09:33:18.170905817-04:00" level=debug msg="Creating filesystem on base device-mapper thin volume"
Jul 12 09:33:18 cent7 strace[2640]: time="2015-07-12T09:33:18.170961968-04:00" level=debug msg="activateDeviceIfNeeded()"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.015072144-04:00" level=debug msg="activateDeviceIfNeeded()"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.073915568-04:00" level=debug msg="UUID for device: /dev/mapper/docker-253:0-16914458-base is:5bc6ce7b-7a82-4776-a0e9-7c9ba4c7e5af"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.076287622-04:00" level=debug msg="[devmapper] deactivateDevice()"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.076399194-04:00" level=debug msg="[devmapper] removeDevice START(docker-253:0-16914458-base)"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.107093766-04:00" level=debug msg="[devmapper] removeDevice END(docker-253:0-16914458-base)"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.107148941-04:00" level=debug msg="[devmapper] deactivateDevice END()"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.113371133-04:00" level=debug msg="Using graph driver devicemapper"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.113424792-04:00" level=debug msg="Using default logging driver json-file"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.116747475-04:00" level=debug msg="Creating images graph"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.121181979-04:00" level=debug msg="Restored 0 elements"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.129439356-04:00" level=debug msg="Creating repository list"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.129695648-04:00" level=info msg="Option DefaultDriver: bridge"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.129720828-04:00" level=info msg="Option DefaultNetwork: bridge"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.157635482-04:00" level=warning msg="Running modprobe bridge nf_nat br_netfilter failed with message: modprobe: WARNING: Module br_netfilter not found.\n, error: exit status 1"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.191969352-04:00" level=info msg="Firewalld running: true"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.192052605-04:00" level=debug msg="Firewalld passthrough: ipv4, [-t nat -D PREROUTING -m addrtype --dst-type LOCAL -j DOCKER]"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.233968014-04:00" level=debug msg="Firewalld passthrough: ipv4, [-t nat -D OUTPUT -m addrtype --dst-type LOCAL ! --dst 127.0.0.0/8 -j DOCKER]"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.246694952-04:00" level=debug msg="Firewalld passthrough: ipv4, [-t nat -D OUTPUT -m addrtype --dst-type LOCAL -j DOCKER]"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.257571149-04:00" level=debug msg="Firewalld passthrough: ipv4, [-t nat -D PREROUTING]"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.270106483-04:00" level=debug msg="Firewalld passthrough: ipv4, [-t nat -D OUTPUT]"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.281987079-04:00" level=debug msg="Firewalld passthrough: ipv4, [-t nat -F DOCKER]"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.292505521-04:00" level=debug msg="Firewalld passthrough: ipv4, [-t nat -X DOCKER]"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.302630976-04:00" level=debug msg="Failed to Initialize Datastore due to datastore initialization requires a valid configuration. Operating in non-clustered mode"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.303661605-04:00" level=debug msg="Setting bridge mac address to 02:42:e7:20:93:02"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.304292582-04:00" level=debug msg="Creating bridge interface \"docker0\" with network 172.17.42.1/16"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.304616548-04:00" level=debug msg="Firewalld passthrough: ipv4, [-t nat -C POSTROUTING -s 172.17.42.1/16 ! -o docker0 -j MASQUERADE]"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.320909945-04:00" level=debug msg="Firewalld passthrough: ipv4, [-t nat -I POSTROUTING -s 172.17.42.1/16 ! -o docker0 -j MASQUERADE]"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.350594410-04:00" level=debug msg="Firewalld passthrough: ipv4, [-D FORWARD -i docker0 -o docker0 -j DROP]"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.365423817-04:00" level=debug msg="Firewalld passthrough: ipv4, [-t filter -C FORWARD -i docker0 -o docker0 -j ACCEPT]"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.383256060-04:00" level=debug msg="Firewalld passthrough: ipv4, [-I FORWARD -i docker0 -o docker0 -j ACCEPT]"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.391447973-04:00" level=debug msg="Firewalld passthrough: ipv4, [-t filter -C FORWARD -i docker0 ! -o docker0 -j ACCEPT]"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.403268610-04:00" level=debug msg="Firewalld passthrough: ipv4, [-I FORWARD -i docker0 ! -o docker0 -j ACCEPT]"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.414896546-04:00" level=debug msg="Firewalld passthrough: ipv4, [-t filter -C FORWARD -o docker0 -m conntrack --ctstate RELATED,ESTABLISHED -j ACCEPT]"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.443082996-04:00" level=debug msg="Firewalld passthrough: ipv4, [-I FORWARD -o docker0 -m conntrack --ctstate RELATED,ESTABLISHED -j ACCEPT]"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.451444757-04:00" level=debug msg="Firewalld passthrough: ipv4, [-t nat -n -L DOCKER]"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.456746182-04:00" level=debug msg="Firewalld passthrough: ipv4, [-t nat -N DOCKER]"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.462384065-04:00" level=debug msg="Firewalld passthrough: ipv4, [-t nat -C PREROUTING -m addrtype --dst-type LOCAL -j DOCKER]"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.472148048-04:00" level=debug msg="Firewalld passthrough: ipv4, [-t nat -A PREROUTING -m addrtype --dst-type LOCAL -j DOCKER]"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.483365653-04:00" level=debug msg="Firewalld passthrough: ipv4, [-t nat -C OUTPUT -m addrtype --dst-type LOCAL -j DOCKER ! --dst 127.0.0.0/8]"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.490249890-04:00" level=debug msg="Firewalld passthrough: ipv4, [-t nat -A OUTPUT -m addrtype --dst-type LOCAL -j DOCKER ! --dst 127.0.0.0/8]"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.499818821-04:00" level=debug msg="Firewalld passthrough: ipv4, [-t filter -n -L DOCKER]"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.510488604-04:00" level=debug msg="Firewalld passthrough: ipv4, [-t filter -N DOCKER]"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.520846804-04:00" level=debug msg="Firewalld passthrough: ipv4, [-t filter -C FORWARD -o docker0 -j DOCKER]"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.531964801-04:00" level=debug msg="Firewalld passthrough: ipv4, [-I FORWARD -o docker0 -j DOCKER]"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.595008993-04:00" level=info msg="Daemon has completed initialization"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.596974875-04:00" level=info msg="Docker daemon" commit=0d03096 execdriver=native-0.2 graphdriver=devicemapper version=1.8.0
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.601040997-04:00" level=debug msg="starting clean shutdown of all containers..."
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.601164367-04:00" level=debug msg="[deviceset docker-253:0-16914458] Shutdown()"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.601291939-04:00" level=debug msg="[devmapper] Shutting down DeviceSet: /var/lib/docker/devicemapper"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.601340677-04:00" level=debug msg="[devmapper] deactivateDevice()"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.602538668-04:00" level=debug msg="[devmapper] deactivateDevice END()"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.602609532-04:00" level=debug msg="[devmapper] deactivatePool()"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.602907507-04:00" level=debug msg="[devmapper] devicemapper.GetDeps() /dev/mapper/docker-253:0-16914458-pool: &devicemapper.Deps{Count:0x2, Filler:0x0, Device:[]uint64(nil)}"
Jul 12 09:33:24 cent7 systemd[1]: docker.service: Got notification message from PID 2643, but reception only permitted for PID 2640
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.631666627-04:00" level=debug msg="[devmapper] deactivatePool END"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.633876380-04:00" level=debug msg="[deviceset docker-253:0-16914458] Shutdown() END"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.640299591-04:00" level=debug msg="Clean shutdown succeded"
Jul 12 09:33:24 cent7 strace[2640]: time="2015-07-12T09:33:24.641466294-04:00" level=fatal msg="Shutting down due to ServeAPI error: No sockets found"
Jul 12 09:33:24 cent7 systemd[1]: docker.service: main process exited, code=exited, status=1/FAILURE
Jul 12 09:33:24 cent7 systemd[1]: Failed to start Docker Application Container Engine.
Jul 12 09:33:24 cent7 systemd[1]: Unit docker.service entered failed state.

@mavenugo
Copy link
Contributor

as @squeaky-pl indicated, enabling strace in the systemd init isnt working. But the output for kill -SIGUSR1 is useful.

@squeaky-pl the output that you provided is not complete. Can you please get the full trace output from /var/log/messages and paste it here ?

@squeaky-pl
Copy link

@mavenugo @mrjana

Aug 12 17:20:54 elena docker: time="2015-08-12T17:20:54.264610263Z" level=info msg="=== BEGIN goroutine stack dump ===\ngoroutine 11 [running]:\ngithub.com/docker/docker/pkg/signal.DumpStacks()\n\t/root/rpmbuild/BUILD/docker-engine/.gopath/src/github.com/docker/docker/pkg/signal/trap.go:60 +0x7a\ngithub.com/docker/docker/daemon.func·025()\n\t/root/rpmbuild/BUILD/docker-engine/.gopath/src/github.com/docker/docker/daemon/debugtrap_unix.go:18 +0x6d\ncreated by github.com/docker/docker/daemon.setupDumpStackTrap\n\t/root/rpmbuild/BUILD/docker-engine/.gopath/src/github.com/docker/docker/daemon/debugtrap_unix.go:20 +0x18e\n\ngoroutine 1 [chan receive]:\ngithub.com/godbus/dbus.(*Object).Call(0xc20845fa70, 0x10f8e90, 0x2b, 0x0, 0x0, 0x0, 0x0, 0x1)\n\t/root/rpmbuild/BUILD/docker-engine/vendor/src/github.com/godbus/dbus/call.go:48 +0xbd\ngithub.com/docker/libnetwork/iptables.checkRunning(0x17230e8)\n\t/root/rpmbuild/BUILD/docker-engine/vendor/src/github.com/docker/libnetwork/iptables/firewalld.go:149 +0xa5\ngithub.com/docker/libnetwork/iptables.FirewalldInit(0x0, 0x0)\n\t/root/rpmbuild/BUILD/docker-engine/vendor/src/github.com/docker/libnetwork/iptables/firewalld.go:51 +0x18c\ngithub.com/docker/libnetwork/drivers/bridge.Init(0x7f98c605ce70, 0xc208457940, 0x0, 0x0)\n\t/root/rpmbuild/BUILD/docker-engine/vendor/src/github.com/docker/libnetwork/drivers/bridge/bridge.go:118 +0x24e\ngithub.com/docker/libnetwork.initDrivers(0x7f98c605ce70, 0xc208457940, 0x0, 0x0)\n\t/root/rpmbuild/BUILD/docker-engine/vendor/src/github.com/docker/libnetwork/drivers_linux.go:20 +0x145\ngithub.com/docker/libnetwork.New(0xc208460860, 0x3, 0x4, 0x0, 0x0, 0x0, 0x0)\n\t/root/rpmbuild/BUILD/docker-engine/vendor/src/github.com/docker/libnetwork/controller.go:132 +0x218\ngithub.com/docker/docker/daemon.initNetworkController(0xc208044a00, 0x0, 0x0, 0x0, 0x0)\n\t/root/rpmbuild/BUILD/docker-engine/.gopath/src/github.com/docker/docker/daemon/daemon_unix.go:328 +0xf0\ngithub.com/docker/docker/daemon.NewDaemon(0xc208044a00, 0xc2080369c0, 0x0, 0x0, 0x0)\n\t/root/rpmbuild/BUILD/docker-engine/.
Aug 12 17:20:54 elena docker: gopath/src/github.com/docker/docker/daemon/daemon.go:692 +0x1a3a\nmain.(*DaemonCli).CmdDaemon(0xc2080d5190, 0xc20800a020, 0x3, 0x3, 0x0, 0x0)\n\t/root/rpmbuild/BUILD/docker-engine/docker/daemon.go:256 +0xed7\nreflect.callMethod(0xc208107e90, 0xc2083f5ce0)\n\t/usr/local/go/src/reflect/value.go:605 +0x179\nreflect.methodValueCall(0xc20800a020, 0x3, 0x3, 0x1, 0xc208107e90, 0x0, 0x0, 0xc208107e90, 0x0, 0x450faf, ...)\n\t/usr/local/go/src/reflect/asm_amd64.s:29 +0x36\ngithub.com/docker/docker/cli.(*Cli).Run(0xc208107dd0, 0xc20800a010, 0x4, 0x4, 0x0, 0x0)\n\t/root/rpmbuild/BUILD/docker-engine/.gopath/src/github.com/docker/docker/cli/cli.go:89 +0x38e\nmain.main()\n\t/root/rpmbuild/BUILD/docker-engine/docker/docker.go:69 +0x428\n\ngoroutine 5 [syscall]:\nos/signal.loop()\n\t/usr/local/go/src/os/signal/signal_unix.go:21 +0x1f\ncreated by os/signal.init·1\n\t/usr/local/go/src/os/signal/signal_unix.go:27 +0x35\n\ngoroutine 17 [syscall, locked to thread]:\nruntime.goexit()\n\t/usr/local/go/src/runtime/asm_amd64.s:2232 +0x1\n\ngoroutine 14 [IO wait]:\nnet.(*pollDesc).Wait(0xc208458990, 0x72, 0x0, 0x0)\n\t/usr/local/go/src/net/fd_poll_runtime.go:84 +0x47\nnet.(*pollDesc).WaitRead(0xc208458990, 0x0, 0x0)\n\t/usr/local/go/src/net/fd_poll_runtime.go:89 +0x43\nnet.(*netFD).readMsg(0xc208458930, 0xc208480960, 0x10, 0x10, 0xc208468820, 0x1000, 0x1000, 0xffffffffffffffff, 0x0, 0x0, ...)\n\t/usr/local/go/src/net/fd_unix.go:296 +0x54e\nnet.(*UnixConn).ReadMsgUnix(0xc208037110, 0xc208480960, 0x10, 0x10, 0xc208468820, 0x1000, 0x1000, 0x0, 0xc20848080c, 0x4, ...)\n\t/usr/local/go/src/net/unixsock_posix.go:147 +0x167\ngithub.com/godbus/dbus.(*oobReader).Read(0xc208468800, 0xc208480960, 0x10, 0x10, 0xc208468800, 0x0, 0x0)\n\t/root/rpmbuild/BUILD/docker-engine/vendor/src/github.com/godbus/dbus/transport_unix.go:21 +0xc5\nio.ReadAtLeast(0x7f98c605d020, 0xc208468800, 0xc208480960, 0x10, 0x10, 0x10, 0x0, 0x0, 0x0)\n\t/usr/local/go/src/io/io.go:298 +0xf1\nio.ReadFull(0x7f98c605d020, 0xc208468800, 0xc208480960, 0x10, 0x10, 0x0, 0x0, 0x0)\n\t/usr
Aug 12 17:20:54 elena docker: /local/go/src/io/io.go:316 +0x6d\ngithub.com/godbus/dbus.(*unixTransport).ReadMessage(0xc20844f2c0, 0xc20845f350, 0x0, 0x0)\n\t/root/rpmbuild/BUILD/docker-engine/vendor/src/github.com/godbus/dbus/transport_unix.go:85 +0x1bf\ngithub.com/godbus/dbus.(*Conn).inWorker(0xc2084626c0)\n\t/root/rpmbuild/BUILD/docker-engine/vendor/src/github.com/godbus/dbus/conn.go:248 +0x58\ncreated by github.com/godbus/dbus.(*Conn).Auth\n\t/root/rpmbuild/BUILD/docker-engine/vendor/src/github.com/godbus/dbus/auth.go:118 +0xe84\n\ngoroutine 10 [chan receive]:\ngithub.com/docker/docker/api/server.(*Server).newServer(0xc208035340, 0x7fff977b3f4c, 0x2, 0x7fff977b3f4c, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)\n\t/root/rpmbuild/BUILD/docker-engine/.gopath/src/github.com/docker/docker/api/server/server_linux.go:41 +0x1d4\ngithub.com/docker/docker/api/server.(*Server).ServeApi(0xc208035340, 0xc2080d5420, 0x1, 0x1, 0x0, 0x0)\n\t/root/rpmbuild/BUILD/docker-engine/.gopath/src/github.com/docker/docker/api/server/server.go:93 +0x23e\nmain.func·007()\n\t/root/rpmbuild/BUILD/docker-engine/docker/daemon.go:242 +0x5b\ncreated by main.(*DaemonCli).CmdDaemon\n\t/root/rpmbuild/BUILD/docker-engine/docker/daemon.go:248 +0xd51\n\ngoroutine 15 [chan receive]:\ngithub.com/godbus/dbus.(*Conn).outWorker(0xc2084626c0)\n\t/root/rpmbuild/BUILD/docker-engine/vendor/src/github.com/godbus/dbus/conn.go:370 +0x58\ncreated by github.com/godbus/dbus.(*Conn).Auth\n\t/root/rpmbuild/BUILD/docker-engine/vendor/src/github.com/godbus/dbus/auth.go:119 +0xea1\n\ngoroutine 16 [chan receive]:\ngithub.com/docker/libnetwork/iptables.signalHandler()\n\t/root/rpmbuild/BUILD/docker-engine/vendor/src/github.com/docker/libnetwork/iptables/firewalld.go:92 +0x57\ncreated by github.com/docker/libnetwork/iptables.FirewalldInit\n\t/root/rpmbuild/BUILD/docker-engine/vendor/src/github.com/docker/libnetwork/iptables/firewalld.go:48 +0x185\n\n=== END goroutine stack dump ==="

@mavenugo
Copy link
Contributor

@squeaky-pl thanks. it looks like the docker daemon is stuck @ FirewalldInit() waiting for the firewalld process to get back with a response. I dont see the same issue with my

$ firewall-cmd --version
0.3.9

@pravinprabhat
Copy link

If docker-selinux is required to be installed, please update the installation guide to avoid probelms:

https://docs.docker.com/installation/centos/#install
4. Install the Docker package.
$ sudo yum install docker-engine

https://docs.docker.com/installation/ubuntulinux/#install
3. Install Docker
$ sudo apt-get install docker-engine

@thaJeztah
Copy link
Member

@pravinprabhat the 1.9 release bundles our own SELinux policy; installing the extra package will no longer be needed once 1.9 is released (which is probably next week)

@simoncpu
Copy link

simoncpu commented Nov 3, 2015

Can confirm, can't start Docker version 1.8.3, build f4bf5c7 on CentOS Linux release 7.1.1503 unless I run setenforce 0.

@thaJeztah
Copy link
Member

@simoncpu please read the discussion above; for 1.8.x you shouldn't use setenforce 0, but manually install the docker-selinux package. Docker 1.9 will have a SELinux policy bundled, so you don't have to install manually.

@simoncpu
Copy link

simoncpu commented Nov 3, 2015

@thaJeztah OK, can confirm that installing docker-selinux works. Thanks!

@jfarrell
Copy link

jfarrell commented Nov 3, 2015

Have seen some startup issues using centos 7.1 with Docker 1.9-rc5 on aws. Setting TimeoutStartSec=0 on the service fixed this, but have seen the daemon take upwards of 3-5 min to start

@cpuguy83
Copy link
Member

cpuguy83 commented Nov 3, 2015

@jfarrell This is not related at all.
Please see the discussion here: #17464 (comment)

@jfarrell
Copy link

jfarrell commented Nov 3, 2015

thanks @cpuguy83, that was the issue, adding --storage-opt dm.fs=xfs fixed the startup to be < 10 sec

@agsmith
Copy link

agsmith commented Nov 5, 2015

Even after installing docker-selinux I still cannot get the docker service to start. I am using ansible to spin up a Centos 7 AWS instance and I get the following:

[centos@ip-172-31-44-105 ~]$ uname -a
Linux ip-172-31-44-105.us-west-2.compute.internal 3.10.0-229.20.1.el7.x86_64 #1 SMP Tue Nov 3 19:10:07 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux
[centos@ip-172-31-44-105 ~]$ rpm -qa | grep docker
docker-selinux-1.8.2-7.el7.centos.x86_64
docker-1.8.2-7.el7.centos.x86_64
[centos@ip-172-31-44-105 ~]$ sudo systemctl status docker
docker.service - Docker Application Container Engine
   Loaded: loaded (/usr/lib/systemd/system/docker.service; disabled)
   Active: failed (Result: timeout) since Thu 2015-11-05 21:45:15 UTC; 15min ago
     Docs: http://docs.docker.com
 Main PID: 1254
   CGroup: /system.slice/docker.service

Nov 05 21:44:00 ip-172-31-44-105.us-west-2.compute.internal systemd[1]: Starting Docker Application Container Engine...
Nov 05 21:44:00 ip-172-31-44-105.us-west-2.compute.internal docker[1254]: time="2015-11-05T21:44:00.851670809Z" level=error msg="WARNING: No --storage-opt dm.thinpooldev specified, using ...ction use"
Nov 05 21:44:00 ip-172-31-44-105.us-west-2.compute.internal docker[1254]: time="2015-11-05T21:44:00.876957288Z" level=info msg="Listening for HTTP on unix (/var/run/docker.sock)"
Nov 05 21:45:00 ip-172-31-44-105.us-west-2.compute.internal systemd[1]: docker.service operation timed out. Terminating.
Nov 05 21:45:15 ip-172-31-44-105.us-west-2.compute.internal systemd[1]: Failed to start Docker Application Container Engine.
Nov 05 21:45:15 ip-172-31-44-105.us-west-2.compute.internal systemd[1]: Unit docker.service entered failed state.
Hint: Some lines were ellipsized, use -l to show in full.

@thaJeztah
Copy link
Member

@agsmith possibly this issue: #17464 ?

@agsmith
Copy link

agsmith commented Nov 5, 2015

@thaJeztah Thanks! Adding -s overlay to the /etc/sysconfig/docker settings did the trick.

@EslamElHusseiny
Copy link

I've tried docker-engine 1.9 on CentOS 7.1 AMI but it didn't work.

  • docker-engine version docker-engine-1.9.0-1.el7.centos.x86_64
  • docker-engine-selinux version docker-engine-selinux-1.9.0-1.el7.centos.noarch
  • kernel version 3.10.0-229.20.1.el7.x86_64
  • CentOS version CentOS Linux release 7.1.1503 (Core)
    /var/log/messages :
docker: time="2015-11-06T13:55:44.541130521Z" level=warning msg="Usage of loopback devices is strongly discouraged for production use. Please use `--storage-opt dm.thinpooldev` or use `man docker` to refer to dm.thinpooldev section."
systemd: docker.service operation timed out. Terminating.
systemd: Failed to start Docker Application Container Engine.
systemd: Unit docker.service entered failed state.

@rjsm
Copy link

rjsm commented Nov 12, 2015

I see the same thing as @EslamElHusseiny. It appears the storage is just too slow in AWS and times out. Running it manually fixes that then starting via systemd works.

ERRO[0000] WARNING: No --storage-opt dm.thinpooldev specified, using loopback; this configuration is strongly discouraged for production use
DEBU[0000] [devmapper]: poolDataMajMin=7:0 poolMetaMajMin=7:1

DEBU[0002] [deviceset] constructDeviceIdMap()
DEBU[0002] Loading data for file /var/lib/docker/devicemapper/metadata/base
DEBU[0002] Added deviceId=1 to DeviceIdMap
DEBU[0002] Loading data for file /var/lib/docker/devicemapper/metadata/transaction-metadata
DEBU[0002] Added deviceId=1 to DeviceIdMap
DEBU[0002] [deviceset] constructDeviceIdMap() END
DEBU[0002] Removing uninitialized base image
DEBU[0002] activateDeviceIfNeeded()
DEBU[0017] [devmapper] removeDevice START(docker-202:1-2059595-base)
DEBU[0017] [devmapper] removeDevice END(docker-202:1-2059595-base)
DEBU[0017] unregisterDevice(1, )
DEBU[0017] Initializing base device-mapper thin volume
DEBU[0017] [devmapper] CreateDevice(poolName=/dev/mapper/docker-202:1-2059595-pool, deviceId=1)
DEBU[0017] Registering device (id 1) with FS size 107374182400
DEBU[0017] registerDevice(1, )
DEBU[0017] Creating filesystem on base device-mapper thin volume
DEBU[0017] activateDeviceIfNeeded()
DEBU[0104] activateDeviceIfNeeded()
DEBU[0104] UUID for device: /dev/mapper/docker-202:1-2059595-base is:ce4b3dde-71ed-4f3e-9e3a-aec833f624b5
DEBU[0104] [devmapper] deactivateDevice()
DEBU[0104] [devmapper] removeDevice START(docker-202:1-2059595-base)
DEBU[0104] [devmapper] removeDevice END(docker-202:1-2059595-base)
DEBU[0104] [devmapper] deactivateDevice END()
INFO[0104] [graphdriver] using prior storage driver "devicemapper"
DEBU[0104] Using graph driver devicemapper
DEBU[0104] Using default logging driver json-file
DEBU[0104] SELinux enabled successfully
DEBU[0104] Creating images graph
DEBU[0104] Restored 0 elements
DEBU[0104] Creating repository list
INFO[0104] Option DefaultDriver: bridge
INFO[0104] Option DefaultNetwork: bridge
WARN[0105] Running modprobe bridge nf_nat br_netfilter failed with message: modprobe: WARNING: Module br_netfilter not found.
insmod /lib/modules/3.10.0-229.20.1.el7.x86_64/kernel/net/llc/llc.ko
insmod /lib/modules/3.10.0-229.20.1.el7.x86_64/kernel/net/802/stp.ko
insmod /lib/modules/3.10.0-229.20.1.el7.x86_64/kernel/net/bridge/bridge.ko
insmod /lib/modules/3.10.0-229.20.1.el7.x86_64/kernel/net/netfilter/nf_nat.ko
, error: exit status 1
INFO[0105] Firewalld running: false
DEBU[0105] /usr/sbin/iptables, [--wait -t nat -D PREROUTING -m addrtype --dst-type LOCAL -j DOCKER]
DEBU[0105] /usr/sbin/iptables, [--wait -t nat -D OUTPUT -m addrtype --dst-type LOCAL ! --dst 127.0.0.0/8 -j DOCKER]
DEBU[0105] /usr/sbin/iptables, [--wait -t nat -D OUTPUT -m addrtype --dst-type LOCAL -j DOCKER]
DEBU[0105] /usr/sbin/iptables, [--wait -t nat -D PREROUTING]
DEBU[0105] /usr/sbin/iptables, [--wait -t nat -D OUTPUT]
DEBU[0105] /usr/sbin/iptables, [--wait -t nat -F DOCKER]
DEBU[0105] /usr/sbin/iptables, [--wait -t nat -X DOCKER]
DEBU[0105] Failed to Initialize Datastore due to datastore initialization requires a valid configuration. Operating in non-clustered mode
DEBU[0105] Setting bridge mac address to 02:42:9d:02:5a:c2
DEBU[0105] Creating bridge interface "docker0" with network 172.17.42.1/16
DEBU[0105] /usr/sbin/iptables, [--wait -t nat -C POSTROUTING -s 172.17.42.1/16 ! -o docker0 -j MASQUERADE]
DEBU[0105] /usr/sbin/iptables, [--wait -t nat -I POSTROUTING -s 172.17.42.1/16 ! -o docker0 -j MASQUERADE]
DEBU[0105] /usr/sbin/iptables, [--wait -D FORWARD -i docker0 -o docker0 -j DROP]
DEBU[0105] /usr/sbin/iptables, [--wait -t filter -C FORWARD -i docker0 -o docker0 -j ACCEPT]
DEBU[0105] /usr/sbin/iptables, [--wait -I FORWARD -i docker0 -o docker0 -j ACCEPT]
DEBU[0105] /usr/sbin/iptables, [--wait -t filter -C FORWARD -i docker0 ! -o docker0 -j ACCEPT]
DEBU[0105] /usr/sbin/iptables, [--wait -I FORWARD -i docker0 ! -o docker0 -j ACCEPT]
DEBU[0105] /usr/sbin/iptables, [--wait -t filter -C FORWARD -o docker0 -m conntrack --ctstate RELATED,ESTABLISHED -j ACCEPT]
DEBU[0105] /usr/sbin/iptables, [--wait -I FORWARD -o docker0 -m conntrack --ctstate RELATED,ESTABLISHED -j ACCEPT]
DEBU[0105] /usr/sbin/iptables, [--wait -t nat -n -L DOCKER]
DEBU[0105] /usr/sbin/iptables, [--wait -t nat -N DOCKER]
DEBU[0105] /usr/sbin/iptables, [--wait -t nat -C PREROUTING -m addrtype --dst-type LOCAL -j DOCKER]
DEBU[0105] /usr/sbin/iptables, [--wait -t nat -A PREROUTING -m addrtype --dst-type LOCAL -j DOCKER]
DEBU[0105] /usr/sbin/iptables, [--wait -t nat -C OUTPUT -m addrtype --dst-type LOCAL -j DOCKER ! --dst 127.0.0.0/8]
DEBU[0105] /usr/sbin/iptables, [--wait -t nat -A OUTPUT -m addrtype --dst-type LOCAL -j DOCKER ! --dst 127.0.0.0/8]
DEBU[0105] /usr/sbin/iptables, [--wait -t filter -n -L DOCKER]
DEBU[0105] /usr/sbin/iptables, [--wait -t filter -N DOCKER]
DEBU[0105] /usr/sbin/iptables, [--wait -t filter -C FORWARD -o docker0 -j DOCKER]
DEBU[0105] /usr/sbin/iptables, [--wait -I FORWARD -o docker0 -j DOCKER]
INFO[0105] Daemon has completed initialization
INFO[0105] Docker daemon commit=bb472f0/1.8.2 execdriver=native-0.2 graphdriver=devicemapper version=1.8.2
^CINFO[0186] Processing signal 'interrupt'
DEBU[0187] starting clean shutdown of all containers...
DEBU[0187] [deviceset docker-202:1-2059595] Shutdown()
DEBU[0187] [devmapper] Shutting down DeviceSet: /var/lib/docker/devicemapper
DEBU[0187] [devmapper] deactivateDevice()
DEBU[0187] [devmapper] deactivateDevice END()
DEBU[0187] [devmapper] deactivatePool()
DEBU[0187] [devmapper] deactivatePool END
DEBU[0187] [deviceset docker-202:1-2059595] Shutdown() END
DEBU[0187] Clean shutdown succeded

@bitsofinfo
Copy link

Same issue, on Azure, Centos 7.1. Following this guide: https://docs.docker.com/engine/installation/centos/

[root@dog-vm-docker-swarm-node3 dogswarm]# systemctl -l status docker.service
docker.service - Docker Application Container Engine
   Loaded: loaded (/usr/lib/systemd/system/docker.service; disabled)
   Active: failed (Result: timeout) since Fri 2015-11-13 20:06:34 UTC; 1min 28s ago
     Docs: https://docs.docker.com
 Main PID: 10973

Nov 13 20:04:52 dog-vm-docker-swarm-node3 docker[10973]: time="2015-11-13T20:04:52.662126893Z" level=info msg="API listen on /var/run/docker.sock"
Nov 13 20:04:53 dog-vm-docker-swarm-node3 docker[10973]: time="2015-11-13T20:04:53.423684537Z" level=warning msg="Usage of loopback devices is strongly discouraged for production use. Please use `--storage-opt dm.thinpooldev` or use `man docker` to refer to dm.thinpooldev section."
Nov 13 20:06:22 dog-vm-docker-swarm-node3 systemd[1]: docker.service operation timed out. Terminating.
Nov 13 20:06:34 dog-vm-docker-swarm-node3 systemd[1]: Failed to start Docker Application Container Engine.
Nov 13 20:06:34 dog-vm-docker-swarm-node3 systemd[1]: Unit docker.service entered failed state.

@sparques
Copy link

I'm hitting this issue as well (centos 7.1, docker 1.8.2). In my case, it would seem the docker service is failing to start because its dependency docker-storage-setup is failing to start.

Nov 19 12:29:09 faze.vay8.net systemd[1]: Starting Docker Storage Setup...
Nov 19 12:29:10 faze.vay8.net docker-storage-setup[1356]: Rounding up size to full physical     extent 12.00 MiB
Nov 19 12:29:10 faze.vay8.net docker-storage-setup[1356]: Volume group "centos" has insufficient free space (0 extents): 3 required.
Nov 19 12:29:10 faze.vay8.net systemd[1]: docker-storage-setup.service: main process exited, code=exited, status=5/NOTINSSTALLED
Nov 19 12:29:10 faze.vay8.net systemd[1]: Failed to start Docker Storage Setup.
Nov 19 12:29:10 faze.vay8.net systemd[1]: Unit docker-storage-setup.service entered failed state.

@thaJeztah
Copy link
Member

@deusnefum I don't think that's related to this issue, also, I think that package is used in the RedHat packaged version of Docker? if you're using the version that's packaged by RedHat/CentOS/Fedora, please report the issue in their issue tracker

@simoncpu
Copy link

Just an FYI, installing docker-selinux prevents a straightforward update:

--> Processing Conflict: docker-engine-selinux-1.9.1-1.el7.centos.noarch conflicts docker-selinux
--> Finished Dependency Resolution
Error: docker-engine-selinux conflicts with docker-selinux-1.8.2-7.el7.centos.x86_64

Update proceeds once docker-selinux is removed.

@EslamElHusseiny
Copy link

@simoncpu, seems like you are switching from docker packages to docker-engine packages, so you need to uninstall docker* and then install docker-engine which includes docker-engine-selinux as well.

@trinitronx
Copy link

On a fresh CentOS 7.1.1503 image (from Amazon AMI ami-61bbf104), I am able to reproduce this by installing docker-1.8.2-10.el7.centos.x86_64 and docker-selinux-1.8.2-10.el7.centos.x86_64 from the CentOS-7 - Extras repo. I ran setenforce 0 to set SELinux to Permissive mode before installing docker.

Behavior is interesting in that the error only happens on a fresh install when started with SystemD. After I started it manually with debug logging & -D, it worked! The stock /usr/lib/systemd/system/docker.service (plus adding DOCKER_STORAGE_OPTIONS="--storage-opt dm.no_warn_on_loop_devices=true" to /etc/sysconfig/docker-storage) ends up starting docker with command line: /usr/bin/docker daemon --storage-opt dm.no_warn_on_loop_devices=true.

The first time, docker needs to set up the devicemapper storage using loopback device. However, it appears to be too slow to complete this, and it hangs with message DEBU[0000] activateDeviceIfNeeded(). SystemD then assumes it did not start, waits for a holdoff period, and tries to re-start docker daemon.

After starting manually with sudo /usr/bin/docker daemon -D -l debug --storage-opt dm.no_warn_on_loop_devices=true, I observe the hang at activateDeviceIfNeeded(), plus some more warnings encountered by the original poster. Eventually, the service starts, and I can run sudo docker version and sudo docker ps in another terminal and see that they are working and outputting the docker API GET requests in the terminal where I started docker daemon manually.

I can then stop docker in my terminal and re-start it via SystemD with: sudo systemctl start docker. After this point, it works because it does not run into the service re-start issue caused by storage backend initialization.

The logs for when I manually start docker daemon are below:

$ sudo /usr/bin/docker daemon -D -l debug  --storage-opt dm.no_warn_on_loop_devices=true
DEBU[0000] Registering DELETE, /containers/{name:.*}
DEBU[0000] Registering DELETE, /images/{name:.*}
DEBU[0000] Registering OPTIONS,
DEBU[0000] Registering HEAD, /containers/{name:.*}/archive
DEBU[0000] Registering GET, /images/{name:.*}/get
DEBU[0000] Registering GET, /images/{name:.*}/json
DEBU[0000] Registering GET, /containers/{name:.*}/changes
DEBU[0000] Registering GET, /containers/{name:.*}/logs
DEBU[0000] Registering GET, /version
DEBU[0000] Registering GET, /images/search
DEBU[0000] Registering GET, /images/{name:.*}/tags
DEBU[0000] Registering GET, /containers/json
DEBU[0000] Registering GET, /containers/{name:.*}/export
DEBU[0000] Registering GET, /containers/{name:.*}/stats
DEBU[0000] Registering GET, /exec/{id:.*}/json
DEBU[0000] Registering GET, /images/json
DEBU[0000] Registering GET, /images/{name:.*}/history
DEBU[0000] Registering GET, /containers/{name:.*}/json
DEBU[0000] Registering GET, /containers/{name:.*}/attach/ws
DEBU[0000] Registering GET, /_ping
DEBU[0000] Registering GET, /events
DEBU[0000] Registering GET, /info
DEBU[0000] Registering GET, /images/get
DEBU[0000] Registering GET, /containers/ps
DEBU[0000] Registering GET, /containers/{name:.*}/top
DEBU[0000] Registering GET, /containers/{name:.*}/archive
DEBU[0000] Registering POST, /images/create
DEBU[0000] Registering POST, /containers/create
DEBU[0000] Registering POST, /containers/{name:.*}/resize
DEBU[0000] Registering POST, /containers/{name:.*}/copy
DEBU[0000] Registering POST, /containers/{name:.*}/exec
DEBU[0000] Registering POST, /exec/{name:.*}/resize
DEBU[0000] Registering POST, /commit
DEBU[0000] Registering POST, /images/load
DEBU[0000] Registering POST, /images/{name:.*}/tag
DEBU[0000] Registering POST, /containers/{name:.*}/unpause
DEBU[0000] Registering POST, /containers/{name:.*}/restart
DEBU[0000] Registering POST, /containers/{name:.*}/wait
DEBU[0000] Registering POST, /containers/{name:.*}/attach
DEBU[0000] Registering POST, /build
DEBU[0000] Registering POST, /images/{name:.*}/push
DEBU[0000] Registering POST, /containers/{name:.*}/kill
DEBU[0000] Registering POST, /containers/{name:.*}/pause
DEBU[0000] Registering POST, /containers/{name:.*}/start
DEBU[0000] Registering POST, /exec/{name:.*}/start
DEBU[0000] Registering POST, /auth
DEBU[0000] Registering POST, /containers/{name:.*}/stop
DEBU[0000] Registering POST, /containers/{name:.*}/rename
DEBU[0000] Registering PUT, /containers/{name:.*}/archive
DEBU[0000] devicemapper: driver version is 4.29.0
DEBU[0000] Generated prefix: docker-202:1-467865
DEBU[0000] Checking for existence of the pool 'docker-202:1-467865-pool'
DEBU[0000] [devmapper]: poolDataMajMin=7:0 poolMetaMajMin=7:1

DEBU[0000] [devmapper]: Major:Minor for device: /dev/loop0 is:7:0
DEBU[0000] [devmapper]: Major:Minor for device: /dev/loop1 is:7:1
ERRO[0000] WARNING: No --storage-opt dm.thinpooldev specified, using loopback; this configuration is strongly discouraged for production use
DEBU[0000] [devmapper]: poolDataMajMin=7:0 poolMetaMajMin=7:1

DEBU[0000] docker group found. gid: 496
INFO[0000] Listening for HTTP on unix (/var/run/docker.sock)
DEBU[0000] [deviceset] constructDeviceIdMap()
DEBU[0000] Loading data for file /usr/local/lib/docker/devicemapper/metadata/base
DEBU[0000] Added deviceId=1 to DeviceIdMap
DEBU[0000] Loading data for file /usr/local/lib/docker/devicemapper/metadata/transaction-metadata
DEBU[0000] Added deviceId=1 to DeviceIdMap
DEBU[0000] [deviceset] constructDeviceIdMap() END
DEBU[0000] Removing uninitialized base image
DEBU[0000] activateDeviceIfNeeded()
DEBU[0003] [devmapper] removeDevice START(docker-202:1-467865-base)
DEBU[0003] [devmapper] removeDevice END(docker-202:1-467865-base)
DEBU[0003] unregisterDevice(1, )
DEBU[0003] Initializing base device-mapper thin volume
DEBU[0003] [devmapper] CreateDevice(poolName=/dev/mapper/docker-202:1-467865-pool, deviceId=1)
DEBU[0003] Registering device (id 1) with FS size 107374182400
DEBU[0003] registerDevice(1, )
DEBU[0003] Creating filesystem on base device-mapper thin volume
DEBU[0003] activateDeviceIfNeeded()
DEBU[0073] activateDeviceIfNeeded()
DEBU[0073] UUID for device: /dev/mapper/docker-202:1-467865-base is:06f7bd1b-1b56-468e-aa25-8dba1ba7e085
DEBU[0073] [devmapper] deactivateDevice()
DEBU[0073] [devmapper] removeDevice START(docker-202:1-467865-base)
DEBU[0073] [devmapper] removeDevice END(docker-202:1-467865-base)
DEBU[0073] [devmapper] deactivateDevice END()
INFO[0073] [graphdriver] using prior storage driver "devicemapper"
DEBU[0073] Using graph driver devicemapper
DEBU[0073] Using default logging driver json-file
DEBU[0073] Creating images graph
DEBU[0073] Restored 0 elements
DEBU[0073] Creating repository list
INFO[0073] Option DefaultDriver: bridge
INFO[0073] Option DefaultNetwork: bridge
WARN[0073] Running modprobe bridge nf_nat br_netfilter failed with message: modprobe: WARNING: Module br_netfilter not found.
insmod /lib/modules/3.10.0-229.14.1.el7.x86_64/kernel/net/llc/llc.ko
insmod /lib/modules/3.10.0-229.14.1.el7.x86_64/kernel/net/802/stp.ko
insmod /lib/modules/3.10.0-229.14.1.el7.x86_64/kernel/net/bridge/bridge.ko
insmod /lib/modules/3.10.0-229.14.1.el7.x86_64/kernel/net/netfilter/nf_conntrack.ko
insmod /lib/modules/3.10.0-229.14.1.el7.x86_64/kernel/net/netfilter/nf_nat.ko
, error: exit status 1
INFO[0073] Firewalld running: false
DEBU[0073] /usr/sbin/iptables, [--wait -t nat -D PREROUTING -m addrtype --dst-type LOCAL -j DOCKER]
DEBU[0074] /usr/sbin/iptables, [--wait -t nat -D OUTPUT -m addrtype --dst-type LOCAL ! --dst 127.0.0.0/8 -j DOCKER]
DEBU[0074] /usr/sbin/iptables, [--wait -t nat -D OUTPUT -m addrtype --dst-type LOCAL -j DOCKER]
DEBU[0074] /usr/sbin/iptables, [--wait -t nat -D PREROUTING]
DEBU[0074] /usr/sbin/iptables, [--wait -t nat -D OUTPUT]
DEBU[0074] /usr/sbin/iptables, [--wait -t nat -F DOCKER]
DEBU[0074] /usr/sbin/iptables, [--wait -t nat -X DOCKER]
DEBU[0074] Failed to Initialize Datastore due to datastore initialization requires a valid configuration. Operating in non-clustered mode
DEBU[0074] Setting bridge mac address to 02:42:96:23:62:13
DEBU[0074] Creating bridge interface "docker0" with network 172.17.42.1/16
DEBU[0074] /usr/sbin/iptables, [--wait -t nat -C POSTROUTING -s 172.17.42.1/16 ! -o docker0 -j MASQUERADE]
DEBU[0074] /usr/sbin/iptables, [--wait -t nat -I POSTROUTING -s 172.17.42.1/16 ! -o docker0 -j MASQUERADE]
DEBU[0074] /usr/sbin/iptables, [--wait -D FORWARD -i docker0 -o docker0 -j DROP]
DEBU[0074] /usr/sbin/iptables, [--wait -t filter -C FORWARD -i docker0 -o docker0 -j ACCEPT]
DEBU[0074] /usr/sbin/iptables, [--wait -I FORWARD -i docker0 -o docker0 -j ACCEPT]
DEBU[0074] /usr/sbin/iptables, [--wait -t filter -C FORWARD -i docker0 ! -o docker0 -j ACCEPT]
DEBU[0074] /usr/sbin/iptables, [--wait -I FORWARD -i docker0 ! -o docker0 -j ACCEPT]
DEBU[0074] /usr/sbin/iptables, [--wait -t filter -C FORWARD -o docker0 -m conntrack --ctstate RELATED,ESTABLISHED -j ACCEPT]
DEBU[0074] /usr/sbin/iptables, [--wait -I FORWARD -o docker0 -m conntrack --ctstate RELATED,ESTABLISHED -j ACCEPT]
DEBU[0074] /usr/sbin/iptables, [--wait -t nat -n -L DOCKER]
DEBU[0074] /usr/sbin/iptables, [--wait -t nat -N DOCKER]
DEBU[0074] /usr/sbin/iptables, [--wait -t nat -C PREROUTING -m addrtype --dst-type LOCAL -j DOCKER]
DEBU[0074] /usr/sbin/iptables, [--wait -t nat -A PREROUTING -m addrtype --dst-type LOCAL -j DOCKER]
DEBU[0074] /usr/sbin/iptables, [--wait -t nat -C OUTPUT -m addrtype --dst-type LOCAL -j DOCKER ! --dst 127.0.0.0/8]
DEBU[0074] /usr/sbin/iptables, [--wait -t nat -A OUTPUT -m addrtype --dst-type LOCAL -j DOCKER ! --dst 127.0.0.0/8]
DEBU[0074] /usr/sbin/iptables, [--wait -t filter -n -L DOCKER]
DEBU[0074] /usr/sbin/iptables, [--wait -t filter -N DOCKER]
DEBU[0074] /usr/sbin/iptables, [--wait -t filter -C FORWARD -o docker0 -j DOCKER]
DEBU[0074] /usr/sbin/iptables, [--wait -I FORWARD -o docker0 -j DOCKER]
INFO[0074] Daemon has completed initialization
INFO[0074] Docker daemon                                 commit=a01dc02/1.8.2 execdriver=native-0.2 graphdriver=devicemapper version=1.8.2-el7.centos
DEBU[0074] Calling GET /version
INFO[0074] GET /v1.20/version
DEBU[0280] Calling GET /containers/json
INFO[0280] GET /v1.20/containers/json
DEBU[0284] Calling GET /version
INFO[0284] GET /v1.20/version

So, on CentOS 7 and RHEL 7... this issue seems to be related to the storage backend initialization taking too long for SystemD to think the service is up.

@danielwhatmuff
Copy link

I have the same issue as @trinitronx

@danielwhatmuff
Copy link

Fresh install of Docker hangs when I attempt to start with systemctl start docker, however it works when started as docker daemon. I have the docker-selinux package installed.

docker -v

Docker version 1.8.2-el7, build a01dc02/1.8.2

uname -a

Linux ip-172-29-0-100.blah.local 3.10.0-327.4.4.el7.x86_64 #1 SMP Thu Dec 17 15:51:24 EST 2015 x86_64 x86_64 x86_64 GNU/Linux

@thaJeztah
Copy link
Member

@trinitronx @danielwhatmuff the default size for devicemapper has been changed back to 10G in docker 1.10 (see #18314). Also note that the CentOS Extras packages are maintained and supported by Red Hat, so any issue with those packages should be reported in their issue tracker, because unfortunately we can't make changes in those packages

@rhatdan
Copy link
Contributor

rhatdan commented Mar 9, 2016

@danielwhatmuff Please open a bugzilla on this issue.

@naftulikay
Copy link

naftulikay commented Aug 12, 2016

This bug is present again in 3.10.0-327.28.2.el7.x86_64 with Docker 1.12.0, build 8eab29e, package version:

Name        : docker-engine
Arch        : x86_64
Version     : 1.12.0
Release     : 1.el7.centos
$ find /etc/systemd /usr/lib/systemd/ -iname '*.socket' | grep docker

Nothing is found, there is no socket unit, I can fix it by scping over the docker.socket file from another host. Evidently it hasn't shipped with Docker 1.12:

[naftuli@jabronie ~]$ yum provides /usr/lib/systemd/system/docker.service | tail
docker-engine-1.12.0-1.el7.centos.x86_64 : The open-source application container
                                         : engine
Repo        : @docker
Matched from:
Filename    : /usr/lib/systemd/system/docker.service

[naftuli@jabronie ~]$ yum provides /usr/lib/systemd/system/docker.socket | tail
docker-engine-1.11.2-1.el7.centos.x86_64 : The open-source application container
                                         : engine
Repo        : docker-main-repo
Matched from:
Filename    : /usr/lib/systemd/system/docker.socket

Docker will not start:

Aug 12 22:41:24 jabronie systemd[1]: Starting Docker Application Container Engine...
Aug 12 22:41:24 jabronie docker[1191]: time="2016-08-12T22:41:24.669596177Z" level=fatal msg="no sockets found via socket activation: make sure the service was started by systemd"
Aug 12 22:41:24 jabronie systemd[1]: docker.service: main process exited, code=exited, status=1/FAILURE
Aug 12 22:41:24 jabronie systemd[1]: Failed to start Docker Application Container Engine.
Aug 12 22:41:24 jabronie systemd[1]: Unit docker.service entered failed state.
Aug 12 22:41:24 jabronie systemd[1]: docker.service failed.

The package is broken by commit 04104c3.

@thaJeztah
Copy link
Member

@rfkrocktk it's not broken, socket activation has been removed for RPM based installs; if your install has an unmodified unit file, docker should work, but if local modifications are found, yum/dnf won't replace that file; see the steps to resolve this here; https://github.com/docker/docker/blob/master/CHANGELOG.md#1120-2016-07-14

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.