Merge pull request #10600 from vrothberg/fix-10596

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,11 +93,11 @@ func (c *Container) readFromLogFile(ctx context.Context, options *logs.LogOption
 	}()
 	// Check if container is still running or paused
 	if options.Follow {
-		go func() {
-			for {
 		state, err := c.State()
-				time.Sleep(watch.POLL_DURATION)
+		if err != nil || state != define.ContainerStateRunning {
-				if err != nil {
+			// 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)
@@ -106,16 +105,29 @@ func (c *Container) readFromLogFile(ctx context.Context, options *logs.LogOption
 			if errors.Cause(err) != define.ErrNoSuchCtr {
 				logrus.Error(err)
 			}
-					break
+			return nil
 		}
-				if state != define.ContainerStateRunning && state != define.ContainerStatePaused {
+
+		// The container is running, so we need to wait until the container exited
+		go func() {
+			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)
 			}
-					break
-				}
-			}
 		}()
 	}
 	return nil

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,
+			Expect(results.OutputToString()).To(ContainSubstring("podman-1"))
-			// but as of 2020-06-17 there's a race condition in which
+			Expect(results.OutputToString()).To(ContainSubstring("podman-2"))
-			// 'logs -f' may not catch all output from a container
-			Expect(results.OutputToString()).To(ContainSubstring("podman"))
 
 			// 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() {