Fixes hanging when using FifoLogWriter

This change fixes the issue with the FifoLogWriter during the
captureFifoToFile call. During os.OpenFile, the operation would block
indefinitely waiting for firecracker to write to the fifo since that
logic was moved before firecracker could do so. This fix will now call
syscall.Open with the syscall.O_NONBLOCK flag instead.

Signed-off-by: xibz <[email protected]>

Author: xibz

machine.go

@@ -576,28 +576,37 @@ func (m *Machine) setupLogging(ctx context.Context) error {
 	return nil
 }
 
-func captureFifoToFile(logger *log.Entry, fifoPath string, fifo io.Writer) error {
-	// create the fifo pipe which will be used
+func captureFifoToFile(logger *log.Entry, fifoPath string, w io.Writer) error {
+	// open the fifo pipe which will be used
 	// to write its contents to a file.
-	fifoPipe, err := os.OpenFile(fifoPath, os.O_RDONLY, 0600)
+	fd, err := syscall.Open(fifoPath, syscall.O_RDONLY|syscall.O_NONBLOCK, 0600)
 	if err != nil {
 		return fmt.Errorf("Failed to open fifo path at %q: %v", fifoPath, err)
 	}
 
-	if err := syscall.Unlink(fifoPath); err != nil {
-		logger.Warnf("Failed to unlink %s", fifoPath)
+	fifoPipe := os.NewFile(uintptr(fd), fifoPath)
+	if fifoPipe == nil {
+		return fmt.Errorf("Invalid file descriptor")
 	}
 
 	logger.Debugf("Capturing %q to writer", fifoPath)
 
-	// Uses a go routine to do a non-blocking io.Copy. The fifo
-	// file should be closed when the appication has finished, since
-	// the forked firecracker application will be closed resulting
-	// in the pipe to return an io.EOF
+	// Uses a goroutine to copy the contents of the fifo pipe to the io.Writer.
+	// In the event that the goroutine finishes, which is caused by either the
+	// context being closed or the application being closed, we will close the
+	// pipe and unlink the fifo path.
 	go func() {
-		defer fifoPipe.Close()
+		defer func() {
+			if err := fifoPipe.Close(); err != nil {
+				logger.Warnf("Failed to close fifo pipe: %v", err)
+			}
+
+			if err := syscall.Unlink(fifoPath); err != nil {
+				logger.Warnf("Failed to unlink %s: %v", fifoPath, err)
+			}
+		}()
 
-		if _, err := io.Copy(fifo, fifoPipe); err != nil {
+		if _, err := io.Copy(w, fifoPipe); err != nil {
 			logger.Warnf("io.Copy failed to copy contents of fifo pipe: %v", err)
 		}
 	}()

machine_test.go

@@ -25,6 +25,7 @@ import (
 	"path/filepath"
 	"strconv"
 	"strings"
+	"sync"
 	"syscall"
 	"testing"
 	"time"
@@ -146,7 +147,12 @@ func TestJailerMicroVMExecution(t *testing.T) {
 	socketPath := filepath.Join(jailerTestPath, "firecracker", "TestJailerMicroVMExecution.socket")
 	logFifo := filepath.Join(tmpDir, "firecracker.log")
 	metricsFifo := filepath.Join(tmpDir, "firecracker-metrics")
+	capturedLog := filepath.Join(tmpDir, "writer.fifo")
+	fw, err := os.OpenFile(capturedLog, os.O_CREATE|os.O_RDWR, 0600)
+	require.NoError(t, err, "failed to open fifo writer file")
 	defer func() {
+		fw.Close()
+		os.Remove(capturedLog)
 		os.Remove(socketPath)
 		os.Remove(logFifo)
 		os.Remove(metricsFifo)
@@ -183,6 +189,7 @@ func TestJailerMicroVMExecution(t *testing.T) {
 			ExecFile:       getFirecrackerBinaryPath(),
 			ChrootStrategy: NewNaiveChrootStrategy(jailerFullRootPath, vmlinuxPath),
 		},
+		FifoLogWriter: fw,
 	}
 
 	if _, err := os.Stat(vmlinuxPath); err != nil {
@@ -250,6 +257,10 @@ func TestJailerMicroVMExecution(t *testing.T) {
 	}
 
 	m.StopVMM()
+
+	info, err := os.Stat(capturedLog)
+	assert.NoError(t, err, "failed to stat captured log file")
+	assert.NotEqual(t, 0, info.Size())
 }
 
 func TestMicroVMExecution(t *testing.T) {
@@ -263,7 +274,12 @@ func TestMicroVMExecution(t *testing.T) {
 	socketPath := filepath.Join(testDataPath, "TestMicroVMExecution.sock")
 	logFifo := filepath.Join(testDataPath, "firecracker.log")
 	metricsFifo := filepath.Join(testDataPath, "firecracker-metrics")
+	capturedLog := filepath.Join(testDataPath, "writer.fifo")
+	fw, err := os.OpenFile(capturedLog, os.O_CREATE|os.O_RDWR, 0600)
+	require.NoError(t, err, "failed to open fifo writer file")
 	defer func() {
+		fw.Close()
+		os.Remove(capturedLog)
 		os.Remove(socketPath)
 		os.Remove(logFifo)
 		os.Remove(metricsFifo)
@@ -292,6 +308,7 @@ func TestMicroVMExecution(t *testing.T) {
 		Debug:             true,
 		DisableValidation: true,
 		NetworkInterfaces: networkIfaces,
+		FifoLogWriter:     fw,
 	}
 
 	ctx := context.Background()
@@ -353,6 +370,10 @@ func TestMicroVMExecution(t *testing.T) {
 	// didn't for some reason, we still need to terminate it:
 	m.StopVMM()
 	m.Wait(vmmCtx)
+
+	info, err := os.Stat(capturedLog)
+	assert.NoError(t, err, "failed to stat captured log file")
+	assert.NotEqual(t, 0, info.Size())
 }
 
 func TestStartVMM(t *testing.T) {
@@ -774,7 +795,7 @@ func TestLogFiles(t *testing.T) {
 }
 
 func TestCaptureFifoToFile(t *testing.T) {
-	fifoPath := filepath.Join(testDataPath, "fifo")
+	fifoPath := filepath.Join(testDataPath, "TestCaptureFifoToFile")
 
 	if err := syscall.Mkfifo(fifoPath, 0700); err != nil {
 		t.Fatalf("Unexpected error during syscall.Mkfifo call: %v", err)
@@ -786,32 +807,90 @@ func TestCaptureFifoToFile(t *testing.T) {
 		t.Fatalf("Failed to open file, %q: %v", fifoPath, err)
 	}
 
-	f.Write([]byte("Hello world!"))
+	expectedBytes := []byte("Hello world!")
+	f.Write(expectedBytes)
 	defer f.Close()
 
-	go func() {
-		t := time.NewTicker(250 * time.Millisecond)
-		select {
-		case <-t.C:
-			f.Close()
-		}
-	}()
+	time.AfterFunc(250*time.Millisecond, func() { f.Close() })
+
+	logPath := fifoPath + ".log"
+	logFile, err := os.OpenFile(logPath, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0644)
+	if err != nil {
+		t.Fatalf("Failed to create log file: %v", err)
+	}
+
+	var wg sync.WaitGroup
+	wg.Add(1)
+
+	testWriter := &fctesting.TestWriter{
+		WriteFn: func(b []byte) (int, error) {
+			defer wg.Done()
+
+			return logFile.Write(b)
+		},
+	}
+
+	if err := captureFifoToFile(fctesting.NewLogEntry(t), fifoPath, testWriter); err != nil {
+		t.Errorf("Unexpected error: %v", err)
+	}
+
+	defer os.Remove(logPath)
+
+	wg.Wait()
+	_, err = os.Stat(logPath)
+	assert.NoError(t, err, "failed to stat file")
+	b, err := ioutil.ReadFile(logPath)
+	assert.NoError(t, err, "failed to read logPath")
+	assert.Equal(t, expectedBytes, b)
+}
+
+func TestCaptureFifoToFile_nonblock(t *testing.T) {
+	fifoPath := filepath.Join(testDataPath, "TestCaptureFifoToFile_nonblock")
 
-	fifoLogPath := fifoPath + ".log"
-	fifo, err := os.OpenFile(fifoLogPath, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0644)
+	if err := syscall.Mkfifo(fifoPath, 0700); err != nil {
+		t.Fatalf("Unexpected error during syscall.Mkfifo call: %v", err)
+	}
+	defer os.Remove(fifoPath)
+
+	logPath := fifoPath + ".log"
+	logFile, err := os.OpenFile(logPath, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0644)
 	if err != nil {
-		t.Fatalf("Failed to create fifo file: %v", err)
+		t.Fatalf("Failed to create log file: %v", err)
+	}
+
+	var wg sync.WaitGroup
+	wg.Add(1)
+
+	testWriter := &fctesting.TestWriter{
+		WriteFn: func(b []byte) (int, error) {
+			defer wg.Done()
+
+			return logFile.Write(b)
+		},
 	}
 
-	if err := captureFifoToFile(fctesting.NewLogEntry(t), fifoPath, fifo); err != nil {
+	if err := captureFifoToFile(fctesting.NewLogEntry(t), fifoPath, testWriter); err != nil {
 		t.Errorf("Unexpected error: %v", err)
 	}
 
-	defer os.Remove(fifoLogPath)
+	defer os.Remove(logPath)
 
-	if _, err := os.Stat(fifoLogPath); err != nil {
-		t.Errorf("Failed to stat file: %v", err)
+	f, err := os.OpenFile(fifoPath, os.O_RDWR, 0600)
+	if err != nil {
+		t.Fatalf("Failed to open file, %q: %v", fifoPath, err)
 	}
+	expectedBytes := []byte("Hello world!")
+	f.Write(expectedBytes)
+	defer f.Close()
+
+	time.AfterFunc(250*time.Millisecond, func() { f.Close() })
+
+	wg.Wait()
+	_, err = os.Stat(logPath)
+	assert.NoError(t, err, "failed to stat file")
+	b, err := ioutil.ReadFile(logPath)
+	assert.NoError(t, err, "failed to read logPath")
+	assert.Equal(t, expectedBytes, b)
 }
 
 func TestSocketPathSet(t *testing.T) {