Fix truncated plugin binary logs

Signed-off-by: Nathan LeClaire <nathan.leclaire@gmail.com>

libmachine/drivers/plugin/localbinary/plugin.go

@@ -79,6 +79,7 @@ type Plugin struct {
 type Executor struct {
 	pluginStdout, pluginStderr io.ReadCloser
 	DriverName                 string
+	cmd                        *exec.Cmd
 	binaryPath                 string
 }
 
@@ -124,14 +125,14 @@ func (lbe *Executor) Start() (*bufio.Scanner, *bufio.Scanner, error) {
 
 	log.Debugf("Launching plugin server for driver %s", lbe.DriverName)
 
-	cmd := exec.Command(lbe.binaryPath)
+	lbe.cmd = exec.Command(lbe.binaryPath)
 
-	lbe.pluginStdout, err = cmd.StdoutPipe()
+	lbe.pluginStdout, err = lbe.cmd.StdoutPipe()
 	if err != nil {
 		return nil, nil, fmt.Errorf("Error getting cmd stdout pipe: %s", err)
 	}
 
-	lbe.pluginStderr, err = cmd.StderrPipe()
+	lbe.pluginStderr, err = lbe.cmd.StderrPipe()
 	if err != nil {
 		return nil, nil, fmt.Errorf("Error getting cmd stderr pipe: %s", err)
 	}
@@ -142,7 +143,7 @@ func (lbe *Executor) Start() (*bufio.Scanner, *bufio.Scanner, error) {
 	os.Setenv(PluginEnvKey, PluginEnvVal)
 	os.Setenv(PluginEnvDriverName, lbe.DriverName)
 
-	if err := cmd.Start(); err != nil {
+	if err := lbe.cmd.Start(); err != nil {
 		return nil, nil, fmt.Errorf("Error starting plugin binary: %s", err)
 	}
 
@@ -150,34 +151,34 @@ func (lbe *Executor) Start() (*bufio.Scanner, *bufio.Scanner, error) {
 }
 
 func (lbe *Executor) Close() error {
+	if err := lbe.cmd.Wait(); err != nil {
+		return fmt.Errorf("Error waiting for binary close: %s", err)
+	}
+
 	if err := lbe.pluginStdout.Close(); err != nil {
-		return err
+		return fmt.Errorf("Error closing plugin stdout: %s", err)
 	}
 
 	if err := lbe.pluginStderr.Close(); err != nil {
-		return err
+		return fmt.Errorf("Error closing plugin stderr: %s", err)
 	}
 
 	return nil
 }
 
 func stream(scanner *bufio.Scanner, streamOutCh chan<- string, stopCh <-chan bool) {
-	lines := make(chan string)
-	go func() {
-		for scanner.Scan() {
-			lines <- scanner.Text()
-		}
-	}()
 	for {
 		select {
 		case <-stopCh:
 			close(streamOutCh)
 			return
-		case line := <-lines:
+		default:
-			streamOutCh <- strings.Trim(line, "\n")
+			scanner.Scan()
+			line := scanner.Text()
 			if err := scanner.Err(); err != nil {
 				log.Warnf("Scanning stream: %s", err)
 			}
+			streamOutCh <- strings.Trim(line, "\n")
 		}
 	}
 }

libmachine/drivers/plugin/register_driver.go

@@ -30,6 +30,7 @@ Please use this plugin through the main 'docker-machine' binary.
 	}
 
 	log.SetDebug(true)
+	os.Setenv("MACHINE_DEBUG", "1")
 
 	rpcd := rpcdriver.NewRPCServerDriver(d)
 	rpc.RegisterName(rpcdriver.RPCServiceNameV0, rpcd)
@@ -50,10 +51,12 @@ Please use this plugin through the main 'docker-machine' binary.
 	for {
 		select {
 		case <-rpcd.CloseCh:
+			log.Debug("Closing plugin on server side")
 			os.Exit(0)
 		case <-rpcd.HeartbeatCh:
 			continue
 		case <-time.After(heartbeatTimeout):
+			// TODO: Add heartbeat retry logic
 			os.Exit(1)
 		}
 	}

libmachine/drivers/rpc/client_driver.go

@@ -189,12 +189,6 @@ func (c *RPCClientDriver) close() error {
 	c.heartbeatDoneCh <- true
 	close(c.heartbeatDoneCh)
 
-	log.Debug("Making call to close connection to plugin binary")
-
-	if err := c.plugin.Close(); err != nil {
-		return err
-	}
-
 	log.Debug("Making call to close driver server")
 
 	if err := c.Client.Call(CloseMethod, struct{}{}, nil); err != nil {
@@ -203,6 +197,12 @@ func (c *RPCClientDriver) close() error {
 
 	log.Debug("Successfully made call to close driver server")
 
+	log.Debug("Making call to close connection to plugin binary")
+
+	if err := c.plugin.Close(); err != nil {
+		return err
+	}
+
 	return nil
 }