From 1590c7bf425f195ede66cefd4d64a109cbb45ddb Mon Sep 17 00:00:00 2001 From: Paul Holzinger Date: Tue, 14 Feb 2023 15:59:10 +0100 Subject: [PATCH 1/3] podman logs: read journald with passthrough The passthrough driver is designed for use in systemd units. By default we can expect systemd to log the output on journald unless the unit sets differen StandardOutput/StandardError settings. At the moment podman logs just errors out when the passthrough driver is used. With this change we will read the journald for the unit messages. The logic is actually very similar to the existing one, we just need to change the filter. We now filter by SYSTEMD_UNIT wich equals to the contianer cgroup, this allows us the actually filter on a per contianer basis even when multiple contianers are started in the same unit, i.e. via podman-kube@.service. The only difference a user will see is that journald will merge stdout/err into one stream so we loose the separation there. Signed-off-by: Paul Holzinger --- libpod/container_log.go | 7 ++++++- libpod/container_log_linux.go | 27 +++++++++++++++++++++++---- libpod/container_log_unsupported.go | 2 +- test/system/250-systemd.bats | 12 ++++++++++-- 4 files changed, 40 insertions(+), 8 deletions(-) diff --git a/libpod/container_log.go b/libpod/container_log.go index e33ede5dd1..680adfd389 100644 --- a/libpod/container_log.go +++ b/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 _, ok := c.config.Labels[systemdDefine.EnvVariable]; ok { + return c.readFromJournal(ctx, options, logChannel, colorID, true) + } 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, false) case define.JSONLogging: // TODO provide a separate implementation of this when Conmon // has support. diff --git a/libpod/container_log_linux.go b/libpod/container_log_linux.go index dc305fabfd..1e4e5c198a 100644 --- a/libpod/container_log_linux.go +++ b/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, isPassthrough bool) 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,28 @@ 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 isPassthrough { + // 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" + } + // FIXME: It looks like it is hardcoded to libpod-ID.scope but I am not + // sure were we set this with all the different cgroup modes??? + match = sdjournal.Match{Field: unitTypeName, Value: "libpod-" + c.ID() + ".scope"} + 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) } diff --git a/libpod/container_log_unsupported.go b/libpod/container_log_unsupported.go index cdce820b4f..736378a6b7 100644 --- a/libpod/container_log_unsupported.go +++ b/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, _ bool) error { return fmt.Errorf("journald logging only enabled with systemd on linux: %w", define.ErrOSNotSupported) } diff --git a/test/system/250-systemd.bats b/test/system/250-systemd.bats index dad551b007..8fab04bb29 100644 --- a/test/system/250-systemd.bats +++ b/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,6 +422,10 @@ 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 # Add a simple `auto-update --dry-run` test here to avoid too much redundancy From d7e96536ee3ead3147cf4f69b8ea408e0d35b49b Mon Sep 17 00:00:00 2001 From: Paul Holzinger Date: Tue, 14 Feb 2023 16:39:14 +0100 Subject: [PATCH 2/3] 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 --- libpod/container_log_linux.go | 94 +++++++++-------------------------- libpod/logs/log.go | 30 ----------- test/system/250-systemd.bats | 6 +++ 3 files changed, 29 insertions(+), 101 deletions(-) diff --git a/libpod/container_log_linux.go b/libpod/container_log_linux.go index 1e4e5c198a..7d1e360b2b 100644 --- a/libpod/container_log_linux.go +++ b/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 - } - - 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 journalToLogLine(entry *sdjournal.JournalEntry) (*logs.LogLine, error) { + line := &logs.LogLine{} -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 } diff --git a/libpod/logs/log.go b/libpod/logs/log.go index b053d91e18..552f0515a4 100644 --- a/libpod/logs/log.go +++ b/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 diff --git a/test/system/250-systemd.bats b/test/system/250-systemd.bats index 8fab04bb29..8c3064f9ef 100644 --- a/test/system/250-systemd.bats +++ b/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}}" From 79a05ca2b4394f3c16a00f4511e387d6b92f1557 Mon Sep 17 00:00:00 2001 From: Paul Holzinger Date: Wed, 15 Feb 2023 19:23:58 +0100 Subject: [PATCH 3/3] podman logs passthrough driver support --cgroups=split When run with --cgroups=split mode (e.g. quadlet) we do not use the a separate cgroup for the container and just run in the unit cgroup. When we filter logs we thus must match the unit name. Added a small test to the quadlet test to make sure it will work. Signed-off-by: Paul Holzinger --- libpod/container_log.go | 6 +++--- libpod/container_log_linux.go | 17 ++++++++++++----- libpod/container_log_unsupported.go | 2 +- test/system/252-quadlet.bats | 6 +++++- 4 files changed, 21 insertions(+), 10 deletions(-) diff --git a/libpod/container_log.go b/libpod/container_log.go index 680adfd389..3ae0c70e84 100644 --- a/libpod/container_log.go +++ b/libpod/container_log.go @@ -38,14 +38,14 @@ func (c *Container) ReadLog(ctx context.Context, options *logs.LogOptions, logCh switch c.LogDriver() { case define.PassthroughLogging: // if running under systemd fallback to a more native journald reading - if _, ok := c.config.Labels[systemdDefine.EnvVariable]; ok { - return c.readFromJournal(ctx, options, logChannel, colorID, true) + 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, false) + return c.readFromJournal(ctx, options, logChannel, colorID, "") case define.JSONLogging: // TODO provide a separate implementation of this when Conmon // has support. diff --git a/libpod/container_log_linux.go b/libpod/container_log_linux.go index 7d1e360b2b..a708ad46da 100644 --- a/libpod/container_log_linux.go +++ b/libpod/container_log_linux.go @@ -32,7 +32,7 @@ func init() { } func (c *Container) readFromJournal(ctx context.Context, options *logs.LogOptions, - logChannel chan *logs.LogLine, colorID int64, isPassthrough bool) error { + 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" { @@ -69,7 +69,7 @@ func (c *Container) readFromJournal(ctx context.Context, options *logs.LogOption return fmt.Errorf("adding filter disjunction to journald logger: %w", err) } - if isPassthrough { + 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. @@ -77,9 +77,16 @@ func (c *Container) readFromJournal(ctx context.Context, options *logs.LogOption if rootless.IsRootless() { unitTypeName = "_SYSTEMD_USER_UNIT" } - // FIXME: It looks like it is hardcoded to libpod-ID.scope but I am not - // sure were we set this with all the different cgroup modes??? - match = sdjournal.Match{Field: unitTypeName, Value: "libpod-" + c.ID() + ".scope"} + // By default we will have our own systemd cgroup with the name libpod-.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) } diff --git a/libpod/container_log_unsupported.go b/libpod/container_log_unsupported.go index 736378a6b7..d524561f42 100644 --- a/libpod/container_log_unsupported.go +++ b/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, _ int64, _ bool) 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) } diff --git a/test/system/252-quadlet.bats b/test/system/252-quadlet.bats index 12551c73b0..03b6497d7d 100644 --- a/test/system/252-quadlet.bats +++ b/test/system/252-quadlet.bats @@ -141,7 +141,7 @@ function remove_secret() { cat > $quadlet_file <