podman logging trace level request logs when log-level set to warn

[ferakpeter]

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

/kind bug

Description

we are running podman with the default logging level, which should be "warn" according to the documentation. we even tried setting log-level=error, but the same behaviour was observed: since upgrading to 3.4.1 (and same with 3.4.0) we receive a vast amount of request logging. The request log lines look like they should be seen only on TRACE level (according to this commit): deaf969

2021-11-05 12:02:51 | @ - - [05/Nov/2021:11:02:51 +0000] "GET /v1.0.0/libpod/info HTTP/1.1" 200 2505 "" "Go-http-client/1.1"
2021-11-05 12:02:50 | @ - - [05/Nov/2021:11:02:50 +0000] "GET /v1.0.0/libpod/info HTTP/1.1" 200 2506 "" "Go-http-client/1.1"
2021-11-05 12:02:48 | @ - - [05/Nov/2021:11:02:48 +0000] "GET /v1.0.0/libpod/info HTTP/1.1" 200 2504 "" "Go-http-client/1.1"
2021-11-05 12:02:43 | @ - - [05/Nov/2021:11:02:43 +0000] "GET /v1.0.0/libpod/info HTTP/1.1" 200 2505 "" "Go-http-client/1.1"
2021-11-05 12:02:27 | @ - - [05/Nov/2021:11:02:27 +0000] "GET /v1.0.0/libpod/info HTTP/1.1" 200 2506 "" "Go-http-client/1.1"
2021-11-05 12:02:21 | @ - - [05/Nov/2021:11:02:21 +0000] "GET /v1.0.0/libpod/info HTTP/1.1" 200 2504 "" "Go-http-client/1.1"

Steps to reproduce the issue:

1. run podman service with --log-level=error or (warn)

2. fetch endpoint GET /v1.0.0/libpod/info

3. check logs

Describe the results you received:
even on log-level=warn and log-level=error we received log messages that are intedened for log-level=trace

Describe the results you expected:
expected to not receive request logging on log-level=warn

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

Output of podman version:

Version:      3.4.1
API Version:  3.4.1
Go Version:   go1.16.8
Built:        Wed Oct 20 14:35:28 2021
OS/Arch:      linux/amd64

Output of podman info --debug:

host:
  arch: amd64
  buildahVersion: 1.23.1
  cgroupControllers:
  - cpuset
  - cpu
  - io
  - memory
  - hugetlb
  - pids
  - misc
  cgroupManager: systemd
  cgroupVersion: v2
  conmon:
    package: conmon-2.0.30-2.fc34.x86_64
    path: /usr/bin/conmon
    version: 'conmon version 2.0.30, commit: '
  cpus: 2
  distribution:
    distribution: fedora
    variant: coreos
    version: "34"
  eventLogger: journald
  hostname: ip-10-100-39-207
  idMappings:
    gidmap: null
    uidmap: null
  kernel: 5.14.14-200.fc34.x86_64
  linkmode: dynamic
  logDriver: k8s-file
  memFree: 261644288
  memTotal: 4054233088
  ociRuntime:
    name: crun
    package: crun-1.2-1.fc34.x86_64
    path: /usr/bin/crun
    version: |-
      crun version 1.2
      commit: 4f6c8e0583c679bfee6a899c05ac6b916022561b
      spec: 1.0.0
      +SYSTEMD +SELINUX +APPARMOR +CAP +SECCOMP +EBPF +CRIU +YAJL
  os: linux
  remoteSocket:
    exists: true
    path: /run/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: false
    seccompEnabled: true
    seccompProfilePath: /usr/share/containers/seccomp.json
    selinuxEnabled: true
  serviceIsRemote: false
  slirp4netns:
    executable: /usr/bin/slirp4netns
    package: slirp4netns-1.1.12-2.fc34.x86_64
    version: |-
      slirp4netns version 1.1.12
      commit: 7a104a101aa3278a2152351a082a6df71f57c9a3
      libslirp: 4.4.0
      SLIRP_CONFIG_VERSION_MAX: 3
      libseccomp: 2.5.0
  swapFree: 0
  swapTotal: 0
  uptime: 3h 23m 30.7s (Approximately 0.12 days)
plugins:
  log:
  - k8s-file
  - none
  - journald
  network:
  - bridge
  - macvlan
  volume:
  - local
registries:
  docker.io:
    Blocked: false
    Insecure: false
    Location: nexus.noenv.com
    MirrorByDigestOnly: false
    Mirrors: null
    Prefix: docker.io
  search:
  - docker.io
store:
  configFile: /etc/containers/storage.conf
  containerStore:
    number: 5
    paused: 0
    running: 5
    stopped: 0
  graphDriverName: overlay
  graphOptions:
    overlay.mountopt: nodev,metacopy=on
  graphRoot: /var/lib/containers/storage
  graphStatus:
    Backing Filesystem: xfs
    Native Overlay Diff: "false"
    Supports d_type: "true"
    Using metacopy: "true"
  imageStore:
    number: 5
  runRoot: /run/containers/storage
  volumePath: /var/lib/containers/storage/volumes
version:
  APIVersion: 3.4.1
  Built: 1634740528
  BuiltTime: Wed Oct 20 14:35:28 2021
  GitCommit: ""
  GoVersion: go1.16.8
  OsArch: linux/amd64
  Version: 3.4.1

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

podman-3.4.1-1.fc34.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/master/troubleshooting.md)

Yes

Additional environment details (AWS, VirtualBox, physical, etc.):
We use CoreOS to run the containers.

[rhatdan]

@jwhonce @baude PTAL

[jwhonce]

@ferakpeter Sorry for the confusion on this change. I agree this should not be logged at all levels but I think it is more important than TRACE. Would logging at INFO be acceptable for your solution? /cc

@rhatdan @baude

[rhatdan]

I think logging at info makes sense.