Docker Crashes and Restarts in unstable state

[BryantChris]

Expected behavior

Use Docker normally: 'docker-compose up' to launch all machines (web, worker, db, redis)
Make code changes, web server restarts and reloads updated code.

Actual behavior

Occasionally, the web server bombs out with a console log like the following:

Exception in thread Thread-6:
Traceback (most recent call last):
  File "threading.py", line 810, in __bootstrap_inner
  File "threading.py", line 763, in run
  File "compose/cli/log_printer.py", line 149, in tail_container_logs
  File "compose/cli/log_printer.py", line 179, in wait_on_exit
  File "compose/container.py", line 239, in wait
  File "site-packages/docker/utils/decorators.py", line 21, in wrapped
  File "site-packages/docker/api/container.py", line 441, in wait
  File "site-packages/docker/client.py", line 174, in _raise_for_status
APIError: 500 Server Error: Internal Server Error ("dial unix /Volumes/UserData/cb/Library/Containers/com.docker.docker/Data/*00000003.00000948: connect: connection refused")

Exception in thread Thread-9:
Traceback (most recent call last):
  File "threading.py", line 810, in __bootstrap_inner
  File "threading.py", line 763, in run
  File "compose/cli/log_printer.py", line 149, in tail_container_logs
  File "compose/cli/log_printer.py", line 179, in wait_on_exit
  File "compose/container.py", line 239, in wait
  File "site-packages/docker/utils/decorators.py", line 21, in wrapped
  File "site-packages/docker/api/container.py", line 441, in wait
  File "site-packages/docker/client.py", line 174, in _raise_for_status
APIError: 500 Server Error: Internal Server Error ("dial unix /Volumes/UserData/cb/Library/Containers/com.docker.docker/Data/*00000003.00000948: connect: connection refused")

Exception in thread Thread-10:
Traceback (most recent call last):
  File "threading.py", line 810, in __bootstrap_inner
  File "threading.py", line 763, in run
  File "compose/cli/log_printer.py", line 149, in tail_container_logs
  File "compose/cli/log_printer.py", line 179, in wait_on_exit
  File "compose/container.py", line 239, in wait
  File "site-packages/docker/utils/decorators.py", line 21, in wrapped
  File "site-packages/docker/api/container.py", line 441, in wait
  File "site-packages/docker/client.py", line 174, in _raise_for_status
APIError: 500 Server Error: Internal Server Error ("dial unix /Volumes/UserData/cb/Library/Containers/com.docker.docker/Data/*00000003.00000948: connect: connection refused")

Exception in thread Thread-7:
Traceback (most recent call last):
  File "threading.py", line 810, in __bootstrap_inner
  File "threading.py", line 763, in run
  File "compose/cli/log_printer.py", line 149, in tail_container_logs
  File "compose/cli/log_printer.py", line 179, in wait_on_exit
  File "compose/container.py", line 239, in wait
  File "site-packages/docker/utils/decorators.py", line 21, in wrapped
  File "site-packages/docker/api/container.py", line 441, in wait
  File "site-packages/docker/client.py", line 174, in _raise_for_status
APIError: 500 Server Error: Internal Server Error ("dial unix /Volumes/UserData/cb/Library/Containers/com.docker.docker/Data/*00000003.00000948: connect: connection refused")
Exception in thread Thread-8:
Traceback (most recent call last):
  File "threading.py", line 810, in __bootstrap_inner
  File "threading.py", line 763, in run
  File "compose/cli/log_printer.py", line 149, in tail_container_logs
  File "compose/cli/log_printer.py", line 179, in wait_on_exit
  File "compose/container.py", line 239, in wait
  File "site-packages/docker/utils/decorators.py", line 21, in wrapped
  File "site-packages/docker/api/container.py", line 441, in wait
  File "site-packages/docker/client.py", line 174, in _raise_for_status
APIError: 500 Server Error: Internal Server Error ("dial unix /Volumes/UserData/cb/Library/Containers/com.docker.docker/Data/*00000003.00000948: connect: connection refused")

Information

Diagnostic ID: F9B62D2C-58B4-4D3D-99AF-6247680F0C16
Docker for Mac: 1.12.0-a (Build 11213)
macOS: Version 10.11.6 (Build 15G31)
[OK] docker-cli
[OK] app
[OK] moby-syslog
[OK] disk
[OK] virtualization
[OK] system
[OK] menubar
[OK] osxfs
[OK] db
[OK] slirp
[OK] moby-console
[OK] logs
[OK] vmnetd
[OK] env
[OK] moby
[OK] driver.amd64-linux

Steps to reproduce

1. No particular pattern to using Docker or making code changes.
2. Typically requires a complete manual restart of Docker once this happens once.

Pasting contents of system console log for Docker events:

8/15/16 3:13:05.267 PM Docker[14647]: dropping unexpected TCP packet sent from 172.18.0.6:36406 to 192.30.253.113:22 (valid sources = 192.168.65.2, 0.0.0.0)
8/15/16 3:13:05.267 PM Docker[14647]: dropping unexpected TCP packet sent from 172.18.0.6:36406 to 192.30.253.113:22 (valid sources = 192.168.65.2, 0.0.0.0)
8/15/16 3:20:28.661 PM Docker[14648]: VM: 2016-08-15 22:20:28 +0000 UTC daemon.warn chronyd: Could not open temporary driftfile /var/lib/chrony/chrony.drift.tmp for writing
8/15/16 3:35:35.996 PM Docker[14648]: Error reading vsyslog length: EOF
8/15/16 3:35:35.997 PM Docker[14648]: Assertion failed: (sc->reply_cons != sc->reply_prod), function send_response_common, file src/pci_virtio_sock.c, line 879.
8/15/16 3:35:35.998 PM Docker[14646]: Fatal unexpected exception: Socket.Closed
8/15/16 3:35:35.999 PM Docker[14647]: PPP.listen: closing connection
8/15/16 3:35:36.000 PM Docker[14648]: virtio-net-vpnkit: initialising, opts="uuid=42cefb5d-92d7-4e6b-90af-84a65cd035a3,path=/Volumes/UserData/cb/Library/Containers/com.docker.docker/Data/s50,macfile=/Volumes/UserData/cb/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/mac.0"
8/15/16 3:35:36.000 PM Docker[14648]: Interface will have uuid 42cefb5d-92d7-4e6b-90af-84a65cd035a3
8/15/16 3:35:36.000 PM Docker[14648]: Connection established with MAC=c0:ff:ee:c0:ff:ee and MTU 1500
8/15/16 3:35:36.001 PM Docker[14648]: virtio-9p: initialising path=/Volumes/UserData/cb/Library/Containers/com.docker.docker/Data/s40,tag=db
8/15/16 3:35:36.001 PM Docker[14648]: virtio-9p: initialising path=/Volumes/UserData/cb/Library/Containers/com.docker.docker/Data/s51,tag=port
8/15/16 3:35:36.001 PM Docker[14648]: linkname /Volumes/UserData/cb/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/tty
8/15/16 3:35:36.001 PM Docker[14648]: COM1 connected to /dev/ttys000
8/15/16 3:35:36.001 PM Docker[14648]: COM1 linked to /Volumes/UserData/cb/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/tty
8/15/16 3:35:36.042 PM Docker[14647]: Socket.Stream: caught Uwt.Uwt_error(Uwt.ENOTCONN, "shutdown", "")
8/15/16 3:35:36.065 PM Docker[23311]: Reap com.docker.osxfs (pid 14646): exit status 1
8/15/16 3:35:36.126 PM Docker[79436]: unexpected EOF
8/15/16 3:35:36.129 PM Docker[23311]: Reap com.docker.osx.hyperkit.linux (pid 67758): exit status 2
8/15/16 3:35:36.155 PM Docker[14647]: Socket.Stream: caught Uwt.Uwt_error(Uwt.ENOTCONN, "shutdown", "")
8/15/16 3:35:36.156 PM Docker[14647]: Socket.Stream: caught Uwt.Uwt_error(Uwt.ECONNREFUSED, "pipe_connect", "")
8/15/16 3:35:36.159 PM Docker[23300]: frontend process failed
8/15/16 3:35:36.176 PM Docker[23311]: Reap com.docker.driver.amd64-linux (pid 14648): exit status 0
8/15/16 3:35:37.096 PM Docker[23311]: Stop 1 children with order 1: com.docker.driver.amd64-linux (pid 14648)
8/15/16 3:35:37.096 PM Docker[23311]: Stop 2 children with order 2: com.docker.osxfs (pid 14646), com.docker.slirp (pid 14647)
8/15/16 3:35:37.096 PM Docker[23311]: Signal terminated to com.docker.slirp (pid 14647)
8/15/16 3:35:37.104 PM Docker[23311]: Reap com.docker.slirp (pid 14647): signal: terminated
8/15/16 3:35:37.197 PM Docker[23311]: Stop 1 children with order 3: com.docker.osx.hyperkit.linux (pid 67758)
8/15/16 3:35:37.197 PM Docker[23311]: Starting com.docker.osx.hyperkit.linux, com.docker.osxfs, com.docker.slirp, com.docker.driver.amd64-linux
8/15/16 3:35:37.200 PM Docker[23311]: Start com.docker.osx.hyperkit.linux (pid 79439)
8/15/16 3:35:37.239 PM Docker[23311]: Start com.docker.osxfs (pid 79440)
8/15/16 3:35:37.243 PM Docker[23311]: Start com.docker.slirp (pid 79441)
8/15/16 3:35:37.249 PM Docker[23311]: Start com.docker.driver.amd64-linux (pid 79442)
8/15/16 3:35:37.255 PM Docker[79439]: API server starting
8/15/16 3:35:37.257 PM Docker[79439]: 🍀 socket path is: /Volumes/UserData/cb/Library/Containers/com.docker.docker/Data/s20
8/15/16 3:35:37.284 PM Docker[79439]: API socket removed
8/15/16 3:35:37.302 PM Docker[79441]: Logging to Apple System Log
8/15/16 3:35:37.302 PM Docker[79441]: Setting handler to ignore all SIGPIPE signals
8/15/16 3:35:37.302 PM Docker[79441]: vpnkit version b071bb4 with hostnet version local  uwt version 0.0.3 hvsock version 0.8.1 
8/15/16 3:35:37.302 PM Docker[79441]: starting port_forwarding port_control_url:fd:4 max_connections:Some 900 vsock_path:/Volumes/UserData/cb/Library/Containers/com.docker.docker/Data/@connect
8/15/16 3:35:37.302 PM Docker[79440]: Logging to Apple System Log
8/15/16 3:35:37.305 PM Docker[79439]: VM shutdown at 2016-08-15 15:35:36 -0700 PDT
8/15/16 3:35:37.315 PM Docker[79442]: Acquired hypervisor lock
8/15/16 3:35:37.318 PM Docker[79442]: Docker is not responding: Get http://./info: dial unix /Volumes/UserData/cb/Library/Containers/com.docker.docker/Data/*00000003.00000948: connect: connection refused: waiting 0.5s
8/15/16 3:35:37.370 PM Docker[79442]: hypervisor: native
8/15/16 3:35:37.371 PM Docker[79442]: filesystem: osxfs
8/15/16 3:35:37.371 PM Docker[79442]: network: hybrid
8/15/16 3:35:37.371 PM Docker[79440]: Using protocol TwoThousand msize 16384
8/15/16 3:35:37.372 PM Docker[79442]: Hypervisor: native; BootProtocol: direct; UefiBootDisk: /Volumes/UserData/cb/UefiBoot.qcow2
8/15/16 3:35:37.372 PM Docker[79442]: Syslog socket is /Volumes/UserData/cb/Library/Containers/com.docker.docker/Data/*00000002.00000202
8/15/16 3:35:37.372 PM Docker[79442]: Logfile is /Volumes/UserData/cb/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/syslog
8/15/16 3:35:37.378 PM Docker[79442]: Launched[79447]: /Applications/Docker.app/Contents/MacOS/com.docker.hyperkit -A -m 4G -c 2 -u -s 0:0,hostbridge -s 31,lpc -s 2:0,virtio-vpnkit,uuid=42cefb5d-92d7-4e6b-90af-84a65cd035a3,path=/Volumes/UserData/cb/Library/Containers/com.docker.docker/Data/s50,macfile=/Volumes/UserData/cb/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/mac.0 -s 3,virtio-blk,file:///Volumes/UserData/cb/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/Docker.qcow2,format=qcow -s 4,virtio-9p,path=/Volumes/UserData/cb/Library/Containers/com.docker.docker/Data/s40,tag=db -s 5,virtio-rnd -s 6,virtio-9p,path=/Volumes/UserData/cb/Library/Containers/com.docker.docker/Data/s51,tag=port -s 7,virtio-sock,guest_cid=3,path=/Volumes/UserData/cb/Library/Containers/com.docker.docker/Data,guest_forwards=2376;1525 -l com1,autopty=/Volumes/UserData/cb/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/tty,log=/Volumes/UserData/cb/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.driver="com.docker.driver.amd64-linux", com.docker.database="com.docker.driver.amd64-linux" ntp=gateway mobyplatform=mac -F /Volumes/UserData/cb/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/hypervisor.pid
8/15/16 3:35:37.407 PM Docker[23300]: dockerState = Starting
8/15/16 3:35:37.417 PM Docker[79441]: attempting to reconnect to database
8/15/16 3:35:37.418 PM Docker[79441]: reconnected transport layer
8/15/16 3:35:37.418 PM Docker[79441]: remove resolver override
8/15/16 3:35:37.418 PM Docker[79441]: using default DNS on 
8/15/16 3:35:37.418 PM Docker[79441]: allowing binds to any IP addresses
8/15/16 3:35:37.419 PM Docker[79441]: Creating slirp server pcap_settings:disabled peer_ip:192.168.65.2 local_ip:192.168.65.1
8/15/16 3:35:37.419 PM Docker[79441]: PPP.negotiate: received ((magic VMN3T)(version 1)(commit ad6ab836187e4111082447b7c0a6a74d01929a5c))
8/15/16 3:35:37.420 PM Docker[79441]: PPP.negotiate: received (Ethernet 42cefb5d-92d7-4e6b-90af-84a65cd035a3)
8/15/16 3:35:37.420 PM Docker[79441]: PPP.negotiate: sending ((mtu 1500)(max_packet_size 1550)(client_macaddr c0:ff:ee:c0:ff:ee))
8/15/16 3:35:37.420 PM Docker[79442]: virtio-net-vpnkit: magic=VMN3T version=1 commit=0123456789012345678901234567890123456789�
8/15/16 3:35:37.420 PM Docker[79441]: PPP.listen: called a second time: doing nothing
8/15/16 3:35:37.420 PM Docker[79441]: TCP/IP ready
8/15/16 3:35:37.420 PM Docker[79441]: stack connected
8/15/16 3:35:37.420 PM Docker[79442]: mirage_block_open file:///Volumes/UserData/cb/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/Docker.qcow2 buffered = true
8/15/16 3:35:37.496 PM Docker[79442]: mirage_block_open returning 0
8/15/16 3:35:37.496 PM Docker[79442]: mirage_block_stat
8/15/16 3:35:37.496 PM Docker[79442]: vsock init 7:0 = /Volumes/UserData/cb/Library/Containers/com.docker.docker/Data, guest_cid = 3
8/15/16 3:35:39.002 PM ReportCrash[79438]: Saved crash report for com.docker.hyperkit[14650] version 0 to /Volumes/UserData/cb/Library/Logs/DiagnosticReports/com.docker.hyperkit_2016-08-15-153538_Chriss-iMac.crash
8/15/16 3:35:40.420 PM Docker[79442]: 
rdmsr to register 0x34 on vcpu 1
8/15/16 3:35:41.048 PM Docker[79442]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/15/16 3:35:41.552 PM Docker[79442]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/15/16 3:35:42.054 PM Docker[79442]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/15/16 3:35:42.559 PM Docker[79442]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/15/16 3:35:43.061 PM Docker[79442]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/15/16 3:35:43.563 PM Docker[79442]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/15/16 3:35:44.068 PM Docker[79442]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/15/16 3:35:44.572 PM Docker[79442]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/15/16 3:35:45.074 PM Docker[79442]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/15/16 3:35:45.213 PM Docker[79440]: transfused: mount /bin/fusermount -o allow_other,max_read=1048576,subtype=osxfs /Users
8/15/16 3:35:45.214 PM Docker[79440]: transfused: mount /bin/fusermount -o allow_other,max_read=1048576,subtype=osxfs /Volumes
8/15/16 3:35:45.215 PM Docker[79440]: transfused: mount /bin/fusermount -o allow_other,max_read=1048576,subtype=osxfs /tmp
8/15/16 3:35:45.216 PM Docker[79440]: transfused: mount /bin/fusermount -o allow_other,max_read=1048576,subtype=osxfs /private
8/15/16 3:35:45.217 PM Docker[79440]: transfused: mount /bin/fusermount -o allow_other,max_read=1048576,subtype=osxfs /host_docker_app
8/15/16 3:35:45.218 PM Docker[79440]: Negotiated transfuse notification channel for /Users
8/15/16 3:35:45.218 PM Docker[79440]: Negotiated transfuse notification channel for /Volumes
8/15/16 3:35:45.218 PM Docker[79440]: Negotiated transfuse notification channel for /tmp
8/15/16 3:35:45.218 PM Docker[79440]: Negotiated transfuse notification channel for /private
8/15/16 3:35:45.218 PM Docker[79440]: Negotiated transfuse notification channel for /host_docker_app
8/15/16 3:35:45.218 PM Docker[79440]: sending continue to client
8/15/16 3:35:45.258 PM Docker[79441]: Using protocol TwoThousand msize 8192
8/15/16 3:35:45.579 PM Docker[79442]: VM: 2016-08-15 22:35:44 +0000 UTC daemon.info vsudd: Connection 1 to: 2376 from: 00000000
8/15/16 3:35:45.601 PM Docker[79442]: VM: 2016-08-15 22:35:44 +0000 UTC daemon.info chronyd: chronyd version 2.3 starting (+CMDMON +NTP +REFCLOCK +RTC +PRIVDROP -SCFILTER -SECHASH +ASYNCDNS +IPV6 -DEBUG)
8/15/16 3:35:45.601 PM Docker[79442]: VM: 2016-08-15 22:35:44 +0000 UTC daemon.warn chronyd: Could not open keyfile /etc/chrony/chrony.keys
8/15/16 3:35:49.855 PM Docker[79442]: VM: 2016-08-15 22:35:48 +0000 UTC daemon.info chronyd: Selected source 192.168.65.1
8/15/16 3:35:49.855 PM Docker[79442]: VM: 2016-08-15 22:35:49 +0000 UTC daemon.warn chronyd: System clock was stepped by 0.881214 seconds
8/15/16 3:35:49.977 PM Docker[79442]: VM: 2016-08-15 22:35:49 +0000 UTC kern.info kernel: IPv6: ADDRCONF(NETDEV_UP): br-9bcf33b701e1: link is not ready
8/15/16 3:35:50.175 PM Docker[79442]: VM: 2016-08-15 22:35:50 +0000 UTC kern.info kernel: IPv6: ADDRCONF(NETDEV_UP): docker0: link is not ready
8/15/16 3:35:50.195 PM Docker[79441]: Creating resource Entry(tcp:0.0.0.0:8888:tcp:172.18.0.6:8888)
8/15/16 3:35:50.196 PM Docker[79441]: Write offset=0 data=[tcp:0.0.0.0:8888:tcp:172.18.0.6:8888] to file
8/15/16 3:35:50.196 PM Docker[79441]: attempting a best-effort bind of ::1:8888
8/15/16 3:35:50.196 PM Docker[79441]: Created instance tcp:0.0.0.0:8888:tcp:172.18.0.6:8888
8/15/16 3:35:50.223 PM Docker[79441]: Creating resource Entry(tcp:0.0.0.0:3000:tcp:172.18.0.6:8000)
8/15/16 3:35:50.224 PM Docker[79441]: Write offset=0 data=[tcp:0.0.0.0:3000:tcp:172.18.0.6:8000] to file
8/15/16 3:35:50.224 PM Docker[79441]: attempting a best-effort bind of ::1:3000
8/15/16 3:35:50.225 PM Docker[79441]: Created instance tcp:0.0.0.0:3000:tcp:172.18.0.6:8000
8/15/16 3:35:50.251 PM Docker[79441]: Creating resource Entry(tcp:0.0.0.0:443:tcp:172.18.0.5:8888)
8/15/16 3:35:50.252 PM Docker[79441]: Write offset=0 data=[tcp:0.0.0.0:443:tcp:172.18.0.5:8888] to file
8/15/16 3:35:50.260 PM Docker[79452]: Client reports version 1, commit 0123456789012345678901234567890123456789
8/15/16 3:35:50.264 PM Docker[79441]: Client.negotiate: received ((magic VMN3T)(version 17)(commit 9cd1dc28d3ac81cb5177ff9728f65200304b36f6))
8/15/16 3:35:50.264 PM Docker[79452]: sendmsg ok
8/15/16 3:35:50.264 PM Docker[79441]: Created instance tcp:0.0.0.0:443:tcp:172.18.0.5:8888
8/15/16 3:35:50.293 PM Docker[79442]: VM: 2016-08-15 22:35:50 +0000 UTC kern.info kernel: IPVS: Creating netns size=2096 id=1
8/15/16 3:35:50.808 PM Docker[79442]: VM: 2016-08-15 22:35:50 +0000 UTC kern.info kernel: IPVS: Creating netns size=2096 id=2
8/15/16 3:35:51.296 PM Docker[79442]: VM: 2016-08-15 22:35:51 +0000 UTC kern.info kernel: IPVS: Creating netns size=2096 id=3
8/15/16 3:35:51.795 PM Docker[79442]: VM: 2016-08-15 22:35:51 +0000 UTC kern.info kernel: IPVS: Creating netns size=2096 id=4
8/15/16 3:35:52.266 PM Docker[79442]: VM: 2016-08-15 22:35:52 +0000 UTC kern.info kernel: IPVS: Creating netns size=2096 id=5
8/15/16 3:35:52.846 PM Docker[79442]: VM: 2016-08-15 22:35:52 +0000 UTC kern.warn kernel: aufs au_opts_verify:1597:dockerd[1532]: dirperm1 breaks the protection by the permission bits on the lower branch
8/15/16 3:35:52.872 PM Docker[79442]: VM: 2016-08-15 22:35:52 +0000 UTC daemon.info init: starting pid 1892, tty '/dev/ttyS0': '/sbin/getty -L 115200 ttyS0 vt100'
8/15/16 3:35:52.884 PM Docker[79442]: Docker is responding
8/15/16 3:35:52.885 PM Docker[79442]: VM: 2016-08-15 22:35:52 +0000 UTC daemon.info vsudd: Connection 2 to: 2376 from: 00000000
8/15/16 3:35:53.002 PM Docker[79439]: VM started at 2016-08-15 15:35:52 -0700 PDT
8/15/16 3:35:53.023 PM Docker[23300]: dockerState = Running
8/15/16 3:35:53.888 PM Docker[79442]: VM: 2016-08-15 22:35:53 +0000 UTC daemon.info vsudd: Connection 3 to: 2376 from: 00000000
8/15/16 3:35:56.207 PM Docker[79442]: VM: 2016-08-15 22:35:56 +0000 UTC daemon.info vsudd: Connection 4 to: 2376 from: 00000000
8/15/16 3:35:56.208 PM Docker[79442]: VM: 2016-08-15 22:35:56 +0000 UTC daemon.info vsudd: 4 Done. read: 96 written: 141
8/15/16 3:35:56.260 PM Docker[79441]: failed to establish 9P connection: Caught EOF on underlying FLOW
8/15/16 3:35:56.260 PM Docker[79471]: EOF reading packet from Unix domain socket: closing
8/15/16 3:35:56.260 PM Docker[79471]: Failed to read hello from client
8/15/16 3:36:00.613 PM Docker[79442]: VM: 2016-08-15 22:36:00 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:00.622 PM Docker[79442]: VM: 2016-08-15 22:36:00 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:00.631 PM Docker[79442]: VM: 2016-08-15 22:36:00 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:00.637 PM Docker[79442]: VM: 2016-08-15 22:36:00 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:00.644 PM Docker[79442]: VM: 2016-08-15 22:36:00 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:00.651 PM Docker[79442]: VM: 2016-08-15 22:36:00 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:00.657 PM Docker[79442]: VM: 2016-08-15 22:36:00 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:00.664 PM Docker[79442]: VM: 2016-08-15 22:36:00 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:00.671 PM Docker[79442]: VM: 2016-08-15 22:36:00 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:00.682 PM Docker[79442]: VM: 2016-08-15 22:36:00 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:00.713 PM Docker[79442]: VM: 2016-08-15 22:36:00 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:00.721 PM Docker[79442]: VM: 2016-08-15 22:36:00 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:00.728 PM Docker[79442]: VM: 2016-08-15 22:36:00 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:00.735 PM Docker[79442]: VM: 2016-08-15 22:36:00 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:00.743 PM Docker[79442]: VM: 2016-08-15 22:36:00 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:00.753 PM Docker[79442]: VM: 2016-08-15 22:36:00 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:00.761 PM Docker[79442]: VM: 2016-08-15 22:36:00 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:00.770 PM Docker[79442]: VM: 2016-08-15 22:36:00 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:00.782 PM Docker[79442]: VM: 2016-08-15 22:36:00 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:00.789 PM Docker[79442]: VM: 2016-08-15 22:36:00 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:00.797 PM Docker[79442]: VM: 2016-08-15 22:36:00 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:00.805 PM Docker[79442]: VM: 2016-08-15 22:36:00 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:00.813 PM Docker[79442]: VM: 2016-08-15 22:36:00 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:00.826 PM Docker[79442]: VM: 2016-08-15 22:36:00 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:00.833 PM Docker[79442]: VM: 2016-08-15 22:36:00 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:00.846 PM Docker[79442]: VM: 2016-08-15 22:36:00 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:00.853 PM Docker[79442]: VM: 2016-08-15 22:36:00 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:00.861 PM Docker[79442]: VM: 2016-08-15 22:36:00 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:00.865 PM Docker[79442]: VM: 2016-08-15 22:36:00 +0000 UTC daemon.info diagnostics: Running /usr/bin/tail
8/15/16 3:36:00.867 PM Docker[79442]: VM: 2016-08-15 22:36:00 +0000 UTC daemon.info diagnostics: Running /usr/bin/tail
8/15/16 3:36:00.877 PM Docker[79442]: VM: 2016-08-15 22:36:00 +0000 UTC daemon.info diagnostics: Running /usr/bin/tail
8/15/16 3:36:02.495 PM Docker[79442]: VM: 2016-08-15 22:36:02 +0000 UTC daemon.info vsudd: Connection 5 to: 2376 from: 00000000
8/15/16 3:36:02.497 PM Docker[79442]: VM: 2016-08-15 22:36:02 +0000 UTC daemon.info vsudd: 5 Done. read: 96 written: 141
8/15/16 3:36:02.519 PM Docker[79441]: failed to establish 9P connection: Caught EOF on underlying FLOW
8/15/16 3:36:02.521 PM Docker[79525]: EOF reading packet from Unix domain socket: closing
8/15/16 3:36:02.522 PM Docker[79525]: Failed to read hello from client
8/15/16 3:36:05.787 PM Docker[79442]: VM: 2016-08-15 22:36:05 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:05.794 PM Docker[79442]: VM: 2016-08-15 22:36:05 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:05.800 PM Docker[79442]: VM: 2016-08-15 22:36:05 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:05.805 PM Docker[79442]: VM: 2016-08-15 22:36:05 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:05.812 PM Docker[79442]: VM: 2016-08-15 22:36:05 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:05.817 PM Docker[79442]: VM: 2016-08-15 22:36:05 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:05.824 PM Docker[79442]: VM: 2016-08-15 22:36:05 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:05.828 PM Docker[79442]: VM: 2016-08-15 22:36:05 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:05.835 PM Docker[79442]: VM: 2016-08-15 22:36:05 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:05.845 PM Docker[79442]: VM: 2016-08-15 22:36:05 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:05.853 PM Docker[79442]: VM: 2016-08-15 22:36:05 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:05.861 PM Docker[79442]: VM: 2016-08-15 22:36:05 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:05.867 PM Docker[79442]: VM: 2016-08-15 22:36:05 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:05.874 PM Docker[79442]: VM: 2016-08-15 22:36:05 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:05.880 PM Docker[79442]: VM: 2016-08-15 22:36:05 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:05.893 PM Docker[79442]: VM: 2016-08-15 22:36:05 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:05.901 PM Docker[79442]: VM: 2016-08-15 22:36:05 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:05.908 PM Docker[79442]: VM: 2016-08-15 22:36:05 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:05.919 PM Docker[79442]: VM: 2016-08-15 22:36:05 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:05.925 PM Docker[79442]: VM: 2016-08-15 22:36:05 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:05.932 PM Docker[79442]: VM: 2016-08-15 22:36:05 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:05.938 PM Docker[79442]: VM: 2016-08-15 22:36:05 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:05.945 PM Docker[79442]: VM: 2016-08-15 22:36:05 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:05.961 PM Docker[79442]: VM: 2016-08-15 22:36:05 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:05.969 PM Docker[79442]: VM: 2016-08-15 22:36:05 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:05.983 PM Docker[79442]: VM: 2016-08-15 22:36:05 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:05.991 PM Docker[79442]: VM: 2016-08-15 22:36:05 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:05.999 PM Docker[79442]: VM: 2016-08-15 22:36:05 +0000 UTC daemon.info diagnostics: Running /bin/cat
8/15/16 3:36:06.003 PM Docker[79442]: VM: 2016-08-15 22:36:06 +0000 UTC daemon.info diagnostics: Running /usr/bin/tail
8/15/16 3:36:06.005 PM Docker[79442]: VM: 2016-08-15 22:36:06 +0000 UTC daemon.info diagnostics: Running /usr/bin/tail
8/15/16 3:36:06.014 PM Docker[79442]: VM: 2016-08-15 22:36:06 +0000 UTC daemon.info diagnostics: Running /usr/bin/tail

[mzdrahal]

I'm witnessing the same behaviour, same software versions as the parent poster.

[kakawait]

Exactly the same issue.

Could be related to moby/moby#24045

[materliu]

the same issue.

[ijc]

There have been some improvements to the vsock code in the 1.12.1-beta27 release so if you are happy trying a beta version of the software it would be useful to know if this has resolved it for you. When switching between the beta and stable branches it is necessary to uninstall Docker for mac.

If it still occurs for any of you with beta27 please open fresh individual tickets against https://github.com/docker/for-mac with the full output of diagnostics (from the whale menu). Providing reproduction steps of any case would also be very useful in tracking this down.

I understand that many of the repro cases are when building proprietary software but if someone was able to par their case down to just the basic build system skeleton required to trigger the issue (removing all the proprietary stuff) or find a subset of their code which they were willing/able to post then we'll stand a much better chance of nailing this once and for all.

[samoht]

Detected symptom of problem 'invariant-violated' in F9B62D2C-58B4-4D3D-99AF-6247680F0C16/20160815-153602.

An invariant within the code of one of the components was not held. Docker needs to be restarted. Please upgrade to a more recent version of Docker which fixes this issue with osxfs.

May be related to #89

The following log matches:

Aug  8 14:42:32 Chriss-iMac Docker[com.docker.driver.amd64-linux][708] <Notice>: VM: 2016-08-08 21:42:32 +0000 UTC daemon.info vsudd: Connection 865 to: 2376 from: 00000000
Aug  8 14:42:32 Chriss-iMac Docker[com.docker.driver.amd64-linux][708] <Notice>: VM: 2016-08-08 21:42:32 +0000 UTC daemon.info vsudd: Connection 866 to: 2376 from: 00000000
Aug  8 14:42:32 Chriss-iMac Docker[com.docker.osxfs][696] <Notice>: Volume.stop 76bf5295c80e576242043887e280a3278eb66496584b06718ffa872913c2784f (paths = [/Volumes/UserData/cb/Documents/Projects/statsketch/backend])
Aug  8 14:42:32 Chriss-iMac Docker[com.docker.osxfs][696] <Error>: WATCH TREE REMOVAL EXISTENCE INVARIANT VIOLATED
Aug  8 14:42:32 Chriss-iMac Docker[com.docker.driver.amd64-linux][708] <Notice>: VM: 2016-08-08 21:42:32 +0000 UTC daemon.info vsudd: 838 Done. read: 310 written: 3104
Aug  8 14:42:32 Chriss-iMac Docker[com.docker.driver.amd64-linux][708] <Notice>: VM: 2016-08-08 21:42:32 +0000 UTC daemon.info vsudd: Connection 867 to: 2376 from: 00000000
Aug  8 14:42:32 Chriss-iMac Docker[com.docker.driver.amd64-linux][708] <Notice>: VM: 2016-08-08 21:42:32 +0000 UTC kern.info kernel: br-bc0c508a31a3: port 4(vethc765f90) entered disabled state

/cc @dsheets

[dsheets]

This invariant violation was a symptom of a use-after-free bug in the file system event watching code which occurred due to multiple containers with volume mounts racing to set up their mounts. It is possible that it caused your hangs or crashes and has been fixed in the recently released Beta 29.3. Please open a new issue for any further problems. Thanks!

[docker-robott]

Closed issues are locked after 30 days of inactivity.
This helps our team focus on active issues.

If you have found a problem that seems similar to this, please open a new issue.

Send feedback to Docker Community Slack channels #docker-for-mac or #docker-for-windows.
/lifecycle locked