trouble with logs output in follow mode

[antonvigo]

Hi there!
We started usage of oidc-proxy recently. In our deployment it's "hidden" from users behind regular NGINX balancer. Before current topic events there was an issue with exec-mode which was solved by adding couple extra headers regarding upgrade from HTTP to websocket connection. But couple days ago we've faced with another problem related to logs output in follow mode as it is mentioned.

Expected behavior: obviously, show new logs lines right after it is generated by app in pod. Here is some piece of output with verbose=10:

I0313 14:02:08.408832   64736 round_trippers.go:466] curl -v -XGET  -H "User-Agent: kubectl/v1.26.0 (linux/amd64) kubernetes/b46a3f8" -H "Accept: application/json, */*" 'https://172.33.20.83:5443/api/v1/namespaces/prj-stage/pods/api-5f7bb46f9d-ng7zv'
I0313 14:02:08.472157   64736 round_trippers.go:553] GET https://172.33.20.83:5443/api/v1/namespaces/prj-stage/pods/api-5f7bb46f9d-ng7zv 200 OK in 63 milliseconds
I0313 14:02:08.472208   64736 round_trippers.go:570] HTTP Statistics: GetConnection 0 ms ServerProcessing 63 ms Duration 63 ms
I0313 14:02:08.472224   64736 round_trippers.go:577] Response Headers:
I0313 14:02:08.472241   64736 round_trippers.go:580]     X-Kubernetes-Pf-Prioritylevel-Uid: 1e8ac442-cf75-4258-9264-58d8cf0041e6
I0313 14:02:08.472262   64736 round_trippers.go:580]     Date: Wed, 13 Mar 2024 11:02:08 GMT
I0313 14:02:08.472337   64736 round_trippers.go:580]     Audit-Id: edd7c547-a5ac-4ef4-b57c-1c2bff76ff26
I0313 14:02:08.472352   64736 round_trippers.go:580]     Cache-Control: no-cache, private
I0313 14:02:08.472367   64736 round_trippers.go:580]     Content-Type: application/json
I0313 14:02:08.472386   64736 round_trippers.go:580]     X-Kubernetes-Pf-Flowschema-Uid: 05f6bb74-21e5-4ae0-ab89-82297907a734
I0313 14:02:08.472720   64736 request.go:1154] Response Body: {"kind":"Pod","apiVersion":"v1","metadata":{"name":"api-5f7bb46f9d-ng7zv",...}}

I0313 14:02:08.476462   64736 round_trippers.go:466] curl -v -XGET  -H "Accept: application/json, */*" -H "User-Agent: kubectl/v1.26.0 (linux/amd64) kubernetes/b46a3f8" 'https://172.33.20.83:5443/api/v1/namespaces/prj-stage/pods/api-5f7bb46f9d-ng7zv/log?container=php&follow=true'
I0313 14:02:08.542457   64736 round_trippers.go:553] GET https://172.33.20.83:5443/api/v1/namespaces/prj-stage/pods/api-5f7bb46f9d-ng7zv/log?container=php&follow=true 200 OK in 65 milliseconds
I0313 14:02:08.542537   64736 round_trippers.go:570] HTTP Statistics: GetConnection 0 ms ServerProcessing 65 ms Duration 65 ms
I0313 14:02:08.542563   64736 round_trippers.go:577] Response Headers:
I0313 14:02:08.542592   64736 round_trippers.go:580]     Content-Type: text/plain
I0313 14:02:08.542618   64736 round_trippers.go:580]     Date: Wed, 13 Mar 2024 11:02:08 GMT
I0313 14:02:08.542642   64736 round_trippers.go:580]     Audit-Id: 0d768658-3c02-45de-80c3-a22c73e1db36
I0313 14:02:08.542666   64736 round_trippers.go:580]     Cache-Control: no-cache, private

Actual behavior: shows some portion of logs missing last 10-15 minutes, updates come with unpredictable manner. Some output is:

I0313 13:55:38.269501   63928 round_trippers.go:466] curl -v -XGET  -H "Accept: application/json, */*" -H "User-Agent: kubectl/v1.26.0 (linux/amd64) kubernetes/b46a3f8" 'https://oidc-proxy.domain.com/api/v1/namespaces/prj-stage/pods/api-5f7bb46f9d-ng7zv'
I0313 13:55:38.325311   63928 round_trippers.go:495] HTTP Trace: DNS Lookup for oidc-proxy.domain.com resolved to [{172.33.3.74 }]
I0313 13:55:38.381576   63928 round_trippers.go:510] HTTP Trace: Dial to tcp:172.33.3.74:443 succeed
I0313 13:55:38.555146   63928 round_trippers.go:553] GET https://oidc-proxy.domain.com/api/v1/namespaces/prj-stage/pods/api-5f7bb46f9d-ng7zv 200 OK in 285 milliseconds
I0313 13:55:38.555226   63928 round_trippers.go:570] HTTP Statistics: DNSLookup 55 ms Dial 56 ms TLSHandshake 60 ms ServerProcessing 111 ms Duration 285 ms
I0313 13:55:38.555262   63928 round_trippers.go:577] Response Headers:
I0313 13:55:38.555293   63928 round_trippers.go:580]     X-Kubernetes-Pf-Prioritylevel-Uid: 1d496c5d-b730-4120-90ef-d07d2b9b0a68
I0313 13:55:38.555328   63928 round_trippers.go:580]     Content-Language: ru
I0313 13:55:38.555357   63928 round_trippers.go:580]     Strict-Transport-Security: max-age=31536000; includeSubDomains
I0313 13:55:38.555380   63928 round_trippers.go:580]     Date: Wed, 13 Mar 2024 10:55:38 GMT
I0313 13:55:38.555408   63928 round_trippers.go:580]     Vary: Accept-Encoding
I0313 13:55:38.555440   63928 round_trippers.go:580]     Audit-Id: 6494530a-ac2f-4f96-81ec-0967a90b45f2
I0313 13:55:38.555466   63928 round_trippers.go:580]     Cache-Control: no-cache, private
I0313 13:55:38.555496   63928 round_trippers.go:580]     X-Kubernetes-Pf-Flowschema-Uid: 18caacf4-fe73-4ebc-a4d2-5f9fa906ac1a
I0313 13:55:38.555529   63928 round_trippers.go:580]     Server: nginx/1.24.0
I0313 13:55:38.555551   63928 round_trippers.go:580]     Content-Type: application/json
I0313 13:55:38.556369   63928 request.go:1154] Response Body: {"kind":"Pod","apiVersion":"v1","metadata":{"name":"api-5f7bb46f9d-ng7zv",...}}

I0313 13:55:38.567576   63928 round_trippers.go:466] curl -v -XGET  -H "Accept: application/json, */*" -H "User-Agent: kubectl/v1.26.0 (linux/amd64) kubernetes/b46a3f8" 'https://oidc-proxy.domain.com/api/v1/namespaces/prj-stage/pods/api-5f7bb46f9d-ng7zv/log?container=php&follow=true'
I0313 13:55:40.336615   63928 round_trippers.go:553] GET https://oidc-proxy.domain.com/api/v1/namespaces/prj-stage/pods/api-5f7bb46f9d-ng7zv/log?container=php&follow=true 200 OK in 1768 milliseconds
I0313 13:55:40.336725   63928 round_trippers.go:570] HTTP Statistics: GetConnection 0 ms ServerProcessing 1768 ms Duration 1768 ms
I0313 13:55:40.336771   63928 round_trippers.go:577] Response Headers:
I0313 13:55:40.336822   63928 round_trippers.go:580]     Vary: Accept-Encoding
I0313 13:55:40.336867   63928 round_trippers.go:580]     Audit-Id: ef13a5a6-3779-4a18-9038-7191994e4de2
I0313 13:55:40.336908   63928 round_trippers.go:580]     Cache-Control: no-cache, private
I0313 13:55:40.336949   63928 round_trippers.go:580]     Content-Language: ru
I0313 13:55:40.336992   63928 round_trippers.go:580]     Server: nginx/1.24.0
I0313 13:55:40.337034   63928 round_trippers.go:580]     Date: Wed, 13 Mar 2024 10:55:38 GMT
I0313 13:55:40.337075   63928 round_trippers.go:580]     Content-Type: text/plain; charset=utf-8
I0313 13:55:40.337117   63928 round_trippers.go:580]     Strict-Transport-Security: max-age=31536000; includeSubDomains

Additional info: kubeconfig is rendered by Gangway service, authentication passed via Dex as LDAP auth-provider. In fact, ldap-auth is the main reason for us to use oidc-proxy.

I almost sure that solution is somewhere in NGINX configuration. But I don't know anything about internal mechanism of oidc-proxy. That's why it's almost impossible for me even to analyze the problem. Any advice or assumptions are welcome!