Hypervisor subprocess exits/restarts during long NPM install

juztinwilzon · April 22, 2016, 11:09pm

Expected behavior

npm install command completes

Actual behavior

Hypervisor is shutting down, and restarting, part way through a large npm install.

Information

the output of:
- pinata diagnose -u Shows everything is okay (docker is restarting)
- syslog -k Sender docker:

Apr 22 16:56:18 MACHINE Docker[11021] : EOF reading packet from Unix domain socket: closing
Apr 22 16:56:18 MACHINE Docker[11017] : Hypervisor subprocess has exitted with code -1
Apr 22 16:56:18 MACHINE Docker[11021] : Failed to read header
Apr 22 16:56:18 MACHINE Docker[11021] : Stopping vmnet interface
Apr 22 16:56:18 MACHINE Docker[50088] : Reap com.docker.driver.amd64-linux (pid 11017): exit status 0
Apr 22 16:56:18 MACHINE Docker[50088] : Reap com.docker.driver.amd64-linux (pid 11015): exit status 2
Apr 22 16:56:19 MACHINE Docker[50088] : Stop 1 children with order 1: com.docker.driver.amd64-linux (pid 11017)
Apr 22 16:56:19 MACHINE Docker[50088] : Stop 2 children with order 2: com.docker.osxfs (pid 11015), com.docker.slirp (pid 11016)
Apr 22 16:56:19 MACHINE Docker[50088] : Signal terminated to com.docker.slirp (pid 11016)
Apr 22 16:56:19 MACHINE Docker[50088] : Reap com.docker.driver.amd64-linux (pid 11016): signal: terminated
Apr 22 16:56:19 MACHINE Docker[50088] : Starting com.docker.osxfs, com.docker.slirp, com.docker.driver.amd64-linux
Apr 22 16:56:19 MACHINE Docker[50088] : Start com.docker.osxfs (pid 11945)
Apr 22 16:56:19 MACHINE Docker[50088] : Start com.docker.slirp (pid 11946)
Apr 22 16:56:19 MACHINE Docker[50088] : Start com.docker.driver.amd64-linux (pid 11947)
Apr 22 16:56:19 MACHINE Docker[11947] : Acquired hypervisor lock
Apr 22 16:56:19 MACHINE Docker[11947] : hypervisor: native
Apr 22 16:56:19 MACHINE Docker[11947] : filesystem: osxfs
Apr 22 16:56:19 MACHINE Docker[11947] : Hypervisor: native; BootProtocol: direct; UefiBootDisk: /Users/[[USERNAME]]/UefiBoot.qcow2
Apr 22 16:56:19 MACHINE Docker[11947] : Docker is not responding: waiting 0.5s
Apr 22 16:56:19 MACHINE Docker[11949] : exec: /Applications/Docker.app/Contents/MacOS/com.docker.driver.amd64-linux []string{…[OMITTED]…}
Apr 22 16:56:19 MACHINE Docker[11951] : Client reports version 12, commit [[COMMIT ID]]
Apr 22 16:56:19 MACHINE Docker[11021] : Vmnet interface stopped
Apr 22 16:56:19 MACHINE Docker[11021] : Vmnet shutdown done
Apr 22 16:56:19 MACHINE Docker[11951] : com.docker.vmnetd reports MAC address: cc:00:ff:ee:00:00
Apr 22 16:56:19 MACHINE Docker[11951] : rx batching enabled (len=64)
Apr 22 16:56:21 MACHINE Docker[11947] : Docker is not responding: waiting 0.5s
```

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
- N/A
host distribution and version ( OSX 10.10.x, OSX 10.11.x, Windows, etc )
- OS X 10.11.4
- Docker Version 1.11.0-beta8 (build: 6072)

Steps to reproduce the behavior

Running the below command within a folder with a moderate number of JS dependancies:

docker run -it --rm -v "$(PWD)":/data digitallyseamless/nodejs-bower-grunt npm install && brunch build

CPU spikes while npm downloads/installs modules. After about a minute all running containers terminals exit with An error occurred trying to connect: EOF and the above errors are logged.

dsheets · April 23, 2016, 3:26pm

Hi Justin,

Could you please post the tracking ID output by pinata diagnose -u?

Also, if you have an example project (open source?) that has “a moderate number of JS dependencies” that exhibits the bug on your machine, we would love to have a way to reproduce the issue.

Sorry about the bug and thanks for participating in the Docker for Mac Beta!

Best regards,

David

jespermjonsson · April 25, 2016, 10:14am

Hi,

I have the exact same issue, it seems that it crashes during NPM installs and when the node_modules directory is in a directory mounted from the host, for example:

 -v `pwd`:/code

And the package.json and node_modules is located inside the /code directory.

Unfortunately it is closed source so I can’t share any sample code, but the container uses “node:0.12” image and is started with:

docker run -it --rm \
	-v `pwd`/../my-project:/code \
	-v `pwd`/build/tmp/frontend/dist:/code/dist \
	node:0.12 bash -c "cd /code && npm install"

It worked on 1.11.0-beta7 but not on 1.11.0-beta8.
Was using OSX 10.10.5 but upgraded to 10.11.4, but the issue is the same.

A temporary workaround that seems to work is to use a named volume mount for just the node modules directory (added before the host mount so it is layered properly):

docker run -it --rm \
	-v frontend-nodemodules-volume:/code/node_modules \
	-v `pwd`/../my-project:/code \
	-v `pwd`/build/tmp/frontend/dist:/code/dist \
	node:0.12 bash -c "cd /code && npm install"

When the error occurs the Docker logs always say “EOR reading packet from Unix domain socket”:

Apr 25 09:24:55 Jespers-MacBook-Pro Docker[15198] : EOF reading packet from Unix domain socket: closing
Apr 25 09:24:55 Jespers-MacBook-Pro Docker[15198] : Failed to read header
Apr 25 09:24:55 Jespers-MacBook-Pro Docker[15194] : Hypervisor subprocess has exitted with code -1
Apr 25 09:24:55 Jespers-MacBook-Pro Docker[15198] : Stopping vmnet interface
Apr 25 09:24:55 Jespers-MacBook-Pro Docker[14118] : Reap com.docker.driver.amd64-linux (pid 15192): exit status 2
Apr 25 09:24:55 Jespers-MacBook-Pro Docker[14118] : Reap com.docker.driver.amd64-linux (pid 15194): exit status 0
Apr 25 09:24:55 Jespers-MacBook-Pro Docker[15198] : Vmnet interface stopped
Apr 25 09:24:55 Jespers-MacBook-Pro Docker[15198] : Vmnet shutdown done
Apr 25 09:24:56 Jespers-MacBook-Pro Docker[14118] : Stop 1 children with order 1: com.docker.driver.amd64-linux (pid 15194)
Apr 25 09:24:56 Jespers-MacBook-Pro Docker[14118] : Stop 2 children with order 2: com.docker.osxfs (pid 15192), com.docker.slirp (pid 15193)
Apr 25 09:24:56 Jespers-MacBook-Pro Docker[14118] : Signal terminated to com.docker.slirp (pid 15193)
Apr 25 09:24:56 Jespers-MacBook-Pro Docker[14118] : Reap com.docker.driver.amd64-linux (pid 15193): signal: terminated

juztinwilzon · April 25, 2016, 5:06pm

I just re-ran the build and then did pinata diagnose -u:

OS X: version 10.11.4 (build: 15E65)
Docker.app: version v1.11.0-beta8.2
Running diagnostic tests:
[OK]      docker-cli
[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/20160425-105401.tar.gz
Most specific failure is: No error was detected
Your unique id is: B6C27AE2-FB83-41A1-91B2-9386251C196A
Please quote this in all correspondence.

I’m beta testing Docker for Mac @ work, so unfortunately it’s a work thing =(
I can post the the package.json:

{
  "name": "project-name",
  "private": true,
  "version": "0.0.1",
  "description": "project-description",
  "main": "app.js",
  "license": "MIT",
  "dependencies": {
    "assetsmanager-brunch": "^1.8.1",
    "auto-reload-brunch": "^1.7.8",
    "bower": "~1.6",
    "brunch": "~1.8",
    "clean-css-brunch": ">= 1.0 < 1.8",
    "css-brunch": ">= 1.0 < 1.8",
    "jaded-brunch": "~1.7",
    "javascript-brunch": ">= 1.0 < 1.8",
    "less-brunch": "~1.8",
    "uglify-js-brunch": ">= 1.0 < 1.8"
  },
  "engines": {
    "node": "~4.1.2"
  },
  "scripts": {
    "install": "bower install -f",
    "start": "brunch watch --server"
  }
}

It usually seems to die about a minute in during gunzTarPe extractions.
Here’s the last line that I’m seeing on a somewhat consistent basis:

npm http fetch 200 https://registry.npmjs.org/source-map/-/source-map-0.1.34.tgz
extract:less -> gunzTarPe - |############################################################################################################################----------------------------|

juztinwilzon · April 25, 2016, 5:30pm

Thanks @jespermjonsson, I was hoping I could use the volume work-around you’ve found as a quick-fix. I guess my luck ran out though, I’ve still got the same issue after a couple of attempts =(