journald logs: simplify entry parsing

It makes little sense to create a log line string from the entry just to
parse it again into a LogLine. We have the typed fields so we can
assemble the logLine direclty, this makes things simpler and more
efficient.

Also entries from the passthrough driver do not use the CONTAINER_ID_FULL
field, instead we can just access c.ID() directly.

Signed-off-by: Paul Holzinger <pholzing@redhat.com>

libpod/container_log_linux.go

@@ -181,26 +181,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()
 			}
@@ -215,76 +206,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/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

@@ -428,6 +428,12 @@ EOF
 $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}}"