opensource/podman
1
0
Fork 0
mirror of https://github.com/containers/podman.git synced 2025-05-17 15:18:43 +08:00
Code Issues Packages Projects Releases Wiki Activity

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

Browse Source 
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 #19545

Signed-off-by: Paul Holzinger <pholzing@redhat.com>
This commit is contained in:
Paul Holzinger
2023-08-08 17:36:43 +02:00
parent 7adc58ffb4
commit a55c2636de
6 changed files with 242 additions and 73 deletions
Download Patch File Download Diff File Expand all files Collapse all files

18
libpod/container_log.go
View File

@ -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

108
libpod/logs/log.go
View File

@ -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:]
}
leftover = line[0]
}
}()
first := 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 {
for {
s, err := rr.Read()
if err != nil {
if !errors.Is(err, io.EOF) {
return nil, fmt.Errorf("reverse log read: %w", err)
}
eof = true
}
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]
// 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
// 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
}
}
return tailLog, nil
}
// 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 s
}
// getColor returns an ANSI escape code for color based on the colorID

137
libpod/logs/log_test.go Normal file
View File

@ -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")
}

5
libpod/logs/reversereader/reversereader.go
View File

@ -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
}

5
pkg/domain/infra/abi/containers.go
View File

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

42
test/system/035-logs.bats
View File

@ -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