From c3f6ef63a27ae23f79995c4019d552ed4dfdd406 Mon Sep 17 00:00:00 2001 From: Valentin Rothberg Date: Tue, 8 Jun 2021 13:44:49 +0200 Subject: [PATCH] logs: k8s-file: fix race Fix a race in the k8s-file logs driver. When "following" the logs, Podman will print the container's logs until the end. Previously, Podman logged until the state transitioned into something non-running which opened up a race with the container still running, possibly in the "stopping" state. To fix the race, log until we've seen the wait event for the specific container. In that case, conmon will have finished writing all logs to the file, and Podman will read it until EOF. Further tweak the integration tests for testing `logs -f` on a running container. Previously, the test only checked for one of two lines stating that there was a race. Indeed the race was in using `run --rm` where a log file may be removed before we could fully read it. Fixes: #10596 Signed-off-by: Valentin Rothberg --- libpod/container_log.go | 54 +++++++++++++++++++++++++---------------- test/e2e/logs_test.go | 14 ++++++----- 2 files changed, 41 insertions(+), 27 deletions(-) diff --git a/libpod/container_log.go b/libpod/container_log.go index c207df8199..a30e4f5cc0 100644 --- a/libpod/container_log.go +++ b/libpod/container_log.go @@ -4,11 +4,10 @@ import ( "context" "fmt" "os" - "time" "github.com/containers/podman/v3/libpod/define" + "github.com/containers/podman/v3/libpod/events" "github.com/containers/podman/v3/libpod/logs" - "github.com/hpcloud/tail/watch" "github.com/pkg/errors" "github.com/sirupsen/logrus" ) @@ -94,27 +93,40 @@ func (c *Container) readFromLogFile(ctx context.Context, options *logs.LogOption }() // Check if container is still running or paused if options.Follow { + state, err := c.State() + if err != nil || state != define.ContainerStateRunning { + // If the container isn't running or if we encountered + // an error getting its state, instruct the logger to + // read the file until EOF. + tailError := t.StopAtEOF() + if tailError != nil && fmt.Sprintf("%v", tailError) != "tail: stop at eof" { + logrus.Error(tailError) + } + if errors.Cause(err) != define.ErrNoSuchCtr { + logrus.Error(err) + } + return nil + } + + // The container is running, so we need to wait until the container exited go func() { - for { - state, err := c.State() - time.Sleep(watch.POLL_DURATION) - if err != nil { - tailError := t.StopAtEOF() - if tailError != nil && fmt.Sprintf("%v", tailError) != "tail: stop at eof" { - logrus.Error(tailError) - } - if errors.Cause(err) != define.ErrNoSuchCtr { - logrus.Error(err) - } - break - } - if state != define.ContainerStateRunning && state != define.ContainerStatePaused { - tailError := t.StopAtEOF() - if tailError != nil && fmt.Sprintf("%v", tailError) != "tail: stop at eof" { - logrus.Error(tailError) - } - break + eventChannel := make(chan *events.Event) + eventOptions := events.ReadOptions{ + EventChannel: eventChannel, + Filters: []string{"event=died", "container=" + c.ID()}, + Stream: true, + } + go func() { + if err := c.runtime.Events(ctx, eventOptions); err != nil { + logrus.Errorf("Error waiting for container to exit: %v", err) } + }() + // Now wait for the died event and signal to finish + // reading the log until EOF. + <-eventChannel + tailError := t.StopAtEOF() + if tailError != nil && fmt.Sprintf("%v", tailError) != "tail: stop at eof" { + logrus.Error(tailError) } }() } diff --git a/test/e2e/logs_test.go b/test/e2e/logs_test.go index 3051031a53..b7a5a6243c 100644 --- a/test/e2e/logs_test.go +++ b/test/e2e/logs_test.go @@ -173,9 +173,9 @@ var _ = Describe("Podman logs", func() { }) It("streaming output: "+log, func() { - containerName := "logs-f-rm" + containerName := "logs-f" - logc := podmanTest.Podman([]string{"run", "--log-driver", log, "--rm", "--name", containerName, "-dt", ALPINE, "sh", "-c", "echo podman; sleep 1; echo podman"}) + logc := podmanTest.Podman([]string{"run", "--log-driver", log, "--name", containerName, "-dt", ALPINE, "sh", "-c", "echo podman-1; sleep 1; echo podman-2"}) logc.WaitWithDefaultTimeout() Expect(logc).To(Exit(0)) @@ -183,10 +183,8 @@ var _ = Describe("Podman logs", func() { results.WaitWithDefaultTimeout() Expect(results).To(Exit(0)) - // TODO: we should actually check for two podman lines, - // but as of 2020-06-17 there's a race condition in which - // 'logs -f' may not catch all output from a container - Expect(results.OutputToString()).To(ContainSubstring("podman")) + Expect(results.OutputToString()).To(ContainSubstring("podman-1")) + Expect(results.OutputToString()).To(ContainSubstring("podman-2")) // Container should now be terminatING or terminatED, but we // have no guarantee of which: 'logs -f' does not necessarily @@ -199,6 +197,10 @@ var _ = Describe("Podman logs", func() { } else { Expect(inspect.ErrorToString()).To(ContainSubstring("no such container")) } + + results = podmanTest.Podman([]string{"rm", "-f", containerName}) + results.WaitWithDefaultTimeout() + Expect(results).To(Exit(0)) }) It("follow output stopped container: "+log, func() {