file logger: fix podman logs --tail with partial lines

There is a problem where our tail code does not handles correctly
partial log lines. This makes podman logs --tail output possibly
incorrect lines when k8s-file is used.

This manifests as flake in CI because partial lines are only sometimes
written, basically always when the output is flushed before writing a
newline.

For our code we must not count partial lines which was already done but
the important thing we must keep reading backwards until the next full
(F) line. This is because all partial (P) lines still must be added to
the full line. See the added tests for details on how the log file looks
like.

While fixing this, I rework the tail logic a bit, there is absolutely no
reason to read the lines in a separate goroutine just to pass the lines
back via channel. We can do this in the same routine.
The logic is very simple, read the lines backwards, append lines to
result and then at the end invert the result slice as tail must return
the lines in the correct order. This more efficient then having to
allocate two different slices or to prepend the line as this would
require a new allocation for each line.

Lastly the readFromLogFile() function wrote the lines back to the log
line channel in the same routine as the log lines we read, this was bad
and causes a deadlock when the returned lines are bigger than the
channel size. There is no reason to allocate a big channel size we can
just write the log lines in a different goroutine, in this case the main
routine were read the logs anyway.

A new system test and unit tests have been added to check corner cases.

Fixes containers#19545

Signed-off-by: Paul Holzinger <pholzing@redhat.com>

libpod/container_log.go

@@ -67,16 +67,6 @@ func (c *Container) readFromLogFile(ctx context.Context, options *logs.LogOption
 		return fmt.Errorf("unable to read log file %s for %s : %w", c.ID(), c.LogPath(), err)
 	}
 	options.WaitGroup.Add(1)
-	if len(tailLog) > 0 {
-		for _, nll := range tailLog {
-			nll.CID = c.ID()
-			nll.CName = c.Name()
-			nll.ColorID = colorID
-			if nll.Since(options.Since) && nll.Until(options.Until) {
-				logChannel <- nll
-			}
-		}
-	}
 	go func() {
 		if options.Until.After(time.Now()) {
 			time.Sleep(time.Until(options.Until))
@@ -87,6 +77,14 @@ func (c *Container) readFromLogFile(ctx context.Context, options *logs.LogOption
 	}()
 
 	go func() {
+		for _, nll := range tailLog {
+			nll.CID = c.ID()
+			nll.CName = c.Name()
+			nll.ColorID = colorID
+			if nll.Since(options.Since) && nll.Until(options.Until) {
+				logChannel <- nll
+			}
+		}
 		defer options.WaitGroup.Done()
 		var line *tail.Line
 		var ok bool

libpod/logs/log.go

@@ -85,86 +85,84 @@ func GetLogFile(path string, options *LogOptions) (*tail.Tail, []*LogLine, error
 
 func getTailLog(path string, tail int) ([]*LogLine, error) {
 	var (
-		nlls       []*LogLine
 		nllCounter int
 		leftover   string
-		partial    string
 		tailLog    []*LogLine
+		eof        bool
 	)
 	f, err := os.Open(path)
 	if err != nil {
 		return nil, err
 	}
+	defer f.Close()
 	rr, err := reversereader.NewReverseReader(f)
 	if err != nil {
 		return nil, err
 	}
 
-	inputs := make(chan []string)
-	go func() {
-		for {
-			s, err := rr.Read()
-			if err != nil {
-				if errors.Is(err, io.EOF) {
-					inputs <- []string{leftover}
-				} else {
-					logrus.Error(err)
-				}
-				close(inputs)
-				if err := f.Close(); err != nil {
-					logrus.Error(err)
-				}
-				break
-			}
-			line := strings.Split(s+leftover, "\n")
-			if len(line) > 1 {
-				inputs <- line[1:]
+	first := true
+
+	for {
+		s, err := rr.Read()
+		if err != nil {
+			if !errors.Is(err, io.EOF) {
+				return nil, fmt.Errorf("reverse log read: %w", err)
 			}
-			leftover = line[0]
+			eof = true
 		}
-	}()
 
-	for i := range inputs {
-		// the incoming array is FIFO; we want FIFO so
-		// reverse the slice read order
-		for j := len(i) - 1; j >= 0; j-- {
-			// lines that are "" are junk
-			if len(i[j]) < 1 {
+		lines := strings.Split(s+leftover, "\n")
+		// we read a chunk of data, so make sure to read the line in inverse order
+		for i := len(lines) - 1; i > 0; i-- {
+			// ignore empty lines
+			if lines[i] == "" {
 				continue
 			}
-			// read the content in reverse and add each nll until we have the same
-			// number of F type messages as the desired tail
-			nll, err := NewLogLine(i[j])
+			nll, err := NewLogLine(lines[i])
 			if err != nil {
 				return nil, err
 			}
-			nlls = append(nlls, nll)
-			if !nll.Partial() {
+			if !nll.Partial() || first {
 				nllCounter++
+				// Even if the last line is partial we need to count it as it will be printed as line.
+				// Because we read backwards the first line we read is the last line in the log.
+				first = false
+			}
+			// We explicitly need to check for more lines than tail because we have
+			// to read to next full line and must keep all partial lines
+			// https://github.com/containers/podman/issues/19545
+			if nllCounter > tail {
+				// because we add lines in the inverse order we must invert the slice in the end
+				return reverseLog(tailLog), nil
 			}
+			// only append after the return here because we do not want to include the next full line
+			tailLog = append(tailLog, nll)
 		}
-		// if we have enough log lines, we can hang up
-		if nllCounter >= tail {
-			break
+		leftover = lines[0]
+
+		// eof was reached
+		if eof {
+			// when we have still a line and do not have enough tail lines already
+			if leftover != "" && nllCounter < tail {
+				nll, err := NewLogLine(leftover)
+				if err != nil {
+					return nil, err
+				}
+				tailLog = append(tailLog, nll)
+			}
+			// because we add lines in the inverse order we must invert the slice in the end
+			return reverseLog(tailLog), nil
 		}
 	}
+}
 
-	// re-assemble the log lines and trim (if needed) to the
-	// tail length
-	for _, nll := range nlls {
-		if nll.Partial() {
-			partial += nll.Msg
-		} else {
-			nll.Msg += partial
-			// prepend because we need to reverse the order again to FIFO
-			tailLog = append([]*LogLine{nll}, tailLog...)
-			partial = ""
-		}
-		if len(tailLog) == tail {
-			break
-		}
+// reverseLog reverse the log line slice, needed for tail as we read lines backwards but still
+// need to print them in the correct order at the end  so use that helper for it.
+func reverseLog(s []*LogLine) []*LogLine {
+	for i, j := 0, len(s)-1; i < j; i, j = i+1, j-1 {
+		s[i], s[j] = s[j], s[i]
 	}
-	return tailLog, nil
+	return s
 }
 
 // getColor returns an ANSI escape code for color based on the colorID

libpod/logs/log_test.go

@@ -0,0 +1,137 @@
+package logs
+
+import (
+	"os"
+	"path/filepath"
+	"testing"
+	"time"
+
+	"github.com/stretchr/testify/assert"
+)
+
+var logTime time.Time
+
+func init() {
+	logTime, _ = time.Parse(LogTimeFormat, "2023-08-07T19:56:34.223758260-06:00")
+}
+
+func makeTestLogLine(typ, msg string) *LogLine {
+	return &LogLine{
+		Device:       "stdout",
+		ParseLogType: typ,
+		Msg:          msg,
+		Time:         logTime,
+	}
+}
+
+func TestGetTailLog(t *testing.T) {
+	tests := []struct {
+		name        string
+		fileContent string
+		tail        int
+		want        []*LogLine
+	}{
+		{
+			name: "simple tail",
+			fileContent: `2023-08-07T19:56:34.223758260-06:00 stdout F line1
+2023-08-07T19:56:34.223758260-06:00 stdout F line2
+2023-08-07T19:56:34.223758260-06:00 stdout F line3
+`,
+			tail: 2,
+			want: []*LogLine{makeTestLogLine("F", "line2"), makeTestLogLine("F", "line3")},
+		},
+		{
+			name: "simple tail with more tail than lines",
+			fileContent: `2023-08-07T19:56:34.223758260-06:00 stdout F line1
+2023-08-07T19:56:34.223758260-06:00 stdout F line2
+2023-08-07T19:56:34.223758260-06:00 stdout F line3
+`,
+			tail: 10,
+			want: []*LogLine{makeTestLogLine("F", "line1"), makeTestLogLine("F", "line2"), makeTestLogLine("F", "line3")},
+		},
+		{
+			name: "tail with partial logs",
+			fileContent: `2023-08-07T19:56:34.223758260-06:00 stdout F line1
+2023-08-07T19:56:34.223758260-06:00 stdout P lin
+2023-08-07T19:56:34.223758260-06:00 stdout F e2
+2023-08-07T19:56:34.223758260-06:00 stdout F line3
+`,
+			tail: 2,
+			want: []*LogLine{makeTestLogLine("P", "lin"), makeTestLogLine("F", "e2"), makeTestLogLine("F", "line3")},
+		},
+		{
+			name: "tail with partial logs and more than lines",
+			fileContent: `2023-08-07T19:56:34.223758260-06:00 stdout F line1
+2023-08-07T19:56:34.223758260-06:00 stdout P lin
+2023-08-07T19:56:34.223758260-06:00 stdout F e2
+2023-08-07T19:56:34.223758260-06:00 stdout F line3
+`,
+			tail: 10,
+			want: []*LogLine{makeTestLogLine("F", "line1"), makeTestLogLine("P", "lin"), makeTestLogLine("F", "e2"), makeTestLogLine("F", "line3")},
+		},
+		{
+			name: "multiple partial lines in a row",
+			fileContent: `2023-08-07T19:56:34.223758260-06:00 stdout F line1
+2023-08-07T19:56:34.223758260-06:00 stdout P l
+2023-08-07T19:56:34.223758260-06:00 stdout P i
+2023-08-07T19:56:34.223758260-06:00 stdout P n
+2023-08-07T19:56:34.223758260-06:00 stdout P e
+2023-08-07T19:56:34.223758260-06:00 stdout F 2
+2023-08-07T19:56:34.223758260-06:00 stdout F line3
+`,
+			tail: 2,
+			want: []*LogLine{makeTestLogLine("P", "l"), makeTestLogLine("P", "i"), makeTestLogLine("P", "n"),
+				makeTestLogLine("P", "e"), makeTestLogLine("F", "2"), makeTestLogLine("F", "line3")},
+		},
+		{
+			name: "partial line at the end",
+			fileContent: `2023-08-07T19:56:34.223758260-06:00 stdout F line1
+2023-08-07T19:56:34.223758260-06:00 stdout P lin
+`,
+			tail: 1,
+			want: []*LogLine{makeTestLogLine("P", "lin")},
+		},
+	}
+	for _, tt := range tests {
+		tt := tt
+		t.Run(tt.name, func(t *testing.T) {
+			dir := t.TempDir()
+			file := filepath.Join(dir, "log")
+			f, err := os.Create(file)
+			assert.NoError(t, err, "create log file")
+			_, err = f.WriteString(tt.fileContent)
+			assert.NoError(t, err, "write log file")
+			f.Close()
+			got, err := getTailLog(file, tt.tail)
+			assert.NoError(t, err, "getTailLog()")
+			assert.Equal(t, tt.want, got, "log lines")
+		})
+	}
+}
+
+func TestGetTailLogBigFiles(t *testing.T) {
+	dir := t.TempDir()
+	file := filepath.Join(dir, "log")
+	f, err := os.Create(file)
+	assert.NoError(t, err, "create log file")
+	want := make([]*LogLine, 0, 2000)
+	for i := 0; i < 1000; i++ {
+		_, err = f.WriteString(`2023-08-07T19:56:34.223758260-06:00 stdout P lin
+2023-08-07T19:56:34.223758260-06:00 stdout F e2
+`)
+		assert.NoError(t, err, "write log file")
+		want = append(want, makeTestLogLine("P", "lin"), makeTestLogLine("F", "e2"))
+	}
+	f.Close()
+
+	// try a big tail greater than the lines
+	got, err := getTailLog(file, 5000)
+	assert.NoError(t, err, "getTailLog()")
+	assert.Equal(t, want, got, "all log lines")
+
+	// try a smaller than lines tail
+	got, err = getTailLog(file, 100)
+	assert.NoError(t, err, "getTailLog()")
+	// this will return the last 200 lines because of partial + full and we only count full lines for tail.
+	assert.Equal(t, want[1800:2000], got, "tail 100 log lines")
+}

libpod/logs/reversereader/reversereader.go

@@ -57,10 +57,7 @@ func (r *ReverseReader) Read() (string, error) {
 	if err != nil && !errors.Is(err, io.EOF) {
 		return "", err
 	}
-	if int64(n) < r.readSize {
-		b = b[0:n]
-	}
 	// Move the offset one pagesize up
 	r.offset -= r.readSize
-	return string(b), nil
+	return string(b[:n]), nil
 }

pkg/domain/infra/abi/containers.go

@@ -1229,10 +1229,7 @@ func (ic *ContainerEngine) ContainerLogs(ctx context.Context, namesOrIds []strin
 		WaitGroup:  &wg,
 	}
 
-	chSize := len(containers) * int(options.Tail)
-	if chSize <= 0 {
-		chSize = 1
-	}
+	chSize := len(containers)
 	logChannel := make(chan *logs.LogLine, chSize)
 
 	libpodContainers := make([]*libpod.Container, len(containers))

test/system/035-logs.bats

@@ -387,4 +387,46 @@ $content--2.*" "logs --until -f on running container works"
 
     _log_test_follow_until journald
 }
+
+# https://github.com/containers/podman/issues/19545
+@test "podman logs --tail, k8s-file with partial lines" {
+    cname="tail_container"
+
+    # "-t" gives us ^Ms (CRs) in the log
+    run_podman run --name $cname --log-driver k8s-file -t $IMAGE echo hi
+
+    # Hand-craft a log file with partial lines and carriage returns
+    run_podman inspect --format '{{.HostConfig.LogConfig.Path}}' $cname
+    logpath="$output"
+    timestamp=$(awk '{print $1}' <"$logpath")
+    cr=$'\r'
+    nl=$'\n'
+    cat >| $logpath <<EOF
+$timestamp stdout F podman1$cr
+$timestamp stdout P podman2
+$timestamp stdout F $cr
+$timestamp stdout F podman3$cr
+EOF
+
+    expect1="podman3${cr}"
+    expect2="podman2${cr}${nl}podman3${cr}"
+    expect3="podman1${cr}${nl}podman2${cr}${nl}podman3${cr}"
+
+    # This always worked
+    run_podman logs --tail 1 $cname
+    assert "$output" = "$expect1" "--tail 1"
+
+    # Prior to this PR, the first line would be "^M" without the podman
+    run_podman logs --tail 2 $cname
+    assert "$output" = "$expect2" "--tail 2"
+
+    # Confirm that we won't overrun
+    for i in 3 4 5; do
+        run_podman logs --tail $i $cname
+        assert "$output" = "$expect3" "--tail $i"
+    done
+
+    run_podman rm $cname
+}
+
 # vim: filetype=sh