rawhide: channel "123" found, 0-3 supported: lost synchronization with multiplexed stream

[edsantiago]

New bug seen in rawhide gating tests:

not ok 48 podman run --log-driver
# (from function `is' in file ./helpers.bash, line 705,
#  in test file ./030-run.bats, line 405)
#   `is "$output" "$msg" "podman logs, with driver '$driver'"' failed
# # podman-remote rm -t 0 --all --force --ignore
# # podman-remote ps --all --external --format {{.ID}} {{.Names}}
# # podman-remote images --all --format {{.Repository}}:{{.Tag}} {{.ID}}
# quay.io/libpod/testimage:20220615 f26aa69bb3f3
# # podman-remote run --name myctr --log-driver none quay.io/libpod/testimage:20220615 echo 4sLiyv9EUxuemZQ
# 4sLiyv9EUxuemZQ
# # podman-remote inspect --format {{.HostConfig.LogConfig.Type}} myctr
# none
# # podman-remote inspect --format {{.HostConfig.LogConfig.Path}} myctr
# # podman-remote logs myctr
# Error: channel "123" found, 0-3 supported: lost synchronization with multiplexed stream
# [ rc=125 (expected) ]
# # podman-remote rm myctr
# 94541611326b65f3b54e28873eb9fd18951f0556760c407386692684f8421491
# # podman-remote run --name myctr --log-driver journald quay.io/libpod/testimage:20220615 echo 3v7S6h4YhD079L7
# 3v7S6h4YhD079L7
# # podman-remote inspect --format {{.HostConfig.LogConfig.Type}} myctr
# journald
# # podman-remote inspect --format {{.HostConfig.LogConfig.Path}} myctr
# # podman-remote logs myctr
# #/vvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvv
# #|     FAIL: podman logs, with driver 'journald'
# #| expected: '3v7S6h4YhD079L7'
# #|   actual: ''
# #\^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

Symptoms:

1. The "123" error
2. No output from podman logs

[mheon]

Potentially a Conmon bug, it could be writing the logs incorrectly.

[lsm5]

hmm, second rerun passed. So, it's a flake.

[lsm5]

https://bodhi.fedoraproject.org/updates/FEDORA-2022-0844660f50 .. tagged for rawhide stable.

[edsantiago]

Here's a super-trivial reproducer:

$ bin/podman-remote logs --timestamps nonexistentcontainer
Error: channel "123" found, 0-3 supported: lost synchronization with multiplexed stream

If you run the server with --log-level=info, you get:

@ - - [14/Sep/2022:06:29:34 -0600] "GET /v4.3.0/libpod/_ping HTTP/1.1" 200 2 "" "Go-http-client/1.1"
INFO[0004] Request Failed(Not Found): no container with name or ID "nonexistentcontainer" found: no such container 

[hhellbusch]

seeing the same issue w/ a customer. the end-user is running on an M1 Macbook via podman machine.

saw a similar report for this at #14517

Restarting the podman machine seemed to have cleared it up.

[github-actions]

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

[edsantiago]

Seen in f36 root

not ok 111 podman stop - can trap signal
# podman-remote [...] run -d quay.io/libpod/testimage:20221018 sh -c trap 'echo Received SIGTERM, finishing; exit' SIGTERM; echo READY; while :; do sleep 1; done
<CID>
# podman-remote [...] logs CID
Error: channel "123" found, 0-3 supported: lost synchronization with multiplexed stream

[edsantiago]

This is still happening and still cluttering CI logs. Super-trivial reproducer (assumes a podman-remote server):

$ bin/podman-remote run -d --name foo --log-driver=none quay.io/libpod/testimage:20221018 top
d8ab54a2a9afc8ff8a7ab617fb6ee64bcae8f283b2c7c75be546b9ed63a28a92
$ bin/podman-remote logs foo
Error: channel "123" found, 0-3 supported: lost synchronization with multiplexed stream

Nothing on the server side. If you run the server with --log-level=trace, the expected "none" message is actually emitted:

INFO[0002] Request Failed(Internal Server Error): failed to obtain logs for Container 'foo': this container is using the 'none' log driver, cannot read logs: this container is not logging output 
time="2023-01-11T15:00:16-07:00" level=trace msg="{\"cause\":\"this container is not logging output\",\"message\":\"failed to obtain logs for Container 'foo': this container is using the 'none' log driver, cannot read logs: this container is not logging output\",\"response\":500}\n" API=response X-Reference-Id=0xc000908000

[mheon]

That specific presentation looks like it ought to be easy to fix. I doubt that fixes the entire bug, though, the other cases reported here don't seem related to log-driver=none

[edsantiago]

@mheon I'm refreshing my memory on this... and, when I filed it, I reported two issues: log output missing (which caused an actual CI test failure), and the "123" thing (which does not).

The missing-output bug is rare, making it hard to track down. The "123" bug, though, keeps distracting me because it shows up bright orange in logs and makes me think it's more serious than it is. If that is indeed easy to fix, it sure would be appreciated.

[edsantiago]

Hmmmm.... then again, I wonder if this is the same issue? f37 remote rootless:

[+0180s] not ok 107 podman logs - --until --follow k8s-file
...
# $ podman-remote --url unix:/tmp/podman_tmp_PIhg logs --until 3s -f 9fLo4xryZA
# nXylDOWTso
# #/vvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvv
# #|     FAIL: logs --until -f on running container works
# #| expected: 'nXylDOWTso
# nXylDOWTso'
# #|   actual: 'nXylDOWTso'
# #\^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

[Luap99]

I pushed a fix for the 123 bug to my ginkgo-v2 PR as I run into this issue there as well: e023a1f
Of course this message just hides the actual server error so it isn't really fixed but at least we now will get the root cause.

[edsantiago]

Fixed in #18282.

(It's possible that the underlying bug, where podman-remote logs are missing, may still exist. If so, I'll open a new bug for it).