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>

2 files changed, 49 insertions, 19 deletions

diff --git a/libpod/container_log_linux.go b/libpod/container_log_linux.go
index 4a541b6e7..ec4fa9724 100644
--- a/libpod/container_log_linux.go
+++ b/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
 	}
diff --git a/libpod/logs/log.go b/libpod/logs/log.go
index bba52408d..308053b47 100644
--- a/libpod/logs/log.go
+++ b/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