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: containers#10596
Signed-off-by: Valentin Rothberg <[email protected]>

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

test/e2e/logs_test.go

@@ -173,20 +173,18 @@ 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))
 
 			results := podmanTest.Podman([]string{"logs", "-f", containerName})
 			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() {