Error: timed out waiting for file with large TTY output

[rlanting]

/kind bug

I ran into a Error: timed out waiting for file error. But not in the same way as the reporter of #13779 and #13600 didn't seem to fix it. This is on rootless podman 4.0.3 on debian with cni.

Steps to reproduce

• podman run --rm --env ALLOW_EMPTY_PASSWORD=yes --name=mysql-test quay.io/bitnami/mysql:8.0
• Wait for [Server] /opt/bitnami/mysql/bin/mysqld: ready for connections. to appear at the end of the log
• Open another shell because the container will stay in the foreground so you can see when it's ready
• podman exec -it mysql-test /bin/bash
• mysql
• show status;
• Cleanup: podman kill mysql-test

Result

Error: timed out waiting for file /home/username/.local/share/containers/storage/overlay-containers/<sha256 1>/userdata/<sha256 2/exit/<sha256 1>: internal libpod error

Expected

Full output and not getting kicked out of the container.

Output of podman version:

Client:       Podman Engine
Version:      4.0.3
API Version:  4.0.3
Go Version:   go1.18.1
Built:        Thu Jan  1 01:00:00 1970
OS/Arch:      linux/amd64

Output of podman info --debug:

host:
  arch: amd64
  buildahVersion: 1.24.1
  cgroupControllers:
  - memory
  - pids
  cgroupManager: systemd
  cgroupVersion: v2
  conmon:
    package: 'conmon: /usr/bin/conmon'
    path: /usr/bin/conmon
    version: 'conmon version 2.0.25, commit: unknown'
  cpus: 6
  distribution:
    distribution: debian
    version: unknown
  eventLogger: journald
  hostname: mirage
  idMappings:
    gidmap:
    - container_id: 0
      host_id: 1000
      size: 1
    - container_id: 1
      host_id: 1279648
      size: 65536
    uidmap:
    - container_id: 0
      host_id: 1000
      size: 1
    - container_id: 1
      host_id: 1279648
      size: 65536
  kernel: 5.16.0-6-amd64
  linkmode: dynamic
  logDriver: journald
  memFree: 4141248512
  memTotal: 67412041728
  networkBackend: cni
  ociRuntime:
    name: crun
    package: 'crun: /usr/bin/crun'
    path: /usr/bin/crun
    version: |-
      crun version 0.17
      commit: 0e9229ae34caaebcb86f1fde18de3acaf18c6d9a
      spec: 1.0.0
      +SYSTEMD +SELINUX +APPARMOR +CAP +SECCOMP +EBPF +YAJL
  os: linux
  remoteSocket:
    exists: true
    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: false
  serviceIsRemote: false
  slirp4netns:
    executable: /usr/bin/slirp4netns
    package: 'slirp4netns: /usr/bin/slirp4netns'
    version: |-
      slirp4netns version 1.0.1
      commit: 6a7b16babc95b6a3056b33fb45b74a6f62262dd4
      libslirp: 4.6.1
  swapFree: 48302649344
  swapTotal: 48318377984
  uptime: 95h 49m 39.02s (Approximately 3.96 days)
plugins:
  log:
  - k8s-file
  - none
  - passthrough
  - journald
  network:
  - bridge
  - macvlan
  - ipvlan
  volume:
  - local
registries: {}
store:
  configFile: /home/username/.config/containers/storage.conf
  containerStore:
    number: 12
    paused: 0
    running: 9
    stopped: 3
  graphDriverName: overlay
  graphOptions: {}
  graphRoot: /home/username/.local/share/containers/storage
  graphStatus:
    Backing Filesystem: extfs
    Native Overlay Diff: "true"
    Supports d_type: "true"
    Using metacopy: "false"
  imageCopyTmpDir: /var/tmp
  imageStore:
    number: 13
  runRoot: /run/user/1000/containers
  volumePath: /home/username/.local/share/containers/storage/volumes
version:
  APIVersion: 4.0.3
  Built: 0
  BuiltTime: Thu Jan  1 01:00:00 1970
  GitCommit: ""
  GoVersion: go1.18.1
  OsArch: linux/amd64
  Version: 4.0.3

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

$ apt list podman
Listing... Done
podman/experimental,now 4.0.3+ds1-1 amd64 [installed]
podman/testing,unstable 3.4.6+ds1-1 i386

Additional information

For quicker reproduction during testing, you can use podman exec -t mysql-test mysql -e "show status;" as command. It will cut off the output. Last output line should contain Uptime_since_flush_status

Originally posted by @rlanting in #13779 (comment)

[Luap99]

@mheon PTAL

[mheon]

Can you clarify your "not getting kicked out of the container" expectation - because podman kill stopping exec sessions is 100% correct behavior.

Otherwise, I would have expected 82c0134 to resolve this, but given it's already in 4.0.3 evidently it's still present.

[rlanting]

<lots of output>
|
| Innodb_system_rows_inserted                           | 0   |
| Innodb_system_rows_read                               | 4679|
Error: timed out waiting for file /home/username/.local/share/containers/storage/overlay-containers/77d2619726995941ac45ef21a44b75353f13eb986fa5bb5db53e4c88df9d24af/userdata/f0c4d137876735e34f59aab676abe53e353394ed5ce69b30339ee72da821fca8/exit/77d2619726995941ac45ef21a44b75353f13eb986fa5bb5db53e4c88df9d24af: internal libpod error
➜  ~ # this is my normal shell prompt

"Kicked out of the container" meaning "dropped back into normal shell" for the secondary shell used to reproduce.

The last step having the kill is there to stop the mysql container that still runs for cleanup.

[mheon]

For clarity here, this is definitely an issue with exec-attach blowing up after a large amount (~14kb) of text is transferred through it, not an issue with a normal exit.

[rlanting]

conmon.log
full-command-output.log

The full data the command returns should be around around 14kb, but with formatting that goes up. The log is 123kb and that's at line 230 out of 482. So I expect working output to be around 300kb.

[rlanting]

I did some testing for easier reproduction and I came to the following:

1. Start a container in shell 1: podman run -it --rm --name=exec-test quay.io/libpod/alpine:latest
2. Attach to that container in shell 2: podman exec -it exec-test /bin/sh
3. Generate data in shell 1: base64 /dev/urandom | head -c 115958 > testfile.txt
4. cat file in shell 2: cat testfile.txt

For me 115958 bytes (113kb) is exactly the size at which it breaks. One fewer and it works fine.

[Luap99]

I am unable to reproduce. It could be the conmon version. I have v2.1.0 installed. Could you try with that?

[Luap99]

Ok I just tried with conmon 2.0.25 and can reproduce.

I am closing this since it is fixed in the latest conmon release.