podman image tree: restore previous behavior

go.mod

@@ -12,7 +12,7 @@ require (
 	github.com/containernetworking/cni v0.8.1
 	github.com/containernetworking/plugins v0.9.1
 	github.com/containers/buildah v1.20.2-0.20210504130217-903dc56408ac
-	github.com/containers/common v0.37.2-0.20210503193405-42134aa138ce
+	github.com/containers/common v0.38.1-0.20210510140555-24645399a050
 	github.com/containers/conmon v2.0.20+incompatible
 	github.com/containers/image/v5 v5.12.0
 	github.com/containers/ocicrypt v1.1.1

go.sum

@@ -197,8 +197,9 @@ github.com/containernetworking/plugins v0.9.1 h1:FD1tADPls2EEi3flPc2OegIY1M9pUa9
 github.com/containernetworking/plugins v0.9.1/go.mod h1:xP/idU2ldlzN6m4p5LmGiwRDjeJr6FLK6vuiUwoH7P8=
 github.com/containers/buildah v1.20.2-0.20210504130217-903dc56408ac h1:rPQTF+1lz+F4uTZgfk2pwqGcEEg9mPSWK58UncsqsrA=
 github.com/containers/buildah v1.20.2-0.20210504130217-903dc56408ac/go.mod h1:0hqcxPCNk/lit/SwBQoXXymCbp2LUa07U0cwrn/T1c0=
-github.com/containers/common v0.37.2-0.20210503193405-42134aa138ce h1:e7VNmGqwfUQkw+D5bms262x1HYqxfN9/+t5SoaFnwTk=
 github.com/containers/common v0.37.2-0.20210503193405-42134aa138ce/go.mod h1:JjU+yvzIGyx8ZsY8nyf7snzs4VSNh1eIaYsqoSKBoRw=
+github.com/containers/common v0.38.1-0.20210510140555-24645399a050 h1:o3UdnXpzCmJwto4y+addBH2NXZObuZ0tXA7COZXNMnQ=
+github.com/containers/common v0.38.1-0.20210510140555-24645399a050/go.mod h1:64dWQkAgrd2cxVh9eDOxJ/IgPOulVFg6G7WLRDTrAuA=
 github.com/containers/conmon v2.0.20+incompatible h1:YbCVSFSCqFjjVwHTPINGdMX1F6JXHGTUje2ZYobNrkg=
 github.com/containers/conmon v2.0.20+incompatible/go.mod h1:hgwZ2mtuDrppv78a/cOBNiCm6O0UMWGx1mu7P00nu5I=
 github.com/containers/image/v5 v5.11.1/go.mod h1:HC9lhJ/Nz5v3w/5Co7H431kLlgzlVlOC+auD/er3OqE=

libpod/container_log_linux.go

@@ -8,12 +8,12 @@ import (
 	"fmt"
 	"io"
 	"math"
+	"strings"
 	"time"
 
 	"github.com/containers/podman/v3/libpod/define"
 	"github.com/containers/podman/v3/libpod/logs"
 	journal "github.com/coreos/go-systemd/v22/sdjournal"
-	"github.com/hpcloud/tail/watch"
 	"github.com/pkg/errors"
 	"github.com/sirupsen/logrus"
 )
@@ -89,21 +89,19 @@ func (c *Container) readFromJournal(ctx context.Context, options *logs.LogOption
 				}
 			}()
 			go func() {
-				for {
-					state, err := c.State()
-					if err != nil {
-						until <- time.Time{}
-						logrus.Error(err)
-						break
-					}
-					time.Sleep(watch.POLL_DURATION)
-					if state != define.ContainerStateRunning && state != define.ContainerStatePaused {
-						until <- time.Time{}
-						break
-					}
-				}
+				// FIXME (#10323): we are facing a terrible
+				// race condition here. At the time the
+				// container dies and `c.Wait()` has returned,
+				// we may not have received all journald logs.
+				// So far there is no other way than waiting
+				// for a second.  Ultimately, `r.Follow` is
+				// racy and we may have to implement our custom
+				// logic here.
+				c.Wait(ctx)
+				time.Sleep(time.Second)
+				until <- time.Time{}
 			}()
-			follower := FollowBuffer{logChannel}
+			follower := journaldFollowBuffer{logChannel, options.Multi}
 			err := r.Follow(until, follower)
 			if err != nil {
 				logrus.Debugf(err.Error())
@@ -124,7 +122,7 @@ func (c *Container) readFromJournal(ctx context.Context, options *logs.LogOption
 			// because we are reusing bytes, we need to make
 			// sure the old data doesn't get into the new line
 			bytestr := string(bytes[:ec])
-			logLine, err2 := logs.NewLogLine(bytestr)
+			logLine, err2 := logs.NewJournaldLogLine(bytestr, options.Multi)
 			if err2 != nil {
 				logrus.Error(err2)
 				continue
@@ -210,16 +208,18 @@ func formatterMessage(entry *journal.JournalEntry) (string, error) {
 	if !ok {
 		return "", fmt.Errorf("no MESSAGE field present in journal entry")
 	}
+	msg = strings.TrimSuffix(msg, "\n")
 	return msg, nil
 }
 
-type FollowBuffer struct {
+type journaldFollowBuffer struct {
 	logChannel chan *logs.LogLine
+	withID     bool
 }
 
-func (f FollowBuffer) Write(p []byte) (int, error) {
+func (f journaldFollowBuffer) Write(p []byte) (int, error) {
 	bytestr := string(p)
-	logLine, err := logs.NewLogLine(bytestr)
+	logLine, err := logs.NewJournaldLogLine(bytestr, f.withID)
 	if err != nil {
 		return -1, err
 	}

libpod/logs/log.go

@@ -206,6 +206,36 @@ func NewLogLine(line string) (*LogLine, error) {
 	return &l, nil
 }
 
+// NewJournaldLogLine creates a LogLine from the specified line from journald.
+// Note that if withID is set, the first item of the message is considerred to
+// be the container ID and set as such.
+func NewJournaldLogLine(line string, withID bool) (*LogLine, error) {
+	splitLine := strings.Split(line, " ")
+	if len(splitLine) < 4 {
+		return nil, errors.Errorf("'%s' is not a valid container log line", line)
+	}
+	logTime, err := time.Parse(LogTimeFormat, splitLine[0])
+	if err != nil {
+		return nil, errors.Wrapf(err, "unable to convert time %s from container log", splitLine[0])
+	}
+	var msg, id string
+	if withID {
+		id = splitLine[3]
+		msg = strings.Join(splitLine[4:], " ")
+	} else {
+		msg = strings.Join(splitLine[3:], " ")
+		// NO ID
+	}
+	l := LogLine{
+		Time:         logTime,
+		Device:       splitLine[1],
+		ParseLogType: splitLine[2],
+		Msg:          msg,
+		CID:          id,
+	}
+	return &l, nil
+}
+
 // Partial returns a bool if the log line is a partial log type
 func (l *LogLine) Partial() bool {
 	return l.ParseLogType == PartialLogType

test/e2e/create_staticip_test.go

@@ -60,8 +60,10 @@ var _ = Describe("Podman create with --ip flag", func() {
 	})
 
 	It("Podman create with specified static IP has correct IP", func() {
+		// NOTE: we force the k8s-file log driver to make sure the
+		// tests are passing inside a container.
 		ip := GetRandomIPAddress()
-		result := podmanTest.Podman([]string{"create", "--name", "test", "--ip", ip, ALPINE, "ip", "addr"})
+		result := podmanTest.Podman([]string{"create", "--log-driver", "k8s-file", "--name", "test", "--ip", ip, ALPINE, "ip", "addr"})
 		result.WaitWithDefaultTimeout()
 		// Rootless static ip assignment without network should error
 		if rootless.IsRootless() {
@@ -83,10 +85,10 @@ var _ = Describe("Podman create with --ip flag", func() {
 	It("Podman create two containers with the same IP", func() {
 		SkipIfRootless("--ip not supported without network in rootless mode")
 		ip := GetRandomIPAddress()
-		result := podmanTest.Podman([]string{"create", "--name", "test1", "--ip", ip, ALPINE, "sleep", "999"})
+		result := podmanTest.Podman([]string{"create", "--log-driver", "k8s-file", "--name", "test1", "--ip", ip, ALPINE, "sleep", "999"})
 		result.WaitWithDefaultTimeout()
 		Expect(result.ExitCode()).To(Equal(0))
-		result = podmanTest.Podman([]string{"create", "--name", "test2", "--ip", ip, ALPINE, "ip", "addr"})
+		result = podmanTest.Podman([]string{"create", "--log-driver", "k8s-file", "--name", "test2", "--ip", ip, ALPINE, "ip", "addr"})
 		result.WaitWithDefaultTimeout()
 		Expect(result.ExitCode()).To(Equal(0))
 		result = podmanTest.Podman([]string{"start", "test1"})

test/e2e/create_test.go

@@ -160,9 +160,12 @@ var _ = Describe("Podman create", func() {
 		if podmanTest.Host.Arch == "ppc64le" {
 			Skip("skip failing test on ppc64le")
 		}
+		// NOTE: we force the k8s-file log driver to make sure the
+		// tests are passing inside a container.
+
 		mountPath := filepath.Join(podmanTest.TempDir, "secrets")
 		os.Mkdir(mountPath, 0755)
-		session := podmanTest.Podman([]string{"create", "--name", "test", "--mount", fmt.Sprintf("type=bind,src=%s,target=/create/test", mountPath), ALPINE, "grep", "/create/test", "/proc/self/mountinfo"})
+		session := podmanTest.Podman([]string{"create", "--log-driver", "k8s-file", "--name", "test", "--mount", fmt.Sprintf("type=bind,src=%s,target=/create/test", mountPath), ALPINE, "grep", "/create/test", "/proc/self/mountinfo"})
 		session.WaitWithDefaultTimeout()
 		Expect(session.ExitCode()).To(Equal(0))
 		session = podmanTest.Podman([]string{"start", "test"})
@@ -173,7 +176,7 @@ var _ = Describe("Podman create", func() {
 		Expect(session.ExitCode()).To(Equal(0))
 		Expect(session.OutputToString()).To(ContainSubstring("/create/test rw"))
 
-		session = podmanTest.Podman([]string{"create", "--name", "test_ro", "--mount", fmt.Sprintf("type=bind,src=%s,target=/create/test,ro", mountPath), ALPINE, "grep", "/create/test", "/proc/self/mountinfo"})
+		session = podmanTest.Podman([]string{"create", "--log-driver", "k8s-file", "--name", "test_ro", "--mount", fmt.Sprintf("type=bind,src=%s,target=/create/test,ro", mountPath), ALPINE, "grep", "/create/test", "/proc/self/mountinfo"})
 		session.WaitWithDefaultTimeout()
 		Expect(session.ExitCode()).To(Equal(0))
 		session = podmanTest.Podman([]string{"start", "test_ro"})
@@ -184,7 +187,7 @@ var _ = Describe("Podman create", func() {
 		Expect(session.ExitCode()).To(Equal(0))
 		Expect(session.OutputToString()).To(ContainSubstring("/create/test ro"))
 
-		session = podmanTest.Podman([]string{"create", "--name", "test_shared", "--mount", fmt.Sprintf("type=bind,src=%s,target=/create/test,shared", mountPath), ALPINE, "grep", "/create/test", "/proc/self/mountinfo"})
+		session = podmanTest.Podman([]string{"create", "--log-driver", "k8s-file", "--name", "test_shared", "--mount", fmt.Sprintf("type=bind,src=%s,target=/create/test,shared", mountPath), ALPINE, "grep", "/create/test", "/proc/self/mountinfo"})
 		session.WaitWithDefaultTimeout()
 		Expect(session.ExitCode()).To(Equal(0))
 		session = podmanTest.Podman([]string{"start", "test_shared"})
@@ -200,7 +203,7 @@ var _ = Describe("Podman create", func() {
 
 		mountPath = filepath.Join(podmanTest.TempDir, "scratchpad")
 		os.Mkdir(mountPath, 0755)
-		session = podmanTest.Podman([]string{"create", "--name", "test_tmpfs", "--mount", "type=tmpfs,target=/create/test", ALPINE, "grep", "/create/test", "/proc/self/mountinfo"})
+		session = podmanTest.Podman([]string{"create", "--log-driver", "k8s-file", "--name", "test_tmpfs", "--mount", "type=tmpfs,target=/create/test", ALPINE, "grep", "/create/test", "/proc/self/mountinfo"})
 		session.WaitWithDefaultTimeout()
 		Expect(session.ExitCode()).To(Equal(0))
 		session = podmanTest.Podman([]string{"start", "test_tmpfs"})

test/e2e/run_networking_test.go

@@ -649,11 +649,13 @@ var _ = Describe("Podman run networking", func() {
 		defer podmanTest.removeCNINetwork(netName)
 
 		name := "nc-server"
-		run := podmanTest.Podman([]string{"run", "-d", "--name", name, "--net", netName, ALPINE, "nc", "-l", "-p", "8080"})
+		run := podmanTest.Podman([]string{"run", "--log-driver", "k8s-file", "-d", "--name", name, "--net", netName, ALPINE, "nc", "-l", "-p", "8080"})
 		run.WaitWithDefaultTimeout()
 		Expect(run.ExitCode()).To(Equal(0))
 
-		run = podmanTest.Podman([]string{"run", "--rm", "--net", netName, "--uidmap", "0:1:4096", ALPINE, "sh", "-c", fmt.Sprintf("echo podman | nc -w 1 %s.dns.podman 8080", name)})
+		// NOTE: we force the k8s-file log driver to make sure the
+		// tests are passing inside a container.
+		run = podmanTest.Podman([]string{"run", "--log-driver", "k8s-file", "--rm", "--net", netName, "--uidmap", "0:1:4096", ALPINE, "sh", "-c", fmt.Sprintf("echo podman | nc -w 1 %s.dns.podman 8080", name)})
 		run.WaitWithDefaultTimeout()
 		Expect(run.ExitCode()).To(Equal(0))
 

test/e2e/run_test.go

@@ -712,7 +712,7 @@ USER bin`, BB)
 
 	It("podman run log-opt", func() {
 		log := filepath.Join(podmanTest.TempDir, "/container.log")
-		session := podmanTest.Podman([]string{"run", "--rm", "--log-opt", fmt.Sprintf("path=%s", log), ALPINE, "ls"})
+		session := podmanTest.Podman([]string{"run", "--rm", "--log-driver", "k8s-file", "--log-opt", fmt.Sprintf("path=%s", log), ALPINE, "ls"})
 		session.WaitWithDefaultTimeout()
 		Expect(session.ExitCode()).To(Equal(0))
 		_, err := os.Stat(log)

test/e2e/toolbox_test.go

@@ -215,7 +215,7 @@ var _ = Describe("Toolbox-specific testing", func() {
 		useradd := fmt.Sprintf("useradd --home-dir %s --shell %s --uid %s %s",
 			homeDir, shell, uid, username)
 		passwd := fmt.Sprintf("passwd --delete %s", username)
-		session = podmanTest.Podman([]string{"create", "--name", "test", "--userns=keep-id", "--user", "root:root", fedoraToolbox, "sh", "-c",
+		session = podmanTest.Podman([]string{"create", "--log-driver", "k8s-file", "--name", "test", "--userns=keep-id", "--user", "root:root", fedoraToolbox, "sh", "-c",
 			fmt.Sprintf("%s; %s; echo READY; sleep 1000", useradd, passwd)})
 		session.WaitWithDefaultTimeout()
 		Expect(session.ExitCode()).To(Equal(0))
@@ -250,7 +250,7 @@ var _ = Describe("Toolbox-specific testing", func() {
 
 		groupadd := fmt.Sprintf("groupadd --gid %s %s", gid, groupName)
 
-		session = podmanTest.Podman([]string{"create", "--name", "test", "--userns=keep-id", "--user", "root:root", fedoraToolbox, "sh", "-c",
+		session = podmanTest.Podman([]string{"create", "--log-driver", "k8s-file", "--name", "test", "--userns=keep-id", "--user", "root:root", fedoraToolbox, "sh", "-c",
 			fmt.Sprintf("%s; echo READY; sleep 1000", groupadd)})
 		session.WaitWithDefaultTimeout()
 		Expect(session.ExitCode()).To(Equal(0))
@@ -294,7 +294,7 @@ var _ = Describe("Toolbox-specific testing", func() {
 		usermod := fmt.Sprintf("usermod --append --groups wheel --home %s --shell %s --uid %s --gid %s %s",
 			homeDir, shell, uid, gid, username)
 
-		session = podmanTest.Podman([]string{"create", "--name", "test", "--userns=keep-id", "--user", "root:root", fedoraToolbox, "sh", "-c",
+		session = podmanTest.Podman([]string{"create", "--log-driver", "k8s-file", "--name", "test", "--userns=keep-id", "--user", "root:root", fedoraToolbox, "sh", "-c",
 			fmt.Sprintf("%s; %s; %s; echo READY; sleep 1000", useradd, groupadd, usermod)})
 		session.WaitWithDefaultTimeout()
 		Expect(session.ExitCode()).To(Equal(0))
@@ -339,6 +339,7 @@ var _ = Describe("Toolbox-specific testing", func() {
 		// These should be most of the switches that Toolbox uses to create a "toolbox" container
 		// https://github.com/containers/toolbox/blob/master/src/cmd/create.go
 		session = podmanTest.Podman([]string{"create",
+			"--log-driver", "k8s-file",
 			"--dns", "none",
 			"--hostname", "toolbox",
 			"--ipc", "host",

test/system/035-logs.bats

@@ -27,13 +27,22 @@ load helpers
     run_podman rm $cid
 }
 
-@test "podman logs - multi" {
+function _log_test_multi() {
+    local driver=$1
+
     skip_if_remote "logs does not support multiple containers when run remotely"
 
+    # Under k8s file, 'podman logs' returns just the facts, Ma'am.
+    # Under journald, there may be other cruft (e.g. container removals)
+    local etc=
+    if [[ $driver =~ journal ]]; then
+        etc='.*'
+    fi
+
     # Simple helper to make the container starts, below, easier to read
     local -a cid
     doit() {
-        run_podman run --rm -d --name "$1" $IMAGE sh -c "$2";
+        run_podman run --log-driver=$driver --rm -d --name "$1" $IMAGE sh -c "$2";
         cid+=($(echo "${output:0:12}"))
     }
 
@@ -47,24 +56,21 @@ load helpers
 
     run_podman logs -f c1 c2
     is "$output" \
-       "${cid[0]} a
-${cid[1]} b
-${cid[1]} c
+       "${cid[0]} a$etc
+${cid[1]} b$etc
+${cid[1]} c$etc
 ${cid[0]} d"   "Sequential output from logs"
 }
 
-@test "podman logs over journald" {
+@test "podman logs - multi k8s-file" {
+    _log_test_multi k8s-file
+}
+
+@test "podman logs - multi journald" {
     # We can't use journald on RHEL as rootless: rhbz#1895105
     skip_if_journald_unavailable
 
-    msg=$(random_string 20)
-
-    run_podman run --name myctr --log-driver journald $IMAGE echo $msg
-
-    run_podman logs myctr
-    is "$output" "$msg" "check that log output equals the container output"
-
-    run_podman rm myctr
+    _log_test_multi journald
 }
 
 # vim: filetype=sh

test/system/070-build.bats

@@ -393,9 +393,9 @@ Labels.$label_name | $label_value
        "image tree: third line"
     is "${lines[3]}" "Image Layers" \
        "image tree: fourth line"
-    is "${lines[4]}"  ".* ID: [0-9a-f]\{12\} Size: .* Top Layer of: \[localhost/build_test:latest]" \
+    is "${lines[4]}" ".* ID: [0-9a-f]\{12\} Size: .* Top Layer of: \[$IMAGE]" \
        "image tree: first layer line"
-    is "${lines[-1]}" ".* ID: [0-9a-f]\{12\} Size: .* Top Layer of: \[$IMAGE]" \
+    is "${lines[-1]}"  ".* ID: [0-9a-f]\{12\} Size: .* Top Layer of: \[localhost/build_test:latest]" \
        "image tree: last layer line"
 
     # FIXME: 'image tree --whatrequires' does not work via remote

test/system/130-kill.bats

@@ -8,7 +8,8 @@ load helpers
 @test "podman kill - test signal handling in containers" {
     # Start a container that will handle all signals by emitting 'got: N'
     local -a signals=(1 2 3 4 5 6 8 10 12 13 14 15 16 20 21 22 23 24 25 26 64)
-    run_podman run -d $IMAGE sh -c \
+    # Force the k8s-file driver until #10323 is fixed.
+    run_podman run --log-driver=k8s-file -d $IMAGE sh -c \
         "for i in ${signals[*]}; do trap \"echo got: \$i\" \$i; done;
         echo READY;
         while ! test -e /stop; do sleep 0.05; done;