Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

default logging to systemd is too verbose #12788

Closed
maclean opened this issue Jan 10, 2022 · 7 comments
Closed

default logging to systemd is too verbose #12788

maclean opened this issue Jan 10, 2022 · 7 comments
Labels
kind/bug Categorizes issue or PR as related to a bug. locked - please file new issue/PR Assist humans wanting to comment on an old issue or PR with locked comments.

Comments

@maclean
Copy link

maclean commented Jan 10, 2022

/kind bug

Description
With the default --log-driver option to podman run, every keystroke is logged to systemd. I can't imagine that this satisfies the normal use case.

Steps to reproduce the issue:

Running a basic busybox image interactively, and simply typing "exit":

  1. podman run -i --tty busybox

  2. journalctl -f

Describe the results you received:
Jan 10 07:40:25 gmlat podman[364027]: 2022-01-10 07:40:25.844830325 -0700 MST m=+0.063144246 image pull busybox
Jan 10 07:40:25 gmlat podman[364027]:
Jan 10 07:40:26 gmlat podman[364027]: 2022-01-10 07:40:26.046021734 -0700 MST m=+0.264335676 container create 034e900e67e6203b54c486a24bc4685914503f7a69006809d381e17d46bec61f (image=docker.io/library/busybox:latest, name=busy_meitner)
Jan 10 07:40:26 gmlat podman[364027]: 2022-01-10 07:40:26.212661989 -0700 MST m=+0.430975918 container init 034e900e67e6203b54c486a24bc4685914503f7a69006809d381e17d46bec61f (image=docker.io/library/busybox:latest, name=busy_meitner)
Jan 10 07:40:26 gmlat conmon[364064]: / #
Jan 10 07:40:26 gmlat podman[364027]: 2022-01-10 07:40:26.270991806 -0700 MST m=+0.489305752 container start 034e900e67e6203b54c486a24bc4685914503f7a69006809d381e17d46bec61f (image=docker.io/library/busybox:latest, name=busy_meitner)
Jan 10 07:40:26 gmlat podman[364027]: 2022-01-10 07:40:26.271288026 -0700 MST m=+0.489602040 container attach 034e900e67e6203b54c486a24bc4685914503f7a69006809d381e17d46bec61f (image=docker.io/library/busybox:latest, name=busy_meitner)
Jan 10 07:40:30 gmlat conmon[364064]: e
Jan 10 07:40:30 gmlat conmon[364064]: x
Jan 10 07:40:30 gmlat conmon[364064]: i
Jan 10 07:40:30 gmlat conmon[364064]: t
Jan 10 07:40:31 gmlat conmon[364064]:
Jan 10 07:40:31 gmlat podman[364027]: 2022-01-10 07:40:31.304799912 -0700 MST m=+5.523113905 container died 034e900e67e6203b54c486a24bc4685914503f7a69006809d381e17d46bec61f (image=docker.io/library/busybox:latest, name=busy_meitner)
Jan 10 07:40:32 gmlat podman[364071]: 2022-01-10 07:40:32.137566439 -0700 MST m=+0.828313341 container cleanup 034e900e67e6203b54c486a24bc4685914503f7a69006809d381e17d46bec61f (image=docker.io/library/busybox:latest, name=busy_meitner)

Describe the results you expected:
Less verbose logging in the default case. Setting --log-driver=none to podman run turns off logging. I believe more control over logging is needed, and that the default log level should not log keystrokes.

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

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

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 for efficiency and not the result of security precautions. In any case the number of characters in the passphrase is logged.

Output of podman version:

podman version 3.4.4

Output of podman info --debug:

host:
  arch: amd64
  buildahVersion: 1.23.1
  cgroupControllers: []
  cgroupManager: cgroupfs
  cgroupVersion: v1
  conmon:
    package: conmon-2.0.30-2.fc35.x86_64
    path: /usr/bin/conmon
    version: 'conmon version 2.0.30, commit: '
  cpus: 2
  distribution:
    distribution: fedora
    variant: workstation
    version: "35"
  eventLogger: journald
  hostname: gmlat
  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.15.12-200.fc35.x86_64
  linkmode: dynamic
  logDriver: journald
  memFree: 1171738624
  memTotal: 12289724416
  ociRuntime:
    name: crun
    package: crun-1.4-1.fc35.x86_64
    path: /usr/bin/crun
    version: |-
      crun version 1.4
      commit: 3daded072ef008ef0840e8eccb0b52a7efbd165d
      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.1.12-2.fc35.x86_64
    version: |-
      slirp4netns version 1.1.12
      commit: 7a104a101aa3278a2152351a082a6df71f57c9a3
      libslirp: 4.6.1
      SLIRP_CONFIG_VERSION_MAX: 3
      libseccomp: 2.5.3
  swapFree: 11862269952
  swapTotal: 12616458240
  uptime: 180h 37m 11.62s (Approximately 7.50 days)
plugins:
  log:
  - k8s-file
  - none
  - journald
  network:
  - bridge
  - macvlan
  volume:
  - local
registries:
  search:
  - docker.io
store:
  configFile: /home/maclean/.config/containers/storage.conf
  containerStore:
    number: 1
    paused: 0
    running: 0
    stopped: 1
  graphDriverName: overlay
  graphOptions: {}
  graphRoot: /home/maclean/.local/share/containers/storage
  graphStatus:
    Backing Filesystem: extfs
    Native Overlay Diff: "true"
    Supports d_type: "true"
    Using metacopy: "false"
  imageStore:
    number: 9
  runRoot: /run/user/1000/containers
  volumePath: /home/maclean/.local/share/containers/storage/volumes
version:
  APIVersion: 3.4.4
  Built: 1638999907
  BuiltTime: Wed Dec  8 14:45:07 2021
  GitCommit: ""
  GoVersion: go1.16.8
  OsArch: linux/amd64
  Version: 3.4.4

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

podman-3.4.4-1.fc35.x86_64
Fedora 35

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.):

@openshift-ci openshift-ci bot added the kind/bug Categorizes issue or PR as related to a bug. label Jan 10, 2022
@jwhonce
Copy link
Member

jwhonce commented Jan 10, 2022

@mheon @haircommander @giuseppe

Note conmon is doing the keystroke logging.

@mheon
Copy link
Member

mheon commented Jan 10, 2022

Would need to be a conmon-level change to log on line, not on character.

I can definitely see why we'd want this for better systemd integration, but I do worry it might compromise some of the other goals of logging (what happens to partial log lines - do we just not record them? Could make debugging containers more difficult...)

@haircommander
Copy link
Collaborator

I believe more control over logging is needed, and that the default log level should not log keystrokes.

naively I could also see this being solved by having a [HIDDEN] or something replace stdin (optionally) but when we're using a terminal I don't think we can differentiate between stdout and stdin so I don't think that'll work.

@mheon yeah I would really like to avoid buffering as it would really complicate the code for processing output. plus in this case, we're only solving half the problem (excessive newlines), while not addressing the potential security concerns of logging confiedential information to the journal

@github-actions
Copy link

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

@rhatdan
Copy link
Member

rhatdan commented Feb 10, 2022

@mheon @haircommander any progress on this?

@haircommander
Copy link
Collaborator

partially, the buffering part is fixed in containers/conmon#321 with conmon 2.1.0, though we still log key strokes, and given the way TTYs are setup in the OCI spec, I'm not sure we can stop...

@mheon
Copy link
Member

mheon commented Feb 11, 2022

Tend to concur; and even if we could stop, I'm not sure we want to. It'd be a breaking change from Docker's behavior.

@rhatdan rhatdan closed this as completed Feb 11, 2022
@github-actions github-actions bot added the locked - please file new issue/PR Assist humans wanting to comment on an old issue or PR with locked comments. label Sep 21, 2023
@github-actions github-actions bot locked as resolved and limited conversation to collaborators Sep 21, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
kind/bug Categorizes issue or PR as related to a bug. locked - please file new issue/PR Assist humans wanting to comment on an old issue or PR with locked comments.
Projects
None yet
Development

No branches or pull requests

5 participants