Merge pull request #145 from xibz/fix-fifo-writer

Fixes issue where FifoLogWriter would hang

Author: xibz

fctesting/test_writer.go

@@ -0,0 +1,12 @@
+package fctesting
+
+// TestWriter is used to mock out writing and/or do other things such as
+// syncing when to do assertions in the event that a writer is used in a
+// goroutine
+type TestWriter struct {
+	WriteFn func([]byte) (int, error)
+}
+
+func (w *TestWriter) Write(b []byte) (int, error) {
+	return w.WriteFn(b)
+}

handlers_test.go

@@ -1,19 +1,16 @@
 package firecracker
 
 import (
-	"bytes"
 	"context"
 	"fmt"
 	"os"
 	"path/filepath"
 	"reflect"
 	"testing"
-	"time"
 
 	models "github.com/firecracker-microvm/firecracker-go-sdk/client/models"
 	ops "github.com/firecracker-microvm/firecracker-go-sdk/client/operations"
 	"github.com/firecracker-microvm/firecracker-go-sdk/fctesting"
-	"github.com/pkg/errors"
 )
 
 func TestHandlerListAppend(t *testing.T) {
@@ -663,76 +660,6 @@ func TestHandlers(t *testing.T) {
 	}
 }
 
-func TestCreateLogFilesHandler(t *testing.T) {
-	logWriterBuf := &bytes.Buffer{}
-	config := Config{
-		LogFifo:       filepath.Join(testDataPath, "firecracker-log.fifo"),
-		MetricsFifo:   filepath.Join(testDataPath, "firecracker-metrics.fifo"),
-		FifoLogWriter: logWriterBuf,
-	}
-
-	defer func() {
-		os.Remove(config.LogFifo)
-		os.Remove(config.MetricsFifo)
-	}()
-
-	ctx := context.Background()
-	m, err := NewMachine(ctx, config, WithLogger(fctesting.NewLogEntry(t)))
-	if err != nil {
-		t.Fatalf("failed to create machine: %v", err)
-	}
-
-	// spin off goroutine to write to Log fifo so we don't block
-	doneChan := make(chan struct{}, 1)
-	go func() {
-		defer close(doneChan)
-
-		// try to open file
-		fifoPipe, err := openFileRetry(config.LogFifo)
-		if err != nil {
-			t.Error(err)
-		}
-
-		if _, err := fifoPipe.WriteString("data\n"); err != nil {
-			t.Errorf("Failed to write to fifo %v", err)
-		}
-
-		fifoPipe.Close()
-		return
-	}()
-
-	// Execute Handler
-	if err := CreateLogFilesHandler.Fn(ctx, m); err != nil {
-		t.Errorf("failed to call CreateLogFilesHandler function: %v", err)
-		return
-	}
-
-	// Block until writing go routine is done to check data that was written
-	<-doneChan
-
-	// Poll for verifying logs were written as we need to allow time
-	// for copying from the log fifo into the FifoLogWriter
-	timer := time.NewTimer(1 * time.Second)
-	for {
-		select {
-		case <-timer.C:
-			t.Fatal("timed out reading from log writer")
-		default:
-			logData, err := logWriterBuf.ReadString('\n')
-			if err != nil {
-				time.Sleep(10 * time.Millisecond)
-				continue
-			}
-
-			if logData != "data\n" {
-				t.Errorf("expected 'data' written to log got '%s'", logData)
-			}
-			return
-		}
-	}
-
-}
-
 func compareHandlerLists(l1, l2 HandlerList) bool {
 	if l1.Len() != l2.Len() {
 		return false
@@ -754,21 +681,3 @@ func compareHandlerLists(l1, l2 HandlerList) bool {
 
 	return true
 }
-
-func openFileRetry(filePath string) (file *os.File, err error) {
-	timer := time.NewTimer(1 * time.Second)
-	for {
-		select {
-		case <-timer.C:
-			err = errors.New("timed out waiting for file")
-			return
-		default:
-			file, err = os.OpenFile(filePath, os.O_WRONLY, os.ModePerm)
-			if err == nil {
-				timer.Stop()
-				return
-			}
-			time.Sleep(10 * time.Millisecond)
-		}
-	}
-}

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) {