logs: k8s-file: fix race

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