From c5bdb6afe741d34c32f779b6ef9508b6f1d05794 Mon Sep 17 00:00:00 2001 From: Paul Holzinger Date: Fri, 9 Sep 2022 11:07:07 +0200 Subject: fix hang with podman events file logger podman --events-backend file events --stream=false should never hang. The problem is that our tail library will wait for the file to be created which makes sense when we do not run with --stream=false. To fix this we can just always create the file when the logger is initialized. This would also help to report errors early on in case the file is not accessible. Fixes part one from #15688 Signed-off-by: Paul Holzinger --- libpod/events/events_linux.go | 2 +- libpod/events/logfile.go | 18 ++++++++++++++++++ libpod/runtime.go | 8 -------- 3 files changed, 19 insertions(+), 9 deletions(-) (limited to 'libpod') diff --git a/libpod/events/events_linux.go b/libpod/events/events_linux.go index e7801af5b..b11467aca 100644 --- a/libpod/events/events_linux.go +++ b/libpod/events/events_linux.go @@ -18,7 +18,7 @@ func NewEventer(options EventerOptions) (Eventer, error) { } return eventer, nil case strings.ToUpper(LogFile.String()): - return EventLogFile{options}, nil + return newLogFileEventer(options) case strings.ToUpper(Null.String()): return NewNullEventer(), nil case strings.ToUpper(Memory.String()): diff --git a/libpod/events/logfile.go b/libpod/events/logfile.go index 519e16629..1b06e22e7 100644 --- a/libpod/events/logfile.go +++ b/libpod/events/logfile.go @@ -12,6 +12,7 @@ import ( "io/ioutil" "os" "path" + "path/filepath" "time" "github.com/containers/podman/v4/pkg/util" @@ -27,6 +28,21 @@ type EventLogFile struct { options EventerOptions } +// newLogFileEventer creates a new EventLogFile eventer +func newLogFileEventer(options EventerOptions) (*EventLogFile, error) { + // Create events log dir + if err := os.MkdirAll(filepath.Dir(options.LogFilePath), 0700); err != nil { + return nil, fmt.Errorf("creating events dirs: %w", err) + } + // We have to make sure the file is created otherwise reading events will hang. + // https://github.com/containers/podman/issues/15688 + fd, err := os.OpenFile(options.LogFilePath, os.O_RDONLY|os.O_CREATE, 0700) + if err != nil { + return nil, err + } + return &EventLogFile{options: options}, fd.Close() +} + // Writes to the log file func (e EventLogFile) Write(ee Event) error { // We need to lock events file @@ -108,6 +124,8 @@ func (e EventLogFile) Read(ctx context.Context, options ReadOptions) error { } }() } + logrus.Debugf("Reading events from file %q", e.options.LogFilePath) + var line *tail.Line var ok bool for { diff --git a/libpod/runtime.go b/libpod/runtime.go index fe90b6df1..03610c687 100644 --- a/libpod/runtime.go +++ b/libpod/runtime.go @@ -466,14 +466,6 @@ func makeRuntime(runtime *Runtime) (retErr error) { } } - // Create events log dir - if err := os.MkdirAll(filepath.Dir(runtime.config.Engine.EventsLogFilePath), 0700); err != nil { - // The directory is allowed to exist - if !errors.Is(err, os.ErrExist) { - return fmt.Errorf("creating events dirs: %w", err) - } - } - // Get us at least one working OCI runtime. runtime.ociRuntimes = make(map[string]OCIRuntime) -- cgit v1.2.3-54-g00ecf From 138b09c7e28de336717191ec79c0b0bdf61b448a Mon Sep 17 00:00:00 2001 From: Paul Holzinger Date: Fri, 9 Sep 2022 11:43:20 +0200 Subject: event backend none: return an error when reading events podman --events-backend none events should return with an error since it will never be able to actually list events. Fixes part three of #15688 Signed-off-by: Paul Holzinger --- cmd/podman/system/events.go | 39 +++++++++++++++++++++------------------ libpod/events/events_linux.go | 2 +- libpod/events/nullout.go | 13 +++++++------ test/system/090-events.bats | 9 +++++++++ 4 files changed, 38 insertions(+), 25 deletions(-) (limited to 'libpod') diff --git a/cmd/podman/system/events.go b/cmd/podman/system/events.go index 3c6a35e83..57279bb02 100644 --- a/cmd/podman/system/events.go +++ b/cmd/podman/system/events.go @@ -99,25 +99,28 @@ func eventsCmd(cmd *cobra.Command, _ []string) error { errChannel <- err }() - for event := range eventChannel { - switch { - case event == nil: - // no-op - case doJSON: - jsonStr, err := event.ToJSONString() - if err != nil { - return err + for { + select { + case err := <-errChannel: + return err + case event := <-eventChannel: + switch { + case event == nil: + // no-op + case doJSON: + jsonStr, err := event.ToJSONString() + if err != nil { + return err + } + fmt.Println(jsonStr) + case cmd.Flags().Changed("format"): + if err := rpt.Execute(event); err != nil { + return err + } + os.Stdout.WriteString("\n") + default: + fmt.Println(event.ToHumanReadable(!noTrunc)) } - fmt.Println(jsonStr) - case cmd.Flags().Changed("format"): - if err := rpt.Execute(event); err != nil { - return err - } - os.Stdout.WriteString("\n") - default: - fmt.Println(event.ToHumanReadable(!noTrunc)) } } - - return <-errChannel } diff --git a/libpod/events/events_linux.go b/libpod/events/events_linux.go index b11467aca..66b125dd5 100644 --- a/libpod/events/events_linux.go +++ b/libpod/events/events_linux.go @@ -20,7 +20,7 @@ func NewEventer(options EventerOptions) (Eventer, error) { case strings.ToUpper(LogFile.String()): return newLogFileEventer(options) case strings.ToUpper(Null.String()): - return NewNullEventer(), nil + return newNullEventer(), nil case strings.ToUpper(Memory.String()): return NewMemoryEventer(), nil default: diff --git a/libpod/events/nullout.go b/libpod/events/nullout.go index 587a1b98b..da3820c23 100644 --- a/libpod/events/nullout.go +++ b/libpod/events/nullout.go @@ -2,10 +2,11 @@ package events import ( "context" + "errors" ) -// EventToNull is an eventer type that only performs write operations -// and only writes to /dev/null. It is meant for unittests only +// EventToNull is an eventer type that does nothing. +// It is meant for unittests only type EventToNull struct{} // Write eats the event and always returns nil @@ -13,14 +14,14 @@ func (e EventToNull) Write(ee Event) error { return nil } -// Read does nothing. Do not use it. +// Read does nothing and returns an error. func (e EventToNull) Read(ctx context.Context, options ReadOptions) error { - return nil + return errors.New("cannot read events with the \"none\" backend") } -// NewNullEventer returns a new null eventer. You should only do this for +// newNullEventer returns a new null eventer. You should only do this for // the purposes of internal libpod testing. -func NewNullEventer() Eventer { +func newNullEventer() Eventer { return EventToNull{} } diff --git a/test/system/090-events.bats b/test/system/090-events.bats index 51a327865..509e7a306 100644 --- a/test/system/090-events.bats +++ b/test/system/090-events.bats @@ -217,3 +217,12 @@ EOF --format="{{.Attributes.$lname}}" assert "$output" = "$lvalue" "podman-events output includes container label" } + +@test "events - backend none should error" { + skip_if_remote "remote does not support --events-backend" + + run_podman 125 --events-backend none events + is "$output" "Error: cannot read events with the \"none\" backend" "correct error message" + run_podman 125 --events-backend none events --stream=false + is "$output" "Error: cannot read events with the \"none\" backend" "correct error message" +} -- cgit v1.2.3-54-g00ecf From 76980a2226278eca1c0b31224ae7bdce59d5eabb Mon Sep 17 00:00:00 2001 From: Paul Holzinger Date: Fri, 9 Sep 2022 13:10:10 +0200 Subject: event backend journald: fix problem with empty journal Currently podman events will just fail with `Error: failed to get journal cursor: failed to get cursor: cannot assign requested address` when the journal contains zero podman events. The problem is that we are using the journal accessors wrong. There is no need to call GetCursor() and compare them manually. The Next() return an integer which tells if it moved to the next or not. This means the we can remove GetCursor() which would fail when there is no entry. This also includes another bug fix. Previously the logic called Next() twice for the first entry which caused us to miss the first entry. To reproduce this issue you can run the following commands: ``` sudo journalctl --rotate sudo journalctl --vacuum-time=1s ``` Note that this will delete the full journal. Now run podman events and it fails but with this patch it works. Now generate a single event, i.e. podman pull alpine, and run podman events --until 1s. I am not sure how to get a reliable test into CI, I really do not want to delete the journal and developer or CI systems. Fixes second part of #15688 Signed-off-by: Paul Holzinger --- libpod/events/journal_linux.go | 100 ++++++++++++++++++++++------------------- 1 file changed, 53 insertions(+), 47 deletions(-) (limited to 'libpod') diff --git a/libpod/events/journal_linux.go b/libpod/events/journal_linux.go index 16ef6504f..4986502a2 100644 --- a/libpod/events/journal_linux.go +++ b/libpod/events/journal_linux.go @@ -112,57 +112,16 @@ func (e EventJournalD) Read(ctx context.Context, options ReadOptions) error { } } - // the api requires a next|prev before getting a cursor - if _, err := j.Next(); err != nil { - return fmt.Errorf("failed to move journal cursor to next entry: %w", err) - } - - prevCursor, err := j.GetCursor() - if err != nil { - return fmt.Errorf("failed to get journal cursor: %w", err) - } for { - select { - case <-ctx.Done(): - // the consumer has cancelled - return nil - default: - // fallthrough - } - - if _, err := j.Next(); err != nil { - return fmt.Errorf("failed to move journal cursor to next entry: %w", err) - } - newCursor, err := j.GetCursor() + entry, err := getNextEntry(ctx, j, options.Stream, untilTime) if err != nil { - return fmt.Errorf("failed to get journal cursor: %w", err) + return err } - if prevCursor == newCursor { - if !options.Stream || (len(options.Until) > 0 && time.Now().After(untilTime)) { - break - } - - // j.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. - t := 5 * time.Second - if len(options.Until) > 0 { - until := time.Until(untilTime) - if until < t { - t = until - } - } - _ = j.Wait(t) - continue + // no entry == we hit the end + if entry == nil { + return nil } - prevCursor = newCursor - entry, err := j.GetEntry() - if err != nil { - return fmt.Errorf("failed to read journal entry: %w", err) - } newEvent, err := newEventFromJournalEntry(entry) if err != nil { // We can't decode this event. @@ -177,7 +136,6 @@ func (e EventJournalD) Read(ctx context.Context, options ReadOptions) error { options.EventChannel <- newEvent } } - return nil } func newEventFromJournalEntry(entry *sdjournal.JournalEntry) (*Event, error) { @@ -238,3 +196,51 @@ func newEventFromJournalEntry(entry *sdjournal.JournalEntry) (*Event, error) { func (e EventJournalD) String() string { return Journald.String() } + +// 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) { + for { + select { + case <-ctx.Done(): + // the consumer has cancelled + return nil, nil + default: + // fallthrough + } + // the api requires a next|prev before reading the event + ret, err := j.Next() + if err != nil { + return nil, fmt.Errorf("failed to move journal cursor to next entry: %w", err) + } + // ret == 0 equals EOF, see sd_journal_next(3) + if ret == 0 { + if !stream || (!untilTime.IsZero() && time.Now().After(untilTime)) { + // we hit the end and should not keep streaming + return nil, nil + } + // keep waiting for the next entry + // j.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. + t := 5 * time.Second + if !untilTime.IsZero() { + until := time.Until(untilTime) + if until < t { + t = until + } + } + _ = j.Wait(t) + continue + } + + entry, err := j.GetEntry() + if err != nil { + return nil, fmt.Errorf("failed to read journal entry: %w", err) + } + return entry, nil + } +} -- cgit v1.2.3-54-g00ecf From cd32b929e35cdb2d6b49853a7b0e5d93921b0979 Mon Sep 17 00:00:00 2001 From: Paul Holzinger Date: Fri, 9 Sep 2022 13:31:03 +0200 Subject: libpod: runtime newEventer() cleanup There is no reason to create a new eventer every time. The libpod runtime already has one attached which should be used instead. Signed-off-by: Paul Holzinger --- libpod/events.go | 12 ++---------- 1 file changed, 2 insertions(+), 10 deletions(-) (limited to 'libpod') diff --git a/libpod/events.go b/libpod/events.go index 60142cb60..ad9c5eafe 100644 --- a/libpod/events.go +++ b/libpod/events.go @@ -133,11 +133,7 @@ func (v *Volume) newVolumeEvent(status events.Status) { // Events is a wrapper function for everyone to begin tailing the events log // with options func (r *Runtime) Events(ctx context.Context, options events.ReadOptions) error { - eventer, err := r.newEventer() - if err != nil { - return err - } - return eventer.Read(ctx, options) + return r.eventer.Read(ctx, options) } // GetEvents reads the event log and returns events based on input filters @@ -149,10 +145,6 @@ func (r *Runtime) GetEvents(ctx context.Context, filters []string) ([]*events.Ev FromStart: true, Stream: false, } - eventer, err := r.newEventer() - if err != nil { - return nil, err - } logEvents := make([]*events.Event, 0, len(eventChannel)) readLock := sync.Mutex{} @@ -164,7 +156,7 @@ func (r *Runtime) GetEvents(ctx context.Context, filters []string) ([]*events.Ev readLock.Unlock() }() - readErr := eventer.Read(ctx, options) + readErr := r.eventer.Read(ctx, options) readLock.Lock() // Wait for the events to be consumed. return logEvents, readErr } -- cgit v1.2.3-54-g00ecf From b3212a6802b9a9dd5311dcbebe68c9c67fd96218 Mon Sep 17 00:00:00 2001 From: Paul Holzinger Date: Mon, 12 Sep 2022 11:15:35 +0200 Subject: set default EventsLogFilePath on first run The current code only sets EventsLogFilePath when the tmp is overwritten from the db. We should always set the default when no path was set in containers.conf. Signed-off-by: Paul Holzinger --- libpod/events.go | 5 +++++ libpod/events/logfile.go | 2 +- libpod/runtime.go | 3 --- 3 files changed, 6 insertions(+), 4 deletions(-) (limited to 'libpod') diff --git a/libpod/events.go b/libpod/events.go index ad9c5eafe..2f9799114 100644 --- a/libpod/events.go +++ b/libpod/events.go @@ -3,6 +3,7 @@ package libpod import ( "context" "fmt" + "path/filepath" "sync" "github.com/containers/podman/v4/libpod/events" @@ -11,6 +12,10 @@ import ( // newEventer returns an eventer that can be used to read/write events func (r *Runtime) newEventer() (events.Eventer, error) { + if r.config.Engine.EventsLogFilePath == "" { + // default, use path under tmpdir when none was explicitly set by the user + r.config.Engine.EventsLogFilePath = filepath.Join(r.config.Engine.TmpDir, "events", "events.log") + } options := events.EventerOptions{ EventerType: r.config.Engine.EventsLogger, LogFilePath: r.config.Engine.EventsLogFilePath, diff --git a/libpod/events/logfile.go b/libpod/events/logfile.go index 1b06e22e7..d749a0d4d 100644 --- a/libpod/events/logfile.go +++ b/libpod/events/logfile.go @@ -38,7 +38,7 @@ func newLogFileEventer(options EventerOptions) (*EventLogFile, error) { // https://github.com/containers/podman/issues/15688 fd, err := os.OpenFile(options.LogFilePath, os.O_RDONLY|os.O_CREATE, 0700) if err != nil { - return nil, err + return nil, fmt.Errorf("failed to create event log file: %w", err) } return &EventLogFile{options: options}, fd.Close() } diff --git a/libpod/runtime.go b/libpod/runtime.go index 03610c687..83c9f53e2 100644 --- a/libpod/runtime.go +++ b/libpod/runtime.go @@ -1030,9 +1030,6 @@ func (r *Runtime) mergeDBConfig(dbConfig *DBConfig) { logrus.Debugf("Overriding tmp dir %q with %q from database", c.TmpDir, dbConfig.LibpodTmp) } c.TmpDir = dbConfig.LibpodTmp - if c.EventsLogFilePath == "" { - c.EventsLogFilePath = filepath.Join(dbConfig.LibpodTmp, "events", "events.log") - } } if !r.storageSet.VolumePathSet && dbConfig.VolumePath != "" { -- cgit v1.2.3-54-g00ecf