Consume infinite disk spaces after wakeup from sleep state

[mainakub]

Expected behavior

After my mac wake up from sleep, Docker should run process normally.

Actual behavior

Docker process “com.docker.hyperkit” consume to much resources!! a lot of CPU time and continue consume my disk space… until my mac got 400 MB space left!!, then I have to kill process.

Information

• the output of:
  • pinata diagnose -u on OSX

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
Error exec: cp -r “/Users/hazz/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/log/dmesg” “/tmp/20160528-131526/moby/var/log/”: exit 1
Error exec: cp -r “/Users/hazz/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/log/docker.log” “/tmp/20160528-131526/moby/var/log/”: exit 1
Error exec: cp -r “/Users/hazz/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/log/messages.0” “/tmp/20160528-131526/moby/var/log/”: exit 1
Error exec: cp -r “/Users/hazz/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/log/proxy-vsockd.log” “/tmp/20160528-131526/moby/var/log/”: exit 1
Error exec: cp -r “/Users/hazz/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/log/vsudd.log” “/tmp/20160528-131526/moby/var/log/”: exit 1
Error exec: tar -cz “/tmp/20160528-131526” > “/tmp/20160528-131526.tar.gz”: exit 1
diagnose: internal error, uncaught exception:
Misc.Failure

-  `DockerDebugInfo.ps1` using Powershell on Windows

• a reproducible case if this is a bug, Dockerfiles FTW
• page URL if this is a docs issue or the name of a man page
• host distribution and version ( OSX 10.10.x, OSX 10.11.x, Windows, etc )

Steps to reproduce the behavior

I’am not sure how this can happen be cause it’s running normally and I found this first time today after I wake up my mac from sleep state.

this is more informations from Docker logs.

May 28 08:58:37 tk Docker[47064] : System wants to wake up
May 28 08:58:37 tk Docker[47064] : Asking com.docker.hyperkit to thaw vcpus
May 28 08:58:37 tk Docker[47064] : vcpu 1 received signal, resuming
May 28 08:58:37 tk Docker[47064] : vcpu 0 received signal, resuming
May 28 08:58:37 tk Docker[47064] : Proxy settings have changed
May 28 08:58:44 tk Docker[47064] : Synchronizing time in VM
May 28 08:58:49 192 Docker[47064] : Proxy settings have changed
May 28 09:00:05 192 Docker[47062] : recvfrom failed with Lwt.Canceled
May 28 09:00:05 192 Docker[47062] : DNS response timed out after 5s
May 28 09:00:08 192 Docker[47062] : recvfrom failed with Lwt.Canceled
May 28 09:00:08 192 Docker[47062] : DNS response timed out after 5s
May 28 09:15:05 192 Docker[47062] : recvfrom failed with Lwt.Canceled
May 28 09:15:05 192 Docker[47062] : DNS response timed out after 5s
May 28 09:15:07 192 Docker[47062] : recvfrom failed with Lwt.Canceled
May 28 09:15:07 192 Docker[47062] : DNS response timed out after 5s
May 28 09:30:05 192 Docker[47062] : recvfrom failed with Lwt.Canceled
May 28 09:30:05 192 Docker[47062] : DNS response timed out after 5s
May 28 09:30:07 192 Docker[47062] : recvfrom failed with Lwt.Canceled
May 28 09:30:07 192 Docker[47062] : DNS response timed out after 5s
May 28 10:15:05 192 Docker[47062] : recvfrom failed with Lwt.Canceled
May 28 10:15:05 192 Docker[47062] : DNS response timed out after 5s
May 28 10:15:07 192 Docker[47062] : recvfrom failed with Lwt.Canceled
May 28 10:15:07 192 Docker[47062] : DNS response timed out after 5s
May 28 11:45:05 192 Docker[47062] : recvfrom failed with Lwt.Canceled
May 28 11:45:05 192 Docker[47062] : DNS response timed out after 5s
May 28 11:45:07 192 Docker[47062] : recvfrom failed with Lwt.Canceled
May 28 11:45:07 192 Docker[47062] : DNS response timed out after 5s
May 28 12:15:05 192 Docker[47062] : recvfrom failed with Lwt.Canceled
May 28 12:15:05 192 Docker[47062] : DNS response timed out after 5s
May 28 12:30:05 192 Docker[47062] : recvfrom failed with Lwt.Canceled
May 28 12:30:05 192 Docker[47062] : DNS response timed out after 5s
May 28 12:30:08 192 Docker[47062] : recvfrom failed with Lwt.Canceled
May 28 12:30:08 192 Docker[47062] : DNS response timed out after 5s
May 28 12:33:44 192 Docker[47064] : System wants to go to sleep
May 28 12:33:44 192 Docker[47064] : Asking com.docker.hyperkit to freeze vcpus
May 28 12:33:44 192 Docker[47064] : vcpu freeze complete: allowing sleep
May 28 12:33:44 192 Docker[47064] : vcpu 1 waiting for signal to resume
May 28 12:33:47 192 Docker[47064] : vcpu 0 waiting for signal to resume
May 28 12:59:33 tk Docker[47064] : System wants to wake up
May 28 12:59:33 tk Docker[47064] : Asking com.docker.hyperkit to thaw vcpus
May 28 12:59:33 tk Docker[47064] : vcpu 1 received signal, resuming
May 28 12:59:33 tk Docker[47064] : vcpu 0 received signal, resuming
May 28 12:59:34 tk Docker[47064] : Proxy settings have changed
May 28 12:59:42 tk Docker[47064] : Synchronizing time in VM
May 28 12:59:44 tk Docker[47064] : Proxy settings have changed
May 28 13:06:22 tk Docker[47039] : Terminating com.docker.osx.hyperkit.linux and waiting until exit
May 28 13:06:22 tk Docker[47058] : Received SIGTERM, shutting down
May 28 13:06:22 tk Docker[47058] : Stop 1 children with order 1: com.docker.driver.amd64-linux (pid 47064)
May 28 13:06:22 tk Docker[47058] : Signal terminated to com.docker.driver.amd64-linux (pid 47064)
May 28 13:06:22 tk Docker[47064] : sending SIGTERM to com.docker.hyperkit pid 47069
May 28 13:06:32 tk Docker[47058] : Timed-out waiting for graceful shutdown
May 28 13:06:32 tk Docker[47058] : Sending a SIGKILL to /Applications/Docker.app/Contents/MacOS/com.docker.driver.amd64-linux
May 28 13:06:32 tk Docker[47058] : Signal killed to com.docker.driver.amd64-linux (pid 47064)
May 28 13:06:32 tk Docker[47058] : Reap com.docker.driver.amd64-linux (pid 47064): signal: killed
May 28 13:06:32 tk Docker[47058] : Stop 2 children with order 2: com.docker.osxfs (pid 47061), com.docker.slirp (pid 47062)
May 28 13:06:32 tk Docker[47058] : Signal terminated to com.docker.osxfs (pid 47061)
May 28 13:06:32 tk Docker[47058] : Signal terminated to com.docker.slirp (pid 47062)
May 28 13:06:32 tk Docker[47058] : Reap com.docker.slirp (pid 47062): signal: terminated
May 28 13:06:32 tk Docker[47058] : Reap com.docker.osxfs (pid 47061): signal: terminated
May 28 13:06:32 tk Docker[47058] : Stop 1 children with order 3: com.docker.backend (pid 47063)
May 28 13:06:32 tk Docker[47058] : Signal terminated to com.docker.backend (pid 47063)
May 28 13:06:32 tk Docker[47058] : Reap com.docker.osx.hyperkit.linux (pid 47063): signal: terminated
May 28 13:06:32 tk Docker[47058] : Stop 1 children with order 4: com.docker.db (pid 47060)
May 28 13:06:32 tk Docker[47058] : Signal terminated to com.docker.db (pid 47060)
May 28 13:06:33 tk Docker[47058] : Reap com.docker.db (pid 47060): exit status 1
May 28 13:06:33 tk Docker[47039] : Notified of termination of com.docker.osx.hyperkit.linux
May 28 13:06:33 tk Docker[47039] : com.docker.osx.hyperkit.linux terminated with exit code 0
— last message repeated 1 time —
May 28 13:06:33 tk Docker[47039] : applicationWillTerminate
May 28 13:08:29 tk Docker[69301] : Application version: 1.11.1-beta13 (7975)
May 28 13:08:29 tk Docker[69301] : OSX Version: Version 10.11.5 (Build 15F34)
May 28 13:08:29 tk Docker[69301] : migrator: start migration process
May 28 13:08:29 tk Docker[69301] : migrator: previous install detected
May 28 13:08:29 tk Docker[69301] : migrator: previous version is 1.11.1-beta13
May 28 13:08:29 tk Docker[69301] : migrator: no migration needed, you are good to go!
May 28 13:08:29 tk Docker[69301] : migrator: end of migration process
May 28 13:08:29 tk Docker[69301] : event tracker initialized
May 28 13:08:29 tk Docker[69301] : Limited access: checking…
May 28 13:08:29 tk Docker[69301] : Bundle path: /Applications/Docker.app
May 28 13:08:29 tk Docker[69312] : Client reports version 1, commit 16dbe555c7dd4304521b21e8286d83fe4864c15c
May 28 13:08:29 tk Docker[69312] : EOF reading packet from Unix domain socket: closing
May 28 13:08:29 tk Docker[69301] : com.docker.docker commit: 16dbe555c7dd4304521b21e8286d83fe4864c15c wants version 15
May 28 13:08:29 tk Docker[69312] : Failed to read command from client
May 28 13:08:29 tk Docker[69301] : com.docker.vmnetd commit: 4151b0fc71e51fb8e551d0a1870893ac99a379bc has version 15
May 28 13:08:29 tk Docker[69301] : probe of /var/tmp/com.docker.vmnetd.socket successful: not reinstalling component
May 28 13:08:29 tk Docker[69313] : Client reports version 1, commit 16dbe555c7dd4304521b21e8286d83fe4864c15c
May 28 13:08:29 tk Docker[69313] : client with uid 501 requests com.docker.vmnetd install symlinks
May 28 13:08:29 tk Docker[69313] : File /usr/local/bin/docker is a symlink
May 28 13:08:30 tk Docker[69313] : File /var/run/docker.sock is a symlink or a socket
May 28 13:08:30 tk Docker[69313] : File /usr/local/bin/docker-compose is a symlink
May 28 13:08:30 tk Docker[69313] : File /var/run/docker.sock is a symlink or a socket
May 28 13:08:30 tk Docker[69313] : File /usr/local/bin/notary is a symlink
May 28 13:08:30 tk Docker[69313] : File /var/run/docker.sock is a symlink or a socket
May 28 13:08:30 tk Docker[69313] : File /usr/local/bin/pinata is a symlink
May 28 13:08:30 tk Docker[69313] : File /var/run/docker.sock is a symlink or a socket
May 28 13:08:30 tk Docker[69313] : File /usr/local/bin/docker-machine is a symlink
May 28 13:08:30 tk Docker[69313] : File /var/run/docker.sock is a symlink or a socket
May 28 13:08:30 tk Docker[69301] : Symlinks are valid.
May 28 13:08:30 tk Docker[69301] : com.docker.osx.hyperkit.linux launched with PID 69317
May 28 13:08:30 tk Docker[69317] : Acquired task manager lock
May 28 13:08:30 tk Docker[69317] : Starting com.docker.db, com.docker.osxfs, com.docker.slirp, com.docker.osx.hyperkit.linux, com.docker.driver.amd64-linux
May 28 13:08:30 tk Docker[69317] : Start com.docker.db (pid 69319)
May 28 13:08:30 tk Docker[69317] : Start com.docker.osxfs (pid 69320)
May 28 13:08:30 tk Docker[69317] : Start com.docker.slirp (pid 69321)
May 28 13:08:30 tk Docker[69317] : Start com.docker.osx.hyperkit.linux (pid 69322)
May 28 13:08:30 tk Docker[69317] : Start com.docker.driver.amd64-linux (pid 69323)
May 28 13:08:30 tk Docker[69322] : API server starting
May 28 13:08:30 tk Docker[69322] : socket path is: /Users/hazz/Library/Containers/com.docker.docker/Data/s20
May 28 13:08:30 tk Docker[69322] : > socket removed.
May 28 13:08:30 tk Docker[69322] : Failed to connect to db: &net.OpError{Op:“dial”, Net:“unix”, Source:net.Addr(nil), Addr:(*net.UnixAddr)(0xc8200ee3a0), Err:(*os.SyscallError)(0xc8200ee3e0)}
May 28 13:08:30 tk Docker[69320] : Logging to Apple System Log
May 28 13:08:30 tk Docker[69321] : Logging to Apple System Log
May 28 13:08:30 tk Docker[69321] : Setting handler to ignore all SIGPIPE signals
May 28 13:08:30 tk Docker[69321] : starting port_forwarding port_control_path:fd:4 vsock_path:/Users/hazz/Library/Containers/com.docker.docker/Data/@connect
May 28 13:08:30 tk Docker[69321] : attempting to reconnect to database on unix /Users/hazz/Library/Containers/com.docker.docker/Data/s40
May 28 13:08:30 tk Docker[69322] : VM has started at 2016-05-26 12:24:47 +0700 ICT
May 28 13:08:30 tk Docker[69323] : Acquired hypervisor lock
May 28 13:08:30 tk Docker[69323] : Docker is not responding: waiting 0.5s
May 28 13:08:30 tk Docker[69321] : reconnected transport layer
May 28 13:08:30 tk Docker[69321] : allowing binds to any IP addresses
May 28 13:08:30 tk Docker[69321] : Creating slirp server pcap_settings:disabled peer_ip:192.168.65.2 local_ip:192.168.65.1
May 28 13:08:30 tk Docker[69323] : hypervisor: native
May 28 13:08:30 tk Docker[69323] : filesystem: osxfs
May 28 13:08:30 tk Docker[69320] : Using protocol TwoThousand msize 16384
May 28 13:08:30 tk Docker[69323] : Hypervisor: native; BootProtocol: direct; UefiBootDisk: /Users/hazz/UefiBoot.qcow2
May 28 13:08:30 tk Docker[69323] : 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=8c5a9cd3-8526-4791-af95-e3a940294017,path=/Users/hazz/Library/Containers/com.docker.docker/Data/s50,macfile=/Users/hazz/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/mac.0 -s 3,virtio-blk,file:///Users/hazz/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/Docker.qcow2,format=qcow -s 4,virtio-9p,path=/Users/hazz/Library/Containers/com.docker.docker/Data/s40,tag=db -s 5,virtio-rnd -s 6,virtio-9p,path=/Users/hazz/Library/Containers/com.docker.docker/Data/s51,tag=port -s 7,virtio-sock,guest_cid=3,path=/Users/hazz/Library/Containers/com.docker.docker/Data,guest_forwards=2376;1525 -l com1,autopty=/Users/hazz/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/tty,log=/Users/hazz/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/hazz/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux", com.docker.database=“com.docker.driver.amd64-linux” -F /Users/hazz/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/hypervisor.pid
May 28 13:08:30 tk Docker[69326] : Starting hyperkit
May 28 13:08:30 tk Docker[69323] : May 28 13:08:30 Docker[69326] : Starting hyperkit
May 28 13:08:30 tk Docker[69321] : PPP.negotiate: received ((magic VMN3T)(version 15)(commit 16dbe555c7dd4304521b21e8286d83fe4864c15c))
May 28 13:08:30 tk Docker[69321] : PPP.negotiate: received (Ethernet 8c5a9cd3-8526-4791-af95-e3a940294017)
May 28 13:08:30 tk Docker[69321] : PPP.negotiate: sending ((mtu 1500)(max_packet_size 1550)(client_macaddr c0:ff:ee:c0:ff:ee))
May 28 13:08:30 tk Docker[69323] : mirage_block_open file:///Users/hazz/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/Docker.qcow2 buffered = true
May 28 13:08:30 tk Docker[69321] : PPP.listen: called a second time: doing nothing
May 28 13:08:30 tk Docker[69323] : mirage_block_open returning 0
May 28 13:08:30 tk Docker[69321] : TCP/IP ready
May 28 13:08:30 tk Docker[69323] : mirage_block_stat
May 28 13:08:30 tk Docker[69323] : vsock init 7:0 = /Users/hazz/Library/Containers/com.docker.docker/Data, guest_cid = 3
May 28 13:08:30 tk Docker[69301] : dockerState = running
May 28 13:08:33 tk Docker[69323] :
rdmsr to register 0x34 on vcpu 1
May 28 13:08:33 tk Docker[69323] : Docker is not responding: waiting 0.5s
— last message repeated 7 times —
May 28 13:08:37 tk Docker[69320] : transfused: mount
May 28 13:08:37 tk Docker[69320] : transfused: /bin/fusermount
May 28 13:08:37 tk Docker[69320] : transfused: -o
May 28 13:08:37 tk Docker[69320] : transfused: allow_other,max_read=1048576,subtype=osxfs
May 28 13:08:37 tk Docker[69320] : transfused: /Mac
May 28 13:08:37 tk Docker[69320] : transfused:
May 28 13:08:37 tk Docker[69320] : osxfs tracing: OFF
May 28 13:08:37 tk Docker[69321] : Using protocol TwoThousand msize 8192
May 28 13:08:38 tk Docker[69323] : Docker is not responding: waiting 0.5s
May 28 13:08:49 tk Docker[69321] : recvfrom failed with Lwt.Canceled
May 28 13:08:49 tk Docker[69321] : DNS response timed out after 5s
May 28 13:08:49 tk Docker[69323] : Docker is not responding: waiting 0.5s
May 28 13:08:51 tk Docker[69321] : recvfrom failed with Lwt.Canceled
May 28 13:08:51 tk Docker[69321] : DNS response timed out after 5s
May 28 13:09:00 tk Docker[69323] : Docker is not responding: waiting 0.5s

[clarkmains]

Same here, resulting in the following files all growing massively until the disk is out of space:

~/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/Docker.qcow2
~/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/log/dmesg
~/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/log/docker.log
~/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/log/vsudd.log

System Version: OS X 10.11.1 (15B42)
Kernel Version: Darwin 15.0.0
Docker Version: 1.11.1-beta13

[luisherrerabenitez (Luis Herrera)]

Check work around here. You might need to
aI Stop Docker (cleaner approach)
b) Delete docker.log file in
/Users/hazz/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/log/
c) Configure Docker Daemon to limit log size and number of log files using pinata
d) Restart Docker

Log files grow unconditionally, will eat all the disk space

I´m experiencing the same problem when using the latest version of Docker Beta: version 1.11.1-beta13 build: 7975. It seems that docker.log is the main culprit ( mine grew up to 115 Gb). I guess the log level configured to debug could be working against us: … time=“2016-05-28T08:08:09.184667006Z” level=debug msg=“Calling GET /v1.23/version” … Docker daemon seems to be on debug mode too (that makes sense for the beta) $ docker info … Debug mode (client): false Debug mode (server): true …