Kourier TLS runtime suite fails sporadically

[skonto]

Actual Behavior

Probe tests fail. See #15695 (comment) for more.

[skonto]

This was proven to be an issue with how pod target is resolved in the activator. Once on a while the cluster IP of the private service is used by the url targeting the pod but activator wrongly assumes that this is always 8112. The actual port for the private service is 443 that maps to 8112.

I debugged this here and here is the output:

{"severity":"info","timestamp":"2025-01-22T17:50:47.692Z","logger":"activator","caller":"handler/handler.go:130","message":"Activator targeting: 10.244.1.10:8112","commit":"64225b5","knative.dev/controller":"activator","knative.dev/pod":"activator-64947fb58f-jfd95"}
{"severity":"info","timestamp":"2025-01-22T17:50:55.745Z","logger":"activator","caller":"handler/handler.go:130","message":"Activator targeting: 10.244.3.14:8112","commit":"64225b5","knative.dev/controller":"activator","knative.dev/pod":"activator-64947fb58f-jfd95"}
{"severity":"info","timestamp":"2025-01-22T17:50:57.812Z","logger":"activator","caller":"handler/handler.go:130","message":"Activator targeting: 10.244.3.15:8112","commit":"64225b5","knative.dev/controller":"activator","knative.dev/pod":"activator-64947fb58f-jfd95"}
{"severity":"info","timestamp":"2025-01-22T17:51:00.880Z","logger":"activator","caller":"handler/handler.go:130","message":"Activator targeting: 10.244.3.16:8112","commit":"64225b5","knative.dev/controller":"activator","knative.dev/pod":"activator-64947fb58f-jfd95"}
{"severity":"info","timestamp":"2025-01-22T17:51:13.959Z","logger":"activator","caller":"handler/handler.go:130","message":"Activator targeting: 10.244.1.11:8112","commit":"64225b5","knative.dev/controller":"activator","knative.dev/pod":"activator-64947fb58f-jfd95"}
{"severity":"info","timestamp":"2025-01-22T17:51:27.002Z","logger":"activator","caller":"handler/handler.go:130","message":"Activator targeting: 10.244.3.17:8112","commit":"64225b5","knative.dev/controller":"activator","knative.dev/pod":"activator-64947fb58f-jfd95"}
{"severity":"info","timestamp":"2025-01-22T17:51:40.045Z","logger":"activator","caller":"handler/handler.go:130","message":"Activator targeting: 10.244.1.12:8112","commit":"64225b5","knative.dev/controller":"activator","knative.dev/pod":"activator-64947fb58f-jfd95"}
{"severity":"info","timestamp":"2025-01-22T17:52:02.092Z","logger":"activator","caller":"handler/handler.go:130","message":"Activator targeting: 10.244.3.18:8112","commit":"64225b5","knative.dev/controller":"activator","knative.dev/pod":"activator-64947fb58f-jfd95"}
{"severity":"info","timestamp":"2025-01-22T17:52:14.138Z","logger":"activator","caller":"handler/handler.go:130","message":"Activator targeting: 10.244.3.19:8112","commit":"64225b5","knative.dev/controller":"activator","knative.dev/pod":"activator-64947fb58f-jfd95"}
{"severity":"info","timestamp":"2025-01-22T17:52:26.180Z","logger":"activator","caller":"handler/handler.go:130","message":"Activator targeting: 10.96.2.212:8112","commit":"64225b5","knative.dev/controller":"activator","knative.dev/pod":"activator-64947fb58f-jfd95"}
{"severity":"info","timestamp":"2025-01-22T17:53:33.112Z","logger":"activator","caller":"handler/handler.go:130","message":"Activator targeting: 10.96.2.212:8112","commit":"64225b5","knative.dev/controller":"activator","knative.dev/pod":"activator-64947fb58f-jfd95"}
{"severity":"info","timestamp":"2025-01-22T17:53:58.103Z","logger":"activator","caller":"handler/handler.go:130","message":"Activator targeting: 10.244.3.21:8112","commit":"64225b5","knative.dev/controller":"activator","knative.dev/pod":"activator-64947fb58f-jfd95"}
{"severity":"info","timestamp":"2025-01-22T17:54:01.209Z","logger":"activator","caller":"handler/handler.go:130","message":"Activator targeting: 10.244.3.22:8112","commit":"64225b5","knative.dev/controller":"activator","knative.dev/pod":"activator-64947fb58f-jfd95"}
{"severity":"info","timestamp":"2025-01-22T17:54:05.333Z","logger":"activator","caller":"handler/handler.go:130","message":"Activator targeting: 10.244.1.13:8112","commit":"64225b5","knative.dev/controller":"activator","knative.dev/pod":"activator-64947fb58f-jfd95"}
{"severity":"info","timestamp":"2025-01-22T17:54:08.443Z","logger":"activator","caller":"handler/handler.go:130","message":"Activator targeting: 10.244.4.12:8112","commit":"64225b5","knative.dev/controller":"activator","knative.dev/pod":"activator-64947fb58f-jfd95"}


stream.go:304: E 17:52:47.397 activator-64947fb58f-jfd95 [activator] [serving-tests/probe-runtime-http-get-wmhzjpwo-00001] error reverse proxying request; sockstat: sockets: used 200
          TCP: inuse 25 orphan 0 tw 20 alloc 1576 mem 43
          UDP: inuse 0 mem 0
          UDPLITE: inuse 0
          RAW: inuse 0
          FRAG: inuse 0 memory 0
           err=timed out dialing 10.96.2.212:8112 after 21.22s
           
$ k get svc -n serving-tests          
probe-runtime-exec-period-1-vbkcvmgz-00001-private         ClusterIP      10.96.141.59    <none>                                                   80/TCP,443/
TCP,9090/TCP,9091/TCP,8022/TCP,8012/TCP   7m57s
probe-runtime-exec-ptzfghny-00001-private                  ClusterIP      10.96.118.34    <none>                                                   80/TCP,443/
TCP,9090/TCP,9091/TCP,8022/TCP,8012/TCP   7m44s
probe-runtime-http-get-period-1-qtobdtaj-00001-private     ClusterIP      10.96.219.206   <none>                                                   80/TCP,443/
TCP,9090/TCP,9091/TCP,8022/TCP,8012/TCP   8m23s
probe-runtime-http-get-wmhzjpwo-00001-private              ClusterIP      10.96.2.212     <none>                                                   80/TCP,443/
TCP,9090/TCP,9091/TCP,8022/TCP,8012/TCP   7m10s
probe-runtime-tcp-socket-hcvoayoq-00001-private            ClusterIP      10.96.28.73     <none>                                                   80/TCP,443/
TCP,9090/TCP,9091/TCP,8022/TCP,8012/TCP   7m22s
probe-runtime-tcp-socket-period-1-zzylxsbu-00001-private   ClusterIP      10.96.64.162    <none>                                                   80/TCP,443/
TCP,9090/TCP,9091/TCP,8022/TCP,8012/TCP   8m10s
r

10.96.2.212 is a cluster IP not a pod IP and so 8112 is not directly accesible.

[dprotaso]

Hey curious - do you have any logging why the activator switched from Pod IP to cluster IP?

[skonto]

For the other services I see:

2025-01-22T17:52:02.391474373Z stdout F {"severity":"debug","timestamp":"2025-01-22T17:52:02.391Z","logger":"activator","caller":"net/revision_backends.go:315","message":"ClusterIP is no longer healthy.","commit":"64225b5","knative.dev/controller":"activator","knative.dev/pod":"activator-64947fb58f-jfd95","knative.dev/key":"serving-tests/probe-runtime-tcp-socket-hcvoayoq-00001"}

2025-01-22T17:52:02.39147817Z stdout F {"severity":"debug","timestamp":"2025-01-22T17:52:02.391Z","logger":"activator","caller":"net/revision_backends.go:422","message":"Revision state","commit":"64225b5","knative.dev/controller":"activator","knative.dev/pod":"activator-64947fb58f-jfd95","knative.dev/key":"serving-tests/probe-runtime-tcp-socket-hcvoayoq-00001","dests":{"ready":"","notReady":""},"healthy":{"keys":""},"clusterIPHealthy":false}

2025-01-22T17:52:02.391481536Z stdout F {"severity":"debug","timestamp":"2025-01-22T17:52:02.391Z","logger":"activator","caller":"net/revision_backends.go:430","message":"Not Probing on timer","commit":"64225b5","knative.dev/controller":"activator","knative.dev/pod":"activator-64947fb58f-jfd95","knative.dev/key":"serving-tests/probe-runtime-tcp-socket-hcvoayoq-00001"}

...
2025-01-22T17:52:12.915257357Z stdout F {"severity":"debug","timestamp":"2025-01-22T17:52:12.914Z","logger":"activator","caller":"net/revision_backends.go:422","message":"Revision state","commit":"64225b5","knative.dev/controller":"activator","knative.dev/pod":"activator-64947fb58f-jfd95","knative.dev/key":"serving-tests/probe-runtime-tcp-socket-hcvoayoq-00001","dests":{"ready":"","notReady":"10.244.3.19:8012"},"healthy":{"keys":"10.244.3.19:8012"},"clusterIPHealthy":false}

...
2025-01-22T17:52:12.942159871Z stdout F {"severity":"debug","timestamp":"2025-01-22T17:52:12.942Z","logger":"activator","caller":"net/revision_backends.go:422","message":"Revision state","commit":"64225b5","knative.dev/controller":"activator","knative.dev/pod":"activator-64947fb58f-jfd95","knative.dev/key":"serving-tests/probe-runtime-tcp-socket-hcvoayoq-00001","dests":{"ready":"10.244.3.19:8012","notReady":""},"healthy":{"keys":"10.244.3.19:8012"},"clusterIPHealthy":false}

ClusterIP never gets ready before the pod.

For the faulty one:

2025-01-22T17:52:17.30845975Z stdout F {"severity":"debug","timestamp":"2025-01-22T17:52:17.308Z","logger":"activator","caller":"net/revision_backends.go:427","message":"Probing on timer","commit":"64225b5","knative.dev/controller":"activator","knative.dev/pod":"activator-64947fb58f-jfd95","knative.dev/key":"serving-tests/probe-runtime-http-get-wmhzjpwo-00001"}

2025-01-22T17:52:25.06541205Z stdout F {"severity":"debug","timestamp":"2025-01-22T17:52:25.065Z","logger":"activator","caller":"net/revision_backends.go:403","message":"ClusterIP is successfully probed: 10.96.2.212:80 (ready backends: 0)","commit":"64225b5","knative.dev/controller":"activator","knative.dev/pod":"activator-64947fb58f-jfd95","knative.dev/key":"serving-tests/probe-runtime-http-get-wmhzjpwo-00001"}

2025-01-22T17:52:25.066174208Z stdout F {"severity":"debug","timestamp":"2025-01-22T17:52:25.065Z","logger":"activator","caller":"net/revision_backends.go:391","message":"ClusterIP 10.96.2.212:80 already probed (ready backends: 1)","commit":"64225b5","knative.dev/controller":"activator","knative.dev/pod":"activator-64947fb58f-jfd95","knative.dev/key":"serving-tests/probe-runtime-http-get-wmhzjpwo-00001"}
...
2025-01-22T17:52:25.066871218Z stdout F {"severity":"info","timestamp":"2025-01-22T17:52:25.066Z","logger":"activator","caller":"net/throttler.go:335","message":"Updating Revision Throttler with: clusterIP = 10.96.2.212:80, trackers = 0, backends = 1","commit":"64225b5","knative.dev/controller":"activator","knative.dev/pod":"activator-64947fb58f-jfd95","knative.dev/key":"serving-tests/probe-runtime-http-get-wmhzjpwo-00001"}

I guess clusterIP passed first. In the logic we have this is legitimate. See here.

activator.log