podman in systemd: improve logging

[vrothberg]

We need to find a way to easier integrate the container/pod logs into the systemd service and journalctl. At the moment, we run containers with --detached such that stderr and stdout don't show up in the service logs and can only be examined via podman logs.

I guess we need a combination of --log-driver=journald and --log-opt tag=... with the later maybe being set to %n (i.e., the unit/service name).

Cc: @mheon @rhatdan @goochjj @storrgie @lucab

[lucab]

Not sure if directly useful for podman, but journald has capabilities for distinguishing/isolating logs from (containerized) services:

• Unit identifier
• Machine ID
• Namespaces

The first has some known races on exit. The third is a recent feature. The second can be used in conjunction with machinectl (see an example on the defunct rkt docs).

[goochjj]

conmon with --log-driver=journald adds CONTAINER_ID, CONTAINER_NAME and CONTAINER_ID_FULL to every log coming from conmon and from the container's stderr and stdout... (and container_tag if specified) Note the CONTAINER_NAME wasn't logged until a merge 27 days ago in #6291 and a related pull in conmon.

The unit identifier should also be logged consistently now that the default is cgroups no-conmon - Journald will get the correct unit context from the cgroup of the process.

[goochjj]

conmon internals log via syslog() when --syslog is passed, which ends up on /dev/log, which gets logged to systemd under the correct unit, with any LogExtraFields in the unit file, but without CONTAINER_xxx metadata. (Because only the logs send to the journald socket have the additional CONTAINER_xxx fields)

So with log-driver journald
stderr + stdout -> journald socket, with CONTAINER_xxx metadata
internal logs -> syslog socket (when --syslog, which podman sets), without any CONTAINER_xxx metadata

I'm currently using an OCI hook to write CONTAINER_ID and CONTAINER_ID_FULL into /run/systemd/units/log-extra-fields:unitname, which adds those fields to the internal logs received via /dev/log. I'm also launching a busybox syslogd instance, that binds to /dev/log inside my container and forwards to the host's /dev/log, which also leverages the log extra fields, so everything gets logged right.

Except the journald driver, which nows receives every field twice, so I get CONTAINER_NAME [ "name", "name" ], but it still seems to work for filtering purposes.

Conmon could leverage writing directly to journald in utils.h so the conmon internal logs have more control, instead of writing to /dev/log they'd now write to the journald socket.

[andrewgdunn]

It'd be extremely nice to have verbose logging about the overall state of all subsystems related to operating the container (podman/conmon/slirp4netns/etc.) in the standard systemd journal. then the container logs itself being done via a tagging mechanism would be fine.

Unifying the logs would maybe be better for usability. It's not clear (until @goochjj starting posting) that I could find the logging via journalctl CONTAINER_NAME=<name>

[goochjj]

Any process spawned by podman would likely log via syslog, and be logged under the systemd unit that spawned podman.

I don't think I agree with your assertion - I'm not sure I agree that utility processes (i.e. podman, conmon, slirp4netns) should identify themselves with the container - they're outside the container. It feels to me like there should be a difference between "inside the container" logs and "outside the container" logs. (Which, based on how conmon is right now, is maintained - conmon logs go to syslog and are attached to the unit, but not the container ID and name, while stderr/stdout from the container ARE tagged properly)

I don't quite know how to accommodate that - by leveraging LogExtraFields I'm attaching that metadata to anything subordinate to the unit.

[andrewgdunn]

I don't think I agree with your assertion - I'm not sure I agree that utility processes (i.e. podman, conmon, slirp4netns) should identify themselves with the container - they're outside the container. It feels to me like there should be a difference between "inside the container" logs and "outside the container" logs. (Which, based on how conmon is right now, is maintained - conmon logs go to syslog and are attached to the unit, but not the container ID and name, while stderr/stdout from the container ARE tagged properly)

I agree with you, consistency and transparency of how one has awareness of those two logging streams would really help.

[github-actions]

A friendly reminder that this issue had no activity for 30 days.

[rhatdan]

@vrothberg @goochjj Any progress on this?

[goochjj]

We probably need to better flesh out exactly what desired state is before this will be actionable

[vrothberg]

I concur. Let's put it on our roadmap. I won't find time this week to think this through.

[vrothberg]

I concur. Let's put it on our roadmap. I won't find time this week to think this through.

I created a card to our internal pipeline to make sure we can tackle it in the future and discuss upstream here what we want and need.

[polendri]

In case the perspective of an ignorant end user is at all helpful here: my expectation when I fired up containers via systemd (generated via podman generate systemd) was to see roughly the same output in journalctl as what podman logs shows. Other logs (e.g. slirp4netns) feels like an implementation detail that I wouldn't want to see unless opting in via config or something.

[yangm97]

It seems like generating units for containers created with --log-driver=journald (or changing the ExecStart line to include said flag) is already enough to get journalctl and systemctl to display the container logs associated with that unit. I haven't tested with pod units though.

Assuming pod units are as good, looks like we only need to add this flag to the unit template in order to close this issue?

[github-actions]

A friendly reminder that this issue had no activity for 30 days.

[RLovelett]

In case the perspective of an ignorant end user is at all helpful here: I tried @yangm97's suggestion and that gives me more or less what I was looking for.

[acastong]

Since the play kube command does not have a --log-driver option, this remains a problem for containers created through this command. A --log-driver option to play kube would allow @yangm97's suggestion to work for pods too.

[rhatdan]

Sounds good, would someone from the community want to open a PR to add this feature?

[andylibrian]

If no one is working on this already, let me take it

/assign

[rhatdan]

@andylibrian You got it, thanks.

[github-actions]

A friendly reminder that this issue had no activity for 30 days.

[andylibrian]

I think this is completed now:

• Generating systemd units for containers created with --log-driver=journald works as expected, logging to journald
• --log-driver arg has been added to play kube

[rhatdan]

Ok I will close.

[maclean]

With the default --log-driver option to podman run, every keystroke is logged to systemd

This even applies to things like pinentry keystrokes. Running pinentry-curses by hand In a Ubuntu Bionic image, on a Fedora 35 host, the passphrase is logged:

pinentry-curses
GETPIN
test
ctrl-D

The following is logged, as seen with journalctl -f:
Jan 09 11:42:55 gmlat conmon[314188]: pinentry-curses > /dev/null
Jan 09 11:42:57 gmlat conmon[314188]:
Jan 09 11:43:00 gmlat conmon[314188]: G
Jan 09 11:43:00 gmlat conmon[314188]: E
Jan 09 11:43:00 gmlat conmon[314188]: T
Jan 09 11:43:01 gmlat conmon[314188]: P
Jan 09 11:43:01 gmlat conmon[314188]: I
Jan 09 11:43:01 gmlat conmon[314188]: N
Jan 09 11:43:02 gmlat conmon[314188]:
Jan 09 11:43:03 gmlat conmon[314188]: t
Jan 09 11:43:04 gmlat conmon[314188]: e
Jan 09 11:43:04 gmlat conmon[314188]: s
Jan 09 11:43:04 gmlat conmon[314188]: t
Jan 09 11:43:05 gmlat conmon[314188]:
Jan 09 11:43:07 gmlat conmon[314188]: [24B blob data]

If I sign something in the container with gpg2, and pinentry is run to fetch the passphrase, the following is logged:
Jan 09 11:46:21 gmlat conmon[314188]: [4B blob data]
Jan 09 11:46:21 gmlat conmon[314188]: [4B blob data]
Jan 09 11:46:21 gmlat conmon[314188]: [4B blob data]
Jan 09 11:46:21 gmlat conmon[314188]: [4B blob data]

Just 4 byte blobs are reported and not the actual keystrokes, but I would guess that this is a side effect of the logger combining output and not the result of security.

Setting --log-driver=none to podman run turns off the logging.

For users that are not aware that keystrokes are logged, this is a security vulnerability.

[travier]

@maclean Please open a new issue to help us track it.