Merge pull request #19562 from Luap99/logs-tail

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

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() {
+	first := true
+
 	for {
 		s, err := rr.Read()
 		if err != nil {
-				if errors.Is(err, io.EOF) {
-					inputs <- []string{leftover}
-				} else {
-					logrus.Error(err)
+			if !errors.Is(err, io.EOF) {
+				return nil, fmt.Errorf("reverse log read: %w", err)
 			}
-				close(inputs)
-				if err := f.Close(); err != nil {
-					logrus.Error(err)
+			eof = true
 		}
-				break
-			}
-			line := strings.Split(s+leftover, "\n")
-			if len(line) > 1 {
-				inputs <- line[1:]
-			}
-			leftover = line[0]
-		}
-	}()
 
-	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)
+		}
+		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
 		}
-		// if we have enough log lines, we can hang up
-		if nllCounter >= tail {
-			break
 	}
 }
 
-	// 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 = ""
+// 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]
 	}
-		if len(tailLog) == tail {
-			break
-		}
-	}
-	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