invoke: capture and return stderr if plugin exits unexpectedly

The way raw_exec invokes the command doesn't actually pass back stderr, despite ExitError having that capability. c.Run() internally calls c.Wait() but that doesn't capture stderr and insert it into the returned ExitError. So we have to do that ourselves. Fixes: #732 Fixes: #759 Signed-off-by: Dan Williams <[email protected]>
containernetworking · Apr 2, 2020 · 10bca02 · 10bca02
1 parent fdcc7b1
commit 10bca02
Show file tree

Hide file tree

Showing 6 changed files with 102 additions and 31 deletions.
diff --git a/libcni/api_test.go b/libcni/api_test.go
@@ -156,7 +156,9 @@ var _ = Describe("Invoking plugins", func() {
 			Expect(debugFile.Close()).To(Succeed())
 			debugFilePath = debugFile.Name()
 
-			debug = &noop_debug.Debug{}
+			debug = &noop_debug.Debug{
+				ReportResult: fmt.Sprintf(` { "result": %q }`, noop_debug.EmptyReportResultMessage),
+			}
 			Expect(debug.WriteDebug(debugFilePath)).To(Succeed())
 
 			pluginConfig = []byte(fmt.Sprintf(`{

diff --git a/pkg/invoke/raw_exec.go b/pkg/invoke/raw_exec.go
@@ -31,34 +31,40 @@ type RawExec struct {
 
 func (e *RawExec) ExecPlugin(ctx context.Context, pluginPath string, stdinData []byte, environ []string) ([]byte, error) {
 	stdout := &bytes.Buffer{}
+	stderr := &bytes.Buffer{}
 	c := exec.CommandContext(ctx, pluginPath)
 	c.Env = environ
 	c.Stdin = bytes.NewBuffer(stdinData)
 	c.Stdout = stdout
-	c.Stderr = e.Stderr
+	c.Stderr = stderr
 	if err := c.Run(); err != nil {
-		return nil, pluginErr(err, stdout.Bytes())
+		return nil, e.pluginErr(err, stdout.Bytes(), stderr.Bytes())
 	}
 
+	// Copy stderr to caller's buffer in case plugin printed to both
+	// stdout and stderr for some reason
+	if e.Stderr != nil && stderr.Len() > 0 {
+		if _, err := stderr.WriteTo(e.Stderr); err != nil {
+			return nil, &types.Error{
+				Msg: fmt.Sprintf("failed to copy netplugin stderr: %v", err),
+			}
+		}
+	}
 	return stdout.Bytes(), nil
 }
 
-func pluginErr(err error, output []byte) error {
-	if exitError, ok := err.(*exec.ExitError); ok {
-		emsg := types.Error{}
-		if len(output) == 0 {
-			if len(exitError.Stderr) == 0 {
-				emsg.Msg = "netplugin failed with no error message"
-			} else {
-				emsg.Msg = fmt.Sprintf("netplugin failed: %q", string(exitError.Stderr))
-			}
-		} else if perr := json.Unmarshal(output, &emsg); perr != nil {
-			emsg.Msg = fmt.Sprintf("netplugin failed but error parsing its diagnostic message %q: %v", string(output), perr)
+func (e *RawExec) pluginErr(err error, stdout, stderr []byte) error {
+	emsg := types.Error{}
+	if len(stdout) == 0 {
+		if len(stderr) == 0 {
+			emsg.Msg = fmt.Sprintf("netplugin failed with no error message: %v", err)
+		} else {
+			emsg.Msg = fmt.Sprintf("netplugin failed: %q", string(stderr))
 		}
-		return &emsg
+	} else if perr := json.Unmarshal(stdout, &emsg); perr != nil {
+		emsg.Msg = fmt.Sprintf("netplugin failed but error parsing its diagnostic message %q: %v", string(stdout), perr)
 	}
-
-	return err
+	return &emsg
 }
 
 func (e *RawExec) FindInPath(plugin string, paths []string) (string, error) {

diff --git a/pkg/invoke/raw_exec_test.go b/pkg/invoke/raw_exec_test.go
@@ -105,14 +105,39 @@ var _ = Describe("RawExec", func() {
 
 	Context("when the plugin errors", func() {
 		BeforeEach(func() {
-			debug.ReportError = "banana"
-			Expect(debug.WriteDebug(debugFileName)).To(Succeed())
+			debug.ReportResult = ""
+		})
+
+		Context("and writes valid error JSON to stdout", func() {
+			It("wraps and returns the error", func() {
+				debug.ReportError = "banana"
+				Expect(debug.WriteDebug(debugFileName)).To(Succeed())
+				_, err := execer.ExecPlugin(ctx, pathToPlugin, stdin, environ)
+				Expect(err).To(HaveOccurred())
+				Expect(err).To(MatchError("banana"))
+			})
 		})
 
-		It("wraps and returns the error", func() {
+		Context("and writes to stderr", func() {
+			It("returns an error message with stderr output", func() {
+				debug.ExitWithCode = 1
+				Expect(debug.WriteDebug(debugFileName)).To(Succeed())
+				_, err := execer.ExecPlugin(ctx, pathToPlugin, stdin, environ)
+				Expect(err).To(HaveOccurred())
+				Expect(err).To(MatchError(`netplugin failed: "some stderr message"`))
+			})
+		})
+	})
+
+	Context("when the plugin errors with no output on stdout or stderr", func() {
+		It("returns the exec error message", func() {
+			debug.ExitWithCode = 1
+			debug.ReportResult = ""
+			debug.ReportStderr = ""
+			Expect(debug.WriteDebug(debugFileName)).To(Succeed())
 			_, err := execer.ExecPlugin(ctx, pathToPlugin, stdin, environ)
 			Expect(err).To(HaveOccurred())
-			Expect(err).To(MatchError("banana"))
+			Expect(err).To(MatchError("netplugin failed with no error message: exit status 1"))
 		})
 	})
 

diff --git a/plugins/test/noop/debug/debug.go b/plugins/test/noop/debug/debug.go
@@ -31,6 +31,7 @@ type Debug struct {
 	ReportError          string
 	ReportStderr         string
 	ReportVersionSupport []string
+	ExitWithCode         int
 
 	// Command stores the CNI command that the plugin received
 	Command string

diff --git a/plugins/test/noop/main.go b/plugins/test/noop/main.go
@@ -110,18 +110,15 @@ func debugBehavior(args *skel.CmdArgs, command string) error {
 	debug.CmdArgs = *args
 	debug.Command = command
 
-	if debug.ReportResult == "" {
-		debug.ReportResult = fmt.Sprintf(` { "result": %q }`, noop_debug.EmptyReportResultMessage)
-	}
-
 	err = debug.WriteDebug(debugFilePath)
 	if err != nil {
 		return err
 	}
 
-	_, err = os.Stderr.WriteString(debug.ReportStderr)
-	if err != nil {
-		return err
+	if debug.ReportStderr != "" {
+		if _, err = os.Stderr.WriteString(debug.ReportStderr); err != nil {
+			return err
+		}
 	}
 
 	if debug.ReportError != "" {
@@ -149,13 +146,16 @@ func debugBehavior(args *skel.CmdArgs, command string) error {
 		if err != nil {
 			return err
 		}
-	} else {
+	} else if debug.ReportResult != "" {
 		_, err = os.Stdout.WriteString(debug.ReportResult)
 		if err != nil {
 			return err
 		}
 	}
 
+	if debug.ExitWithCode > 0 {
+		os.Exit(debug.ExitWithCode)
+	}
 	return nil
 }
 

diff --git a/plugins/test/noop/noop_test.go b/plugins/test/noop/noop_test.go
@@ -196,9 +196,46 @@ var _ = Describe("No-op plugin", func() {
 			Expect(debug.WriteDebug(debugFileName)).To(Succeed())
 		})
 
-		It("substitutes a helpful message for the test author", func() {
-			expectedResultString := fmt.Sprintf(` { "result": %q }`, noop_debug.EmptyReportResultMessage)
+		It("returns no result", func() {
+			session, err := gexec.Start(cmd, GinkgoWriter, GinkgoWriter)
+			Expect(err).NotTo(HaveOccurred())
+			Eventually(session).Should(gexec.Exit(0))
+			Expect(session.Out.Contents()).To(Equal([]byte{}))
+
+			debug, err := noop_debug.ReadDebug(debugFileName)
+			Expect(err).NotTo(HaveOccurred())
+			Expect(debug.ReportResult).To(Equal(""))
+		})
+	})
+
+	Context("when the ExitWithCode debug field is set", func() {
+		BeforeEach(func() {
+			debug.ReportResult = ""
+			debug.ExitWithCode = 3
+			Expect(debug.WriteDebug(debugFileName)).To(Succeed())
+		})
 
+		It("returns no result and exits with the expected code", func() {
+			session, err := gexec.Start(cmd, GinkgoWriter, GinkgoWriter)
+			Expect(err).NotTo(HaveOccurred())
+			Eventually(session).Should(gexec.Exit(3))
+			Expect(session.Out.Contents()).To(Equal([]byte{}))
+
+			debug, err := noop_debug.ReadDebug(debugFileName)
+			Expect(err).NotTo(HaveOccurred())
+			Expect(debug.ReportResult).To(Equal(""))
+		})
+	})
+
+	Context("when the ReportResult debug field is set", func() {
+		var expectedResultString = fmt.Sprintf(` { "result": %q }`, noop_debug.EmptyReportResultMessage)
+
+		BeforeEach(func() {
+			debug.ReportResult = expectedResultString
+			Expect(debug.WriteDebug(debugFileName)).To(Succeed())
+		})
+
+		It("substitutes a helpful message for the test author", func() {
 			session, err := gexec.Start(cmd, GinkgoWriter, GinkgoWriter)
 			Expect(err).NotTo(HaveOccurred())
 			Eventually(session).Should(gexec.Exit(0))