Expected behavior
After a computer reboot, docker info (and related) should work.
Actual behavior
docker info hangs.
I tried resetting Docker to factory defaults, and the problem came back after a couple of boot cycles.
Information
pwnage:heap pwnall$ pinata diagnose -u
OS X: version 10.11.5 (build: 15F34)
Docker.app: version v1.11.1-beta12
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
Error echo "00000003.0000f3a6" | nc -U /Users/pwnall/Library/Containers/com.docker.docker/Data/@connect > /tmp/20160520-032124/diagnostics.tar: timeout after 30.00s
Docker logs are being collected into /tmp/20160520-032124.tar.gz
Most specific failure is: No error was detected
Your unique id is: CCB2C150-8E99-4694-B2D3-2CF05B5FAB1F
Please quote this in all correspondence.
In case it helps, here is a seemingly relevant snippet of syslog -k Sender Docker
May 20 03:09:09 pwnage Docker[83] <Notice>: com.docker.vmnetd starting
May 20 03:09:32 pwnage Docker[1238] <Notice>: launching...
May 20 03:09:32 pwnage Docker[1238] <Notice>: accessing preferences...
May 20 03:09:32 pwnage Docker[1238] <Notice>: bundle path: /Applications/Docker.app/Contents/Library/LoginItems/DockerHelper.app
May 20 03:09:32 pwnage Docker[1238] <Notice>: auto start: true
May 20 03:09:32 pwnage Docker[1238] <Notice>: launch path: Optional("/Applications/Docker.app")
May 20 03:09:32 pwnage Docker[1238] <Notice>: Docker.app sucessfully launched from: /Applications/Docker.app
May 20 03:09:32 pwnage Docker[1238] <Notice>: terminating...
May 20 03:09:32 pwnage Docker[1372] <Notice>: Application version: 1.11.1-beta12 (7528)
May 20 03:09:32 pwnage Docker[1372] <Notice>: OSX Version: Version 10.11.5 (Build 15F34)
May 20 03:09:32 pwnage Docker[1372] <Notice>: migrator: start migration process
May 20 03:09:32 pwnage Docker[1372] <Notice>: migrator: previous install detected
May 20 03:09:32 pwnage Docker[1372] <Notice>: migrator: previous version is 1.11.1-beta12
May 20 03:09:32 pwnage Docker[1372] <Notice>: migrator: no migration needed, you are good to go!
May 20 03:09:32 pwnage Docker[1372] <Notice>: migrator: end of migration process
May 20 03:09:32 pwnage Docker[1372] <Notice>: event tracker initialized
May 20 03:09:32 pwnage Docker[1372] <Notice>: Limited access: checking...
May 20 03:09:33 pwnage Docker[1372] <Notice>: Bundle path: /Applications/Docker.app
May 20 03:09:33 pwnage Docker[1384] <Notice>: Client reports version 1, commit 4151b0fc71e51fb8e551d0a1870893ac99a379bc
May 20 03:09:33 pwnage Docker[1384] <Notice>: EOF reading packet from Unix domain socket: closing
May 20 03:09:33 pwnage Docker[1384] <Error>: Failed to read command from client
May 20 03:09:33 pwnage Docker[1372] <Notice>: com.docker.docker commit: 4151b0fc71e51fb8e551d0a1870893ac99a379bc wants version 15
May 20 03:09:33 pwnage Docker[1372] <Notice>: com.docker.vmnetd commit: 4151b0fc71e51fb8e551d0a1870893ac99a379bc has version 15
May 20 03:09:33 pwnage Docker[1372] <Notice>: probe of /var/tmp/com.docker.vmnetd.socket successful: not reinstalling component
May 20 03:09:33 pwnage Docker[1385] <Notice>: Client reports version 1, commit 4151b0fc71e51fb8e551d0a1870893ac99a379bc
May 20 03:09:33 pwnage Docker[1385] <Critical>: client with uid 501 requests com.docker.vmnetd install symlinks
May 20 03:09:33 pwnage Docker[1385] <Critical>: File /usr/local/bin/docker is a symlink
May 20 03:09:33 pwnage Docker[1385] <Critical>: File /usr/local/bin/docker-compose is a symlink
May 20 03:09:33 pwnage Docker[1385] <Critical>: File /var/run/docker.sock is a symlink or a socket
May 20 03:09:33 pwnage Docker[1385] <Critical>: File /usr/local/bin/notary is a symlink
May 20 03:09:33 pwnage Docker[1385] <Critical>: File /var/run/docker.sock is a symlink or a socket
May 20 03:09:33 pwnage Docker[1385] <Critical>: File /usr/local/bin/pinata is a symlink
May 20 03:09:33 pwnage Docker[1385] <Critical>: File /var/run/docker.sock is a symlink or a socket
May 20 03:09:33 pwnage Docker[1385] <Critical>: File /usr/local/bin/docker-machine is a symlink
May 20 03:09:33 pwnage Docker[1385] <Critical>: File /var/run/docker.sock is a symlink or a socket
May 20 03:09:33 pwnage Docker[1372] <Notice>: Symlinks are valid.
May 20 03:09:33 pwnage Docker[1372] <Notice>: com.docker.osx.hyperkit.linux launched with PID 1389
May 20 03:09:33 pwnage Docker[1389] <Notice>: Acquired task manager lock
May 20 03:09:33 pwnage Docker[1389] <Notice>: Starting com.docker.db, com.docker.osxfs, com.docker.slirp, com.docker.osx.hyperkit.linux, com.docker.driver.amd64-linux
May 20 03:09:33 pwnage Docker[1389] <Notice>: Start com.docker.db (pid 1392)
May 20 03:09:33 pwnage Docker[1389] <Notice>: Start com.docker.osxfs (pid 1393)
May 20 03:09:33 pwnage Docker[1389] <Notice>: Start com.docker.slirp (pid 1395)
May 20 03:09:33 pwnage Docker[1389] <Notice>: Start com.docker.osx.hyperkit.linux (pid 1396)
May 20 03:09:33 pwnage Docker[1396] <Notice>: API server starting
May 20 03:09:33 pwnage Docker[1389] <Notice>: Start com.docker.driver.amd64-linux (pid 1397)
May 20 03:09:33 pwnage Docker[1396] <Notice>: 🍀 socket path is: /Users/pwnall/Library/Containers/com.docker.docker/Data/s20
May 20 03:09:33 pwnage Docker[1396] <Notice>: > socket removed.
May 20 03:09:33 pwnage Docker[1393] <Notice>: Logging to Apple System Log
May 20 03:09:33 pwnage Docker[1396] <Notice>: VM has started at 2016-05-20 03:06:25 -0700 PDT
May 20 03:09:33 pwnage Docker[1395] <Notice>: Logging to Apple System Log
May 20 03:09:33 pwnage Docker[1395] <Notice>: Setting handler to ignore all SIGPIPE signals
May 20 03:09:33 pwnage Docker[1395] <Notice>: starting port_forwarding port_control_path:fd:4 vsock_path:/Users/pwnall/Library/Containers/com.docker.docker/Data/@connect
May 20 03:09:33 pwnage Docker[1395] <Notice>: attempting to reconnect to database on unix /Users/pwnall/Library/Containers/com.docker.docker/Data/s40
May 20 03:09:33 pwnage Docker[1395] <Notice>: reconnected transport layer
May 20 03:09:33 pwnage Docker[1395] <Notice>: allowing binds to any IP addresses
May 20 03:09:33 pwnage Docker[1395] <Notice>: Creating slirp server pcap_settings:disabled peer_ip:192.168.65.2 local_ip:192.168.65.1
May 20 03:09:33 pwnage Docker[1397] <Notice>: Acquired hypervisor lock
May 20 03:09:33 pwnage Docker[1397] <Notice>: Docker is not responding: waiting 0.5s
May 20 03:09:33 pwnage Docker[1397] <Notice>: hypervisor: native
May 20 03:09:33 pwnage Docker[1397] <Notice>: filesystem: osxfs
May 20 03:09:33 pwnage Docker[1393] <Notice>: Using protocol TwoThousand msize 16384
May 20 03:09:33 pwnage Docker[1397] <Notice>: Hypervisor: native; BootProtocol: direct; UefiBootDisk: /Users/pwnall/UefiBoot.qcow2
May 20 03:09:33 pwnage Docker[1397] <Notice>: Launching: /Applications/Docker.app/Contents/MacOS/com.docker.hyperkit -A -m 2G -c 4 -u -s 0:0,hostbridge -s 31,lpc -s 2:0,virtio-ipc,uuid=526b5369-bac9-4021-b2db-3d3f3df76faa,path=/Users/pwnall/Library/Containers/com.docker.docker/Data/s50,macfile=/Users/pwnall/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/mac.0 -s 3,virtio-blk,file:///Users/pwnall/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/Docker.qcow2,format=qcow -s 4,virtio-9p,path=/Users/pwnall/Library/Containers/com.docker.docker/Data/s40,tag=db -s 5,virtio-rnd -s 6,virtio-9p,path=/Users/pwnall/Library/Containers/com.docker.docker/Data/s51,tag=port -s 7,virtio-sock,guest_cid=3,path=/Users/pwnall/Library/Containers/com.docker.docker/Data,guest_forwards=2376;1525 -l com1,autopty=/Users/pwnall/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/tty,log=/Users/pwnall/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/pwnall/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux", com.docker.database="com.docker.driver.amd64-linux" -F /Users/pwnall/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/hypervisor.pid
May 20 03:09:33 pwnage Docker[1400] <Notice>: Starting xhyve
May 20 03:09:33 pwnage Docker[1397] <Notice>: May 20 03:09:33 Docker[1400] <Notice>: Starting xhyve
May 20 03:09:33 pwnage Docker[1395] <Notice>: PPP.negotiate: received ((magic VMN3T)(version 15)(commit 4151b0fc71e51fb8e551d0a1870893ac99a379bc))
May 20 03:09:33 pwnage Docker[1395] <Notice>: PPP.negotiate: received (Ethernet 526b5369-bac9-4021-b2db-3d3f3df76faa)
May 20 03:09:33 pwnage Docker[1395] <Notice>: PPP.negotiate: sending ((mtu 1500)(max_packet_size 1550)(client_macaddr c0:ff:ee:c0:ff:ee))
May 20 03:09:33 pwnage Docker[1397] <Notice>: mirage_block_open file:///Users/pwnall/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/Docker.qcow2 buffered = true
May 20 03:09:33 pwnage Docker[1395] <Notice>: PPP.listen: called a second time: doing nothing
May 20 03:09:33 pwnage Docker[1395] <Notice>: TCP/IP ready
May 20 03:09:33 pwnage Docker[1397] <Notice>: mirage_block_open returning 0
May 20 03:09:33 pwnage Docker[1397] <Notice>: mirage_block_stat
May 20 03:09:33 pwnage Docker[1397] <Notice>: vsock init 7:0 = /Users/pwnall/Library/Containers/com.docker.docker/Data, guest_cid = 3
May 20 03:09:33 pwnage Docker[1372] <Notice>: dockerState = running
May 20 03:09:37 pwnage Docker[1397] <Notice>:
rdmsr to register 0x34 on vcpu 3
May 20 03:09:37 pwnage Docker[1397] <Notice>: Docker is not responding: waiting 0.5s
--- last message repeated 5 times ---
May 20 03:09:40 pwnage Docker[1393] <Error>: transfused: mount
May 20 03:09:40 pwnage Docker[1393] <Error>: transfused: /bin/fusermount
May 20 03:09:40 pwnage Docker[1393] <Error>: transfused: -o
May 20 03:09:40 pwnage Docker[1393] <Error>: transfused: allow_other,max_read=1048576,subtype=osxfs
May 20 03:09:40 pwnage Docker[1393] <Error>: transfused: /Mac
May 20 03:09:40 pwnage Docker[1393] <Error>: transfused:
May 20 03:09:40 pwnage Docker[1393] <Notice>: osxfs tracing: OFF
May 20 03:09:40 pwnage Docker[1395] <Notice>: Using protocol TwoThousand msize 8192
May 20 03:09:42 pwnage Docker[1397] <Notice>: Docker is responding
May 20 03:09:42 pwnage Docker[1396] <Notice>: VM has started at 2016-05-20 03:09:42 -0700 PDT
Steps to reproduce the behavior
- Install Docker for Mac on OSX 10.11.5
- Reboot the computer
- Try running
docker info