podman image tree: restore previous behavior

The initial version of libimage changed the order of layers which has
now been restored to remain backwards compatible.

Further changes:

 * Fix a bug in the journald logging which requires to strip trailing
   new lines from the message.  The system tests did not pass due to
   empty new lines.  Triggered by changing the default logger to
   journald in containers/common.

 * Fix another bug in the journald logging which embedded the container
   ID inside the message rather than the specifid field.  That surfaced
   in a preceeding whitespace of each log line which broke the system
   tests.

 * Alter the system tests to make sure that the k8s-file and the
   journald logging drivers are executed.

 * A number of e2e tests have been changed to force the k8s-file driver
   to make them pass when running inside a root container.

 * Increase the timeout in a kill test which seems to take longer now.
   Reasons are unknown.  Tests passed earlier and no signal-related
   changes happend.  It may be CI VM flake since some system tests but
   other flaked.

Signed-off-by: Valentin Rothberg <rothberg@redhat.com>

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;