Merge pull request #16992 from Luap99/log-since

several podman logs fixes

libpod/container_log.go

@@ -72,6 +72,14 @@ func (c *Container) readFromLogFile(ctx context.Context, options *logs.LogOption
 			}
 		}
 	}
+	go func() {
+		if options.Until.After(time.Now()) {
+			time.Sleep(time.Until(options.Until))
+			if err := t.Stop(); err != nil {
+				logrus.Errorf("Stopping logger: %v", err)
+			}
+		}
+	}()
 
 	go func() {
 		defer options.WaitGroup.Done()

libpod/container_log_linux.go

@@ -80,39 +80,27 @@ func (c *Container) readFromJournal(ctx context.Context, options *logs.LogOption
 		return fmt.Errorf("adding filter to journald logger: %v: %w", match, err)
 	}
 
-	if err := journal.SeekHead(); err != nil {
+	if options.Since.IsZero() {
+		if err := journal.SeekHead(); err != nil {
+			return err
+		}
+	} else {
+		// seek based on time which helps to reduce unnecessary event reads
+		if err := journal.SeekRealtimeUsec(uint64(options.Since.UnixMicro())); err != nil {
+			return err
+		}
+	}
+
+	c.lock.Lock()
+	if err := c.syncContainer(); err != nil {
+		c.lock.Unlock()
 		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
-	var containerCouldBeLogging bool
-	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)
-	}
+	// The initial "containerCouldBeLogging" state must be correct, we cannot rely on the start event being still in the journal.
+	// This can happen if the journal was rotated after the container was started or when --since is used.
+	// https://github.com/containers/podman/issues/16950
+	containerCouldBeLogging := c.ensureState(define.ContainerStateRunning, define.ContainerStateStopping)
+	c.lock.Unlock()
 
 	options.WaitGroup.Add(1)
 	go func() {
@@ -142,59 +130,20 @@ 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()
-			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()
+			entry, err := events.GetNextEntry(ctx, journal, !doTail && options.Follow && containerCouldBeLogging, options.Until)
 			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

@@ -121,10 +121,19 @@ func (e EventJournalD) Read(ctx context.Context, options ReadOptions) error {
 		if _, err := j.Previous(); err != nil {
 			return fmt.Errorf("failed to move journal cursor to previous entry: %w", err)
 		}
+	} else if len(options.Since) > 0 {
+		since, err := util.ParseInputTime(options.Since, true)
+		if err != nil {
+			return err
+		}
+		// seek based on time which helps to reduce unnecessary event reads
+		if err := j.SeekRealtimeUsec(uint64(since.UnixMicro())); err != nil {
+			return err
+		}
 	}
 
 	for {
-		entry, err := getNextEntry(ctx, j, options.Stream, untilTime)
+		entry, err := GetNextEntry(ctx, j, options.Stream, untilTime)
 		if err != nil {
 			return err
 		}
@@ -210,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

@@ -298,4 +298,89 @@ $contentC" "logs -f on exitted container works"
 
     _log_test_follow journald
 }
+
+function _log_test_follow_since() {
+    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 $IMAGE echo "$content"
+    # Using --since 0s can flake because the log might written in the second as the logs call is made.
+    # The -1s makes sure we only read logs that would be created 1s in the future which cannot happen.
+    run_podman ${events_backend} logs --since -1s -f $cname
+    assert "$output" == "" "logs --since -f on exited container works"
+
+    run_podman ${events_backend} rm -t 0 -f $cname
+
+    # Now do the same with a running container to check #16950.
+    run_podman ${events_backend} run --log-driver=$driver --name $cname -d $IMAGE \
+        sh -c "sleep 0.5; while :; do echo $content && sleep 3; done"
+
+    # sleep is required to make sure the podman event backend no longer sees the start event in the log
+    # This value must be greater or equal than the the value given in --since below
+    sleep 0.2
+
+    # Make sure podman logs actually follows by giving a low timeout and check that the command times out
+    PODMAN_TIMEOUT=2 run_podman 124 ${events_backend} logs --since 0.1s -f $cname
+    assert "$output" =~ "^$content
+timeout: sending signal TERM to command.*" "logs --since -f on running container works"
+
+    run_podman ${events_backend} rm -t 0 -f $cname
+}
+
+@test "podman logs - --since --follow k8s-file" {
+    _log_test_follow_since k8s-file
+}
+
+@test "podman logs - --since --follow journald" {
+    # We can't use journald on RHEL as rootless: rhbz#1895105
+    skip_if_journald_unavailable
+
+    _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 k8s-file" {
+    _log_test_follow_until k8s-file
+}
+
+@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