Expected behavior
Docker process to remain stable
Actual behavior
Docker process restarts causing all containers to terminate
Information
In my development setup I have two containers started independently.
First container is a postgresql database attached to a data volume container created from the same image.
The second has Django, Gunicorn & Nginx. All the application code and nginx configs are accessed from the Mac via 15 host volume mounts.
The only connection between the two containers is via the 5432 port.
I believe the problem might be related to the host / data volumes. Earlier betas would fail due to performance issues accessing the files over the host mounts. Those have now gone, but performing the following “docker cp” is very slow.
docker cp $(VOL_DATA):$(VOL_PATH) - | gzip > backup-$(VOL_DATA)-$(date +%Y-%m-%d"_"%H_%M_%S).tgz
Newrelic logging at the time of the crash doesn’t indicate high load nor high I/O, so not sure it’s directly related to
https://forums.docker.com/t/virtio-9p-unexpected-eof-reading-did-the-9p-server-crash-error-when-running-i-o-intensive-application-on-docker-for-mac-bets/11550/16
Docker has 3 CPUs and 8GB allocated to it.
Not sure if related, but I’ve symlinked the “com.docker.docker” onto an SSD.
~/Library/Containers/com.docker.docker -> /Volumes/disk-2/com.docker.docker
OS X: version 10.11.3 (build: 15D21)
Docker.app: version: v1.11.1-beta14.5.m
Running diagnostic tests:
[OK] docker-cli
[OK] Moby booted
[OK] driver.amd64-linux
[OK] vmnetd
[OK] osxfs
[OK] db
[OK] slirp
[OK] menubar
[OK] environment
[OK] Docker
[OK] VT-x
Docker logs are being collected into /tmp/20160609-143927.tar.gz
Most specific failure is: No error was detected
Your unique id is: FE75486B-2746-457A-AB8C-3EEC21501215
Console syslog output below.
Jun 9 14:30:12 ip-192-168-1-18 Docker[45907]: Fatal unexpected exception: Transfuse.Socket_closed Jun 9 14:30:12 ip-192-168-1-18 Docker[10543]: Reap com.docker.osxfs (pid 45907): exit status 1 Jun 9 14:30:13 ip-192-168-1-18 Docker[10543]: Stop 1 children with order 1: com.docker.driver.amd64-linux (pid 45909) Jun 9 14:30:13 ip-192-168-1-18 Docker[10543]: Signal terminated to com.docker.driver.amd64-linux (pid 45909) Jun 9 14:30:13 ip-192-168-1-18 Docker[45909]: sending SIGTERM to com.docker.hyperkit pid 45911 Jun 9 14:30:18 ip-192-168-1-18 Docker[45909]: virtio-net-vpnkit: initialising, opts="uuid=7ec9af45-8c66-4692-9d32-e578a958df6c,path=/Users/ablake/Library/Containers/com.docker.docker/Data/s50,macfile=/Users/ablake/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/mac.0" Jun 9 14:30:18 ip-192-168-1-18 Docker[45909]: Interface will have uuid 7ec9af45-8c66-4692-9d32-e578a958df6c Jun 9 14:30:18 ip-192-168-1-18 Docker[45909]: Connection established with MAC=c0:ff:ee:c0:ff:ee and MTU 1500 Jun 9 14:30:18 ip-192-168-1-18 Docker[45909]: virtio-9p: initialising path=/Users/ablake/Library/Containers/com.docker.docker/Data/s40,tag=db Jun 9 14:30:18 ip-192-168-1-18 Docker[45909]: virtio-9p: initialising path=/Users/ablake/Library/Containers/com.docker.docker/Data/s51,tag=port Jun 9 14:30:18 ip-192-168-1-18 Docker[45909]: linkname /Users/ablake/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/tty Jun 9 14:30:18 ip-192-168-1-18 Docker[45909]: COM1 connected to /dev/ttys004 Jun 9 14:30:18 ip-192-168-1-18 Docker[45909]: COM1 linked to /Users/ablake/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/tty Jun 9 14:30:18 ip-192-168-1-18 Docker[45908]: PPP.listen: closing connection Jun 9 14:30:18 ip-192-168-1-18 Docker[44606]: VM has shutdown at 2016-06-09 14:30:18 +0100 BST Jun 9 14:30:18 ip-192-168-1-18 Docker[10543]: Reap com.docker.driver.amd64-linux (pid 45909): exit status 0 Jun 9 14:30:18 ip-192-168-1-18 Docker[10524]: dockerState = starting Jun 9 14:30:18 ip-192-168-1-18 Docker[10543]: Stop 2 children with order 2: com.docker.osxfs (pid 45907), com.docker.slirp (pid 45908) Jun 9 14:30:18 ip-192-168-1-18 Docker[10543]: Signal terminated to com.docker.slirp (pid 45908) Jun 9 14:30:18 ip-192-168-1-18 Docker[10543]: Reap com.docker.slirp (pid 45908): signal: terminated Jun 9 14:30:18 ip-192-168-1-18 Docker[10543]: Starting com.docker.osxfs, com.docker.slirp, com.docker.driver.amd64-linux Jun 9 14:30:18 ip-192-168-1-18 Docker[10543]: Start com.docker.osxfs (pid 47947) Jun 9 14:30:18 ip-192-168-1-18 Docker[10543]: Start com.docker.slirp (pid 47948) Jun 9 14:30:18 ip-192-168-1-18 Docker[10543]: Start com.docker.driver.amd64-linux (pid 47949) Jun 9 14:30:18 ip-192-168-1-18 Docker[47947]: Logging to Apple System Log Jun 9 14:30:18 ip-192-168-1-18 Docker[47948]: Logging to Apple System Log Jun 9 14:30:18 ip-192-168-1-18 Docker[47948]: Setting handler to ignore all SIGPIPE signals Jun 9 14:30:18 ip-192-168-1-18 Docker[47948]: starting port_forwarding port_control_path:fd:4 vsock_path:/Users/ablake/Library/Containers/com.docker.docker/Data/@connect Jun 9 14:30:18 ip-192-168-1-18 Docker[47948]: attempting to reconnect to database on unix /Users/ablake/Library/Containers/com.docker.docker/Data/s40 Jun 9 14:30:18 ip-192-168-1-18 Docker[47948]: reconnected transport layer Jun 9 14:30:18 ip-192-168-1-18 Docker[47948]: allowing binds to any IP addresses Jun 9 14:30:18 ip-192-168-1-18 Docker[47948]: Creating slirp server pcap_settings:disabled peer_ip:192.168.65.2 local_ip:192.168.65.1 Jun 9 14:30:18 ip-192-168-1-18 Docker[47949]: Acquired hypervisor lock Jun 9 14:30:18 ip-192-168-1-18 Docker[47949]: Docker is not responding: waiting 0.5s Jun 9 14:30:18 ip-192-168-1-18 Docker[47949]: hypervisor: native Jun 9 14:30:18 ip-192-168-1-18 Docker[47949]: filesystem: osxfs Jun 9 14:30:18 ip-192-168-1-18 Docker[47947]: Using protocol TwoThousand msize 16384 Jun 9 14:30:18 ip-192-168-1-18 Docker[47949]: Hypervisor: native; BootProtocol: direct; UefiBootDisk: /Users/ablake/UefiBoot.qcow2 Jun 9 14:30:18 ip-192-168-1-18 Docker[47949]: Launching: /Applications/Docker.app/Contents/MacOS/com.docker.hyperkit -A -m 8G -c 3 -u -s 0:0,hostbridge -s 31,lpc -s 2:0,virtio-vpnkit,uuid=7ec9af45-8c66-4692-9d32-e578a958df6c,path=/Users/ablake/Library/Containers/com.docker.docker/Data/s50,macfile=/Users/ablake/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/mac.0 -s 3,virtio-blk,file:///Users/ablake/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/Docker.qcow2,format=qcow -s 4,virtio-9p,path=/Users/ablake/Library/Containers/com.docker.docker/Data/s40,tag=db -s 5,virtio-rnd -s 6,virtio-9p,path=/Users/ablake/Library/Containers/com.docker.docker/Data/s51,tag=port -s 7,virtio-sock,guest_cid=3,path=/Users/ablake/Library/Containers/com.docker.docker/Data,guest_forwards=2376;1525 -l com1,autopty=/Users/ablake/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/tty,log=/Users/ablake/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/console-ring -f kexec,/Applications/Docker.app/Contents/Resources/moby/vmlinuz64,/Applications/Docker.app/Contents/Resources/moby/initrd.img,earlyprintk=serial console=ttyS0 com.docker.driverDir="/Users/ablake/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux", com.docker.database="com.docker.driver.amd64-linux" -F /Users/ablake/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/hypervisor.pid Jun 9 14:30:18 ip-192-168-1-18 Docker[47948]: PPP.negotiate: received ((magic VMN3T)(version 1)(commit 984649fbd63d53a62b34f08b59694d4d569b74d5)) Jun 9 14:30:18 ip-192-168-1-18 Docker[47948]: PPP.negotiate: received (Ethernet 7ec9af45-8c66-4692-9d32-e578a958df6c) Jun 9 14:30:18 ip-192-168-1-18 Docker[47948]: PPP.negotiate: sending ((mtu 1500)(max_packet_size 1550)(client_macaddr c0:ff:ee:c0:ff:ee)) Jun 9 14:30:18 ip-192-168-1-18 Docker[47949]: virtio-net-vpnkit: magic=VMN3T version=1 commit=0123456789012345678901234567890123456789 Jun 9 14:30:18 ip-192-168-1-18 Docker[47948]: PPP.listen: called a second time: doing nothing Jun 9 14:30:18 ip-192-168-1-18 Docker[47948]: TCP/IP ready Jun 9 14:30:18 ip-192-168-1-18 Docker[47949]: mirage_block_open file:///Users/ablake/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/Docker.qcow2 buffered = true Jun 9 14:30:18 ip-192-168-1-18 Docker[47949]: mirage_block_open returning 0 Jun 9 14:30:18 ip-192-168-1-18 Docker[47949]: mirage_block_stat Jun 9 14:30:18 ip-192-168-1-18 Docker[47949]: vsock init 7:0 = /Users/ablake/Library/Containers/com.docker.docker/Data, guest_cid = 3 Jun 9 14:30:21 ip-192-168-1-18 Docker[47949]: Jun 9 14:30:21 ip-192-168-1-18 Docker[47949]: Docker is not responding: waiting 0.5s Jun 9 14:30:22 ip-192-168-1-18 Docker[47949]: Docker is not responding: waiting 0.5s Jun 9 14:30:23 ip-192-168-1-18 Docker[47947]: transfused: mount Jun 9 14:30:23 ip-192-168-1-18 Docker[47947]: transfused: /bin/fusermount Jun 9 14:30:23 ip-192-168-1-18 Docker[47947]: transfused: -o Jun 9 14:30:23 ip-192-168-1-18 Docker[47947]: transfused: allow_other,max_read=1048576,subtype=osxfs Jun 9 14:30:23 ip-192-168-1-18 Docker[47947]: transfused: /Mac Jun 9 14:30:23 ip-192-168-1-18 Docker[47947]: osxfs tracing: OFF Jun 9 14:30:23 ip-192-168-1-18 Docker[47947]: transfused: Jun 9 14:30:23 ip-192-168-1-18 Docker[47949]: Docker is not responding: waiting 0.5s Jun 9 14:30:24 ip-192-168-1-18 Docker[47948]: Using protocol TwoThousand msize 8192 Jun 9 14:30:26 ip-192-168-1-18 Docker[47949]: Docker is responding Jun 9 14:30:26 ip-192-168-1-18 Docker[44606]: VM has started at 2016-06-09 14:30:26 +0100 BST Jun 9 14:30:26 ip-192-168-1-18 Docker[10524]: dockerState = running
Steps to reproduce the behavior
- Unfortunately I can’t share my Dockerfiles
- Happens several times a day during development.