Docker-compose slow, crashes app, unusable in beta13

davidham · May 26, 2016, 5:35pm

Expected behavior

I have an app in two containers, a Rails app in one container and a Postgres database in another. I run them in docker-compose. I also have browsersync running as part of my gulp setup and refreshing the page as I make changes, though the crashing happens whether I use the gulp proxy or not. The beta12 I installed on Monday ran them with no issues.

Actual behavior

Under beta13, the app runs very slowly and crashes often. It’s not just the app though; the Docker daemon crashes and kills both containers, and I have to docker-compose up again to start them.

Information

$ pinata diagnose -u
OS X: version 10.11.5 (build: 15F34)
Docker.app: version v1.11.1-beta13
Running diagnostic tests:
[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/20160526-121823.tar.gz
Most specific failure is: No error was detected
Your unique id is: 6F8334E6-2BF2-4163-8435-8DC7508A0941

Running OSX 10.11.5.

Steps to reproduce the behavior

docker-compose up -d
Use the app normally.
After a few very slow pageviews, app crashes

Things I tried

Stopping Docker and restarting
Restarting computer
Uninstalling Docker and reinstalling from scratch

Also, here is a dump from the Docker logs:

5/26/16 12:13:16.870 PM Docker[5313]: Creating resource Entry(5cf866e1e19d7c3166e9101c17697b1c3811c1e34a9f877ce6a7b55633d6f603)
5/26/16 12:13:16.872 PM Docker[5313]: Write offset=0 data=[5cf866e1e19d7c3166e9101c17697b1c3811c1e34a9f877ce6a7b55633d6f603:/Users/davidham/Sites/PharmaStart/app] to file
5/26/16 12:13:16.872 PM Docker[5313]: Volume.start 5cf866e1e19d7c3166e9101c17697b1c3811c1e34a9f877ce6a7b55633d6f603 (paths = [/Users/davidham/Sites/PharmaStart/app])
5/26/16 12:13:16.876 PM Docker[5313]: Created instance 5cf866e1e19d7c3166e9101c17697b1c3811c1e34a9f877ce6a7b55633d6f603
5/26/16 12:13:16.913 PM Docker[5314]: Creating resource Entry(tcp:0.0.0.0:443:tcp:172.17.0.3:3000)
5/26/16 12:13:16.916 PM Docker[5314]: Write offset=0 data=[tcp:0.0.0.0:443:tcp:172.17.0.3:3000] to file
5/26/16 12:13:16.923 PM Docker[5558]: Client reports version 1, commit 0123456789012345678901234567890123456789
5/26/16 12:13:16.923 PM Docker[5314]: Client.negotiate: received ((magic VMN3T)(version 15)(commit 16dbe555c7dd4304521b21e8286d83fe4864c15c))
5/26/16 12:13:16.923 PM Docker[5558]: sendmsg ok
5/26/16 12:13:16.924 PM Docker[5314]: Created instance tcp:0.0.0.0:443:tcp:172.17.0.3:3000
5/26/16 12:16:21.501 PM Docker[5314]: Socket.TCPV4.write tcp:0.0.0.0:443:tcp:172.17.0.3:3000: caught Unix.Unix_error(Unix.EPIPE, "write", "") returning Eof
5/26/16 12:16:21.501 PM Docker[5314]: tcp:0.0.0.0:443:tcp:172.17.0.3:3000 proxy failed with flow proxy b: write failed with Eof
5/26/16 12:16:21.927 PM Docker[5314]: Socket.TCPV4.write tcp:0.0.0.0:443:tcp:172.17.0.3:3000: caught Unix.Unix_error(Unix.EPIPE, "write", "") returning Eof
5/26/16 12:16:21.927 PM Docker[5314]: tcp:0.0.0.0:443:tcp:172.17.0.3:3000 proxy failed with flow proxy b: write failed with Eof
5/26/16 12:16:24.520 PM Docker[5314]: Socket.TCPV4.write tcp:0.0.0.0:443:tcp:172.17.0.3:3000: caught Unix.Unix_error(Unix.EPIPE, "write", "") returning Eof
5/26/16 12:16:24.520 PM Docker[5314]: tcp:0.0.0.0:443:tcp:172.17.0.3:3000 proxy failed with flow proxy b: write failed with Eof
5/26/16 12:16:24.663 PM Docker[5314]: Socket.TCPV4.write tcp:0.0.0.0:443:tcp:172.17.0.3:3000: caught Unix.Unix_error(Unix.EPIPE, "write", "") returning Eof
5/26/16 12:16:24.663 PM Docker[5314]: tcp:0.0.0.0:443:tcp:172.17.0.3:3000 proxy failed with flow proxy b: write failed with Eof
5/26/16 12:16:24.866 PM Docker[5314]: Socket.TCPV4.write tcp:0.0.0.0:443:tcp:172.17.0.3:3000: caught Unix.Unix_error(Unix.EPIPE, "write", "") returning Eof
5/26/16 12:16:24.866 PM Docker[5314]: tcp:0.0.0.0:443:tcp:172.17.0.3:3000 proxy failed with flow proxy b: write failed with Eof
5/26/16 12:16:25.631 PM Docker[5314]: Socket.TCPV4.write tcp:0.0.0.0:443:tcp:172.17.0.3:3000: caught Unix.Unix_error(Unix.EPIPE, "write", "") returning Eof
5/26/16 12:16:25.631 PM Docker[5314]: tcp:0.0.0.0:443:tcp:172.17.0.3:3000 proxy failed with flow proxy b: write failed with Eof
5/26/16 12:16:25.776 PM Docker[5314]: Socket.TCPV4.write tcp:0.0.0.0:443:tcp:172.17.0.3:3000: caught Unix.Unix_error(Unix.EPIPE, "write", "") returning Eof
5/26/16 12:16:25.776 PM Docker[5314]: tcp:0.0.0.0:443:tcp:172.17.0.3:3000 proxy failed with flow proxy b: write failed with Eof
5/26/16 12:16:26.094 PM Docker[5314]: Socket.TCPV4.write tcp:0.0.0.0:443:tcp:172.17.0.3:3000: caught Unix.Unix_error(Unix.EPIPE, "write", "") returning Eof
5/26/16 12:16:26.095 PM Docker[5314]: tcp:0.0.0.0:443:tcp:172.17.0.3:3000 proxy failed with flow proxy b: write failed with Eof
5/26/16 12:16:26.523 PM Docker[5314]: Socket.TCPV4.write tcp:0.0.0.0:443:tcp:172.17.0.3:3000: caught Unix.Unix_error(Unix.EPIPE, "write", "") returning Eof
5/26/16 12:16:26.523 PM Docker[5314]: tcp:0.0.0.0:443:tcp:172.17.0.3:3000 proxy failed with flow proxy b: write failed with Eof
5/26/16 12:16:48.467 PM Docker[5314]: Socket.TCPV4.write tcp:0.0.0.0:443:tcp:172.17.0.3:3000: caught Unix.Unix_error(Unix.EPIPE, "write", "") returning Eof
5/26/16 12:16:48.467 PM Docker[5314]: tcp:0.0.0.0:443:tcp:172.17.0.3:3000 proxy failed with flow proxy b: write failed with Eof
5/26/16 12:16:50.912 PM Docker[5314]: Socket.TCPV4.write tcp:0.0.0.0:443:tcp:172.17.0.3:3000: caught Unix.Unix_error(Unix.EPIPE, "write", "") returning Eof
5/26/16 12:16:50.912 PM Docker[5314]: tcp:0.0.0.0:443:tcp:172.17.0.3:3000 proxy failed with flow proxy b: write failed with Eof
5/26/16 12:16:51.346 PM Docker[5314]: Socket.TCPV4.write tcp:0.0.0.0:443:tcp:172.17.0.3:3000: caught Unix.Unix_error(Unix.EPIPE, "write", "") returning Eof
5/26/16 12:16:51.346 PM Docker[5314]: tcp:0.0.0.0:443:tcp:172.17.0.3:3000 proxy failed with flow proxy b: write failed with Eof
5/26/16 12:16:51.850 PM Docker[5314]: Socket.TCPV4.write tcp:0.0.0.0:443:tcp:172.17.0.3:3000: caught Unix.Unix_error(Unix.EPIPE, "write", "") returning Eof
5/26/16 12:16:51.850 PM Docker[5314]: tcp:0.0.0.0:443:tcp:172.17.0.3:3000 proxy failed with flow proxy b: write failed with Eof
5/26/16 12:16:51.938 PM Docker[5314]: Socket.TCPV4.write tcp:0.0.0.0:443:tcp:172.17.0.3:3000: caught Unix.Unix_error(Unix.EPIPE, "write", "") returning Eof
5/26/16 12:16:51.938 PM Docker[5314]: tcp:0.0.0.0:443:tcp:172.17.0.3:3000 proxy failed with flow proxy b: write failed with Eof
5/26/16 12:17:08.287 PM Docker[5313]: Unknown exception caught: End_of_file
5/26/16 12:17:08.287 PM Docker[5313]: Fatal unexpected exception: End_of_file
5/26/16 12:17:08.292 PM Docker[5310]: Reap com.docker.osxfs (pid 5313): exit status 1
5/26/16 12:17:08.431 PM Docker[5314]: Socket.TCPV4.write tcp:0.0.0.0:443:tcp:172.17.0.3:3000: caught Unix.Unix_error(Unix.EPIPE, "write", "") returning Eof
5/26/16 12:17:08.431 PM Docker[5314]: tcp:0.0.0.0:443:tcp:172.17.0.3:3000 proxy failed with flow proxy a: write failed with Eof
5/26/16 12:17:09.296 PM Docker[5310]: Stop 1 children with order 1: com.docker.driver.amd64-linux (pid 5316)
5/26/16 12:17:09.296 PM Docker[5310]: Signal terminated to com.docker.driver.amd64-linux (pid 5316)
5/26/16 12:17:09.306 PM Docker[5316]: sending SIGTERM to com.docker.hyperkit pid 5319
5/26/16 12:17:15.339 PM Docker[5316]: virtio-net-ipc: initialising uuid=444d6909-97a3-41db-89ea-73740d880d86,path=/Users/davidham/Library/Containers/com.docker.docker/Data/s50,macfile=/Users/davidham/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/mac.0
5/26/16 12:17:15.340 PM Docker[5316]: Interface will have uuid 444d6909-97a3-41db-89ea-73740d880d86
5/26/16 12:17:15.340 PM Docker[5316]: Connection established with MAC=c0:ff:ee:c0:ff:ee and MTU 1500
5/26/16 12:17:15.340 PM Docker[5316]: virtio-9p: initialising path=/Users/davidham/Library/Containers/com.docker.docker/Data/s40,tag=db
5/26/16 12:17:15.340 PM Docker[5316]: virtio-9p: initialising path=/Users/davidham/Library/Containers/com.docker.docker/Data/s51,tag=port
5/26/16 12:17:15.340 PM Docker[5316]: linkname /Users/davidham/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/tty
5/26/16 12:17:15.340 PM Docker[5316]: COM1 connected to /dev/ttys000
5/26/16 12:17:15.340 PM Docker[5316]: COM1 linked to /Users/davidham/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/tty
5/26/16 12:17:15.358 PM Docker[5314]: PPP.listen: closing connection
5/26/16 12:17:15.377 PM Docker[5315]: VM has shutdown at 2016-05-26 12:17:15 -0500 CDT
5/26/16 12:17:15.380 PM Docker[5310]: Reap com.docker.driver.amd64-linux (pid 5316): exit status 0
5/26/16 12:17:15.404 PM Docker[5280]: dockerState = starting
5/26/16 12:17:15.407 PM Docker[5310]: Stop 2 children with order 2: com.docker.osxfs (pid 5313), com.docker.slirp (pid 5314)
5/26/16 12:17:15.407 PM Docker[5310]: Signal terminated to com.docker.slirp (pid 5314)
5/26/16 12:17:15.411 PM Docker[5310]: Reap com.docker.slirp (pid 5314): signal: terminated
5/26/16 12:17:15.513 PM Docker[5310]: Starting com.docker.osxfs, com.docker.slirp, com.docker.driver.amd64-linux
5/26/16 12:17:15.515 PM Docker[5310]: Start com.docker.osxfs (pid 5705)
5/26/16 12:17:15.518 PM Docker[5310]: Start com.docker.slirp (pid 5706)
5/26/16 12:17:15.521 PM Docker[5310]: Start com.docker.driver.amd64-linux (pid 5707)
5/26/16 12:17:15.541 PM Docker[5707]: Acquired hypervisor lock
5/26/16 12:17:15.544 PM Docker[5707]: Docker is not responding: waiting 0.5s
5/26/16 12:17:15.545 PM Docker[5705]: Logging to Apple System Log
5/26/16 12:17:15.548 PM Docker[5706]: Logging to Apple System Log
5/26/16 12:17:15.548 PM Docker[5706]: Setting handler to ignore all SIGPIPE signals
5/26/16 12:17:15.548 PM Docker[5706]: starting port_forwarding port_control_path:fd:4 vsock_path:/Users/davidham/Library/Containers/com.docker.docker/Data/@connect
5/26/16 12:17:15.548 PM Docker[5706]: attempting to reconnect to database on unix /Users/davidham/Library/Containers/com.docker.docker/Data/s40
5/26/16 12:17:15.550 PM Docker[5706]: reconnected transport layer
5/26/16 12:17:15.551 PM Docker[5706]: allowing binds to any IP addresses
5/26/16 12:17:15.554 PM Docker[5706]: Creating slirp server pcap_settings:disabled peer_ip:192.168.65.2 local_ip:192.168.65.1
5/26/16 12:17:15.618 PM Docker[5707]: hypervisor: native
5/26/16 12:17:15.618 PM Docker[5707]: filesystem: osxfs
5/26/16 12:17:15.619 PM Docker[5705]: Using protocol TwoThousand msize 16384
5/26/16 12:17:15.620 PM Docker[5707]: Hypervisor: native; BootProtocol: direct; UefiBootDisk: /Users/davidham/UefiBoot.qcow2
5/26/16 12:17:15.620 PM Docker[5707]: Launching: /Applications/Docker.app/Contents/MacOS/com.docker.hyperkit -A -m 2G -c 2 -u -s 0:0,hostbridge -s 31,lpc -s 2:0,virtio-ipc,uuid=444d6909-97a3-41db-89ea-73740d880d86,path=/Users/davidham/Library/Containers/com.docker.docker/Data/s50,macfile=/Users/davidham/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/mac.0 -s 3,virtio-blk,file:///Users/davidham/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/Docker.qcow2,format=qcow -s 4,virtio-9p,path=/Users/davidham/Library/Containers/com.docker.docker/Data/s40,tag=db -s 5,virtio-rnd -s 6,virtio-9p,path=/Users/davidham/Library/Containers/com.docker.docker/Data/s51,tag=port -s 7,virtio-sock,guest_cid=3,path=/Users/davidham/Library/Containers/com.docker.docker/Data,guest_forwards=2376;1525 -l com1,autopty=/Users/davidham/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/tty,log=/Users/davidham/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/davidham/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux", com.docker.database="com.docker.driver.amd64-linux" -F /Users/davidham/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/hypervisor.pid
5/26/16 12:17:15.647 PM Docker[5709]: Starting hyperkit
5/26/16 12:17:15.647 PM Docker[5707]: May 26 12:17:15  Docker[5709] <Notice>: Starting hyperkit
5/26/16 12:17:15.647 PM Docker[5706]: PPP.negotiate: received ((magic VMN3T)(version 15)(commit 16dbe555c7dd4304521b21e8286d83fe4864c15c))
5/26/16 12:17:15.647 PM Docker[5706]: PPP.negotiate: received (Ethernet 444d6909-97a3-41db-89ea-73740d880d86)
5/26/16 12:17:15.647 PM Docker[5706]: PPP.negotiate: sending ((mtu 1500)(max_packet_size 1550)(client_macaddr c0:ff:ee:c0:ff:ee))
5/26/16 12:17:15.648 PM Docker[5707]: mirage_block_open file:///Users/davidham/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/Docker.qcow2 buffered = true
5/26/16 12:17:15.648 PM Docker[5707]: mirage_block_open returning 0
5/26/16 12:17:15.648 PM Docker[5707]: mirage_block_stat
5/26/16 12:17:15.649 PM Docker[5707]: vsock init 7:0 = /Users/davidham/Library/Containers/com.docker.docker/Data, guest_cid = 3
5/26/16 12:17:15.649 PM Docker[5706]: PPP.listen: called a second time: doing nothing
5/26/16 12:17:15.649 PM Docker[5706]: TCP/IP ready
5/26/16 12:17:17.458 PM Docker[5707]: 
rdmsr to register 0x34 on vcpu 1
5/26/16 12:17:17.545 PM Docker[5707]: Docker is not responding: waiting 0.5s
5/26/16 12:17:18.049 PM Docker[5707]: Docker is not responding: waiting 0.5s
5/26/16 12:17:18.554 PM Docker[5707]: Docker is not responding: waiting 0.5s
5/26/16 12:17:19.056 PM Docker[5707]: Docker is not responding: waiting 0.5s
5/26/16 12:17:19.558 PM Docker[5707]: Docker is not responding: waiting 0.5s
5/26/16 12:17:20.050 PM Docker[5705]: transfused: mount 
5/26/16 12:17:20.051 PM Docker[5705]: transfused: /bin/fusermount 
5/26/16 12:17:20.051 PM Docker[5705]: transfused: -o 
5/26/16 12:17:20.051 PM Docker[5705]: transfused: allow_other,max_read=1048576,subtype=osxfs 
5/26/16 12:17:20.051 PM Docker[5705]: transfused: /Mac 
5/26/16 12:17:20.051 PM Docker[5705]: transfused: 
5/26/16 12:17:20.052 PM Docker[5705]: osxfs tracing: OFF 
5/26/16 12:17:20.060 PM Docker[5707]: Docker is not responding: waiting 0.5s
5/26/16 12:17:20.060 PM Docker[5706]: Using protocol TwoThousand msize 8192
5/26/16 12:17:21.791 PM Docker[5707]: Docker is responding
5/26/16 12:17:21.803 PM Docker[5315]: VM has started at 2016-05-26 12:17:21 -0500 CDT
5/26/16 12:17:21.859 PM Docker[5280]: dockerState = running
5/26/16 12:18:23.914 PM Docker[5756]: EOF reading packet from Unix domain socket: closing
5/26/16 12:18:23.915 PM Docker[5756]: Failed to read hello from client
5/26/16 12:18:23.916 PM Docker[5706]: server loop caught Failure("Caught EOF on underlying FLOW"): no further requests will be processed

cregeith · May 27, 2016, 9:32am

Hi,

Same issue there, with docker-compose and rails app.

This is logs when crashing

May 27 11:18:18 android-f729a1a2b75be60b Docker[4339] <Error>: recvfrom failed with Lwt.Canceled
May 27 11:18:18 android-f729a1a2b75be60b Docker[4339] <Error>: DNS response timed out after 5s
May 27 11:22:13 android-f729a1a2b75be60b Docker[4338] <Error>: Unknown exception caught: End_of_file
May 27 11:22:13 android-f729a1a2b75be60b Docker[4338] <Error>: Fatal unexpected exception: End_of_file
May 27 11:22:13 android-f729a1a2b75be60b Docker[4335] <Notice>: Reap com.docker.osxfs (pid 4338): exit status 1
May 27 11:22:14 android-f729a1a2b75be60b Docker[4335] <Notice>: Stop 1 children with order 1: com.docker.driver.amd64-linux (pid 4341)
May 27 11:22:14 android-f729a1a2b75be60b Docker[4335] <Notice>: Signal terminated to com.docker.driver.amd64-linux (pid 4341)
May 27 11:22:14 android-f729a1a2b75be60b Docker[4341] <Notice>: sending SIGTERM to com.docker.hyperkit pid 4344
May 27 11:22:19 android-f729a1a2b75be60b Docker[4341] <Notice>: virtio-net-ipc: initialising uuid=9165ba41-14ce-4de0-b4f2-b1437e3be6cc,path=/var/tmp/com.docker.vmnetd.socket,macfile=/Users/mickael/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/mac.0
May 27 11:22:19 android-f729a1a2b75be60b Docker[4341] <Notice>: Interface will have uuid 9165ba41-14ce-4de0-b4f2-b1437e3be6cc
May 27 11:22:19 android-f729a1a2b75be60b Docker[4341] <Notice>: Connection established with MAC=6e:02:5d:7d:cf:32 and MTU 1500
May 27 11:22:19 android-f729a1a2b75be60b Docker[4341] <Notice>: virtio-net-ipc: initialising uuid=65eadca0-5e7e-4ff5-a2b1-8b91759a1724,path=/Users/mickael/Library/Containers/com.docker.docker/Data/s50,macfile=/Users/mickael/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/mac.1
May 27 11:22:19 android-f729a1a2b75be60b Docker[4341] <Notice>: Interface will have uuid 65eadca0-5e7e-4ff5-a2b1-8b91759a1724
May 27 11:22:19 android-f729a1a2b75be60b Docker[4341] <Notice>: Connection established with MAC=c0:ff:ee:c0:ff:ee and MTU 1500
May 27 11:22:19 android-f729a1a2b75be60b Docker[4341] <Notice>: virtio-9p: initialising path=/Users/mickael/Library/Containers/com.docker.docker/Data/s40,tag=db
May 27 11:22:19 android-f729a1a2b75be60b Docker[4341] <Notice>: virtio-9p: initialising path=/Users/mickael/Library/Containers/com.docker.docker/Data/s51,tag=port
May 27 11:22:19 android-f729a1a2b75be60b Docker[4341] <Notice>: linkname /Users/mickael/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/tty
May 27 11:22:19 android-f729a1a2b75be60b Docker[4341] <Notice>: COM1 connected to /dev/ttys000
May 27 11:22:19 android-f729a1a2b75be60b Docker[4341] <Notice>: COM1 linked to /Users/mickael/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/tty
May 27 11:22:19 android-f729a1a2b75be60b Docker[4339] <Notice>: PPP.listen: closing connection
May 27 11:22:19 android-f729a1a2b75be60b Docker[4345] <Notice>: EOF reading packet from Unix domain socket: closing
May 27 11:22:19 android-f729a1a2b75be60b Docker[4345] <Error>: Failed to read header
May 27 11:22:19 android-f729a1a2b75be60b Docker[4345] <Notice>: Stopping vmnet interface
May 27 11:22:19 android-f729a1a2b75be60b Docker[4340] <Notice>: VM has shutdown at 2016-05-27 11:22:19 +0200 CEST
May 27 11:22:19 android-f729a1a2b75be60b Docker[4335] <Notice>: Reap com.docker.driver.amd64-linux (pid 4341): exit status 0
May 27 11:22:19 android-f729a1a2b75be60b Docker[4345] <Notice>: Vmnet interface stopped
May 27 11:22:19 android-f729a1a2b75be60b Docker[4345] <Notice>: Vmnet shutdown done
May 27 11:22:19 android-f729a1a2b75be60b Docker[4322] <Notice>: dockerState = starting
May 27 11:22:19 android-f729a1a2b75be60b Docker[4335] <Notice>: Stop 2 children with order 2: com.docker.osxfs (pid 4338), com.docker.slirp (pid 4339)
May 27 11:22:19 android-f729a1a2b75be60b Docker[4335] <Notice>: Signal terminated to com.docker.slirp (pid 4339)
May 27 11:22:19 android-f729a1a2b75be60b Docker[4335] <Notice>: Reap com.docker.slirp (pid 4339): signal: terminated
May 27 11:22:19 android-f729a1a2b75be60b Docker[4335] <Notice>: Starting com.docker.osxfs, com.docker.slirp, com.docker.driver.amd64-linux
May 27 11:22:19 android-f729a1a2b75be60b Docker[4335] <Notice>: Start com.docker.osxfs (pid 4429)
May 27 11:22:19 android-f729a1a2b75be60b Docker[4335] <Notice>: Start com.docker.slirp (pid 4430)
May 27 11:22:19 android-f729a1a2b75be60b Docker[4335] <Notice>: Start com.docker.driver.amd64-linux (pid 4431)
May 27 11:22:19 android-f729a1a2b75be60b Docker[4429] <Notice>: Logging to Apple System Log
May 27 11:22:19 android-f729a1a2b75be60b Docker[4430] <Notice>: Logging to Apple System Log
May 27 11:22:19 android-f729a1a2b75be60b Docker[4430] <Notice>: Setting handler to ignore all SIGPIPE signals
May 27 11:22:19 android-f729a1a2b75be60b Docker[4430] <Notice>: starting port_forwarding port_control_path:fd:4 vsock_path:/Users/mickael/Library/Containers/com.docker.docker/Data/@connect
May 27 11:22:19 android-f729a1a2b75be60b Docker[4430] <Notice>: attempting to reconnect to database on unix /Users/mickael/Library/Containers/com.docker.docker/Data/s40
May 27 11:22:19 android-f729a1a2b75be60b Docker[4430] <Notice>: reconnected transport layer
May 27 11:22:19 android-f729a1a2b75be60b Docker[4430] <Notice>: allowing binds to any IP addresses
May 27 11:22:19 android-f729a1a2b75be60b Docker[4430] <Notice>: Creating slirp server pcap_settings:disabled peer_ip:192.168.65.2 local_ip:192.168.65.1
May 27 11:22:19 android-f729a1a2b75be60b Docker[4431] <Notice>: Acquired hypervisor lock
May 27 11:22:19 android-f729a1a2b75be60b Docker[4431] <Notice>: Docker is not responding: waiting 0.5s
May 27 11:22:19 android-f729a1a2b75be60b Docker[4431] <Notice>: hypervisor: native
May 27 11:22:19 android-f729a1a2b75be60b Docker[4431] <Notice>: filesystem: osxfs
May 27 11:22:19 android-f729a1a2b75be60b Docker[4429] <Notice>: Using protocol TwoThousand msize 16384
May 27 11:22:19 android-f729a1a2b75be60b Docker[4431] <Notice>: Hypervisor: native; BootProtocol: direct; UefiBootDisk: /Users/mickael/UefiBoot.qcow2
May 27 11:22:19 android-f729a1a2b75be60b Docker[4431] <Notice>: Launching: /Applications/Docker.app/Contents/MacOS/com.docker.hyperkit -A -m 4G -c 4 -u -s 0:0,hostbridge -s 31,lpc -s 2:0,virtio-ipc,uuid=9165ba41-14ce-4de0-b4f2-b1437e3be6cc,path=/var/tmp/com.docker.vmnetd.socket,macfile=/Users/mickael/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/mac.0 -s 3:0,virtio-ipc,uuid=65eadca0-5e7e-4ff5-a2b1-8b91759a1724,path=/Users/mickael/Library/Containers/com.docker.docker/Data/s50,macfile=/Users/mickael/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/mac.1 -s 4,virtio-blk,file:///Users/mickael/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/Docker.qcow2,format=qcow -s 5,virtio-9p,path=/Users/mickael/Library/Containers/com.docker.docker/Data/s40,tag=db -s 6,virtio-rnd -s 7,virtio-9p,path=/Users/mickael/Library/Containers/com.docker.docker/Data/s51,tag=port -s 8,virtio-sock,guest_cid=3,path=/Users/mickael/Library/Containers/com.docker.docker/Data,guest_forwards=2376;1525 -l com1,autopty=/Users/mickael/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/tty,log=/Users/mickael/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/mickael/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux", com.docker.database="com.docker.driver.amd64-linux" -F /Users/mickael/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/hypervisor.pid
May 27 11:22:19 android-f729a1a2b75be60b Docker[4433] <Notice>: Starting hyperkit
May 27 11:22:19 android-f729a1a2b75be60b Docker[4431] <Notice>: May 27 11:22:19  Docker[4433] <Notice>: Starting hyperkit
May 27 11:22:19 android-f729a1a2b75be60b Docker[4434] <Notice>: Client reports version 15, commit 16dbe555c7dd4304521b21e8286d83fe4864c15c
May 27 11:22:19 android-f729a1a2b75be60b Docker[4434] <Notice>: com.docker.vmnetd reports MAC address: 6e:02:5d:7d:cf:32
May 27 11:22:19 android-f729a1a2b75be60b Docker[4434] <Notice>: rx batching enabled (len=64)
May 27 11:22:19 android-f729a1a2b75be60b Docker[4430] <Notice>: PPP.negotiate: received ((magic VMN3T)(version 15)(commit 16dbe555c7dd4304521b21e8286d83fe4864c15c))
May 27 11:22:19 android-f729a1a2b75be60b Docker[4430] <Notice>: PPP.negotiate: received (Ethernet 65eadca0-5e7e-4ff5-a2b1-8b91759a1724)
May 27 11:22:19 android-f729a1a2b75be60b Docker[4430] <Notice>: PPP.negotiate: sending ((mtu 1500)(max_packet_size 1550)(client_macaddr c0:ff:ee:c0:ff:ee))
May 27 11:22:19 android-f729a1a2b75be60b Docker[4430] <Notice>: PPP.listen: called a second time: doing nothing
May 27 11:22:19 android-f729a1a2b75be60b Docker[4430] <Notice>: TCP/IP ready
May 27 11:22:19 android-f729a1a2b75be60b Docker[4431] <Notice>: mirage_block_open file:///Users/mickael/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/Docker.qcow2 buffered = true
May 27 11:22:19 android-f729a1a2b75be60b Docker[4431] <Notice>: mirage_block_open returning 0
May 27 11:22:19 android-f729a1a2b75be60b Docker[4431] <Notice>: mirage_block_stat
May 27 11:22:19 android-f729a1a2b75be60b Docker[4431] <Notice>: vsock init 8:0 = /Users/mickael/Library/Containers/com.docker.docker/Data, guest_cid = 3
May 27 11:22:22 android-f729a1a2b75be60b Docker[4431] <Notice>:
	rdmsr to register 0x34 on vcpu 3
May 27 11:22:22 android-f729a1a2b75be60b Docker[4431] <Notice>: Docker is not responding: waiting 0.5s
--- last message repeated 7 times ---
May 27 11:22:26 android-f729a1a2b75be60b Docker[4429] <Error>: transfused: mount
May 27 11:22:26 android-f729a1a2b75be60b Docker[4429] <Error>: transfused: /bin/fusermount
May 27 11:22:26 android-f729a1a2b75be60b Docker[4429] <Error>: transfused: -o
May 27 11:22:26 android-f729a1a2b75be60b Docker[4429] <Error>: transfused: allow_other,max_read=1048576,subtype=osxfs
May 27 11:22:26 android-f729a1a2b75be60b Docker[4429] <Error>: transfused: /Mac
May 27 11:22:26 android-f729a1a2b75be60b Docker[4429] <Error>: transfused:
May 27 11:22:26 android-f729a1a2b75be60b Docker[4429] <Notice>: osxfs tracing: OFF
May 27 11:22:26 android-f729a1a2b75be60b Docker[4430] <Notice>: Using protocol TwoThousand msize 8192
May 27 11:22:28 android-f729a1a2b75be60b Docker[4431] <Notice>: Docker is responding
May 27 11:22:28 android-f729a1a2b75be60b Docker[4340] <Notice>: VM has started at 2016-05-27 11:22:28 +0200 CEST
May 27 11:22:28 android-f729a1a2b75be60b Docker[4322] <Notice>: dockerState = running

davidham · May 27, 2016, 1:59pm

I was only able to resolve this by downgrading to beta12.

davidham · May 31, 2016, 4:22pm

Docker team, whatever you did in the 13.1 hotfix seems to have solved the issue. It’s noticeably faster than beta 12 too, nice work!