diff --git a/libpod/container_log.go b/libpod/container_log.go index c49b54eb16..e33ede5dd1 100644 --- a/libpod/container_log.go +++ b/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() diff --git a/libpod/container_log_linux.go b/libpod/container_log_linux.go index 7e95f2449f..e8b9a52a7e 100644 --- a/libpod/container_log_linux.go +++ b/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()) { diff --git a/libpod/events/journal_linux.go b/libpod/events/journal_linux.go index da2156c2c8..6c0cc15803 100644 --- a/libpod/events/journal_linux.go +++ b/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(): diff --git a/test/system/035-logs.bats b/test/system/035-logs.bats index f9ac33d2c7..8f378054af 100644 --- a/test/system/035-logs.bats +++ b/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