Skip to content

Commit

Permalink
journald: podman logs --until --follow exit after time
Browse files Browse the repository at this point in the history 
When you use podman logs with --until and --follow it should exit after
the requested until time and not keep hanging forever.

To make this work I reworked the code to use the better journald event
reading code for logs as well. this correctly uses the sd_journal API
without having to compare the cursors to find the EOF.

The same problems exists for the k8s-file driver, I will fix this in the
next commit.

Signed-off-by: Paul Holzinger <[email protected]>
  • Loading branch information
@Luap99
Luap99 committed Jan 6, 2023
1 parent c674b3d commit 767947a
Show file tree
Hide file tree
Showing 3 changed files with 43 additions and 77 deletions.
79 changes: 5 additions & 74 deletions libpod/container_log_linux.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -90,20 +90,6 @@ func (c *Container) readFromJournal(ctx context.Context, options *logs.LogOption
return err
}
}
// API requires Next() immediately after SeekHead().
if _, err := journal.Next(); err != nil {
return fmt.Errorf("next journal: %w", err)
}

// API requires a next|prev before getting a cursor.
if _, err := journal.Previous(); err != nil {
return fmt.Errorf("previous journal: %w", err)
}

// Note that the initial cursor may not yet be ready, so we'll do an
// exponential backoff.
var cursor string
var cursorError error

c.lock.Lock()
if err := c.syncContainer(); err != nil {
Expand All @@ -116,22 +102,6 @@ func (c *Container) readFromJournal(ctx context.Context, options *logs.LogOption
containerCouldBeLogging := c.ensureState(define.ContainerStateRunning, define.ContainerStateStopping)
c.lock.Unlock()

for i := 1; i <= 3; i++ {
cursor, cursorError = journal.GetCursor()
hundreds := 1
for j := 1; j < i; j++ {
hundreds *= 2
}
if cursorError != nil {
time.Sleep(time.Duration(hundreds*100) * time.Millisecond)
continue
}
break
}
if cursorError != nil {
return fmt.Errorf("initial journal cursor: %w", cursorError)
}

options.WaitGroup.Add(1)
go func() {
defer func() {
Expand Down Expand Up @@ -160,57 +130,18 @@ func (c *Container) readFromJournal(ctx context.Context, options *logs.LogOption
tailQueue = nil
doTail = false
}
lastReadCursor := ""
for {
select {
case <-ctx.Done():
// Remote client may have closed/lost the connection.
return
default:
// Fallthrough
}

if lastReadCursor != "" {
// Advance to next entry if we read this one.
if _, err := journal.Next(); err != nil {
logrus.Errorf("Failed to move journal cursor to next entry: %v", err)
return
}
}

// Fetch the location of this entry, presumably either
// the one that follows the last one we read, or that
// same last one, if there is no next entry (yet).
cursor, err = journal.GetCursor()
entry, err := events.GetNextEntry(ctx, journal, !doTail && options.Follow && containerCouldBeLogging, options.Until)
if err != nil {
logrus.Errorf("Failed to get journal cursor: %v", err)
logrus.Errorf("Failed to get journal entry: %v", err)
return
}

// Hit the end of the journal (so far?).
if cursor == lastReadCursor {
// entry nil == EOF in journal
if entry == nil {
if doTail {
doTailFunc()
continue
}
// Unless we follow, quit.
if !options.Follow || !containerCouldBeLogging {
return
}

// journal.Wait() is blocking, this would cause the goroutine to hang forever
// if no more journal entries are generated and thus if the client
// has closed the connection in the meantime to leak memory.
// Waiting only 5 seconds makes sure we can check if the client closed in the
// meantime at least every 5 seconds.
journal.Wait(5 * time.Second)
continue
}
lastReadCursor = cursor

// Read the journal entry.
entry, err := journal.GetEntry()
if err != nil {
logrus.Errorf("Failed to get journal entry: %v", err)
return
}

Expand Down
6 changes: 3 additions & 3 deletions libpod/events/journal_linux.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -133,7 +133,7 @@ func (e EventJournalD) Read(ctx context.Context, options ReadOptions) error {
}

for {
entry, err := getNextEntry(ctx, j, options.Stream, untilTime)
entry, err := GetNextEntry(ctx, j, options.Stream, untilTime)
if err != nil {
return err
}
Expand Down Expand Up @@ -219,10 +219,10 @@ func (e EventJournalD) String() string {
return Journald.String()
}

// getNextEntry returns the next entry in the journal. If the end of the
// GetNextEntry returns the next entry in the journal. If the end of the
// journal is reached and stream is not set or the current time is after
// the until time this function return nil,nil.
func getNextEntry(ctx context.Context, j *sdjournal.Journal, stream bool, untilTime time.Time) (*sdjournal.JournalEntry, error) {
func GetNextEntry(ctx context.Context, j *sdjournal.Journal, stream bool, untilTime time.Time) (*sdjournal.JournalEntry, error) {
for {
select {
case <-ctx.Done():
Expand Down
35 changes: 35 additions & 0 deletions test/system/035-logs.bats
View file
Original file line number Diff line number Diff line change
Expand Up @@ -344,4 +344,39 @@ timeout: sending signal TERM to command.*" "logs --since -f on running container
_log_test_follow_since journald
}

function _log_test_follow_until() {
local driver=$1
cname=$(random_string)
content=$(random_string)
local events_backend=$(_additional_events_backend $driver)

if [[ -n "${events_backend}" ]]; then
skip_if_remote "remote does not support --events-backend"
fi

run_podman ${events_backend} run --log-driver=$driver --name $cname -d $IMAGE \
sh -c "while :; do echo $content && sleep 2; done"

t0=$SECONDS
# The logs command should exit after the until time even when follow is set
PODMAN_TIMEOUT=10 run_podman ${events_backend} logs --until 3s -f $cname
t1=$SECONDS

# The delta should be 3 but because it could be a bit longer on a slow system such as CI we also accept 4.
delta_t=$(( $t1 - $t0 ))
assert $delta_t -gt 2 "podman logs --until: exited too early!"
assert $delta_t -lt 5 "podman logs --until: exited too late!"

assert "$output" == "$content
$content" "logs --until -f on running container works"

run_podman ${events_backend} rm -t 0 -f $cname
}

@test "podman logs - --until --follow journald" {
# We can't use journald on RHEL as rootless: rhbz#1895105
skip_if_journald_unavailable

_log_test_follow_until journald
}
# vim: filetype=sh

0 comments on commit 767947a

Please sign in to comment.