non-tty logs/container attach format broken

[chilikk]

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

/kind bug

Description

Podman seems to have a bug in attach format which is described here https://docs.docker.com/engine/api/v1.41/#tag/Container/operation/ContainerAttach

The bug only seems to appear for the log items produced before the attach command is executed, not after

Steps to reproduce the issue:

1. Start a container which prints a 4-byte message on stdout each second during 10 seconds
2. Wait for 5 seconds
3. Attach to the container and save the output

The same steps in form of a script:

sudo podman run -d --rm --name test alpine sh -c 'for i in $(seq 0 10); do printf "%03d\n" $i; sleep 1; done'
sleep 5
sudo curl -X POST --unix /run/podman/podman.sock 'http://localhost/containers/test/attach?logs=true&stream=true&stdout=true' --output dump.bin

Describe the results you received:

Looking at the dump.bin produced with the above reproduction procedure, one can clearly see how the length field is incorrect (indicates 3 bytes for a 4-byte payload) during the first 5 seconds, and correct (indicates 4 bytes) during the last 5 seconds.

h01:~$ xxd -c12 dump.bin 
00000000: 0100 0000 0000 0003 3030 300a  ........000.
0000000c: 0100 0000 0000 0003 3030 310a  ........001.
00000018: 0100 0000 0000 0003 3030 320a  ........002.
00000024: 0100 0000 0000 0003 3030 330a  ........003.
00000030: 0100 0000 0000 0003 3030 340a  ........004.
0000003c: 0100 0000 0000 0003 3030 350a  ........005.
00000048: 0100 0000 0000 0004 3030 360a  ........006.
00000054: 0100 0000 0000 0004 3030 370a  ........007.
00000060: 0100 0000 0000 0004 3030 380a  ........008.
0000006c: 0100 0000 0000 0004 3030 390a  ........009.
00000078: 0100 0000 0000 0004 3031 300a  ........010.

Describe the results you expected:

I expected the length to be 4 for all messages.

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

Output of podman version:

$ podman version
Client:       Podman Engine
Version:      4.3.1
API Version:  4.3.1
Go Version:   go1.19.4
Built:        Tue Dec 13 02:00:33 2022
OS/Arch:      linux/amd64

Output of podman info:

$ podman info
host:
  arch: amd64
  buildahVersion: 1.28.0
  cgroupControllers: []
  cgroupManager: cgroupfs
  cgroupVersion: v1
  conmon:
    package: conmon-2.1.5-r0
    path: /usr/bin/conmon
    version: 'conmon version 2.1.5, commit: unknown'
  cpuUtilization:
    idlePercent: 99.74
    systemPercent: 0.12
    userPercent: 0.15
  cpus: 1
  distribution:
    distribution: alpine
    version: 3.17.0
  eventLogger: file
  hostname: h01
  idMappings:
    gidmap:
    - container_id: 0
      host_id: 1000
      size: 1
    uidmap:
    - container_id: 0
      host_id: 1000
      size: 1
  kernel: 5.15.82-0-virt
  linkmode: dynamic
  logDriver: k8s-file
  memFree: 1847091200
  memTotal: 2087096320
  networkBackend: netavark
  ociRuntime:
    name: crun
    package: crun-1.7.2-r0
    path: /usr/bin/crun
    version: |-
      crun version 1.7.2
      commit: 0356bf4aff9a133d655dc13b1d9ac9424706cac4
      rundir: /tmp/podman-run-1000/crun
      spec: 1.0.0
      +SELINUX +APPARMOR +CAP +SECCOMP +EBPF +YAJL
  os: linux
  remoteSocket:
    path: /tmp/podman-run-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: /etc/containers/seccomp.json
    selinuxEnabled: false
  serviceIsRemote: false
  slirp4netns:
    executable: /usr/bin/slirp4netns
    package: slirp4netns-1.2.0-r0
    version: |-
      slirp4netns version 1.2.0
      commit: 656041d45cfca7a4176f6b7eed9e4fe6c11e8383
      libslirp: 4.7.0
      SLIRP_CONFIG_VERSION_MAX: 4
      libseccomp: 2.5.4
  swapFree: 0
  swapTotal: 0
  uptime: 0h 46m 48.00s
plugins:
  authorization: null
  log:
  - k8s-file
  - none
  - passthrough
  network:
  - bridge
  - macvlan
  volume:
  - local
registries:
  search:
  - docker.io
store:
  configFile: /home/docker/.config/containers/storage.conf
  containerStore:
    number: 0
    paused: 0
    running: 0
    stopped: 0
  graphDriverName: overlay
  graphOptions: {}
  graphRoot: /home/docker/.local/share/containers/storage
  graphRootAllocated: 4226809856
  graphRootUsed: 286416896
  graphStatus:
    Backing Filesystem: xfs
    Native Overlay Diff: "true"
    Supports d_type: "true"
    Using metacopy: "false"
  imageCopyTmpDir: /var/tmp
  imageStore:
    number: 0
  runRoot: /tmp/podman-run-1000/containers
  volumePath: /home/docker/.local/share/containers/storage/volumes
version:
  APIVersion: 4.3.1
  Built: 1670896833
  BuiltTime: Tue Dec 13 02:00:33 2022
  GitCommit: ""
  GoVersion: go1.19.4
  Os: linux
  OsArch: linux/amd64
  Version: 4.3.1

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

$ apk info podman
podman-4.3.1-r1 description:
Simple management tool for pods, containers and images

podman-4.3.1-r1 webpage:
https://podman.io/

podman-4.3.1-r1 installed size:
39 MiB

Have you tested with the latest version of Podman and have you checked the Podman Troubleshooting Guide?

Yes

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

[Luap99]

Is it always 5 seconds? Or is it the amount of seconds you sleep.

[chilikk]

The amount of seconds you sleep. My guess is that the log items produced before the attach API call is done have the wrong format, while the log items produced after the API call are correct.

[Luap99]

Yeah I found the bug, the hard part is to write a good test