Merge pull request #17502 from Luap99/passthrough-logs

podman logs: read journald with passthrough

libpod/container_log.go

@@ -10,6 +10,7 @@ import (
 	"github.com/containers/podman/v4/libpod/define"
 	"github.com/containers/podman/v4/libpod/events"
 	"github.com/containers/podman/v4/libpod/logs"
+	systemdDefine "github.com/containers/podman/v4/pkg/systemd/define"
 	"github.com/nxadm/tail"
 	"github.com/nxadm/tail/watch"
 	"github.com/sirupsen/logrus"
@@ -36,11 +37,15 @@ func (r *Runtime) Log(ctx context.Context, containers []*Container, options *log
 func (c *Container) ReadLog(ctx context.Context, options *logs.LogOptions, logChannel chan *logs.LogLine, colorID int64) error {
 	switch c.LogDriver() {
 	case define.PassthroughLogging:
+		// if running under systemd fallback to a more native journald reading
+		if unitName, ok := c.config.Labels[systemdDefine.EnvVariable]; ok {
+			return c.readFromJournal(ctx, options, logChannel, colorID, unitName)
+		}
 		return fmt.Errorf("this container is using the 'passthrough' log driver, cannot read logs: %w", define.ErrNoLogs)
 	case define.NoLogging:
 		return fmt.Errorf("this container is using the 'none' log driver, cannot read logs: %w", define.ErrNoLogs)
 	case define.JournaldLogging:
-		return c.readFromJournal(ctx, options, logChannel, colorID)
+		return c.readFromJournal(ctx, options, logChannel, colorID, "")
 	case define.JSONLogging:
 		// TODO provide a separate implementation of this when Conmon
 		// has support.

libpod/container_log_linux.go

@@ -31,7 +31,8 @@ func init() {
 	logDrivers = append(logDrivers, define.JournaldLogging)
 }
 
-func (c *Container) readFromJournal(ctx context.Context, options *logs.LogOptions, logChannel chan *logs.LogLine, colorID int64) error {
+func (c *Container) readFromJournal(ctx context.Context, options *logs.LogOptions,
+	logChannel chan *logs.LogLine, colorID int64, passthroughUnit string) error {
 	// We need the container's events in the same journal to guarantee
 	// consistency, see #10323.
 	if options.Follow && c.runtime.config.Engine.EventsLogger != "journald" {
@@ -67,10 +68,35 @@ func (c *Container) readFromJournal(ctx context.Context, options *logs.LogOption
 	if err := journal.AddDisjunction(); err != nil {
 		return fmt.Errorf("adding filter disjunction to journald logger: %w", err)
 	}
-	match = sdjournal.Match{Field: "CONTAINER_ID_FULL", Value: c.ID()}
-	if err := journal.AddMatch(match.String()); err != nil {
-		return fmt.Errorf("adding filter to journald logger: %v: %w", match, err)
+
+	if passthroughUnit != "" {
+		// Match based on systemd unit which is the container is cgroup
+		// so we get the exact logs for a single container even in the
+		// play kube case where a single unit starts more than one container.
+		unitTypeName := "_SYSTEMD_UNIT"
+		if rootless.IsRootless() {
+			unitTypeName = "_SYSTEMD_USER_UNIT"
+		}
+		// By default we will have our own systemd cgroup with the name libpod-<ID>.scope.
+		value := "libpod-" + c.ID() + ".scope"
+		if c.config.CgroupsMode == cgroupSplit {
+			// If cgroup split the container runs in the unit cgroup so we use this for logs,
+			// the good thing is we filter the podman events already out below.
+			// Thus we are left with the real container log and possibly podman output (e.g. logrus).
+			value = passthroughUnit
+		}
+
+		match = sdjournal.Match{Field: unitTypeName, Value: value}
+		if err := journal.AddMatch(match.String()); err != nil {
+			return fmt.Errorf("adding filter to journald logger: %v: %w", match, err)
+		}
+	} else {
+		match = sdjournal.Match{Field: "CONTAINER_ID_FULL", Value: c.ID()}
+		if err := journal.AddMatch(match.String()); err != nil {
+			return fmt.Errorf("adding filter to journald logger: %v: %w", match, err)
+		}
 	}
+
 	if err := journal.AddMatch(uidMatch.String()); err != nil {
 		return fmt.Errorf("adding filter to journald logger: %v: %w", uidMatch, err)
 	}
@@ -162,26 +188,17 @@ func (c *Container) readFromJournal(ctx context.Context, options *logs.LogOption
 				continue
 			}
 
-			var message string
-			var formatError error
-
-			if options.Multi {
-				message, formatError = journalFormatterWithID(entry)
-			} else {
-				message, formatError = journalFormatter(entry)
-			}
-
-			if formatError != nil {
-				logrus.Errorf("Failed to parse journald log entry: %v", formatError)
-				return
-			}
-
-			logLine, err := logs.NewJournaldLogLine(message, options.Multi)
-			logLine.ColorID = colorID
+			logLine, err := journalToLogLine(entry)
 			if err != nil {
-				logrus.Errorf("Failed parse log line: %v", err)
+				logrus.Errorf("Failed parse journal entry: %v", err)
 				return
 			}
+			id := c.ID()
+			if len(id) > 12 {
+				id = id[:12]
+			}
+			logLine.CID = id
+			logLine.ColorID = colorID
 			if options.UseName {
 				logLine.CName = c.Name()
 			}
@@ -196,76 +213,37 @@ func (c *Container) readFromJournal(ctx context.Context, options *logs.LogOption
 	return nil
 }
 
-func journalFormatterWithID(entry *sdjournal.JournalEntry) (string, error) {
-	output, err := formatterPrefix(entry)
-	if err != nil {
-		return "", err
-	}
+func journalToLogLine(entry *sdjournal.JournalEntry) (*logs.LogLine, error) {
+	line := &logs.LogLine{}
 
-	id, ok := entry.Fields["CONTAINER_ID_FULL"]
-	if !ok {
-		return "", errors.New("no CONTAINER_ID_FULL field present in journal entry")
-	}
-	if len(id) > 12 {
-		id = id[:12]
-	}
-	output += fmt.Sprintf("%s ", id)
-	// Append message
-	msg, err := formatterMessage(entry)
-	if err != nil {
-		return "", err
-	}
-	output += msg
-	return output, nil
-}
-
-func journalFormatter(entry *sdjournal.JournalEntry) (string, error) {
-	output, err := formatterPrefix(entry)
-	if err != nil {
-		return "", err
-	}
-	// Append message
-	msg, err := formatterMessage(entry)
-	if err != nil {
-		return "", err
-	}
-	output += msg
-	return output, nil
-}
-
-func formatterPrefix(entry *sdjournal.JournalEntry) (string, error) {
 	usec := entry.RealtimeTimestamp
-	tsString := time.Unix(0, int64(usec)*int64(time.Microsecond)).Format(logs.LogTimeFormat)
-	output := fmt.Sprintf("%s ", tsString)
+	line.Time = time.Unix(0, int64(usec)*int64(time.Microsecond))
+
 	priority, ok := entry.Fields["PRIORITY"]
 	if !ok {
-		return "", errors.New("no PRIORITY field present in journal entry")
+		return nil, errors.New("no PRIORITY field present in journal entry")
 	}
 	switch priority {
 	case journaldLogOut:
-		output += "stdout "
+		line.Device = "stdout"
 	case journaldLogErr:
-		output += "stderr "
+		line.Device = "stderr"
 	default:
-		return "", errors.New("unexpected PRIORITY field in journal entry")
+		return nil, errors.New("unexpected PRIORITY field in journal entry")
 	}
 
 	// if CONTAINER_PARTIAL_MESSAGE is defined, the log type is "P"
 	if _, ok := entry.Fields["CONTAINER_PARTIAL_MESSAGE"]; ok {
-		output += fmt.Sprintf("%s ", logs.PartialLogType)
+		line.ParseLogType = logs.PartialLogType
 	} else {
-		output += fmt.Sprintf("%s ", logs.FullLogType)
+		line.ParseLogType = logs.FullLogType
 	}
 
-	return output, nil
-}
-
-func formatterMessage(entry *sdjournal.JournalEntry) (string, error) {
-	// Finally, append the message
-	msg, ok := entry.Fields["MESSAGE"]
+	line.Msg, ok = entry.Fields["MESSAGE"]
 	if !ok {
-		return "", errors.New("no MESSAGE field present in journal entry")
+		return nil, errors.New("no MESSAGE field present in journal entry")
 	}
-	msg = strings.TrimSuffix(msg, "\n")
-	return msg, nil
+	line.Msg = strings.TrimSuffix(line.Msg, "\n")
+
+	return line, nil
 }

libpod/container_log_unsupported.go

@@ -11,6 +11,6 @@ import (
 	"github.com/containers/podman/v4/libpod/logs"
 )
 
-func (c *Container) readFromJournal(_ context.Context, _ *logs.LogOptions, _ chan *logs.LogLine, colorID int64) error {
+func (c *Container) readFromJournal(_ context.Context, _ *logs.LogOptions, _ chan *logs.LogLine, _ int64, _ string) error {
 	return fmt.Errorf("journald logging only enabled with systemd on linux: %w", define.ErrOSNotSupported)
 }

libpod/logs/log.go

@@ -243,36 +243,6 @@ 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 considered 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, fmt.Errorf("'%s' is not a valid container log line", line)
-	}
-	logTime, err := time.Parse(LogTimeFormat, splitLine[0])
-	if err != nil {
-		return nil, fmt.Errorf("unable to convert time %s from container log: %w", splitLine[0], err)
-	}
-	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/system/250-systemd.bats

@@ -383,11 +383,15 @@ metadata:
 spec:
   containers:
   - command:
-    - top
+    - sh
+    - -c
+    - echo a stdout; echo a stderr 1>&2; sleep inf
     image: $IMAGE
     name: a
   - command:
-    - top
+    - sh
+    - -c
+    - echo b stdout; echo b stderr 1>&2; sleep inf
     image: $IMAGE
     name: b
 EOF
@@ -418,8 +422,18 @@ EOF
     for name in "a" "b"; do
         run_podman container inspect test_pod-${name} --format "{{.HostConfig.LogConfig.Type}}"
         assert $output != "passthrough"
+        # check that we can get the logs with passthrough when we run in a systemd unit
+        run_podman logs test_pod-$name
+        assert "$output" == "$name stdout
+$name stderr" "logs work with passthrough"
     done
 
+    # we cannot assume the ordering between a b, this depends on timing and would flake in CI
+    # use --names so we do not have to get the ID
+    run_podman pod logs --names test_pod
+    assert "$output" =~ ".*^test_pod-a a stdout.*" "logs from container a shown"
+    assert "$output" =~ ".*^test_pod-b b stdout.*" "logs from container b shown"
+
     # Add a simple `auto-update --dry-run` test here to avoid too much redundancy
     # with 255-auto-update.bats
     run_podman auto-update --dry-run --format "{{.Unit}},{{.Container}},{{.Image}},{{.Updated}},{{.Policy}}"

test/system/252-quadlet.bats

@@ -141,7 +141,7 @@ function remove_secret() {
     cat > $quadlet_file <<EOF
 [Container]
 Image=$IMAGE
-Exec=sh -c "echo STARTED CONTAINER; echo "READY=1" | socat -u STDIN unix-sendto:\$NOTIFY_SOCKET; top"
+Exec=sh -c "echo STARTED CONTAINER; echo "READY=1" | socat -u STDIN unix-sendto:\$NOTIFY_SOCKET; sleep inf"
 Notify=yes
 EOF
 
@@ -152,6 +152,10 @@ EOF
     run journalctl "--since=$STARTED_TIME" --unit="$QUADLET_SERVICE_NAME"
     is "$output" '.*STARTED CONTAINER.*'
 
+    # check that we can read the logs from the container with podman logs
+    run_podman logs $QUADLET_CONTAINER_NAME
+    assert "$output" == "STARTED CONTAINER" "podman logs works on quadlet container"
+
     run_podman container inspect  --format "{{.State.Status}}" $QUADLET_CONTAINER_NAME
     is "$output" "running" "container should be started by systemd and hence be running"