remote: pod logs: catch-up delay

[edsantiago]

As best I can tell, podman-remote pod logs is sometimes not actually fully catching up, so a system test is failing

# podman-remote --url unix:/tmp/podman_tmp_tAJi logs 9f7628c570de2a8939936681617a216ebc6cc43943bc4f64874c2e7850c81f20
#/vvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvv
#|     FAIL: test string received on container
#| expected: 'uwOjtSVXmcfjVrydfvPFF9zoVWdfov'
#|   actual: ''
#\^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

The code in question is doing echo teststring | nc localhost PORT, then immediately running podman logs on a container in a pod.

podman/test/system/200-pod.bats

Lines 300 to 307 in 2a9df07

	# send a random string to the container. This will cause the container
	# to output the string to its logs, then exit.
	teststring=$(random_string 30)
	echo "$teststring" | nc 127.0.0.1 $port_out
	# Confirm that the container log output is the string we sent it.
	run_podman logs $cid
	is "$output" "$teststring" "test string received on container"

• fedora-36-aarch64 : sys remote fedora-36-aarch64 root host [remote]
  • PR Avoid unnecessary timeout of 250msec when waiting on container shutdown #16088
    • 10-10 07:08
• fedora-36-aarch64 : sys remote fedora-36-aarch64 root host [remote]
  • PR Improve generate systemd format #15837
    • 09-21 08:13
• fedora-36-aarch64 : sys remote fedora-36-aarch64 root host [remote]
  • PR fixes data race in system.Events and nil error logging #15665
    • 09-08-2022 06:58

Seems to have started 08-Sept, which suggests a real code problem because that test code hasn't changed since June 2020.

[edsantiago]

Recent flakes, to remind everyone that this is still not fixed:

• fedora-36-aarch64 : sys remote fedora-36-aarch64 root host [remote]
  • PR build(deps): bump github.com/stretchr/testify from 1.8.0 to 1.8.1 #16275
    • 10-24 09:20
  • PR container/pod id file: truncate instead of throwing an error #16273
    • 10-25 04:55
  • PR Set up minikube for k8s testing #15826
    • 10-18 12:06

[edsantiago]

Another one in remote f36-aarch64 root:

# podman-remote logs e622101a248a44fac7660fa0c95d354c7f519785e952e665c57a275af9d3ff6c
#/vvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvv
#|     FAIL: test string received on container
#| expected: '8UhHQsrXptSI4strBWkKJTBSfaKaWK'
#|   actual: ''
#\^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

Although in CI I only see this on podman-remote tests, yesterday I saw this flake on a 1mt VM:

✗ podman logs - since journald                                                  
   (from function `is' in file test/system/helpers.bash, line 743,                                                                                              
    from function `_log_test_since' in file test/system/035-logs.bats, line 189,                    
    in test file test/system/035-logs.bats, line 211)                                                                                                           
     `_log_test_since journald' failed                                                                                                                          
   # /root/go/podman/bin/podman rm -t 0 --all --force --ignore                                                                                                  
   # /root/go/podman/bin/podman ps --all --external --format {{.ID}} {{.Names}}                                                                                 
   # /root/go/podman/bin/podman images --all --format {{.Repository}}:{{.Tag}} {{.ID}}
   quay.io/libpod/testimage:20221018 f5a99120db64                                                                                                               
   # /root/go/podman/bin/podman run --log-driver=journald -d --name test quay.io/libpod/testimage:20221018 sh -c echo before_bDnJJB3Ydm_journald; trap 'echo aft
er_DRQNIJ59TR_journald; exit' SIGTERM; while :; do sleep 1; done
   cf99c637a0d167926ab15d44e597ed4e9fc8e60d3ddfc3498d27531a39bece3e                                                                                             
   # /root/go/podman/bin/podman stop test                                                                                                                       
   test                                                                                                                                                         
   # /root/go/podman/bin/podman logs test                                                                                                                       
   before_bDnJJB3Ydm_journald           
   #/vvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvv
   #|     FAIL: podman logs test        
   #| expected: 'before_bDnJJB3Ydm_journald                
   after_DRQNIJ59TR_journald'           
   #|   actual: 'before_bDnJJB3Ydm_journald' 
   #\^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

No idea if there's a connection, and the VM is long gone.

[edsantiago]

Here's another non-remote logs flake (in f37 root):

podman create with --mount flag
   ...
         # podman [options] create --log-driver k8s-file --name test --mount type=bind,src=/tmp/podman_test336222415/secrets,target=/create/test quay.io/libpod/alpine:latest grep /create/test /proc/self/mountinfo
         35df13069504efe8e7675e87256b9340f734768f2efbcb0ced8e3747cd90d5a5
         # podman [options] start test
         test
         # podman [options] logs test
         [no output from podman logs]
         ....
           Expected
               <string>: 
           to contain substring
               <string>: /create/test rw

I'm not saying the bug is in podman-logs, but maybe I am.

[edsantiago]

And another one in int tests, also a podman-logs that spits out nothing.

[edsantiago]

I'm going to hope that this was fixed in #16437