Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

events: no duplicates when streaming during a log rotation #17771

Merged
merged 1 commit into from
Mar 15, 2023
Merged

events: no duplicates when streaming during a log rotation #17771

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
145 changes: 117 additions & 28 deletions libpod/events/logfile.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -57,22 +57,8 @@ func (e EventLogFile) Write(ee Event) error {
return err
}

rotated, err := rotateLog(e.options.LogFilePath, eventJSONString, e.options.LogFileMaxSize)
if err != nil {
return fmt.Errorf("rotating log file: %w", err)
}

if rotated {
rEvent := NewEvent(Rotate)
rEvent.Type = System
rEvent.Name = e.options.LogFilePath
rotateJSONString, err := rEvent.ToJSONString()
if err != nil {
return err
}
if err := e.writeString(rotateJSONString); err != nil {
return err
}
if _, err := rotateLog(e.options.LogFilePath, eventJSONString, e.options.LogFileMaxSize); err != nil {
return err
}

return e.writeString(eventJSONString)
Expand All @@ -83,21 +69,42 @@ func (e EventLogFile) writeString(s string) error {
if err != nil {
return err
}
if _, err := f.WriteString(s + "\n"); err != nil {
return err
}
return nil
return writeToFile(s, f)
}

func writeToFile(s string, f *os.File) error {
_, err := f.WriteString(s + "\n")
return err
}

func (e EventLogFile) getTail(options ReadOptions) (*tail.Tail, error) {
reopen := true
seek := tail.SeekInfo{Offset: 0, Whence: io.SeekEnd}
if options.FromStart || !options.Stream {
seek.Whence = 0
reopen = false
}
stream := options.Stream
return tail.TailFile(e.options.LogFilePath, tail.Config{ReOpen: reopen, Follow: stream, Location: &seek, Logger: tail.DiscardingLogger, Poll: true})
return tail.TailFile(e.options.LogFilePath, tail.Config{ReOpen: stream, Follow: stream, Location: &seek, Logger: tail.DiscardingLogger, Poll: true})
}

func (e EventLogFile) readRotateEvent(event *Event) (begin bool, end bool, err error) {
if event.Status != Rotate {
return
}
if event.Details.Attributes == nil {
// may be an old event before storing attributes in the rotate event
return
}
switch event.Details.Attributes[rotateEventAttribute] {
case rotateEventBegin:
begin = true
return
case rotateEventEnd:
end = true
return
default:
err = fmt.Errorf("unknown rotate-event attribute %q", event.Details.Attributes[rotateEventAttribute])
return
}
}

// Reads from the log file
Expand Down Expand Up @@ -125,8 +132,26 @@ func (e EventLogFile) Read(ctx context.Context, options ReadOptions) error {
}
logrus.Debugf("Reading events from file %q", e.options.LogFilePath)

// Get the time *before* starting to read. Comparing the timestamps
// with events avoids returning events more than once after a log-file
// rotation.
readTime, err := func() (time.Time, error) {
// We need to lock events file
lock, err := lockfile.GetLockFile(e.options.LogFilePath + ".lock")
if err != nil {
return time.Time{}, err
}
lock.Lock()
defer lock.Unlock()
return time.Now(), nil
}()
if err != nil {
return err
}

var line *tail.Line
var ok bool
var skipRotate bool
for {
select {
case <-ctx.Done():
Expand All @@ -146,11 +171,30 @@ func (e EventLogFile) Read(ctx context.Context, options ReadOptions) error {
return err
}
switch event.Type {
case Image, Volume, Pod, System, Container, Network:
// no-op
case Image, Volume, Pod, Container, Network:
// no-op
case System:
begin, end, err := e.readRotateEvent(event)
if err != nil {
return err
}
if begin && event.Time.After(readTime) {
// If the rotation event happened _after_ we
// started reading, we need to ignore/skip
// subsequent event until the end of the
// rotation.
skipRotate = true
logrus.Debugf("Skipping already read events after log-file rotation: %v", event)
} else if end {
// This rotate event
skipRotate = false
}
default:
return fmt.Errorf("event type %s is not valid in %s", event.Type.String(), e.options.LogFilePath)
}
if skipRotate {
continue
}
if applyFilters(event, filterMap) {
options.EventChannel <- event
}
Expand All @@ -162,8 +206,43 @@ func (e EventLogFile) String() string {
return LogFile.String()
}

const (
rotateEventAttribute = "io.podman.event.rotate"
rotateEventBegin = "begin"
rotateEventEnd = "end"
)

func writeRotateEvent(f *os.File, logFilePath string, begin bool) error {
rEvent := NewEvent(Rotate)
rEvent.Type = System
rEvent.Name = logFilePath
rEvent.Attributes = make(map[string]string)
if begin {
rEvent.Attributes[rotateEventAttribute] = rotateEventBegin
} else {
rEvent.Attributes[rotateEventAttribute] = rotateEventEnd
}
rotateJSONString, err := rEvent.ToJSONString()
if err != nil {
return err
}
return writeToFile(rotateJSONString, f)
}

// Rotates the log file if the log file size and content exceeds limit
func rotateLog(logfile string, content string, limit uint64) (bool, error) {
needsRotation, err := logNeedsRotation(logfile, content, limit)
if err != nil || !needsRotation {
return false, err
}
if err := truncate(logfile); err != nil {
return false, err
}
return true, nil
}

// logNeedsRotation return true if the log file needs to be rotated.
func logNeedsRotation(logfile string, content string, limit uint64) (bool, error) {
if limit == 0 {
return false, nil
}
Expand All @@ -181,9 +260,6 @@ func rotateLog(logfile string, content string, limit uint64) (bool, error) {
return false, nil
}

if err := truncate(logfile); err != nil {
return false, err
}
return true, nil
}

Expand Down Expand Up @@ -224,9 +300,16 @@ func truncate(filePath string) error {
return err
}
}

if err := writeRotateEvent(tmp, filePath, true); err != nil {
return fmt.Errorf("writing rotation event begin marker: %w", err)
}
if _, err := reader.WriteTo(tmp); err != nil {
return fmt.Errorf("writing truncated contents: %w", err)
}
if err := writeRotateEvent(tmp, filePath, false); err != nil {
return fmt.Errorf("writing rotation event end marker: %w", err)
}

if err := renameLog(tmp.Name(), filePath); err != nil {
return fmt.Errorf("writing back %s to %s: %w", tmp.Name(), filePath, err)
Expand Down Expand Up @@ -254,6 +337,12 @@ func renameLog(from, to string) error {
}
defer fFrom.Close()

// Remove the old file to make sure we're not truncating current
// readers.
if err := os.Remove(to); err != nil {
return fmt.Errorf("recreating file %s: %w", to, err)
}
vrothberg marked this conversation as resolved.
Show resolved Hide resolved

fTo, err := os.Create(to)
if err != nil {
return err
Expand Down
18 changes: 8 additions & 10 deletions libpod/events/logfile_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,7 @@ package events

import (
"os"
"strings"
"testing"

"github.com/stretchr/testify/require"
Expand Down Expand Up @@ -75,12 +76,6 @@ func TestTruncationOutput(t *testing.T) {
8
9
10
`
contentAfter := `6
7
8
9
10
`
// Create dummy file
tmp, err := os.CreateTemp("", "log-rotation")
Expand All @@ -99,11 +94,14 @@ func TestTruncationOutput(t *testing.T) {
require.NoError(t, err)
afterTruncation, err := os.ReadFile(tmp.Name())
require.NoError(t, err)

// Test if rotation was successful
require.NoError(t, err, "Log content has changed")
// Content has changed
require.NotEqual(t, beforeTruncation, afterTruncation)
require.Equal(t, string(afterTruncation), contentAfter)
split := strings.Split(string(afterTruncation), "\n")
require.Len(t, split, 8) // 2 events + 5 rotated lines + last new line
require.Contains(t, split[0], "\"Attributes\":{\"io.podman.event.rotate\":\"begin\"}")
require.Equal(t, split[1:6], []string{"6", "7", "8", "9", "10"})
require.Contains(t, split[6], "\"Attributes\":{\"io.podman.event.rotate\":\"end\"}")
require.Contains(t, split[7], "")
}

func TestRenameLog(t *testing.T) {
Expand Down
81 changes: 77 additions & 4 deletions test/system/090-events.bats
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -209,17 +209,90 @@ EOF
expectedContentAfterTruncation=$PODMAN_TMPDIR/truncated.txt

run_podman create $IMAGE
CONTAINERS_CONF=$containersConf run_podman rm $output
ctrID=$output
CONTAINERS_CONF=$containersConf run_podman rm $ctrID
tail -n52 $eventsFile >> $expectedContentAfterTruncation

# Make sure the events file looks as expected.
is "$(cat $eventsFile)" "$(cat $expectedContentAfterTruncation)" "events file has been rotated"

# Make sure that `podman events` can read the file, and that it returns the
# same amount of events. We checked the contents before.
CONTAINERS_CONF=$containersConf run_podman events --stream=false --since="2022-03-06T11:26:42.723667984+02:00"
assert "${#lines[@]}" = 51 "Number of events returned"
is "${lines[-2]}" ".* log-rotation $eventsFile"
CONTAINERS_CONF=$containersConf run_podman events --stream=false --since="2022-03-06T11:26:42.723667984+02:00" --format=json
assert "${#lines[@]}" = 52 "Number of events returned"
is "${lines[0]}" "{\"Name\":\"$eventsFile\",\"Status\":\"log-rotation\",\"Time\":\".*\",\"Type\":\"system\",\"Attributes\":{\"io.podman.event.rotate\":\"begin\"}}"
is "${lines[-2]}" "{\"Name\":\"$eventsFile\",\"Status\":\"log-rotation\",\"Time\":\".*\",\"Type\":\"system\",\"Attributes\":{\"io.podman.event.rotate\":\"end\"}}"
is "${lines[-1]}" "{\"ID\":\"$ctrID\",\"Image\":\"$IMAGE\",\"Name\":\".*\",\"Status\":\"remove\",\"Time\":\".*\",\"Type\":\"container\",\"Attributes\":{.*}}"
}

@test "events log-file no duplicates" {
skip_if_remote "setting CONTAINERS_CONF logger options does not affect remote client"

# This test makes sure that events are not returned more than once when
# streaming during a log-file rotation.
eventsFile=$PODMAN_TMPDIR/events.txt
eventsJSON=$PODMAN_TMPDIR/events.json
containersConf=$PODMAN_TMPDIR/containers.conf
cat >$containersConf <<EOF
[engine]
events_logger="file"
events_logfile_path="$eventsFile"
# The populated file has a size of 11300, so let's create a couple of events to
# force a log rotation.
events_logfile_max_size=11300
EOF

_populate_events_file $eventsFile
CONTAINERS_CONF=$containersConf timeout --kill=10 20 \
$PODMAN events --stream=true --since="2022-03-06T11:26:42.723667984+02:00" --format=json > $eventsJSON &

# Now wait for the above podman-events process to write to the eventsJSON
# file, so we know it's reading.
retries=20
while [[ $retries -gt 0 ]]; do
if [ -s $eventsJSON ]; then
break
fi
retries=$((retries - 1))
sleep 0.5
done
assert $retries -gt 0 \
"Timed out waiting for podman-events to start reading pre-existing events"

CONTAINERS_CONF=$containersConf run_podman create $IMAGE
ctrID=$output
CONTAINERS_CONF=$containersConf run_podman rm -f $ctrID

# Now wait for the last event above to be read by the `podman-events`
# process above.
retries=20
while [[ $retries -gt 0 ]]; do
run grep "\"Status\"\:\"remove\"," $eventsJSON
if [[ $status -eq 0 ]]; then
break
fi
retries=$((retries - 1))
sleep 0.5
done
test "$status" = 0 || die "Did not find expected 'Status:remove' line in log"

# Make sure that the log file has been rotated as expected.
run cat $eventsFile
assert "${#lines[@]}" = 54 "Number of events in $eventsFile" # 49 previous + 2 rotation + pull/create/rm
is "${lines[0]}" "{\"Name\":\"$eventsFile\",\"Status\":\"log-rotation\",\"Time\":\".*\",\"Type\":\"system\",\"Attributes\":{\"io.podman.event.rotate\":\"begin\"}}"
is "${lines[1]}" "{\"Name\":\"busybox\",\"Status\":\"pull\",\"Time\":\"2022-04-06T11:26:42.723667951+02:00\",\"Type\":\"image\",\"Attributes\":null}"
is "${lines[49]}" "{\"Name\":\"busybox\",\"Status\":\"pull\",\"Time\":\"2022-04-06T11:26:42.723667999+02:00\",\"Type\":\"image\",\"Attributes\":null}"
is "${lines[50]}" "{\"Name\":\"$eventsFile\",\"Status\":\"log-rotation\",\"Time\":\".*\",\"Type\":\"system\",\"Attributes\":{\"io.podman.event.rotate\":\"end\"}}"
is "${lines[53]}" "{\"ID\":\"$ctrID\",\"Image\":\"$IMAGE\",\"Name\":\".*\",\"Status\":\"remove\",\"Time\":\".*\",\"Type\":\"container\",\"Attributes\":{.*}}"


# Make sure that the JSON stream looks as expected. That means it has all
# events and no duplicates.
run cat $eventsJSON
is "${lines[0]}" "{\"Name\":\"busybox\",\"Status\":\"pull\",\"Time\":\"2022-04-06T11:26:42.7236679+02:00\",\"Type\":\"image\",\"Attributes\":null}"
is "${lines[99]}" "{\"Name\":\"busybox\",\"Status\":\"pull\",\"Time\":\"2022-04-06T11:26:42.723667999+02:00\",\"Type\":\"image\",\"Attributes\":null}"
is "${lines[100]}" "{\"Name\":\"$eventsFile\",\"Status\":\"log-rotation\",\"Time\":\".*\",\"Type\":\"system\",\"Attributes\":{\"io.podman.event.rotate\":\"end\"}}"
is "${lines[103]}" "{\"ID\":\"$ctrID\",\"Image\":\"$IMAGE\",\"Name\":\".*\",\"Status\":\"remove\",\"Time\":\".*\",\"Type\":\"container\",\"Attributes\":{.*}}"
}

# Prior to #15633, container labels would not appear in 'die' log events
Expand Down