veyron/services/mgmt/node/impl: fix data race around stdoutpipe
The issue was introduced back in http://go/vcl/5902, when Cos wanted a more
robust way to interleave stdout from the child and the parent node
managers. However, as explained in
http://golang.org/pkg/os/exec/#Cmd.StdoutPipe, it is incorrect to try to call
Wait on the cmd while reads on the pipe are still in progress.
The fix we're going with is to just dump stdout of the child to a log file
instead of using a pipe (the same as what we do for stderr). We could then
choose to transcribe the contents of the stdout file to the parent's os.Stdout,
but instead we decided to dump everything to vlog. I don't see a reason to merge
the child's stdout with the parent's anymore, and this also simplifies the test
logic in impl_test, where we're now receiving and dealing with stdout output
from the parent only.
This fixes a long-standing jenkins veyron-go-race failure cause, most recently
reported as http://go/vissues/386.
Change-Id: I5d223db822a4132e0c0cae78a3ca3b9b4c957a60
diff --git a/services/mgmt/node/impl/impl_test.go b/services/mgmt/node/impl/impl_test.go
index 37b5bb9..0ba9f13 100644
--- a/services/mgmt/node/impl/impl_test.go
+++ b/services/mgmt/node/impl/impl_test.go
@@ -367,12 +367,6 @@
t.Fatalf("current link didn't change")
}
- // This is from the child node manager started by the node manager
- // as an update test.
- readPID(t, nms)
-
- nms.Expect("v2NM terminating")
-
updateNodeExpectError(t, "factoryNM", verror.Exists) // Update already in progress.
nmh.CloseStdin()
@@ -399,8 +393,7 @@
// Create a third version of the node manager and issue an update.
crDir, crEnv = credentialsForChild("nodemanager")
defer os.RemoveAll(crDir)
- *envelope = envelopeFromShell(sh, crEnv, nodeManagerCmd, application.NodeManagerTitle,
- "v3NM")
+ *envelope = envelopeFromShell(sh, crEnv, nodeManagerCmd, application.NodeManagerTitle, "v3NM")
updateNode(t, "v2NM")
scriptPathV3 := evalLink()
@@ -408,12 +401,7 @@
t.Fatalf("current link didn't change")
}
- // This is from the child node manager started by the node manager
- // as an update test.
- readPID(t, nms)
- // Both the parent and child node manager should terminate upon successful
- // update.
- nms.ExpectSetRE("v3NM terminating", "v2NM terminating")
+ nms.Expect("v2NM terminating")
nmh.Shutdown(os.Stderr, os.Stderr)
diff --git a/services/mgmt/node/impl/node_service.go b/services/mgmt/node/impl/node_service.go
index 1ddf4da..773d4d9 100644
--- a/services/mgmt/node/impl/node_service.go
+++ b/services/mgmt/node/impl/node_service.go
@@ -183,33 +183,29 @@
path := filepath.Join(workspace, "noded.sh")
cmd := exec.Command(path)
- // We use a combination of a pipe and file to capture output from
- // the child node manager more reliably than merging their
- // stdout, stderr file descriptors.
-
- // Using a pipe reduces the likelihood of the two processes corrupting
- // each other's output.
- stdout, err := cmd.StdoutPipe()
- if err != nil {
- vlog.Errorf("StdoutPipe() failed: %v", err)
- return errOperationFailed
- }
- go func(r io.Reader) {
- scanner := bufio.NewScanner(r)
- for scanner.Scan() {
- fmt.Fprintf(os.Stdout, "%s\n", scanner.Text())
+ for k, v := range map[string]*io.Writer{
+ "stdout": &cmd.Stdout,
+ "stderr": &cmd.Stderr,
+ } {
+ // Using a log file makes it less likely that stdout and stderr
+ // output will be lost if the child crashes.
+ file, err := i.newLogfile(fmt.Sprintf("noded-test-%s", k))
+ if err != nil {
+ return err
}
- }(stdout)
+ fName := file.Name()
+ defer os.Remove(fName)
+ *v = file
- // Using a log file for stderr makes it less likely that error output
- // will be lost if the child crashes.
- stderr, err := i.newLogfile("noded-test-stderr")
- if err != nil {
- return err
+ defer func() {
+ if f, err := os.Open(fName); err == nil {
+ scanner := bufio.NewScanner(f)
+ for scanner.Scan() {
+ vlog.Infof("[testNodeManager %s] %s", k, scanner.Text())
+ }
+ }
+ }()
}
- defer os.Remove(stderr.Name())
-
- cmd.Stderr = stderr
// Setup up the child process callback.
callbackState := i.callback
@@ -234,13 +230,6 @@
vlog.Errorf("Clean() failed: %v", err)
}
}
- logFile := stderr.Name()
- if f, err := os.Open(logFile); err == nil {
- scanner := bufio.NewScanner(f)
- for scanner.Scan() {
- vlog.Infof("%s", scanner.Text())
- }
- }
}()
// Wait for the child process to start.
testTimeout := 10 * time.Second
