search

docker / for-mac

Bug reports for Docker Desktop for Mac
https://www.docker.com/products/docker#/mac
2.43k stars 118 forks source link

Docker CLI commands - Error response from daemon: Bad response from Docker engine #201

Closed hallmark closed 7 years ago

hallmark commented 8 years ago

Expected behavior

Docker CLI commands should run correctly. Including after macOS recovers from a crash.

Actual behavior

Docker CLI commands return Error response from daemon: Bad response from Docker engine. Examples:

$ docker ps
Error response from daemon: Bad response from Docker engine

$ docker version
Client:
 Version:      1.12.0
 API version:  1.24
 Go version:   go1.6.3
 Git commit:   8eab29e
 Built:        Thu Jul 28 21:04:48 2016
 OS/Arch:      darwin/amd64
 Experimental: true
Error response from daemon: Bad response from Docker engine

$ docker-compose down
ERROR: Bad response from Docker engine

Information

Diagnostic ID: 101ABC7F-5588-401D-AF41-75E647F7BC7F Docker for Mac: 1.12.0-beta21 (Build 11019) macOS: Version 10.11.5 (Build 15F34) [ERROR] docker-cli docker ps failed [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. Have OS X El Capitan crash somehow.
  2. Reboot/recover.
  3. Docker for Mac automatically starts (preference set).
  4. Attempt to run Docker commands from CLI.
  5. Restart Docker for Mac, multiple times, in failed attempts to restore functionality.

Will try "Reset to factory defaults" soon if that's the only option, but not looking forward to losing all my images/volumes.

Over the past several Docker for Mac beta updates, I have not restarted the MBP at all. It is completely possible that this issue is not related to the crash but could simply be related to restarting the Mac after a recent Docker for Mac beta update.

Edit:

FYI: After performing the "Reset to factory defaults" operation, Docker is back to normal and working. However, I'm leaving this issue open for now to allow Docker for Mac engineers to take a look at the diagnostics and Console.app logs below, in case they would like to fix this behavior without forcing users to resort to a "hard reset."

hallmark commented 8 years ago

These were visible in Console.app, printed out twice per second:

8/9/16 4:42:55.576 PM Docker[14807]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 4:42:56.077 PM Docker[14807]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 4:42:56.582 PM Docker[14807]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 4:42:57.085 PM Docker[14807]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
hallmark commented 8 years ago

Output to Console.app after selecting "Reset to factory defaults," in case this output contains any useful troubleshooting info for the original issue:

8/9/16 4:45:23.645 PM Docker[14807]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 4:45:24.152 PM Docker[14807]: Docker is not responding: Get http://./info: net/http: HTTP/1 transport connection broken: readLoopPeekFailLocked: EOF: waiting 0.5s
8/9/16 4:45:24.655 PM Docker[14807]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 4:45:25.160 PM Docker[14807]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 4:45:25.664 PM Docker[14807]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 4:45:26.165 PM Docker[14807]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 4:45:26.669 PM Docker[14807]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 4:45:26.686 PM authexec[14863]: executing /System/Library/ScriptingAdditions/StandardAdditions.osax/Contents/MacOS/uid
8/9/16 4:45:27.174 PM Docker[14807]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 4:45:27.679 PM Docker[14807]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 4:45:28.184 PM Docker[14807]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 4:45:28.685 PM Docker[14807]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 4:45:29.063 PM Docker[14789]: Terminating com.docker.osx.hyperkit.linux and waiting until exit
8/9/16 4:45:29.064 PM Docker[14800]: Received SIGTERM, shutting down
8/9/16 4:45:29.064 PM Docker[14800]: Stop 1 children with order 1: com.docker.driver.amd64-linux (pid 14807)
8/9/16 4:45:29.064 PM Docker[14800]: Signal terminated to com.docker.driver.amd64-linux (pid 14807)
8/9/16 4:45:29.064 PM Docker[14807]: sending SIGTERM to com.docker.hyperkit pid 14811
8/9/16 4:45:29.190 PM Docker[14807]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 4:45:29.458 PM taskgated[205]: no application identifier provided, can't use provisioning profiles [pid=14864]
8/9/16 4:45:29.477 PM taskgated[205]: no application identifier provided, can't use provisioning profiles [pid=14865]
8/9/16 4:45:29.694 PM Docker[14807]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 4:45:30.199 PM Docker[14807]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 4:45:30.704 PM Docker[14807]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 4:45:31.209 PM Docker[14807]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 4:45:31.714 PM Docker[14807]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 4:45:32.219 PM Docker[14807]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 4:45:32.720 PM Docker[14807]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 4:45:33.223 PM Docker[14807]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 4:45:33.724 PM Docker[14807]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 4:45:34.225 PM Docker[14807]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 4:45:34.726 PM Docker[14807]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 4:45:35.232 PM Docker[14807]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 4:45:35.737 PM Docker[14807]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 4:45:36.242 PM Docker[14807]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 4:45:36.747 PM Docker[14807]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 4:45:37.252 PM Docker[14807]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 4:45:37.755 PM Docker[14807]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 4:45:38.259 PM Docker[14807]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 4:45:38.764 PM Docker[14807]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 4:45:39.091 PM Docker[14800]: Timed-out waiting for graceful shutdown
8/9/16 4:45:39.092 PM Docker[14800]: Sending a SIGKILL to /Applications/Docker.app/Contents/MacOS/com.docker.driver.amd64-linux
8/9/16 4:45:39.092 PM Docker[14800]: Signal killed to com.docker.driver.amd64-linux (pid 14807)
8/9/16 4:45:39.095 PM Docker[14800]: Reap com.docker.driver.amd64-linux (pid 14807): signal: killed
8/9/16 4:45:39.096 PM Docker[14800]: Stop 2 children with order 2: com.docker.osxfs (pid 14804), com.docker.slirp (pid 14805)
8/9/16 4:45:39.096 PM Docker[14800]: Signal terminated to com.docker.osxfs (pid 14804)
8/9/16 4:45:39.096 PM Docker[14800]: Signal terminated to com.docker.slirp (pid 14805)
8/9/16 4:45:39.097 PM Docker[14800]: Reap com.docker.osxfs (pid 14804): signal: terminated
8/9/16 4:45:39.097 PM Docker[14800]: Reap com.docker.slirp (pid 14805): signal: terminated
8/9/16 4:45:39.201 PM Docker[14800]: Stop 1 children with order 3: com.docker.osx.hyperkit.linux (pid 14806)
8/9/16 4:45:39.201 PM Docker[14800]: Signal terminated to com.docker.osx.hyperkit.linux (pid 14806)
8/9/16 4:45:39.204 PM Docker[14800]: Reap com.docker.osx.hyperkit.linux (pid 14806): signal: terminated
8/9/16 4:45:39.205 PM Docker[14864]: unexpected EOF
8/9/16 4:45:39.246 PM Docker[14789]: frontend process failed
8/9/16 4:45:39.302 PM Docker[14800]: Stop 1 children with order 4: com.docker.db (pid 14803)
8/9/16 4:45:39.302 PM Docker[14800]: Signal terminated to com.docker.db (pid 14803)
8/9/16 4:45:40.356 PM taskgated[205]: no application identifier provided, can't use provisioning profiles [pid=14867]
8/9/16 4:45:40.366 PM Docker[14867]: dial unix /Users/mture200/Library/Containers/com.docker.docker/Data/s20: connect: connection refused
8/9/16 4:45:40.374 PM taskgated[205]: no application identifier provided, can't use provisioning profiles [pid=14868]
8/9/16 4:45:40.446 PM Docker[14789]: frontend process failed
8/9/16 4:45:40.537 PM Docker[14789]: com.docker.osx.hyperkit.linux termination timed out and has been killed
8/9/16 4:45:40.549 PM Docker[14869]: Client reports version 1, commit 5a44e81a0513f32f5c49f7d2966570893451f32f
8/9/16 4:45:40.549 PM Docker[14869]: client with uid 1767711893 requests com.docker.vmnetd uninstall symlinks
8/9/16 4:45:40.561 PM Docker[14869]: File /usr/local/bin/docker is a symlink
8/9/16 4:45:40.574 PM Docker[14869]: File /usr/local/bin/docker-compose is a symlink
8/9/16 4:45:40.574 PM Docker[14869]: File /usr/local/bin/notary is a symlink
8/9/16 4:45:40.575 PM Docker[14869]: File /usr/local/bin/docker-machine is a symlink
8/9/16 4:45:40.575 PM Docker[14869]: File /var/run/docker.sock is a symlink or a socket
8/9/16 4:45:40.577 PM Docker[14870]: Client reports version 1, commit 5a44e81a0513f32f5c49f7d2966570893451f32f
8/9/16 4:45:40.578 PM Docker[14871]: Client reports version 1, commit 5a44e81a0513f32f5c49f7d2966570893451f32f
8/9/16 4:45:40.578 PM Docker[14871]: client requests com.docker.vmnetd uninstall
8/9/16 4:45:40.595 PM Docker[14871]: com.docker.vmnetd uninstall complete
8/9/16 4:45:40.601 PM Docker[14871]: Deleted /var/tmp/com.docker.vmnetd.socket
8/9/16 4:45:40.953 PM cfprefsd[1103]: cfprefsd failed to open /Users/mture200/Library/Group Containers/group.com.docker/Library/Preferences/group.com.docker.plist.yiPOgWO for writing. Cancelling attempt to save preferences. Errno was 2
8/9/16 4:45:41.557 PM taskgated[205]: no application identifier provided, can't use provisioning profiles [pid=14873]
8/9/16 4:45:41.567 PM Docker[14873]: dial unix /Users/mture200/Library/Containers/com.docker.docker/Data/s20: connect: no such file or directory
8/9/16 4:45:41.575 PM taskgated[205]: no application identifier provided, can't use provisioning profiles [pid=14874]
8/9/16 4:45:41.646 PM Docker[14789]: frontend process failed
8/9/16 4:45:42.757 PM taskgated[205]: no application identifier provided, can't use provisioning profiles [pid=14875]
8/9/16 4:45:42.766 PM Docker[14875]: dial unix /Users/mture200/Library/Containers/com.docker.docker/Data/s20: connect: no such file or directory
8/9/16 4:45:42.775 PM taskgated[205]: no application identifier provided, can't use provisioning profiles [pid=14876]
8/9/16 4:45:42.846 PM Docker[14789]: frontend process failed
8/9/16 4:45:43.074 PM Docker[14800]: EOF on watchdog pipe: shutting down
8/9/16 4:45:43.119 PM taskgated[205]: no application identifier provided, can't use provisioning profiles [pid=14878]
8/9/16 4:45:43.175 PM Docker[14878]: Application version: 1.12.0-beta21 (11019)
8/9/16 4:45:43.175 PM Docker[14878]: Administrator user: false
8/9/16 4:45:43.191 PM Docker[14878]: OSX Version: Version 10.11.5 (Build 15F34)
8/9/16 4:45:43.383 PM Docker[14878]: migrator: start migration process
8/9/16 4:45:43.384 PM Docker[14878]: migrator: no previous version detected. Performing all migrations for now...
8/9/16 4:45:43.384 PM Docker[14878]: migrator: 18 migrations to perform
8/9/16 4:45:43.384 PM Docker[14878]: migrator: migrating for version 1.10.3-beta5 ...
8/9/16 4:45:43.385 PM Docker[14878]: migrator: migration succeeded for version 1.10.3-beta5
8/9/16 4:45:43.385 PM Docker[14878]: migrator: migrating for version 1.11.0-beta6 ...
8/9/16 4:45:43.386 PM Docker[14878]: migrator: migration succeeded for version 1.11.0-beta6
8/9/16 4:45:43.386 PM Docker[14878]: migrator: migrating for version 1.11.0-beta7 ...
8/9/16 4:45:43.386 PM Docker[14878]: migrator: migration succeeded for version 1.11.0-beta7
8/9/16 4:45:43.386 PM Docker[14878]: migrator: migrating for version 1.11.0-beta8 ...
8/9/16 4:45:43.386 PM Docker[14878]: migrator: migration succeeded for version 1.11.0-beta8
8/9/16 4:45:43.387 PM Docker[14878]: migrator: migrating for version 1.11.0-beta9 ...
8/9/16 4:45:43.387 PM Docker[14878]: migrator: migration succeeded for version 1.11.0-beta9
8/9/16 4:45:43.387 PM Docker[14878]: migrator: migrating for version 1.11.1-beta10 ...
8/9/16 4:45:43.387 PM Docker[14878]: migrator: migration succeeded for version 1.11.1-beta10
8/9/16 4:45:43.387 PM Docker[14878]: migrator: migrating for version 1.11.1-beta11 ...
8/9/16 4:45:43.388 PM Docker[14878]: migrator: migration succeeded for version 1.11.1-beta11
8/9/16 4:45:43.388 PM Docker[14878]: migrator: migrating for version 1.11.1-beta12 ...
8/9/16 4:45:43.388 PM Docker[14878]: migrator: migration succeeded for version 1.11.1-beta12
8/9/16 4:45:43.388 PM Docker[14878]: migrator: migrating for version 1.11.1-beta13 ...
8/9/16 4:45:43.388 PM Docker[14878]: migrator: migration succeeded for version 1.11.1-beta13
8/9/16 4:45:43.389 PM Docker[14878]: migrator: migrating for version 1.11.1-beta13.1 ...
8/9/16 4:45:43.389 PM Docker[14878]: migrator: migration succeeded for version 1.11.1-beta13.1
8/9/16 4:45:43.389 PM Docker[14878]: migrator: migrating for version 1.11.1-beta14 ...
8/9/16 4:45:43.389 PM Docker[14878]: migrator: migration succeeded for version 1.11.1-beta14
8/9/16 4:45:43.389 PM Docker[14878]: migrator: migrating for version 1.11.2-beta15 ...
8/9/16 4:45:43.390 PM Docker[14878]: migrator: migration succeeded for version 1.11.2-beta15
8/9/16 4:45:43.390 PM Docker[14878]: migrator: migrating for version 1.12.0-rc2-beta16 ...
8/9/16 4:45:43.390 PM Docker[14878]: migrator: migration succeeded for version 1.12.0-rc2-beta16
8/9/16 4:45:43.390 PM Docker[14878]: migrator: migrating for version 1.12.0-rc2-beta17 ...
8/9/16 4:45:43.390 PM Docker[14878]: migrator: migration succeeded for version 1.12.0-rc2-beta17
8/9/16 4:45:43.391 PM Docker[14878]: migrator: migrating for version 1.12.0-rc3-beta18 ...
8/9/16 4:45:43.391 PM Docker[14878]: migrator: migration succeeded for version 1.12.0-rc3-beta18
8/9/16 4:45:43.391 PM Docker[14878]: migrator: migrating for version 1.12.0-rc4-beta19 ...
8/9/16 4:45:43.391 PM Docker[14878]: migrator: migration succeeded for version 1.12.0-rc4-beta19
8/9/16 4:45:43.391 PM Docker[14878]: migrator: migrating for version 1.12.0-rc4-beta20 ...
8/9/16 4:45:43.392 PM Docker[14878]: migrator: migration succeeded for version 1.12.0-rc4-beta20
8/9/16 4:45:43.392 PM Docker[14878]: migrator: migrating for version 1.12.0-beta21 ...
8/9/16 4:45:43.392 PM Docker[14878]: migrator: migration succeeded for version 1.12.0-beta21
8/9/16 4:45:43.392 PM Docker[14878]: migrator: end of migration process
8/9/16 4:45:43.412 PM Docker[14878]: event tracker initialized
8/9/16 4:45:46.128 PM Docker[14878]: Bundle path: /Applications/Docker.app
8/9/16 4:45:49.321 PM Docker[14800]: Timed-out waiting for graceful shutdown
8/9/16 4:45:49.321 PM Docker[14800]: Sending a SIGKILL to /Applications/Docker.app/Contents/MacOS/com.docker.db
8/9/16 4:45:49.321 PM Docker[14800]: Signal killed to com.docker.db (pid 14803)
8/9/16 4:45:49.322 PM Docker[14800]: Reap com.docker.db (pid 14803): signal: killed
8/9/16 4:45:49.577 PM SecurityAgent[14887]: activateIgnoringOtherApps:1
8/9/16 4:45:49.580 PM SecurityAgent[14887]: makeKeyAndOrderFront
8/9/16 4:45:49.611 PM SecurityAgent[14887]: com.apple.SecurityAgent.consoleLogin.UIShown
8/9/16 4:45:53.585 PM Docker[14878]: privileged installation of com.docker.vmnetd successful
8/9/16 4:45:55.609 PM Docker[14889]: com.docker.vmnetd starting
8/9/16 4:45:55.610 PM Docker[14890]: EOF reading packet from Unix domain socket: closing
8/9/16 4:45:55.610 PM Docker[14891]: Client reports version 1, commit 5a44e81a0513f32f5c49f7d2966570893451f32f
8/9/16 4:45:55.610 PM Docker[14890]: Failed to read hello from client
8/9/16 4:45:55.611 PM Docker[14891]: client with uid 1767711893 requests com.docker.vmnetd install symlinks
8/9/16 4:45:55.868 PM Docker[14891]: User 1767711893 has container folder /Users/mture200/Library/Containers/com.docker.docker/Data/s60
8/9/16 4:45:56.021 PM Docker[14891]: User 1767711893 has container folder /Users/mture200/Library/Containers/com.docker.docker/Data/s60
8/9/16 4:45:56.021 PM Docker[14891]: File /var/run/docker.sock is a symlink or a socket
8/9/16 4:45:56.022 PM Docker[14891]: User 1767711893 has container folder /Users/mture200/Library/Containers/com.docker.docker/Data/s60
8/9/16 4:45:56.022 PM Docker[14891]: File /var/run/docker.sock is a symlink or a socket
8/9/16 4:45:56.259 PM Docker[14891]: User 1767711893 has container folder /Users/mture200/Library/Containers/com.docker.docker/Data/s60
8/9/16 4:45:56.259 PM Docker[14891]: File /var/run/docker.sock is a symlink or a socket
8/9/16 4:45:56.259 PM Docker[14878]: Symlinks are not correctly installed.
hallmark commented 8 years ago

And then after selecting yes in the dialog box to migrate from the existing "default" machine:

8/9/16 4:47:41.251 PM Docker[14878]: progress 0.00
8/9/16 4:47:49.850 PM Docker[14878]: progress 1.00
8/9/16 4:47:59.217 PM Docker[14878]: progress 2.00
8/9/16 4:48:09.685 PM Docker[14878]: progress 3.00
8/9/16 4:48:20.142 PM Docker[14878]: progress 4.00
8/9/16 4:48:22.848 PM Docker[14878]: progress 5.00
8/9/16 4:48:23.171 PM Docker[14878]: progress 6.00
8/9/16 4:48:23.485 PM Docker[14878]: progress 7.00
8/9/16 4:48:23.806 PM Docker[14878]: progress 8.00
8/9/16 4:48:24.130 PM Docker[14878]: progress 9.00
8/9/16 4:48:24.447 PM Docker[14878]: progress 10.00
8/9/16 4:48:24.779 PM Docker[14878]: progress 11.00
8/9/16 4:48:25.106 PM Docker[14878]: progress 12.00
8/9/16 4:48:25.432 PM Docker[14878]: progress 13.00
8/9/16 4:48:25.753 PM Docker[14878]: progress 14.00
8/9/16 4:48:26.079 PM Docker[14878]: progress 15.00
8/9/16 4:48:26.402 PM Docker[14878]: progress 16.00
8/9/16 4:48:26.725 PM Docker[14878]: progress 17.00
8/9/16 4:48:27.000 PM com.apple.CDScheduler[47]: Thermal pressure state: 2 Memory pressure state: 0
8/9/16 4:48:27.013 PM com.apple.CDScheduler[1099]: Thermal pressure state: 2 Memory pressure state: 0
8/9/16 4:48:27.067 PM Docker[14878]: progress 18.00
8/9/16 4:48:27.388 PM Docker[14878]: progress 19.00
8/9/16 4:48:27.713 PM Docker[14878]: progress 20.00
8/9/16 4:48:28.041 PM Docker[14878]: progress 21.00
8/9/16 4:48:28.364 PM Docker[14878]: progress 22.00
8/9/16 4:48:28.690 PM Docker[14878]: progress 23.00
8/9/16 4:48:29.011 PM Docker[14878]: progress 24.00
8/9/16 4:48:29.336 PM Docker[14878]: progress 25.00
8/9/16 4:48:29.660 PM Docker[14878]: progress 26.00
8/9/16 4:48:29.985 PM Docker[14878]: progress 27.00
8/9/16 4:48:30.311 PM Docker[14878]: progress 28.00
8/9/16 4:48:30.635 PM Docker[14878]: progress 29.00
8/9/16 4:48:30.963 PM Docker[14878]: progress 30.00
8/9/16 4:48:31.279 PM Docker[14878]: progress 31.00
8/9/16 4:48:31.597 PM Docker[14878]: progress 32.00
8/9/16 4:48:31.917 PM Docker[14878]: progress 33.00
8/9/16 4:48:32.253 PM Docker[14878]: progress 34.00
8/9/16 4:48:32.572 PM Docker[14878]: progress 35.00
8/9/16 4:48:32.890 PM Docker[14878]: progress 36.00
8/9/16 4:48:33.209 PM Docker[14878]: progress 37.00
8/9/16 4:48:33.534 PM Docker[14878]: progress 38.00
8/9/16 4:48:33.857 PM Docker[14878]: progress 39.00
8/9/16 4:48:34.194 PM Docker[14878]: progress 40.00
8/9/16 4:48:34.514 PM Docker[14878]: progress 41.00
8/9/16 4:48:34.850 PM Docker[14878]: progress 42.00
8/9/16 4:48:35.175 PM Docker[14878]: progress 43.00
8/9/16 4:48:35.492 PM Docker[14878]: progress 44.00
8/9/16 4:48:35.816 PM Docker[14878]: progress 45.00
8/9/16 4:48:36.151 PM Docker[14878]: progress 46.00
8/9/16 4:48:36.474 PM Docker[14878]: progress 47.00
8/9/16 4:48:36.793 PM Docker[14878]: progress 48.00
8/9/16 4:48:37.119 PM Docker[14878]: progress 49.00
8/9/16 4:48:38.603 PM Docker[14878]: progress 50.00
8/9/16 4:48:38.920 PM Docker[14878]: progress 51.00
8/9/16 4:48:39.234 PM Docker[14878]: progress 52.00
8/9/16 4:48:39.554 PM Docker[14878]: progress 53.00
8/9/16 4:48:39.870 PM Docker[14878]: progress 54.00
8/9/16 4:48:40.191 PM Docker[14878]: progress 55.00
8/9/16 4:48:40.515 PM Docker[14878]: progress 56.00
8/9/16 4:48:40.842 PM Docker[14878]: progress 57.00
8/9/16 4:48:41.161 PM Docker[14878]: progress 58.00
8/9/16 4:48:41.481 PM Docker[14878]: progress 59.00
8/9/16 4:48:41.803 PM Docker[14878]: progress 60.00
8/9/16 4:48:42.129 PM Docker[14878]: progress 61.00
8/9/16 4:48:42.451 PM Docker[14878]: progress 62.00
8/9/16 4:48:43.048 PM Docker[14878]: progress 63.00
8/9/16 4:48:43.503 PM Docker[14878]: progress 64.00
8/9/16 4:48:45.381 PM Docker[14878]: progress 65.00
8/9/16 4:48:46.361 PM Docker[14878]: progress 66.00
8/9/16 4:48:46.874 PM Docker[14878]: progress 67.00
8/9/16 4:48:47.507 PM Docker[14878]: progress 68.00
8/9/16 4:48:48.051 PM Docker[14878]: progress 69.00
8/9/16 4:48:49.605 PM Docker[14878]: progress 70.00
8/9/16 4:48:50.246 PM Docker[14878]: progress 71.00
8/9/16 4:48:52.104 PM Docker[14878]: progress 72.00
8/9/16 4:48:52.641 PM Docker[14878]: progress 73.00
8/9/16 4:48:53.210 PM Docker[14878]: progress 74.00
8/9/16 4:48:54.464 PM Docker[14878]: progress 75.00
8/9/16 4:48:55.720 PM Docker[14878]: progress 76.00
8/9/16 4:48:57.421 PM Docker[14878]: progress 77.00
8/9/16 4:48:58.165 PM Docker[14878]: progress 78.00
8/9/16 4:49:00.487 PM Docker[14878]: progress 79.00
8/9/16 4:49:01.477 PM Docker[14878]: progress 80.00
8/9/16 4:49:01.950 PM Docker[14878]: progress 81.00
8/9/16 4:49:02.317 PM Docker[14878]: progress 82.00
8/9/16 4:49:02.742 PM Docker[14878]: progress 83.00
8/9/16 4:49:03.244 PM Docker[14878]: progress 84.00
8/9/16 4:49:03.588 PM Docker[14878]: progress 85.00
8/9/16 4:49:04.713 PM Docker[14878]: progress 86.00
8/9/16 4:49:05.893 PM Docker[14878]: progress 87.00
8/9/16 4:49:06.582 PM Docker[14878]: progress 88.00
8/9/16 4:49:07.325 PM Docker[14878]: progress 89.00
8/9/16 4:49:09.568 PM Docker[14878]: progress 90.00
8/9/16 4:49:10.706 PM Docker[14878]: progress 91.00
8/9/16 4:49:12.075 PM Docker[14878]: progress 92.00
8/9/16 4:49:12.981 PM Docker[14878]: progress 93.00
8/9/16 4:49:13.813 PM Docker[14878]: progress 94.00
8/9/16 4:49:14.204 PM Docker[14878]: progress 95.00
8/9/16 4:49:14.646 PM Docker[14878]: progress 96.00
8/9/16 4:49:15.767 PM Docker[14878]: progress 97.00
8/9/16 4:49:16.097 PM Docker[14878]: progress 98.00
8/9/16 4:49:16.421 PM Docker[14878]: progress 99.00
8/9/16 4:49:16.740 PM Docker[14878]: progress 100.00
8/9/16 4:49:17.009 PM Docker[14878]: progress 100.00
8/9/16 4:49:17.010 PM Docker[14878]: Converting machine default volume done
8/9/16 4:49:54.000 PM kernel[0]: Sandbox: repmgr(66) System Policy: deny(1) mach-priv-task-port
8/9/16 4:49:58.250 PM launchservicesd[90]: SecTaskLoadEntitlements failed error=22
8/9/16 4:49:58.251 PM launchservicesd[90]: SecTaskLoadEntitlements failed error=22
8/9/16 4:49:58.255 PM launchservicesd[90]: SecTaskLoadEntitlements failed error=22
hallmark commented 8 years ago

And finally, after the migration finished, clicking 'ok' in the dialog box appears to allow Docker to finish loading up:

8/9/16 5:00:15.196 PM lsd[1105]: LaunchServices: Could not store lsd-identifiers file at /private/var/db/lsd/com.apple.lsdschemes.plist
8/9/16 5:00:15.207 PM taskgated[205]: no application identifier provided, can't use provisioning profiles [pid=15374]
8/9/16 5:00:15.208 PM Docker[14878]: com.docker.osx.hyperkit.linux launched with PID 15374
8/9/16 5:00:15.236 PM taskgated[205]: no application identifier provided, can't use provisioning profiles [pid=15375]
8/9/16 5:00:15.269 PM Docker[15374]: Acquired task manager lock
8/9/16 5:00:15.271 PM taskgated[205]: no application identifier provided, can't use provisioning profiles [pid=15376]
8/9/16 5:00:15.271 PM Docker[15374]: Maximum number of file descriptors is 10240
8/9/16 5:00:15.279 PM Docker[15374]: Starting com.docker.db, com.docker.osxfs, com.docker.slirp, com.docker.osx.hyperkit.linux, com.docker.driver.amd64-linux
8/9/16 5:00:15.282 PM Docker[15374]: Start com.docker.db (pid 15377)
8/9/16 5:00:15.289 PM Docker[15374]: Start com.docker.osxfs (pid 15378)
8/9/16 5:00:15.292 PM Docker[15374]: Start com.docker.slirp (pid 15379)
8/9/16 5:00:15.297 PM Docker[15374]: Start com.docker.osx.hyperkit.linux (pid 15381)
8/9/16 5:00:15.301 PM Docker[15374]: Start com.docker.driver.amd64-linux (pid 15382)
8/9/16 5:00:15.302 PM Docker[15375]: dial unix /Users/mture200/Library/Containers/com.docker.docker/Data/s20: connect: no such file or directory
8/9/16 5:00:15.307 PM taskgated[205]: no application identifier provided, can't use provisioning profiles [pid=15381]
8/9/16 5:00:15.313 PM taskgated[205]: no application identifier provided, can't use provisioning profiles [pid=15382]
8/9/16 5:00:15.318 PM taskgated[205]: no application identifier provided, can't use provisioning profiles [pid=15380]
8/9/16 5:00:15.321 PM Docker[15381]: API server starting
8/9/16 5:00:15.323 PM Docker[15381]: 🍀 socket path is: /Users/mture200/Library/Containers/com.docker.docker/Data/s20
8/9/16 5:00:15.327 PM taskgated[205]: no application identifier provided, can't use provisioning profiles [pid=15383]
8/9/16 5:00:15.356 PM Docker[15378]: Logging to Apple System Log
8/9/16 5:00:15.369 PM Docker[15381]: Failed to watch the com.docker.driver.amd64-linux/state/ directory in the database: 9p: No such file or directory
8/9/16 5:00:15.370 PM Docker[14878]: frontend process failed
8/9/16 5:00:15.391 PM Docker[15379]: Logging to Apple System Log
8/9/16 5:00:15.391 PM Docker[15379]: Setting handler to ignore all SIGPIPE signals
8/9/16 5:00:15.391 PM Docker[15379]: vpnkit version b071bb4 with hostnet version local  uwt version 0.0.3 hvsock version 0.8.1 
8/9/16 5:00:15.391 PM Docker[15379]: starting port_forwarding port_control_url:fd:4 max_connections:Some 900 vsock_path:/Users/mture200/Library/Containers/com.docker.docker/Data/@connect
8/9/16 5:00:15.436 PM taskgated[205]: no application identifier provided, can't use provisioning profiles [pid=15384]
8/9/16 5:00:15.436 PM Docker[15382]: Acquired hypervisor lock
8/9/16 5:00:15.450 PM Docker[15382]: Docker is not responding: Get http://./info: dial unix /Users/mture200/Library/Containers/com.docker.docker/Data/*00000003.00000948: connect: no such file or directory: waiting 0.5s
8/9/16 5:00:15.519 PM Docker[15382]: hypervisor: native
8/9/16 5:00:15.519 PM Docker[15382]: filesystem: osxfs
8/9/16 5:00:15.519 PM Docker[15382]: network: hybrid
8/9/16 5:00:15.579 PM Docker[15378]: Using protocol TwoThousand msize 16384
8/9/16 5:00:15.580 PM Docker[15382]: Hypervisor: native; BootProtocol: direct; UefiBootDisk: /Users/mture200/UefiBoot.qcow2
8/9/16 5:00:15.580 PM Docker[15382]: Syslog socket is /Users/mture200/Library/Containers/com.docker.docker/Data/*00000002.00000202
8/9/16 5:00:15.583 PM Docker[15382]: Logfile is /Users/mture200/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/syslog
8/9/16 5:00:15.583 PM Docker[15382]: Launched[15385]: /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-vpnkit,uuid=623bf050-969f-468c-ac9d-f0037a6fbfb0,path=/Users/mture200/Library/Containers/com.docker.docker/Data/s50,macfile=/Users/mture200/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/mac.0 -s 3,virtio-blk,file:///Users/mture200/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/Docker.qcow2,format=qcow -s 4,virtio-9p,path=/Users/mture200/Library/Containers/com.docker.docker/Data/s40,tag=db -s 5,virtio-rnd -s 6,virtio-9p,path=/Users/mture200/Library/Containers/com.docker.docker/Data/s51,tag=port -s 7,virtio-sock,guest_cid=3,path=/Users/mture200/Library/Containers/com.docker.docker/Data,guest_forwards=2376;1525 -l com1,autopty=/Users/mture200/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/tty,log=/Users/mture200/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 /Users/mture200/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/hypervisor.pid
8/9/16 5:00:15.603 PM Docker[15379]: attempting to reconnect to database
8/9/16 5:00:15.605 PM Docker[15379]: reconnected transport layer
8/9/16 5:00:15.605 PM Docker[15379]: remove resolver override
8/9/16 5:00:15.605 PM Docker[15379]: using default DNS on 
8/9/16 5:00:15.606 PM Docker[15379]: allowing binds to any IP addresses
8/9/16 5:00:15.606 PM Docker[15379]: Creating slirp server pcap_settings:disabled peer_ip:192.168.65.2 local_ip:192.168.65.1
8/9/16 5:00:15.607 PM Docker[15379]: PPP.negotiate: received ((magic VMN3T)(version 1)(commit 5a44e81a0513f32f5c49f7d2966570893451f32f))
8/9/16 5:00:15.607 PM Docker[15379]: PPP.negotiate: received (Ethernet 623bf050-969f-468c-ac9d-f0037a6fbfb0)
8/9/16 5:00:15.607 PM Docker[15382]: virtio-net-vpnkit: magic=VMN3T version=1 commit=0123456789012345678901234567890123456789
8/9/16 5:00:15.607 PM Docker[15379]: PPP.negotiate: sending ((mtu 1500)(max_packet_size 1550)(client_macaddr c0:ff:ee:c0:ff:ee))
8/9/16 5:00:15.607 PM Docker[15379]: PPP.listen: called a second time: doing nothing
8/9/16 5:00:15.607 PM Docker[15379]: TCP/IP ready
8/9/16 5:00:15.607 PM Docker[15379]: stack connected
8/9/16 5:00:15.608 PM Docker[15382]: mirage_block_open file:///Users/mture200/Library/Containers/com.docker.docker/Data/com.docker.driver.amd64-linux/Docker.qcow2 buffered = true
8/9/16 5:00:15.608 PM Docker[15382]: mirage_block_open returning 0
8/9/16 5:00:15.608 PM Docker[15382]: mirage_block_stat
8/9/16 5:00:15.608 PM Docker[15382]: vsock init 7:0 = /Users/mture200/Library/Containers/com.docker.docker/Data, guest_cid = 3
8/9/16 5:00:16.371 PM Docker[15381]: Failed to read the last-start-time key: 9p: No such file or directory
8/9/16 5:00:16.372 PM Docker[15381]: Failed to read the last-shutdown-time key: 9p: No such file or directory
8/9/16 5:00:16.372 PM Docker[15381]: VM shutdown at 1969-12-31 16:00:00 -0800 PST
8/9/16 5:00:16.481 PM taskgated[205]: no application identifier provided, can't use provisioning profiles [pid=15386]
8/9/16 5:00:16.502 PM taskgated[205]: no application identifier provided, can't use provisioning profiles [pid=15387]
8/9/16 5:00:17.823 PM Docker[15382]: 
rdmsr to register 0x34 on vcpu 3
8/9/16 5:00:18.448 PM Docker[15382]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 5:00:18.949 PM Docker[15382]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 5:00:19.450 PM Docker[15382]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 5:00:19.951 PM Docker[15382]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 5:00:20.451 PM Docker[15382]: Docker is not responding: Get http://./info: EOF: waiting 0.5s
8/9/16 5:00:20.568 PM Docker[15378]: transfused: mount /bin/fusermount -o allow_other,max_read=1048576,subtype=osxfs /host_docker_app
8/9/16 5:00:20.569 PM Docker[15378]: transfused: mount /bin/fusermount -o allow_other,max_read=1048576,subtype=osxfs /private
8/9/16 5:00:20.570 PM Docker[15378]: transfused: mount /bin/fusermount -o allow_other,max_read=1048576,subtype=osxfs /tmp
8/9/16 5:00:20.571 PM Docker[15378]: transfused: mount /bin/fusermount -o allow_other,max_read=1048576,subtype=osxfs /Volumes
8/9/16 5:00:20.572 PM Docker[15378]: transfused: mount /bin/fusermount -o allow_other,max_read=1048576,subtype=osxfs /Users
8/9/16 5:00:20.573 PM Docker[15378]: Negotiated transfuse notification channel for /host_docker_app
8/9/16 5:00:20.573 PM Docker[15378]: Negotiated transfuse notification channel for /private
8/9/16 5:00:20.573 PM Docker[15378]: Negotiated transfuse notification channel for /tmp
8/9/16 5:00:20.573 PM Docker[15378]: Negotiated transfuse notification channel for /Volumes
8/9/16 5:00:20.573 PM Docker[15378]: Negotiated transfuse notification channel for /Users
8/9/16 5:00:20.573 PM Docker[15378]: sending continue to client
8/9/16 5:00:20.610 PM Docker[15379]: Using protocol TwoThousand msize 8192
8/9/16 5:00:20.872 PM Docker[15382]: VM: 2016-08-10 00:00:20 +0000 UTC daemon.info chronyd: chronyd version 2.3 starting (+CMDMON +NTP +REFCLOCK +RTC +PRIVDROP -SCFILTER -SECHASH +ASYNCDNS +IPV6 -DEBUG)
8/9/16 5:00:20.872 PM Docker[15382]: VM: 2016-08-10 00:00:20 +0000 UTC daemon.warn chronyd: Could not open keyfile /etc/chrony/chrony.keys
8/9/16 5:00:20.954 PM Docker[15382]: VM: 2016-08-10 00:00:20 +0000 UTC daemon.info vsudd: Connection 1 to: 2376 from: 00000000
8/9/16 5:00:22.697 PM Docker[15382]: VM: 2016-08-10 00:00:22 +0000 UTC kern.notice kernel: random: nonblocking pool is initialized
8/9/16 5:00:25.109 PM Docker[15382]: VM: 2016-08-10 00:00:25 +0000 UTC daemon.info chronyd: Selected source 192.168.65.1
8/9/16 5:00:26.545 PM taskgated[205]: no application identifier provided, can't use provisioning profiles [pid=15388]
8/9/16 5:00:26.568 PM taskgated[205]: no application identifier provided, can't use provisioning profiles [pid=15389]
8/9/16 5:00:27.000 PM kernel[0]: process com.docker.hyper[15385] caught causing excessive wakeups. EXC_RESOURCE supressed due to audio playback
8/9/16 5:00:36.368 PM com.apple.CDScheduler[1099]: Thermal pressure state: 2 Memory pressure state: 0
8/9/16 5:00:36.369 PM com.apple.CDScheduler[47]: Thermal pressure state: 2 Memory pressure state: 0
8/9/16 5:00:36.631 PM taskgated[205]: no application identifier provided, can't use provisioning profiles [pid=15390]
8/9/16 5:00:36.655 PM taskgated[205]: no application identifier provided, can't use provisioning profiles [pid=15391]
8/9/16 5:00:46.694 PM taskgated[205]: no application identifier provided, can't use provisioning profiles [pid=15392]
8/9/16 5:00:46.717 PM taskgated[205]: no application identifier provided, can't use provisioning profiles [pid=15393]
8/9/16 5:00:56.786 PM taskgated[205]: no application identifier provided, can't use provisioning profiles [pid=15394]
8/9/16 5:00:56.815 PM taskgated[205]: no application identifier provided, can't use provisioning profiles [pid=15395]
8/9/16 5:01:06.831 PM taskgated[205]: no application identifier provided, can't use provisioning profiles [pid=15396]
8/9/16 5:01:06.854 PM taskgated[205]: no application identifier provided, can't use provisioning profiles [pid=15397]
8/9/16 5:01:16.932 PM taskgated[205]: no application identifier provided, can't use provisioning profiles [pid=15398]
8/9/16 5:01:16.954 PM taskgated[205]: no application identifier provided, can't use provisioning profiles [pid=15399]
8/9/16 5:01:16.969 PM Docker[15382]: VM: 2016-08-10 00:01:16 +0000 UTC kern.info kernel: IPv6: ADDRCONF(NETDEV_UP): docker0: link is not ready
8/9/16 5:01:17.037 PM Docker[15382]: VM: 2016-08-10 00:01:17 +0000 UTC kern.warn kernel: aufs au_opts_verify:1597:dockerd[1560]: dirperm1 breaks the protection by the permission bits on the lower branch
8/9/16 5:01:17.096 PM Docker[15382]: Docker is responding
8/9/16 5:01:17.099 PM Docker[15382]: VM: 2016-08-10 00:01:17 +0000 UTC daemon.info vsudd: Connection 2 to: 2376 from: 00000000
8/9/16 5:01:17.109 PM Docker[15381]: Failed to read the last-shutdown-time key: 9p: No such file or directory
8/9/16 5:01:17.109 PM Docker[15381]: VM started at 2016-08-09 17:01:17 -0700 PDT
8/9/16 5:01:17.118 PM Docker[15382]: VM: 2016-08-10 00:01:17 +0000 UTC daemon.info init: starting pid 1708, tty '/dev/ttyS0': '/sbin/getty -L 115200 ttyS0 vt100'
8/9/16 5:01:17.469 PM Docker[14878]: dockerState = Starting
8/9/16 5:01:17.483 PM taskgated[205]: no application identifier provided, can't use provisioning profiles [pid=15400]
8/9/16 5:01:17.502 PM taskgated[205]: no application identifier provided, can't use provisioning profiles [pid=15401]
8/9/16 5:01:18.098 PM Docker[15382]: VM: 2016-08-10 00:01:18 +0000 UTC daemon.info vsudd: Connection 3 to: 2376 from: 00000000
mchiang0610 commented 7 years ago

Merging with #119

samoht commented 7 years ago

Detected symptom of problem 'moby-kernel-froze' in 101ABC7F-5588-401D-AF41-75E647F7BC7F/20160809-115108.

The kernel inside the VM stalled so Docker must be restarted.

May be related to docker/for-mac#87

The following log matches:

Aug  6 08:46:03 CACSVLO-15349 Docker[com.docker.driver.amd64-linux][13736] <Notice>: vcpu 2 received signal, resuming
Aug  6 08:46:03 CACSVLO-15349 Docker[com.docker.driver.amd64-linux][13736] <Notice>: vcpu 1 received signal, resuming
Aug  6 08:46:03 CACSVLO-15349 Docker[com.docker.driver.amd64-linux][13736] <Notice>: vcpu 3 received signal, resuming
Aug  6 08:46:03 CACSVLO-15349 Docker[com.docker.driver.amd64-linux][13736] <Notice>: vcpu 0 received signal, resuming
Aug  6 08:46:03 CACSVLO-15349 Docker[com.docker.driver.amd64-linux][13736] <Error>: VM: 2016-08-06 09:43:37 +0000 UTC kern.error kernel: INFO: rcu_sched self-detected stall on CPU
Aug  6 08:46:03 CACSVLO-15349 Docker[com.docker.driver.amd64-linux][13736] <Error>: VM: 2016-08-06 09:43:37 +0000 UTC kern.error kernel: INFO: rcu_sched self-detected stall on CPU
Aug  6 08:46:03 CACSVLO-15349 Docker[com.docker.driver.amd64-linux][13736] <Error>: VM: 2016-08-06 09:43:37 +0000 UTC kern.error kernel: INFO: rcu_sched self-detected stall on CPU
Aug  6 08:46:03 CACSVLO-15349 Docker[com.docker.driver.amd64-linux][13736] <Error>: VM: 2016-08-06 09:43:37 +0000 UTC kern.error kernel: INFO: rcu_sched self-detected stall on CPU
docker-robott commented 4 years ago

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