Merge pull request #157 from xibz/fix-race-fifo

Fixes race with io.Copy and O_NONBLOCK file

Author: xibz

go.mod

@@ -3,6 +3,7 @@ module github.com/firecracker-microvm/firecracker-go-sdk
 go 1.11
 
 require (
+	github.com/containerd/fifo v0.0.0-20190816180239-bda0ff6ed73c
 	github.com/containernetworking/cni v0.7.2-0.20190807151350-8c6c47d1c7fc
 	github.com/containernetworking/plugins v0.8.2
 	github.com/go-openapi/errors v0.17.1

go.sum

@@ -8,6 +8,8 @@ github.com/alexflint/go-filemutex v0.0.0-20171022225611-72bdc8eae2ae/go.mod h1:C
 github.com/asaskevich/govalidator v0.0.0-20180720115003-f9ffefc3facf h1:eg0MeVzsP1G42dRafH3vf+al2vQIJU0YHX+1Tw87oco=
 github.com/asaskevich/govalidator v0.0.0-20180720115003-f9ffefc3facf/go.mod h1:lB+ZfQJz7igIIfQNfa7Ml4HSf2uFQQRzpGGRXenZAgY=
 github.com/buger/jsonparser v0.0.0-20180808090653-f4dd9f5a6b44/go.mod h1:bbYlZJ7hK1yFx9hf58LP0zeX7UjIGs20ufpu3evjr+s=
+github.com/containerd/fifo v0.0.0-20190816180239-bda0ff6ed73c h1:KFbqHhDeaHM7IfFtXHfUHMDaUStpM2YwBR+iJCIOsKk=
+github.com/containerd/fifo v0.0.0-20190816180239-bda0ff6ed73c/go.mod h1:ODA38xgv3Kuk8dQz2ZQXpnv/UZZUHUCL7pnLehbXgQI=
 github.com/containernetworking/cni v0.7.0/go.mod h1:LGwApLUm2FpoOfxTDEeq8T9ipbpZ61X79hmU3w8FmsY=
 github.com/containernetworking/cni v0.7.2-0.20190807151350-8c6c47d1c7fc h1:zUNdrf9w09mWodVhZ9hX4Yk4Uu84n/OgdfPattAwwt8=
 github.com/containernetworking/cni v0.7.2-0.20190807151350-8c6c47d1c7fc/go.mod h1:LGwApLUm2FpoOfxTDEeq8T9ipbpZ61X79hmU3w8FmsY=

handlers.go

@@ -152,7 +152,7 @@ var CreateLogFilesHandler = Handler{
 		)
 
 		if m.Cfg.FifoLogWriter != nil {
-			if err := m.captureFifoToFile(m.logger, logFifoPath, m.Cfg.FifoLogWriter); err != nil {
+			if err := m.captureFifoToFile(ctx, m.logger, logFifoPath, m.Cfg.FifoLogWriter); err != nil {
 				m.logger.Warnf("captureFifoToFile() returned %s. Continuing anyway.", err)
 			}
 		}

machine.go

@@ -27,6 +27,7 @@ import (
 	"syscall"
 	"time"
 
+	"github.com/containerd/fifo"
 	"github.com/containernetworking/plugins/pkg/ns"
 	"github.com/gofrs/uuid"
 	"github.com/hashicorp/go-multierror"
@@ -582,19 +583,14 @@ func (m *Machine) setupLogging(ctx context.Context) error {
 	return nil
 }
 
-func (m *Machine) captureFifoToFile(logger *log.Entry, fifoPath string, w io.Writer) error {
+func (m *Machine) captureFifoToFile(ctx context.Context, logger *log.Entry, fifoPath string, w io.Writer) error {
 	// open the fifo pipe which will be used
 	// to write its contents to a file.
-	fd, err := syscall.Open(fifoPath, syscall.O_RDONLY|syscall.O_NONBLOCK, 0600)
+	fifoPipe, err := fifo.OpenFifo(ctx, fifoPath, syscall.O_RDONLY|syscall.O_NONBLOCK, 0600)
 	if err != nil {
 		return fmt.Errorf("Failed to open fifo path at %q: %v", fifoPath, err)
 	}
 
-	fifoPipe := os.NewFile(uintptr(fd), fifoPath)
-	if fifoPipe == nil {
-		return fmt.Errorf("Invalid file descriptor")
-	}
-
 	logger.Debugf("Capturing %q to writer", fifoPath)
 
 	// this goroutine is to track the life of the application along with whether
@@ -623,7 +619,7 @@ func (m *Machine) captureFifoToFile(logger *log.Entry, fifoPath string, w io.Wri
 		}()
 
 		if _, err := io.Copy(w, fifoPipe); err != nil {
-			logger.Warnf("io.Copy failed to copy contents of fifo pipe: %v", err)
+			logger.WithError(err).Warn("io.Copy failed to copy contents of fifo pipe")
 		}
 	}()
 

machine_test.go

@@ -835,7 +835,7 @@ func TestCaptureFifoToFile(t *testing.T) {
 	m := &Machine{
 		exitCh: make(chan struct{}),
 	}
-	if err := m.captureFifoToFile(fctesting.NewLogEntry(t), fifoPath, testWriter); err != nil {
+	if err := m.captureFifoToFile(context.Background(), fctesting.NewLogEntry(t), fifoPath, testWriter); err != nil {
 		t.Errorf("Unexpected error: %v", err)
 	}
 
@@ -877,12 +877,19 @@ func TestCaptureFifoToFile_nonblock(t *testing.T) {
 	m := &Machine{
 		exitCh: make(chan struct{}),
 	}
-	if err := m.captureFifoToFile(fctesting.NewLogEntry(t), fifoPath, testWriter); err != nil {
+	if err := m.captureFifoToFile(context.Background(), fctesting.NewLogEntry(t), fifoPath, testWriter); err != nil {
 		t.Errorf("Unexpected error: %v", err)
 	}
 
 	defer os.Remove(logPath)
 
+	// we sleep here to check to see the io.Copy is working properly in
+	// captureFifoToFile. This is due to the fifo being opened with O_NONBLOCK,
+	// which causes io.Copy to exit immediately with no error.
+	//
+	// https://github.com/firecracker-microvm/firecracker-go-sdk/issues/156
+	time.Sleep(250 * time.Millisecond)
+
 	f, err := os.OpenFile(fifoPath, os.O_RDWR, 0600)
 	if err != nil {
 		t.Fatalf("Failed to open file, %q: %v", fifoPath, err)
@@ -1066,14 +1073,20 @@ func TestCaptureFifoToFile_leak(t *testing.T) {
 	logger := fctesting.NewLogEntry(t)
 	logger.Logger.Level = logrus.WarnLevel
 	logger.Logger.Out = loggerBuffer
-	err = m.captureFifoToFile(logger, fifoPath, buf)
+	err = m.captureFifoToFile(context.Background(), logger, fifoPath, buf)
 	assert.NoError(t, err, "failed to capture fifo to file")
 	close(m.exitCh)
 
 	// wait sometime for the logs to populate
 	time.Sleep(250 * time.Millisecond)
-	expected := `io.Copy failed to copy contents of fifo pipe: read testdata/TestCaptureFifoToFileLeak.fifo: file already closed`
-	assert.Contains(t, loggerBuffer.String(), expected)
+	expectedClosedFifo := `reading from a closed fifo`
+	expectedClosedFile := `file already closed`
+	logs := loggerBuffer.String()
+	if !(strings.Contains(logs, expectedClosedFifo) ||
+		strings.Contains(logs, expectedClosedFile)) {
+
+		t.Errorf("logs did not container a closed fifo error or closed file")
+	}
 }
 
 func TestWaitWithKill(t *testing.T) {