RFE: Use --log-driver none when not running --detached

[har7an]

Is this a BUG REPORT or FEATURE REQUEST? (leave only one on its own line)

/kind feature

Description

When running heavy container workloads, especially tools that produce a lot of output on stdout, the system can freeze entirely. I noticed this first when running bees from a container, I have meanwhile reported it to systemd since I assume it is a bug there: systemd/systemd#23804

This seems to happen when the journal grows beyond a certain size (?). The freeze comes creeping, but once I realize it is happening I cannot do anything against it any longer.

I propose that the --log-driver setting is automatically set to none (from the default journald) when a container is run with the -i/--interactive without the -d/--detach CLI argument. The rationale for this is that any container running interactively not running detached will most likely run in the foreground (unless being sent to the background via Ctrl+P, Ctrl+Q), hence there is no need to preserve all of its output in the system journal. I don't expect bash to pipe a recording of all my terminal sessions to the journal either.

Steps to reproduce the issue:

# On the host
$ podman run --rm -it --log-driver journald registry.fedoraproject.org/fedora:36
# In the container
$ while true; do ls -lR /; sleep 1; done

Let it run for a while. You can get a copy of the whole output when calling journalctl -f in another terminal.

Describe the results you received:

The system freezes after about 95 minutes. On the next boot I find that my journal is multiple gigabytes in size and contains many million lines of text.

Describe the results you expected:

The system operates as usual. The output of the container commands isn't piped to the journal.

Additional information you deem important (e.g. issue happens only occasionally):

On my system the issue is reproducible very reliably. It first occured about 3 weeks ago when I started experimenting with bees. Yesterday it happened again after running a lot of interactive containers to replace CLI tools I use infrequently.

Output of podman version:

Client:       Podman Engine
Version:      4.1.0
API Version:  4.1.0
Go Version:   go1.18.2
Built:        Mon May 30 18:03:28 2022
OS/Arch:      linux/amd64

Output of podman info --debug:

host:
  arch: amd64
  buildahVersion: 1.26.1
  cgroupControllers:
  - memory
  - pids
  cgroupManager: systemd
  cgroupVersion: v2
  conmon:
    package: conmon-2.1.0-2.fc36.x86_64
    path: /usr/bin/conmon
    version: 'conmon version 2.1.0, commit: '
  cpuUtilization:
    idlePercent: 98.39
    systemPercent: 0.4
    userPercent: 1.21
  cpus: 12
  distribution:
    distribution: fedora
    variant: silverblue
    version: "36"
  eventLogger: journald
  hostname: sttng
  idMappings:
    gidmap:
    - container_id: 0
      host_id: 1000
      size: 1
    - container_id: 1
      host_id: 100000
      size: 65536
    uidmap:
    - container_id: 0
      host_id: 1000
      size: 1
    - container_id: 1
      host_id: 100000
      size: 65536
  kernel: 5.18.5-200.fc36.x86_64
  linkmode: dynamic
  logDriver: journald
  memFree: 9263976448
  memTotal: 16591605760
  networkBackend: netavark
  ociRuntime:
    name: crun
    package: crun-1.4.5-1.fc36.x86_64
    path: /usr/bin/crun
    version: |-
      crun version 1.4.5
      commit: c381048530aa750495cf502ddb7181f2ded5b400
      spec: 1.0.0
      +SYSTEMD +SELINUX +APPARMOR +CAP +SECCOMP +EBPF +CRIU +YAJL
  os: linux
  remoteSocket:
    path: /run/user/1000/podman/podman.sock
  security:
    apparmorEnabled: false
    capabilities: CAP_CHOWN,CAP_DAC_OVERRIDE,CAP_FOWNER,CAP_FSETID,CAP_KILL,CAP_NET_BIND_SERVICE,CAP_SETFCAP,CAP_SETGID,CAP_SETPCAP,CAP_SETUID,CAP_SYS_CHROOT
    rootless: true
    seccompEnabled: true
    seccompProfilePath: /usr/share/containers/seccomp.json
    selinuxEnabled: true
  serviceIsRemote: false
  slirp4netns:
    executable: /usr/bin/slirp4netns
    package: slirp4netns-1.2.0-0.2.beta.0.fc36.x86_64
    version: |-
      slirp4netns version 1.2.0-beta.0
      commit: 477db14a24ff1a3de3a705e51ca2c4c1fe3dda64
      libslirp: 4.6.1
      SLIRP_CONFIG_VERSION_MAX: 3
      libseccomp: 2.5.3
  swapFree: 8589930496
  swapTotal: 8589930496
  uptime: 36m 1.16s
plugins:
  log:
  - k8s-file
  - none
  - passthrough
  - journald
  network:
  - bridge
  - macvlan
  volume:
  - local
registries:
  search:
  - registry.fedoraproject.org
  - registry.access.redhat.com
  - docker.io
  - quay.io
store:
  configFile: /var/home/ahartmann/.config/containers/storage.conf
  containerStore:
    number: 8
    paused: 0
    running: 0
    stopped: 8
  graphDriverName: overlay
  graphOptions: {}
  graphRoot: /var/home/ahartmann/.local/share/containers/storage
  graphRootAllocated: 498387124224
  graphRootUsed: 84117934080
  graphStatus:
    Backing Filesystem: btrfs
    Native Overlay Diff: "true"
    Supports d_type: "true"
    Using metacopy: "false"
  imageCopyTmpDir: /var/tmp
  imageStore:
    number: 44
  runRoot: /run/user/1000/containers
  volumePath: /var/home/ahartmann/.local/share/containers/storage/volumes
version:
  APIVersion: 4.1.0
  Built: 1653926608
  BuiltTime: Mon May 30 18:03:28 2022
  GitCommit: ""
  GoVersion: go1.18.2
  Os: linux
  OsArch: linux/amd64
  Version: 4.1.0

Package info (e.g. output of rpm -q podman or apt list podman):

podman-4.1.0-8.fc36.x86_64

Have you tested with the latest version of Podman and have you checked the Podman Troubleshooting Guide? (https://github.com/containers/podman/blob/main/troubleshooting.md)

• Test with latest version: No

Additional environment details (AWS, VirtualBox, physical, etc.):

Host is a Fedora 36 Silverblue (Version 36.20220617.0)

[Luap99]

--interactive does not tell if the process is run in the foreground or not, --detach is used for that.

The main problem is that without logs podman logs becomes non functional for this container. I don't have strong about about this request but we should not change this behaviour until the next major version IMO.

[har7an]

--interactive does not tell if the process is run in the foreground or not, --detach is used for that.

Whoops, seems I misunderstood that. You're right, it says so in the docs as well. I have updated the issue description.

The main problem is that without logs podman logs becomes non functional for this container.

That's an interesting point, I wasn't aware of that.

[har7an]

How is the log driver in podman implemented? I.e. when I run a container interactively and then detach it via Ctrl+p,Ctrl+q, would it be possible to change the log driver dynamically (Or better: Add a new log driver that does this)? I think that would solve the problem about podman logs. Of course it would only log what the user hasn't seen in the interactive session before he detached the container. Would that hurt anyones use case?

[mheon]

That's still a breaking change. The expectation is that podman logs shows all logs; it lets you look back and identify everything that a container has done. I am strongly against this change; I don't see any significant benefit.

If we're seeing issues with journal performance, we can look into fixes for that (or, potentially, improve the file driver to make it a more viable alternative). Disabling logging should not be the solution.

[har7an]

it lets you look back and identify everything that a container has done.

Is there really an application for this? Do people have use cases where they run containers interactively and still resort to podman logs to find out what their tools have done? If that is the case then please feel free to close this issue immediately, but it's the first time I hear of this. I wouldn't want to disable logging entirely, but just when a container isn't detached.

Can I at least change the default behavior on my machine? I see that the man page for containers.conf includes a log_driver setting, but that doesn't mention "none" as an option:

log_driver="k8s-file"

Logging driver for the container. Available options: k8s-file and journald.

Is this an oversight?

Also that doesn't really solve the problem: If I change the default to --log-driver=none I'll have to actively think about enabling the logs for containers I run detached. If I leave it as is I'll have to actively remember disabling the logs when running interactive containers, or otherwise I run the risk of flooding my journal and crashing my system again. It's not the sort of obvious oversight such as when I forget to relabel my volume mounts or similar.

Would it maybe be possible to add a new "dynamic" log driver, but not use it as default then?

[mheon]

Yes, none will work for log_driver in containers.conf.

Again, a dynamic driver sounds like a hack around bad behavior; let's just fix the existing drivers to behave sanely.

[har7an]

Yes, none will work for log_driver in containers.conf.

Thanks for clarifying. Where can I file a PR to add this to the manpage/config file?

a dynamic driver sounds like a hack around bad behavior

I was arguing more out of a user-friendliness perspective. Opening your journalctl -b and finding it is multiple million lines long is a shocking discovery on a system with an uptime < 2 hours.

let's just fix the existing drivers to behave sanely

I agree with that, see the issue I raised against systemd. I was just thinking maybe it'd be worthwhile discussing this proposal here not as a workaround but maybe a new default behavior.

You have made it clear, however, that from your point of view this is very unlikely to happen. I'll leave this open in case someone else wants to state their opinions on this. Us two arguing isn't really representative of the broader podman user base I guess. Feel free to close this issue if you see no point in further discussing it.

[rhatdan]

Converting to a discussion.

[rhatdan]

@mheon what do you think about adding a flag --log-opt detached-nolog
Or something like this. Then users could set this by default if they wanted this behavior.

[mheon]

I'm not strictly opposed, but this all seems like a hack around the fact that journald logging is misbehaving when containers write large amounts of logs. IMO, we'd be better off either addressing that (not sure how yet; maybe add logging backpressure to slow the app when we're spamming the journal too much?) or improving rotation on the file driver instead so we can recommend that.

[rhatdan]

I am not sure that both wouldn't be nice. Backpressure would slow the container down, and in the case that I don't care about foreground output being logged, I would rather have the output dropped then slow down the container.

[har7an]

maybe add logging backpressure to slow the app when we're spamming the journal too much?

I don't think that's the right approach, because I think that systemd has its own mechanisms for handling message flooding. At least when I ls -lR / repeatedly, the log will sometimes tell me that multiple hundred thousand lines of similar logs have been skipped. The man page for journald says this:

RateLimitIntervalSec=, RateLimitBurst=
    Configures the rate limiting that is applied to all messages generated on the system. If,
    in the time interval defined by RateLimitIntervalSec=, more messages than specified in
    RateLimitBurst= are logged by a service, all further messages within the interval are
    dropped until the interval is over.

Reading this I'm not even sure whether the journal would tell us when we write too many messages. But I'm no expert on systemd journal.

[Hi-Angel]

Hello, I've read through the discussion and am quite confused on the outcomes.

So, @har7an points out that running a podman run should not log by default. The reason is unrelated to misbehavior of systemd or whatever: the logging by default is simply pointless. No one would expect every command that is typed into podman run to be logged elsewhere besides the terminal scrollback, and so the logging is usually covered by external means.

We are using Podman in CI, and needless to say I was very surprised to see that every build with thousands of lines gets written to our journal for no reason.

@rhatdan then converted the issue to discussion, for reasons to me unclear.

Then later discussion went on discussing systemd nuances, which I don't see how is relevant to the problem regarding the bad defaults.

So, what about the original problem? While on it, should perhaps this be converted back to an issue?

[mheon]

We do not have intention of changing the defaults. There is a general expectation that the podman logs command works when Podman is used as a CLI tool. I recognize that CI usage of Podman does not require this, but we have to work on other systems too. Is changing containers.conf to default log_driver to none in your CI images not an option?

[voidpointertonull]

That's rather unfortunate because the default is really unexpected, outside of podman I don't have anything spamming into the system log when just running as-is.
The unexpected logging is also a security problem as information expected to be temporary gets permanently stored without any sort of opt-in or notice, and what's even worse is that rootless container logs go into the system log too, so while there's a push for separately encrypted homes, Podman goes in the other direction and makes user information available outside of what's usually a protected environment.

The podman logs twist is a bit interesting because that's broken anyway in most cases when terminals are actually used in an interactive way. Apparently podman logs just excludes data it can't handle while systemd shows a whole lot of [30B blob data] messages even for lines it could show, so logging of interactive terminals is of questionable usefulness best case, and dangerous due to the output skipping in worst case.

Then as the default is desired to be changed to get behavior to be in line with practically all other programs, another odd quirk tends to come up which is the apparently conditional parsing of $HOME/.config/containers/containers.conf . I believe this could be a rootful/rootless difference, but in environments where this doesn't really matter and log_driver = "none" is the only desired config change, this was another odd surprise.
This one is more understandable, but it was odd to need a conditional check to see if deploying as root as if it's a homeless (hah) user.

Overall, the podman logs problem is understandable, but to summarize:

• The system log getting spammed is an unexpected side effect, not a requirement of that working
• Even rootless container output getting spammed to the system log really can't be explained as anything else but an oversight
• Interactive terminal logging is not just unexpected, it's also broken because terminals were never meant to be logged which is why a lot of programs tend to have non-interactive modes suitable for logging

[mheon]

On podman logs not working properly - are you referring to terminal applications using control characters (things like top) or to something else? If this is programs like top, that isn't a reason not to log - we certainly can't print everything the container is doing, but we can at least provide a record of commands run in it and errors that might occur. It's a valuable debugging tool for developing inside a container. I do not see us disabling that by default. If you're not referring to that, you may well have found a bug - details would be appreciated.

On the conditional parsing of containers.conf - that is indeed a root/rootless difference. Root only reads /usr/share/containers/containers.conf and /etc/containers/containers.conf. I was going to suggest that as a possible RFE, but on reading the code, it sounds like we've already changed things to read from $HOME for root as well as of 5.0, so it's already fixed.

Finally: we do support a file-backed log driver, which was previously the default. We swapped it out for journald for, among other reasons, its superior integration with systemd with Podman is run within a systemd unit (e.g. podman generate systemd or Quadlet). We recognize that the default is definitely not good for some use-cases (many rootless users all logging to the journal, for example), but it does work well for others, and it's just a default that can be easily changed by containers.conf.

[Hi-Angel]

On podman logs not working properly - are you referring to terminal applications using control characters (things like top) or to something else? If this is programs like top, that isn't a reason not to log - we certainly can't print everything the container is doing, but we can at least provide a record of commands run in it and errors that might occur. It's a valuable debugging tool for developing inside a container.

Debugging tools are not meant to be enabled by default. Are you running Linux kernel with all debugging prints enabled? Are you having "vulkan validation layers" enabled in every game you run? Do you by any chance run every command line application with --verbose flag and WINE with WINEDEBUG=+all?

[voidpointertonull]

are you referring to terminal applications using control characters (things like top)

Referring to this case.
Typically other tools record (some?) control characters too so the resulting log file is not straight-forward to process, while Podman seems to just ignore I guess lines with control characters as for example watch -n1 echo test resulted in just no output added to podman logs, making it quite unreliable, therefore I don't really see the point.

I'm not saying that logging isn't valuable, just like others I'm pointing it out that it's unexpected when it's done by default, especially for interactive terminals. Think of how surprised people would get if their terminal emulators would start logging too, especially if user commands would get into the system log on a multi-user setup.

it sounds like we've already changed things to read from $HOME for root as well as of 5.0

Looking forward to this, the more seamless logic is, the better.
Really just mentioned it because I'm happy with all the other defaults, logging is the only weird oddity, and I like to minimize the scope of changes, so even when deploying as root, it would be still great to leave the global config alone so no other user would be affected.

Finally: we do support a file-backed log driver, which was previously the default. We swapped it out for journald

Figured this was the likely case, but there are some really undesirable resulting quirks coming from that. Some related brainstorming:

• The mentioned problem of scope creep in the form of an excessive amount of user data escaping into not just a significantly broader scope, but even ending up on non-volatile storage was never a justified sacrifice, it's just really a security concern
• While most people likely no longer care at this point, the surprise non-volatile I/O is really not welcome either. I tend to run a lot of "throwaway" containers with -it --rm, and if I wouldn't disable logging, I would have a ton of pointless writes which would only wear down flash memory without ever being read. Sure, the flags don't have any logging implications documented, but the user intention is quite obviously an interactive container which doesn't leave anything after behind itself aside from cache and I/O explicitly allowed to escape.
• I found systemd/journald a bit clunky when it comes to these kind of issues, but I've recently started using namespacing for a kind of similar issue. Ironically I had kind of the opposite issue, I wanted the output to be available when running journalctl normally, but namespaces are separated, so it may be just the right solution here.

As an example for the separate namespace, I have /etc/systemd/[email protected] containing:

[Journal]
Storage=volatile

Service files where long term logging is not desired, but spamming is expected contain:

[Service]
LogNamespace=volatile

Then while journalctl as-is doesn't show the output (actually desired here), journalctl --namespace=volatile shows the log as expected, and (theoretically) nothing is stored on non-volatile storage devices.

it does work well for others, and it's just a default that can be easily changed

The problem is the unexpected behavior with some quite negative consequences.
The vast majority of programs have an opt-in approach for logging, often not even supporting it directly but just expecting stdout to be captured. I believe that logging alone is also rarely desired, in most cases it goes hand in hand with other requirements which makes a service manager reasonable to use.
So I have a bit of difficulty imagining who could be a fan of logging everything even rootless containers into the system log by default. If I want logging, then with almost no exception I want a systemd service in general, and when I just run a "bare" command, I get surprised by logging by default all the time.

[Luap99]

Changing the default just so is not an option as it must be considered a breaking change, it is a long standing behavior so it is possible that there are users relying on it. Sure it may not be what you expect but that does not mean that all users think the same.

I agree with your overall points but having different behaviors for logging when attched/detached also requires extra documentation and can be confusing as we now have two different logging defaults that depend on another option (--detach). So something like using --log-driver none as default and --log-driver journald when running with detach is possible but not straight forward either, the user can overwrite the default with --log-driver but now what is about the log_driver containers.conf option? If it is set does it effect both the attached/detached variant? What if users what to have different defaults for both cases, so this likely means to options but then again changing the meaning of an option would be breaking change. These are problems that require actual engineering work and agreements on how this should work.

Attached/Detached is not so clear defined as well, users can attach any time via podman attach or detach via the ctrl+P, ctrl+Q key combo, so what should the log driver do? Should it just start/stop logging then? How would it know what log driver to use? Either way as logging is done by conmon (or conmon-rs in the future) it would need to be implemented there and doing it would neither be intuitive nor simple when podman logs just start/stops in the middle.

So are you willing to do that work? Write a proper design on how to implement this and get approval for the majority of the maintainers, you can attend over Community Cabal meetings to talk to us if you like to discus such things. Of course written form here on github also works.

The fact is that it is a old default (I think docker does the same) and apart from the few voices here it doesn't seem to cause issues for most users I would assume so it was never really something we considered.