journald: podman logs --until --follow exit after time

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 <pholzing@redhat.com>

libpod/container_log_linux.go

@@ -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 {
@@ -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() {
@@ -160,59 +130,20 @@ func (c *Container) readFromJournal(ctx context.Context, options *logs.LogOption
 			tailQueue = nil
 			doTail = false
 		}
-		lastReadCursor := ""
 		for {
-			select {
+			entry, err := events.GetNextEntry(ctx, journal, !doTail && options.Follow && containerCouldBeLogging, options.Until)
-			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()
-			if err != nil {
-				logrus.Errorf("Failed to get journal cursor: %v", err)
-				return
-			}
-
-			// Hit the end of the journal (so far?).
-			if cursor == lastReadCursor {
-				if doTail {
-					doTailFunc()
-				}
-				// 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
 			}
+			// entry nil == EOF in journal
+			if entry == nil {
+				if doTail {
+					doTailFunc()
+					continue
+				}
+				return
+			}
 
 			entryTime := time.Unix(0, int64(entry.RealtimeTimestamp)*int64(time.Microsecond))
 			if (entryTime.Before(options.Since) && !options.Since.IsZero()) || (entryTime.After(options.Until) && !options.Until.IsZero()) {

libpod/events/journal_linux.go

@@ -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
 		}
@@ -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():

test/system/035-logs.bats

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