libcontainer/logs/logs_linux_test.go

package logs

import (
	"bytes"
	"io"
	"os"
	"testing"
	"time"

	"github.com/sirupsen/logrus"
)

const msgErr = `"level":"error"`

func TestLoggingToFile(t *testing.T) {
	l := runLogForwarding(t)

	msg := `"level":"info","msg":"kitten"`
	logToLogWriter(t, l, msg)
	finish(t, l)
	check(t, l, msg, msgErr)
}

func TestLogForwardingDoesNotStopOnJsonDecodeErr(t *testing.T) {
	l := runLogForwarding(t)

	logToLogWriter(t, l, `"invalid-json-with-kitten"`)
	checkWait(t, l, msgErr, "")

	truncateLogFile(t, l.file)

	msg := `"level":"info","msg":"puppy"`
	logToLogWriter(t, l, msg)
	finish(t, l)
	check(t, l, msg, msgErr)
}

func TestLogForwardingDoesNotStopOnLogLevelParsingErr(t *testing.T) {
	l := runLogForwarding(t)

	msg := `"level":"alert","msg":"puppy"`
	logToLogWriter(t, l, msg)
	checkWait(t, l, msgErr, msg)

	truncateLogFile(t, l.file)

	msg = `"level":"info","msg":"puppy"`
	logToLogWriter(t, l, msg)
	finish(t, l)
	check(t, l, msg, msgErr)
}

func TestLogForwardingStopsAfterClosingTheWriter(t *testing.T) {
	l := runLogForwarding(t)

	msg := `"level":"info","msg":"sync"`
	logToLogWriter(t, l, msg)

	// Do not use finish() here as we check done pipe ourselves.
	l.w.Close()
	select {
	case <-l.done:
	case <-time.After(10 * time.Second):
		t.Fatal("log forwarding did not stop after closing the pipe")
	}

	check(t, l, msg, msgErr)
}

func logToLogWriter(t *testing.T, l *log, message string) {
	t.Helper()
	_, err := l.w.Write([]byte("{" + message + "}\n"))
	if err != nil {
		t.Fatalf("failed to write %q to log writer: %v", message, err)
	}
}

type log struct {
	w    io.WriteCloser
	file *os.File
	done chan error
}

func runLogForwarding(t *testing.T) *log {
	t.Helper()
	logR, logW, err := os.Pipe()
	if err != nil {
		t.Fatal(err)
	}
	t.Cleanup(func() {
		logR.Close()
		logW.Close()
	})

	tempFile, err := os.CreateTemp("", "")
	if err != nil {
		t.Fatal(err)
	}
	t.Cleanup(func() {
		tempFile.Close()
		os.Remove(tempFile.Name())
	})

	logrus.SetOutput(tempFile)
	logrus.SetFormatter(&logrus.JSONFormatter{})
	doneForwarding := ForwardLogs(logR)

	return &log{w: logW, done: doneForwarding, file: tempFile}
}

func finish(t *testing.T, l *log) {
	t.Helper()
	l.w.Close()
	if err := <-l.done; err != nil {
		t.Fatalf("ForwardLogs: %v", err)
	}
}

func truncateLogFile(t *testing.T, file *os.File) {
	t.Helper()

	err := file.Truncate(0)
	if err != nil {
		t.Fatalf("failed to truncate log file: %v", err)
	}
}

// check checks that the file contains txt and does not contain notxt.
func check(t *testing.T, l *log, txt, notxt string) {
	t.Helper()
	contents, err := os.ReadFile(l.file.Name())
	if err != nil {
		t.Fatal(err)
	}
	if txt != "" && !bytes.Contains(contents, []byte(txt)) {
		t.Fatalf("%s does not contain %s", contents, txt)
	}
	if notxt != "" && bytes.Contains(contents, []byte(notxt)) {
		t.Fatalf("%s does contain %s", contents, notxt)
	}
}

// checkWait is like check, but if the file is empty,
// it waits until it's not.
func checkWait(t *testing.T, l *log, txt string, notxt string) {
	t.Helper()
	const (
		delay = 100 * time.Millisecond
		iter  = 3
	)
	for i := 0; ; i++ {
		st, err := l.file.Stat()
		if err != nil {
			t.Fatal(err)
		}
		if st.Size() > 0 {
			break
		}
		if i == iter {
			t.Fatalf("waited %s for file %s to be non-empty but it still is", iter*delay, l.file.Name())
		}
		time.Sleep(delay)
	}

	check(t, l, txt, notxt)
}