Docker crashes when contained app serves many large http requests

[collin]

Expected behavior

Docker will not crash when serving many large http requests.

Actual behavior

We have a django app in docker that serves many http requests. In local development docker will crash. Sometimes it takes many refresh cycles to trigger this crash, sometimes it happens very quickly. We can also exacerbate the issue by increasing the size of http responses.

Later in this issue report I have linked to a github repository that can be used to consistently reproduce this crash. That repository serves a single html page that includes 1000 <script> tags that all request a ~1MB file. (In our experience docker crashes at around request 60)

Information

Diagnostic ID: 3358725D-1E1F-4B4C-AFC1-BD7DA2B1B7C6

Docker for Mac: version: 1.12.2-rc1-beta27 (179c18c)
OS X: version 10.12 (build: 16A323)
logs: /tmp/3358725D-1E1F-4B4C-AFC1-BD7DA2B1B7C6/20161007-103602.tar.gz
[OK]     docker-cli
[OK]     virtualization kern.hv_support
[OK]     menubar
[OK]     moby-syslog
[OK]     dns
[OK]     disk
[OK]     system
[OK]     app
[OK]     osxfs
[OK]     virtualization VT-X
[OK]     db
[OK]     slirp
[OK]     logs
[OK]     env
[OK]     vmnetd
[OK]     moby-console
[OK]     moby
[OK]     driver.amd64-linux

Steps to reproduce the behavior

Clone this repository: https://github.com/theonion/crash-docker and follow instructions in README.

Should see a bunch of server logging ending something like this:

web_1  | [pid: 8|app: 0|req: 56/56] 172.17.0.1 () {40 vars in 657 bytes} [Fri Oct  7 18:58:20 2016] GET /static/big-script.js?cb=61 => generated 938740 bytes in 23 msecs via sendfile() (HTTP/1.1 200) 4 headers in 156 bytes (0 switches on core 0)
web_1  | [pid: 8|app: 0|req: 57/57] 172.17.0.1 () {40 vars in 657 bytes} [Fri Oct  7 18:58:20 2016] GET /static/big-script.js?cb=62 => generated 938740 bytes in 18 msecs via sendfile() (HTTP/1.1 200) 4 headers in 156 bytes (0 switches on core 0)
web_1  | [pid: 8|app: 0|req: 58/58] 172.17.0.1 () {40 vars in 657 bytes} [Fri Oct  7 18:58:20 2016] GET /static/big-script.js?cb=63 => generated 938740 bytes in 15 msecs via sendfile() (HTTP/1.1 200) 4 headers in 156 bytes (0 switches on core 0)
web_1  | [pid: 8|app: 0|req: 59/59] 172.17.0.1 () {40 vars in 657 bytes} [Fri Oct  7 18:58:20 2016] GET /static/big-script.js?cb=64 => generated 938740 bytes in 21 msecs via sendfile() (HTTP/1.1 200) 4 headers in 156 bytes (0 switches on core 0)
web_1  | [pid: 8|app: 0|req: 60/60] 172.17.0.1 () {40 vars in 657 bytes} [Fri Oct  7 18:58:20 2016] GET /static/big-script.js?cb=65 => generated 938740 bytes in 16 msecs via sendfile() (HTTP/1.1 200) 4 headers in 156 bytes (0 switches on core 0)
web_1  | [pid: 8|app: 0|req: 61/61] 172.17.0.1 () {40 vars in 657 bytes} [Fri Oct  7 18:58:20 2016] GET /static/big-script.js?cb=66 => generated 938740 bytes in 40 msecs via sendfile() (HTTP/1.1 200) 4 headers in 156 bytes (0 switches on core 0)
Unexpected API error for crash_web_1 (HTTP code 502)
Response body:
Bad response from Docker engine

[collin]

From the README of the linked repository:

This repository will consistently crash docker for mac

git clone https://github.com/theonion/crash-docker.git
cd crash-docker
docker-compose up

Open your web browser and visit http://localhost:9090/

Docker should crash.

Why does it crash?

I believe it has to do with requesting many large files and breaking some of the
socket code here: https://github.com/docker/hyperkit/blob/ab368eb453dab1a03a3e8463388d7f3f1841ec42/src/pci_virtio_sock.c#L869

I tracked this line down by looking at the syslog output:

 Assertion failed: (s->local_shutdown != VIRTIO_VSOCK_FLAG_SHUTDOWN_ALL), function shutdown_local_sock, file src/pci_virtio_sock.c, line 869.

Here is the longer output from syslog -w -k Sender Docker during a crash.

 Assertion failed: (s->local_shutdown != VIRTIO_VSOCK_FLAG_SHUTDOWN_ALL), function shutdown_local_sock, file src/pci_virtio_sock.c, line 869.
 virtio-net-vpnkit: initialising, opts="uuid=ec0385d7-02e3-4c82-a1dd-6b984d74feed,path=/Users/collinmiller/Library/Containers/com.docker.docker/Data/s50,macfile=/Users/collinmiller/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/mac.0"
 Interface will have uuid ec0385d7-02e3-4c82-a1dd-6b984d74feed
 Connection established with MAC=c0:ff:ee:c0:ff:ee and MTU 1500
 virtio-9p: initialising path=/Users/collinmiller/Library/Containers/com.docker.docker/Data/s40,tag=db
 virtio-9p: initialising path=/Users/collinmiller/Library/Containers/com.docker.docker/Data/s51,tag=port
 linkname /Users/collinmiller/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/tty
 COM1 connected to /dev/ttys009
 COM1 linked to /Users/collinmiller/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/tty
 Socket.Stream: caught Uwt.Uwt_error(Uwt.ENOTCONN, "shutdown", "")
--- last message repeated 3 times ---
 Fatal unexpected exception: Socket.Closed
 PPP.listen: closing connection
 Socket.Stream: caught Uwt.Uwt_error(Uwt.ECONNREFUSED, "pipe_connect", "")
--- last message repeated 1 time ---
 Socket.Stream: caught Uwt.Uwt_error(Uwt.ENOTCONN, "shutdown", "")
 Reap com.docker.osxfs (pid 13579): exit status 1
 VM shutdown at 2016-10-07 10:26:10 -0500 CDT
 Reap com.docker.driver.amd64-linux (pid 13581): exit status 0
 Socket.Stream: caught Uwt.Uwt_error(Uwt.ECONNREFUSED, "pipe_connect", "")
--- last message repeated 7 times ---
 Stop 1 children with order 1: com.docker.driver.amd64-linux (pid 13581)
 Stop 2 children with order 2: com.docker.osxfs (pid 13579), com.docker.slirp (pid 13580)
 Signal terminated to com.docker.slirp (pid 13580)
 Reap com.docker.slirp (pid 13580): signal: terminated
 Starting com.docker.osxfs, com.docker.slirp, com.docker.driver.amd64-linux
 Start com.docker.osxfs (pid 13765)
 Start com.docker.slirp (pid 13766)
 Start com.docker.driver.amd64-linux (pid 13767)
 Logging to Apple System Log
 Logging to Apple System Log
 Setting handler to ignore all SIGPIPE signals
 vpnkit version 9cb6374ebfd0656961901478e9fc8cf65d000678 with hostnet version local  uwt version 0.0.3 hvsock version 0.10.0
 starting port_forwarding port_control_url:fd:4 vsock_path:/Users/collinmiller/Library/Containers/com.docker.docker/Data/@connect
 hosts file has bindings for localhost broadcasthost localhost
 Acquired hypervisor lock
 Docker is not responding: Get http://./info: dial unix /Users/collinmiller/Library/Containers/com.docker.docker/Data/*00000003.00000948: connect: connection refused: waiting 0.5s

[samoht]

Thanks for your report! That issue should normally be fixed moby/hyperkit#62 and we will ship these patches in the next Beta of Docker for Mac. Would be great if you could test it when it is out (normally in the next few days) and report if it works for you or not. Thanks!

[ijc]

I was able to repro the issue with 1.12.2-rc1-beta27 (12496).

I tested the current docker for mac master (at commit ea06b4e124477b5c5e6371ef229cfe64effa67b8) and it didn't crash, the web browser kept spinning and the compose log filled with

web_1  | [pid: 6|app: 0|req: 1001/1001] 172.17.0.1 () {36 vars in 547 bytes} [Mon Oct 10 09:55:39 2016] GET /static/big-script.js?cb=346 => generated 938740 bytes in 9 msecs via sendfile() (HTTP/1.1 200) 4 headers in 156 bytes (0 switches on core 0)

Which I think is correct operation.

I refreshed a few times (it seemed to be counting higher each time) and still didn't manage to crash it. So I'm going to conclude that moby/hyperkit#62 really has fixed the issue. This fix we become public in beta28.

Given that I'm going to proactively close this issue, please do ping for reopen if it somehow turns out not to be fixed in beta28.

[collin]

Thank you for the prompt and detailed response. Looking forward to beta28 💃💃💃💃💃

There will be much rejoicing.

[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