podman logs --tail, with json-file, misses partial lines

[edsantiago]

[ Split off from #18501 ]

Basically, podman does not correctly handle a log like this:

$ cat -vET ~/.local/share/containers/storage/overlay-containers/$cid/userdata/ctr.log
2023-08-07T19:56:34.223758260-06:00 stdout F podman^M$
2023-08-07T19:56:34.223758260-06:00 stdout P podman$
2023-08-07T19:56:34.223816701-06:00 stdout F ^M$             <------ this actually goes with the prior line
2023-08-07T19:56:34.223816701-06:00 stdout F podman^M$
$ bin/podman logs --tail 2 $cid | cat -vET
^M$
podman^M$

Causes flakes in e2e tests, because they use podman run -dt, which is IMHO a bug, except that it let us find this issues, so maybe it's not a bug. (I cleaned up run -it in #18343 but did not touch -dt)

Reproducer:

$ nl="        <----- basically doublequote, enter, doublequote, enter
"
$ cr="^M"      <-------- control-V for quote-next-character, control-M for CR
$ while :;do cid=$(bin/podman run --log-driver json-file -dt quay.io/libpod/testimage:20221018 sh -c "echo podman;echo podman;echo podman");bin/podman wait $cid;logs=$(bin/podman logs --tail 2 $cid); test "$logs" = "podman${cr}${nl}podman${cr}" || break;bin/podman rm $cid;done

[Luap99]

From a quick look at the code it looks like it tries to handle this case but it is clearly no working properly. I take a stab at it.

[Luap99]

Also FYI, json-file == k8s-file in case you see the same thing there as well

[edsantiago]

This is an easy one; I have a fix in progress, with tests. Give me an hour or two... unless you already have it fixed.

[Luap99]

I have a fix (proper rework to simplify the code) but no tests written yet.

[edsantiago]

I'll let you continue with your fix then, since it's probably better Go than mine. Here's a test, use whatever you like from it.

# #19545
@test "podman logs --tail, json-file with partial lines" {
    cname="tail_container"

    # "-t" gives us ^Ms (CRs) in the log
    run_podman run --name $cname --log-driver json-file -t $IMAGE echo hi

    # Hand-craft a log file with partial lines and carriage returns
    run_podman inspect --format '{{.HostConfig.LogConfig.Path}}' $cname
    logpath="$output"
    timestamp=$(awk '{print $1}' <"$logpath")
    cr=$'\r'
    nl=$'\n'
    cat >| $logpath <<EOF
$timestamp stdout F podman1$cr
$timestamp stdout P podman2
$timestamp stdout F $cr
$timestamp stdout F podman3$cr
EOF

    expect1="podman3${cr}"
    expect2="podman2${cr}${nl}podman3${cr}"
    expect3="podman1${cr}${nl}podman2${cr}${nl}podman3${cr}"

    # This always worked
    run_podman logs --tail 1 $cname
    assert "$output" = "$expect1" "--tail 1"

    # Prior to this PR, the first line would be "^M" without the podman
    run_podman logs --tail 2 $cname
    assert "$output" = "$expect2" "--tail 2"

    # Confirm that we won't overrun
    for i in 3 4 5; do
        run_podman logs --tail $i $cname
        assert "$output" = "$expect3" "--tail $i"
    done

    run_podman rm $cname
}

[Luap99]

Thanks for the test, I will also add unit tests as there seems to be quite a few different cases that all need to be covered.

Also note that the \r is only a symptom which likely results in the partial lines in the first place but the partial line handling is broken no matter what.