flake: podman logs: sometimes emits wrong output

[edsantiago]

podman logs is sometimes returning the wrong result. It actually seems to be a problem with the stored output, not podman logs itself; i.e. once a container gets in this bad state, all future podman logs commands will fail.

Simpleminded overview (not a reproducer):

$ ./bin/podman run -t --name test IMG sh -c 'echo 1;echo 2'
1
2
$ ./bin/podman logs test
<something other than '1 2'>

Sample failed results:

• '1', 2nd line is empty
• empty line, '2' on second line
• empty line, '12' on second line

Context: seeing this kind of regularly in integration tests:

Podman logs [It] Make sure logs match expected length

• gce_instance:fedora : int podman fedora-33 root host
  • PR REST API v2 - ping - fix typo in header #8487
    • 11-25 15:45
• gce_instance:prior-fedora : int podman fedora-32 root container
  • PR The slirp4netns sandbox requires pivot_root #8852
    • 12-29 12:50
  • PR remote copy #8747
    • 12-18 09:21
    • 12-18 09:21
    • 12-18 09:21
• gce_instance:prior-fedora : int podman fedora-32 root host
  • PR system tests (remote): reenable basic exec test #8871
    • 01-04 09:59
    • 01-04 09:59
    • 01-04 09:59
• gce_instance:prior-fedora : int podman fedora-32 rootless host
  • PR Fix missing options in volume's display while setting uid and gid #8793
    • 12-22 20:58
    • 12-22 20:58
    • 12-22 20:58
  • PR Set NetNS mode instead of value #8792
    • 12-23 14:13
    • 12-23 14:13
    • 12-23 14:13
• gce_instance:prior-ubuntu : int podman ubuntu-19 root host
  • PR Allow multiple --network flags for podman run/create #8410
    • 11-20 11:53

Reproducer [podman-logs-flake.sh.txt]:

#!/bin/sh

img=quay.io/libpod/testimage:20200929
expect=

while :;do
    ./bin/podman run -t --name test $img sh -c 'echo 1;echo 2'
# The integration test has a 'wait'; this is not actually necessary, test will fail even without it
#    ./bin/podman wait test
    x=$(./bin/podman logs test)
    printf "%q\n" $x

    # First time through
    if [[ -z "$expect" ]]; then
        expect=$x
    fi

    if [[ "$x" != "$expect" ]]; then
        echo -ne '\a'
        echo "*********************"
        echo
        exit
    fi
    ./bin/podman rm test
done

It takes several hours to fail on my laptop. Once it fails, the container is left in place, and all subsequent podman log test commands will remain consistent with the first failure.

master @ 23f25b8. Seems to happen both root and rootless, f32 and f33; even once on ubuntu 19.

[edsantiago]

Update: it's looking likely that the -t is the culprit. I've had the reproducer running for the last 3+ hours, without -t, and no failure yet. I'll let it run overnight.

[edsantiago]

Forgot to update here: the job without -t ran all night, over twelve hours. I stopped it, added back -t, job failed within two hours.

[Luap99]

Can you paste the content of the log file please? It could be that podman logs works correct and the file is wrong.

[edsantiago]

Good idea.

$ ./bin/podman logs test | cat -vET
1^M$
^M$
$ cat -vET ~/.local/share/containers/storage/overlay-containers/<sha>/userdata/ctr.log
2021-01-05T09:30:48.745347870-07:00 stdout F 1^M$
2021-01-05T09:30:48.745347870-07:00 stdout P 2$
2021-01-05T09:30:48.745582542-07:00 stdout F ^M$

On a good container:

$ cat -vET ~/.local/share/containers/storage/overlay-containers/<sha>/userdata/ctr.log
2021-01-06T13:53:05.349022525-07:00 stdout F 1^M$
2021-01-06T13:53:05.349022525-07:00 stdout F 2^M$

[Luap99]

OK podman logs is wrong. I will open a PR.

[Luap99]

#8904