Podman log file max size limit not working

[ElMassas]

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

/kind bug

Description

Upon setting a log-size-max as a general container config in /ect/containers/containers.conf, podman does not respect this limit and exceeds it.
I've tried this in 3 ways.

Steps to reproduce the issue:

First Way with general config

1. Create configuration file in /ect/containers/containers.conf with the following:

[containers]
log_size_max=80000

2. Restart Containers with podman restart {{container_id}}

3. Check if global configuration is set with: ps -ef | grep conmon | grep log-size-max

4. Check if file(ctr.log) size exceeds the given limit

Second way with podman commands

1. Start container with podman container run {{image}} --log-opt max-size=10mb

2. Check if file(ctr.log) size exceeds the given limit

With truncate

1. Truncate log file size with: truncate -s 10K {{path_to_file}}

Describe the results you received:

Every time the log file exceed the given limit, however, sometimes it did turn lower size and removed some logging information, but it would go right back to exceeding the max size limit.

Describe the results you expected:

Hoped to see the file remaining under the given limit.

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

Output of podman version:

Version:      3.0.1
API Version:  3.0.0
Go Version:   go1.15.2
Built:        Thu Jan  1 00:00:00 1970
OS/Arch:      linux/arm64

Output of podman info --debug:

(paste your output here)

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

host:
  arch: arm64
  buildahVersion: 1.19.4
  cgroupManager: systemd
  cgroupVersion: v1
  conmon:
    package: 'conmon: /usr/libexec/podman/conmon'
    path: /usr/libexec/podman/conmon
    version: 'conmon version 2.0.27, commit: '
  cpus: 2
  distribution:
    distribution: debian
    version: "10"
  eventLogger: journald
  hostname: name
  idMappings:
    gidmap: null
    uidmap: null
  kernel: 4.19.0-14-arm64
  linkmode: dynamic
  memFree: 723587072
  memTotal: 4058054656
  ociRuntime:
    name: crun
    package: 'crun: /usr/bin/crun'
    path: /usr/bin/crun
    version: |-
      crun version 0.18.1-7931a-dirty
      commit: 7931a1eab0590eff4041c1f74e2844b297c31cea
      spec: 1.0.0
      +SYSTEMD +SELINUX +APPARMOR +CAP +SECCOMP +EBPF +CRIU +YAJL
  os: linux
  remoteSocket:
    path: /run/podman/podman.sock
  security:
    apparmorEnabled: true
    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: false
    seccompEnabled: true
    selinuxEnabled: false
  slirp4netns:
    executable: ""
    package: ""
    version: ""
  swapFree: 0
  swapTotal: 0
  uptime: 2192h 37m 28.83s (Approximately 91.33 days)
registries:
  search:
  - docker.io
  - quay.io
store:
  configFile: /etc/containers/storage.conf
  containerStore:
    number: 1
    paused: 0
    running: 1
    stopped: 0
  graphDriverName: overlay
  graphOptions:
    overlay.mountopt: nodev,metacopy=on
  graphRoot: /var/lib/containers/storage
  graphStatus:
    Backing Filesystem: extfs
    Native Overlay Diff: "false"
    Supports d_type: "true"
    Using metacopy: "true"
  imageStore:
    number: 1
  runRoot: /run/containers/storage
  volumePath: /var/lib/containers/storage/volumes
version:
  APIVersion: 3.0.0
  Built: 0
  BuiltTime: Thu Jan  1 00:00:00 1970
  GitCommit: ""
  GoVersion: go1.15.2
  OsArch: linux/arm64
  Version: 3.0.1

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

Yes

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

AWS

[mheon]

Can you do a podman run --log-level=debug command with this field set in containers.conf (image and command don't matter, just need to run a container) and provide the full output? Need to see if it was passed on to Conmon

[umohnani8]

Took a look at this and this might be a conmon issue because we are passing down the log max size to conmon correctly

✗ podman --log-level debug container run -d --log-opt max-size=10b fedora echo "one two three four five six seven eight nine ten eleven twelve"
...
DEBU[0000] running conmon: /usr/bin/conmon               args="[--api-version 1 -c 897d41ec7b461bfb09ea998919dc080f9ca02d43cddc7f82abdd0
6f63d5df260 -u 897d41ec7b461bfb09ea998919dc080f9ca02d43cddc7f82abdd06f63d5df260 -r /usr/bin/crun -b /home/umohnani/.local/share/containe
rs/storage/overlay-containers/897d41ec7b461bfb09ea998919dc080f9ca02d43cddc7f82abdd06f63d5df260/userdata -p /run/user/1000/containers/ove
rlay-containers/897d41ec7b461bfb09ea998919dc080f9ca02d43cddc7f82abdd06f63d5df260/userdata/pidfile -n adoring_rubin --exit-dir /run/user/
1000/libpod/tmp/exits --full-attach -l k8s-file:/home/umohnani/.local/share/containers/storage/overlay-containers/897d41ec7b461bfb09ea99
8919dc080f9ca02d43cddc7f82abdd06f63d5df260/userdata/ctr.log --log-level debug --syslog --log-size-max 10 --conmon-pidfile /run/user/1000
/containers/overlay-containers/897d41ec7b461bfb09ea998919dc080f9ca02d43cddc7f82abdd06f63d5df260/userdata/conmon.pid --exit-command /usr/
local/bin/podman --exit-command-arg --root --exit-command-arg /home/umohnani/.local/share/containers/storage --exit-command-arg --runroot --exit-command-arg /run/user/1000/containers --exit-command-arg --log-level --exit-command-arg debug --exit-command-arg --cgroup-manager --exit-command-arg cgroupfs --exit-command-arg --tmpdir --exit-command-arg /run/user/1000/libpod/tmp --exit-command-arg --runtime --exit-command-arg crun --exit-command-arg --storage-driver --exit-command-arg overlay --exit-command-arg --storage-opt --exit-command-arg overlay.mount_program=/usr/bin/fuse-overlayfs --exit-command-arg --events-backend --exit-command-arg journald --exit-command-arg --syslog --exit-command-arg container --exit-command-arg cleanup --exit-command-arg 897d41ec7b461bfb09ea998919dc080f9ca02d43cddc7f82abdd06f63d5df260]"
DEBU[0000] Received: 1815667                             
INFO[0000] Got Conmon PID as 1815664                    
DEBU[0000] Created container 897d41ec7b461bfb09ea998919dc080f9ca02d43cddc7f82abdd06f63d5df260 in OCI runtime 
DEBU[0000] Starting container 897d41ec7b461bfb09ea998919dc080f9ca02d43cddc7f82abdd06f63d5df260 with command [echo one two three four five six seven eight nine ten eleven twelve] 
DEBU[0000] Started container 897d41ec7b461bfb09ea998919dc080f9ca02d43cddc7f82abdd06f63d5df260 
897d41ec7b461bfb09ea998919dc080f9ca02d43cddc7f82abdd06f63d5df260

And when I look at the size of the log file, it is bigger than the limit I set

✗ ls -lh /home/umohnani/.local/share/containers/storage/overlay-containers/897d41ec7b461bfb09ea998919dc080f9ca02
d43cddc7f82abdd06f63d5df260/userdata/ctr.log 
  rw-------  1  umohnani  umohnani   108 B    Wed Aug 18 16:11:24 2021    ctr.log

✗ cat /home/umohnani/.local/share/containers/storage/overlay-containers/897d41ec7b461bfb09ea998919dc080f9ca02d43
cddc7f82abdd06f63d5df260/userdata/ctr.log                            
2021-08-18T16:11:24.947533008-04:00 stdout F one two three four five six seven eight nine ten eleven twelve

@mheon wdyt?

[mheon]

We're sending --log-size-max 10 to Conmon. That looks correct?

@haircommander PTAL

[github-actions]

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

[haircommander]

Ok I did have a moment to look at this. this is still an issue, and is definitely the fault of conmon.

the time we take log size into account is incorrect. we currently first read the line length from an already read buffer, then check whether we would exceed by writing it, and rotate the buffer. The problem if we don't page out the actual output once we do so. Since we read 8192 bytes at a time (or fewer if we find a newline), the log length will always be between the max and max + 8192. I would consider this behavior buggy and worthy of fixing, though I can't currently commit to fixing it myself. I will move this to the conmon repo.

[zawadaa]

Hi! Some progress? I can rotate log by myself but I think that "ugly hack" ;-)