Skip to content

Conversation

zhengkezhou1
Copy link
Contributor

@zhengkezhou1 zhengkezhou1 commented Jun 11, 2025

Add health checking for Upstram: epp.

Fix #240

Copy link

netlify bot commented Jun 11, 2025

Deploy Preview for gateway-api-inference-extension ready!

Name Link
🔨 Latest commit b7aa93a
🔍 Latest deploy log https://app.netlify.com/projects/gateway-api-inference-extension/deploys/684eaa1a60e3770008a9de19
😎 Deploy Preview https://deploy-preview-966--gateway-api-inference-extension.netlify.app
📱 Preview on mobile
Toggle QR Code...

QR Code

Use your smartphone camera to open QR code link.

To edit notification comments on pull requests, go to your Netlify project configuration.

@k8s-ci-robot k8s-ci-robot added the cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. label Jun 11, 2025
@k8s-ci-robot k8s-ci-robot requested review from danehans and Jeffwan June 11, 2025 14:11
@k8s-ci-robot k8s-ci-robot added the needs-ok-to-test Indicates a PR that requires an org member to verify it is safe to test. label Jun 11, 2025
@k8s-ci-robot
Copy link
Contributor

Hi @zhengkezhou1. Thanks for your PR.

I'm waiting for a kubernetes-sigs member to verify that this patch is reasonable to test. If it is, they should reply with /ok-to-test on its own line. Until that is done, I will not automatically test new commits in this PR, but the usual testing commands by org members will still work. Regular contributors should join the org to skip this step.

Once the patch is verified, the new status will be reflected by the ok-to-test label.

I understand the commands that are listed here.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes-sigs/prow repository.

@k8s-ci-robot k8s-ci-robot added the size/S Denotes a PR that changes 10-29 lines, ignoring generated files. label Jun 11, 2025
@zhengkezhou1
Copy link
Contributor Author

Hi @danehans! can you give a look? I have no idea what went wrong, I tried many times to fix it but couldn't, here are what I observed::

Health checking failed:

[2025-06-11 13:55:27.132][1][debug][hc] [source/extensions/health_checkers/grpc/health_checker_impl.cc:248] [Tags: "ConnectionId":"64"] connection/stream error health_flags=/failed_active_hc
[2025-06-11 13:55:32.136][1][debug][hc] [source/extensions/health_checkers/grpc/health_checker_impl.cc:248] [Tags: "ConnectionId":"66"] connection/stream error health_flags=/failed_active_hc

A TLS connection error occurred,

TLS_error:|268435703:SSL routines:OPENSSL_internal:WRONG_VERSION_NUMBER:TLS_error_end

NOTE: I changed the default value of secureServing by passing secureServing false, and it didn't seem to work

epp  | {"level":"info","ts":"2025-06-11T14:15:03Z","logger":"setup","caller":"cmd/main.go:155","msg":"Flags processed","flags":{"DestinationEndpointHintMetadataNamespace":"envoy.lb","certPath":"","destinationEndpointHintKey":"x-gateway-destination-endpoint","grpcHealthPort":9003,"grpcPort":9002,"kubeconfig":"","kvCacheUsagePercentageMetric":"vllm:gpu_cache_usage_perc","loraInfoMetric":"vllm:lora_requests_info","metricsPort":9090,"poolName":"vllm-llama3-8b-instruct","poolNamespace":"inf-ext-e2e","refreshMetricsInterval":50000000,"refreshPrometheusMetricsInterval":5000000000,"secureServing":true,"totalQueuedRequestsMetric":"vllm:num_requests_waiting","v":4,"zap-devel":true,"zap-encoder":{},"zap-log-level":{},"zap-stacktrace-level":{},"zap-time-encoding":{}}}

Full logs follow:

epp logs

epp  | {"level":"info","ts":"2025-06-11T14:15:03Z","logger":"setup","caller":"cmd/main.go:155","msg":"Flags processed","flags":{"DestinationEndpointHintMetadataNamespace":"envoy.lb","certPath":"","destinationEndpointHintKey":"x-gateway-destination-endpoint","grpcHealthPort":9003,"grpcPort":9002,"kubeconfig":"","kvCacheUsagePercentageMetric":"vllm:gpu_cache_usage_perc","loraInfoMetric":"vllm:lora_requests_info","metricsPort":9090,"poolName":"vllm-llama3-8b-instruct","poolNamespace":"inf-ext-e2e","refreshMetricsInterval":50000000,"refreshPrometheusMetricsInterval":5000000000,"secureServing":true,"totalQueuedRequestsMetric":"vllm:num_requests_waiting","v":4,"zap-devel":true,"zap-encoder":{},"zap-log-level":{},"zap-stacktrace-level":{},"zap-time-encoding":{}}}
{"level":"info","ts":"2025-06-11T14:15:03Z","logger":"saturation-detector-config","caller":"env/env.go:34","msg":"Environment variable not set, using default value","key":"SD_QUEUE_DEPTH_THRESHOLD","defaultValue":5}
{"level":"info","ts":"2025-06-11T14:15:03Z","logger":"saturation-detector-config","caller":"env/env.go:34","msg":"Environment variable not set, using default value","key":"SD_KV_CACHE_UTIL_THRESHOLD","defaultValue":0.8}
{"level":"info","ts":"2025-06-11T14:15:03Z","logger":"saturation-detector-config","caller":"env/env.go:34","msg":"Environment variable not set, using default value","key":"SD_METRICS_STALENESS_THRESHOLD","defaultValue":0.2}
{"level":"info","ts":"2025-06-11T14:15:03Z","logger":"saturation-detector-config","caller":"saturationdetector/config.go:68","msg":"SaturationDetector configuration loaded from env","config":"&{QueueDepthThreshold:5 KVCacheUtilThreshold:0.8 MetricsStalenessThreshold:200ms}"}
epp  | {"level":"Level(-2)","ts":"2025-06-11T14:15:04Z","logger":"SaturationDetector","caller":"saturationdetector/saturationdetector.go:88","msg":"Creating new SaturationDetector","queueDepthThreshold":5,"kvCacheUtilThreshold":0.8,"metricsStalenessThreshold":"200ms"}
{"level":"info","ts":"2025-06-11T14:15:04Z","logger":"setup","caller":"cmd/main.go:301","msg":"ExtProc server runner added to manager."}
{"level":"info","ts":"2025-06-11T14:15:04Z","logger":"setup","caller":"cmd/main.go:268","msg":"Controller manager starting"}
{"level":"info","ts":"2025-06-11T14:15:04Z","logger":"controller-runtime.metrics","caller":"server/server.go:208","msg":"Starting metrics server"}
{"level":"info","ts":"2025-06-11T14:15:04Z","logger":"controller-runtime.metrics","caller":"server/server.go:247","msg":"Serving metrics server","bindAddress":":9090","secure":false}
{"level":"Level(-3)","ts":"2025-06-11T14:15:04Z","logger":"controller-runtime.cache","caller":"cache/reflector.go:357","msg":"Starting reflector","type":"*v1alpha2.InferenceModel","resyncPeriod":39113.219589,"reflector":"pkg/mod/k8s.io/client-go@v0.33.1/tools/cache/reflector.go:285"}
{"level":"Level(-3)","ts":"2025-06-11T14:15:04Z","logger":"controller-runtime.cache","caller":"cache/reflector.go:403","msg":"Listing and watching","type":"*v1alpha2.InferenceModel","reflector":"pkg/mod/k8s.io/client-go@v0.33.1/tools/cache/reflector.go:285"}
{"level":"Level(-2)","ts":"2025-06-11T14:15:04Z","logger":"controller-runtime.cache","caller":"cache/reflector.go:430","msg":"Caches populated","type":"*v1alpha2.InferenceModel","reflector":"pkg/mod/k8s.io/client-go@v0.33.1/tools/cache/reflector.go:285"}
{"level":"info","ts":"2025-06-11T14:15:04Z","caller":"runnable/grpc.go:35","msg":"gRPC server starting","name":"health"}
{"level":"info","ts":"2025-06-11T14:15:04Z","caller":"controller/controller.go:246","msg":"Starting EventSource","controller":"pod","controllerGroup":"","controllerKind":"Pod","source":"kind source: *v1.Pod"}
{"level":"info","ts":"2025-06-11T14:15:04Z","caller":"controller/controller.go:246","msg":"Starting EventSource","controller":"inferencepool","controllerGroup":"inference.networking.x-k8s.io","controllerKind":"InferencePool","source":"kind source: *v1alpha2.InferencePool"}
epp  | {"level":"Level(-3)","ts":"2025-06-11T14:15:04Z","logger":"controller-runtime.cache","caller":"cache/reflector.go:357","msg":"Starting reflector","type":"*v1alpha2.InferencePool","resyncPeriod":33361.222978347,"reflector":"pkg/mod/k8s.io/client-go@v0.33.1/tools/cache/reflector.go:285"}
{"level":"Level(-3)","ts":"2025-06-11T14:15:04Z","logger":"controller-runtime.cache","caller":"cache/reflector.go:403","msg":"Listing and watching","type":"*v1alpha2.InferencePool","reflector":"pkg/mod/k8s.io/client-go@v0.33.1/tools/cache/reflector.go:285"}
{"level":"info","ts":"2025-06-11T14:15:04Z","caller":"runnable/grpc.go:44","msg":"gRPC server listening","name":"health","port":9003}
{"level":"info","ts":"2025-06-11T14:15:04Z","caller":"controller/controller.go:246","msg":"Starting EventSource","controller":"inferencemodel","controllerGroup":"inference.networking.x-k8s.io","controllerKind":"InferenceModel","source":"kind source: *v1alpha2.InferenceModel"}
epp  | {"level":"Level(-3)","ts":"2025-06-11T14:15:04Z","logger":"controller-runtime.cache","caller":"cache/reflector.go:357","msg":"Starting reflector","type":"*v1.Pod","resyncPeriod":34402.857457632,"reflector":"pkg/mod/k8s.io/client-go@v0.33.1/tools/cache/reflector.go:285"}
{"level":"Level(-3)","ts":"2025-06-11T14:15:04Z","logger":"controller-runtime.cache","caller":"cache/reflector.go:403","msg":"Listing and watching","type":"*v1.Pod","reflector":"pkg/mod/k8s.io/client-go@v0.33.1/tools/cache/reflector.go:285"}
{"level":"Level(-2)","ts":"2025-06-11T14:15:04Z","logger":"controller-runtime.cache","caller":"cache/reflector.go:430","msg":"Caches populated","type":"*v1alpha2.InferencePool","reflector":"pkg/mod/k8s.io/client-go@v0.33.1/tools/cache/reflector.go:285"}
{"level":"Level(-2)","ts":"2025-06-11T14:15:04Z","logger":"controller-runtime.cache","caller":"cache/reflector.go:430","msg":"Caches populated","type":"*v1.Pod","reflector":"pkg/mod/k8s.io/client-go@v0.33.1/tools/cache/reflector.go:285"}
{"level":"info","ts":"2025-06-11T14:15:04Z","caller":"controller/controller.go:186","msg":"Starting Controller","controller":"pod","controllerGroup":"","controllerKind":"Pod"}
{"level":"info","ts":"2025-06-11T14:15:04Z","caller":"controller/controller.go:195","msg":"Starting workers","controller":"pod","controllerGroup":"","controllerKind":"Pod","worker count":1}
{"level":"info","ts":"2025-06-11T14:15:04Z","caller":"controller/controller.go:186","msg":"Starting Controller","controller":"inferencepool","controllerGroup":"inference.networking.x-k8s.io","controllerKind":"InferencePool"}
{"level":"info","ts":"2025-06-11T14:15:04Z","caller":"controller/controller.go:195","msg":"Starting workers","controller":"inferencepool","controllerGroup":"inference.networking.x-k8s.io","controllerKind":"InferencePool","worker count":1}
{"level":"Level(-2)","ts":"2025-06-11T14:15:04Z","caller":"controller/inferencepool_reconciler.go:45","msg":"Reconciling InferencePool","controller":"inferencepool","controllerGroup":"inference.networking.x-k8s.io","controllerKind":"InferencePool","InferencePool":{"name":"vllm-llama3-8b-instruct","namespace":"inf-ext-e2e"},"namespace":"inf-ext-e2e","name":"vllm-llama3-8b-instruct","reconcileID":"3b2c5827-fa09-49f3-9f43-10dba5cdd30e","inferencePool":{"name":"vllm-llama3-8b-instruct","namespace":"inf-ext-e2e"}}
{"level":"info","ts":"2025-06-11T14:15:04Z","caller":"controller/controller.go:186","msg":"Starting Controller","controller":"inferencemodel","controllerGroup":"inference.networking.x-k8s.io","controllerKind":"InferenceModel"}
{"level":"info","ts":"2025-06-11T14:15:04Z","caller":"controller/controller.go:195","msg":"Starting workers","controller":"inferencemodel","controllerGroup":"inference.networking.x-k8s.io","controllerKind":"InferenceModel","worker count":1}
epp  | {"level":"Level(-4)","ts":"2025-06-11T14:15:04Z","caller":"datastore/datastore.go:125","msg":"Updating inference pool endpoints","controller":"inferencepool","controllerGroup":"inference.networking.x-k8s.io","controllerKind":"InferencePool","InferencePool":{"name":"vllm-llama3-8b-instruct","namespace":"inf-ext-e2e"},"namespace":"inf-ext-e2e","name":"vllm-llama3-8b-instruct","reconcileID":"3b2c5827-fa09-49f3-9f43-10dba5cdd30e","inferencePool":{"name":"vllm-llama3-8b-instruct","namespace":"inf-ext-e2e"},"selector":{"app":"vllm-llama3-8b-instruct"}}
{"level":"info","ts":"2025-06-11T14:15:07Z","caller":"runnable/grpc.go:35","msg":"gRPC server starting","name":"ext-proc"}
{"level":"info","ts":"2025-06-11T14:15:07Z","caller":"runnable/grpc.go:44","msg":"gRPC server listening","name":"ext-proc","port":9002}
{"level":"Level(-3)","ts":"2025-06-11T14:15:17Z","caller":"controller/pod_reconciler.go:51","msg":"Pod being reconciled","controller":"pod","controllerGroup":"","controllerKind":"Pod","Pod":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-75dcm","namespace":"inf-ext-e2e"},"namespace":"inf-ext-e2e","name":"vllm-llama3-8b-instruct-77ff4f95f9-75dcm","reconcileID":"441fff43-a190-4d19-b969-ca10c052cc89","name":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-75dcm","namespace":"inf-ext-e2e"}}
{"level":"Level(-4)","ts":"2025-06-11T14:15:17Z","caller":"controller/pod_reconciler.go:96","msg":"Pod removed or not added","controller":"pod","controllerGroup":"","controllerKind":"Pod","Pod":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-75dcm","namespace":"inf-ext-e2e"},"namespace":"inf-ext-e2e","name":"vllm-llama3-8b-instruct-77ff4f95f9-75dcm","reconcileID":"441fff43-a190-4d19-b969-ca10c052cc89","name":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-75dcm","namespace":"inf-ext-e2e"}}
{"level":"Level(-3)","ts":"2025-06-11T14:15:17Z","caller":"controller/pod_reconciler.go:51","msg":"Pod being reconciled","controller":"pod","controllerGroup":"","controllerKind":"Pod","Pod":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-qx8st","namespace":"inf-ext-e2e"},"namespace":"inf-ext-e2e","name":"vllm-llama3-8b-instruct-77ff4f95f9-qx8st","reconcileID":"0cb62c8c-283c-4418-a3eb-5b093dcb12d5","name":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-qx8st","namespace":"inf-ext-e2e"}}
{"level":"Level(-4)","ts":"2025-06-11T14:15:17Z","caller":"controller/pod_reconciler.go:96","msg":"Pod removed or not added","controller":"pod","controllerGroup":"","controllerKind":"Pod","Pod":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-qx8st","namespace":"inf-ext-e2e"},"namespace":"inf-ext-e2e","name":"vllm-llama3-8b-instruct-77ff4f95f9-qx8st","reconcileID":"0cb62c8c-283c-4418-a3eb-5b093dcb12d5","name":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-qx8st","namespace":"inf-ext-e2e"}}
{"level":"Level(-3)","ts":"2025-06-11T14:15:17Z","caller":"controller/pod_reconciler.go:51","msg":"Pod being reconciled","controller":"pod","controllerGroup":"","controllerKind":"Pod","Pod":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-s6l92","namespace":"inf-ext-e2e"},"namespace":"inf-ext-e2e","name":"vllm-llama3-8b-instruct-77ff4f95f9-s6l92","reconcileID":"b6614bc3-099a-4be5-8c19-9ec015216757","name":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-s6l92","namespace":"inf-ext-e2e"}}
{"level":"Level(-4)","ts":"2025-06-11T14:15:17Z","caller":"controller/pod_reconciler.go:96","msg":"Pod removed or not added","controller":"pod","controllerGroup":"","controllerKind":"Pod","Pod":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-s6l92","namespace":"inf-ext-e2e"},"namespace":"inf-ext-e2e","name":"vllm-llama3-8b-instruct-77ff4f95f9-s6l92","reconcileID":"b6614bc3-099a-4be5-8c19-9ec015216757","name":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-s6l92","namespace":"inf-ext-e2e"}}
{"level":"Level(-3)","ts":"2025-06-11T14:15:17Z","caller":"controller/pod_reconciler.go:51","msg":"Pod being reconciled","controller":"pod","controllerGroup":"","controllerKind":"Pod","Pod":{"name"epp  | 0360-4fb5-9f76-35423caf2116","name":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-75dcm","namespace":"inf-ext-e2e"}}nstruct-77ff4f95f9-75dcm","reconcileID":"fa2873f3-
{"level":"Level(-4)","ts":"2025-06-11T14:15:17Z","caller":"controller/pod_reconciler.go:96","msg":"Pod removed or not added","controller":"pod","controllerGroup":"","controllerKind":"Pod","Pod":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-75dcm","namespace":"inf-ext-e2e"},"namespace":"inf-ext-e2e","name":"vllm-llama3-8b-instruct-77ff4f95f9-75dcm","reconcileID":"fa2873f3-0360-4fb5-9f76-35423caf2116","name":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-75dcm","namespace":"inf-ext-e2e"}}
{"level":"Level(-3)","ts":"2025-06-11T14:15:17Z","caller":"controller/pod_reconciler.go:51","msg":"Pod being reconciled","controller":"pod","controllerGroup":"","controllerKind":"Pod","Pod":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-s6l92","namespace":"inf-ext-e2e"},"namespace":"inf-ext-e2e","name":"vllm-llama3-8b-instruct-77ff4f95f9-s6l92","reconcileID":"f4ea4974-07a4-4c92-9b4b-393a6c5953e2","name":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-s6l92","namespace":"inf-ext-e2e"}}
{"level":"Level(-4)","ts":"2025-06-11T14:15:17Z","caller":"controller/pod_reconciler.go:96","msg":"Pod removed or not added","controller":"pod","controllerGroup":"","controllerKind":"Pod","Pod":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-s6l92","namespace":"inf-ext-e2e"},"namespace":"inf-ext-e2e","name":"vllm-llama3-8b-instruct-77ff4f95f9-s6l92","reconcileID":"f4ea4974-07a4-4c92-9b4b-393a6c5953e2","name":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-s6l92","namespace":"inf-ext-e2e"}}
{"level":"Level(-3)","ts":"2025-06-11T14:15:17Z","caller":"controller/pod_reconciler.go:51","msg":"Pod being reconciled","controller":"pod","controllerGroup":"","controllerKind":"Pod","Pod":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-qx8st","namespace":"inf-ext-e2e"},"namespace":"inf-ext-e2e","name":"vllm-llama3-8b-instruct-77ff4f95f9-qx8st","reconcileID":"4b27873f-6328-4faa-bc80-be2242c03118","name":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-qx8st","namespace":"inf-ext-e2e"}}
{"level":"Level(-4)","ts":"2025-06-11T14:15:17Z","caller":"controller/pod_reconciler.go:96","msg":"Pod removed or not added","controller":"pod","controllerGroup":"","controllerKind":"Pod","Pod":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-qx8st","namespace":"inf-ext-e2e"},"namespace":"inf-ext-e2e","name":"vllm-llama3-8b-instruct-77ff4f95f9-qx8st","reconcileID":"4b27873f-6328-4faa-bc80-be2242c03118","name":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-qx8st","namespace":"inf-ext-e2e"}}
{"level":"Level(-3)","ts":"2025-06-11T14:15:17Z","caller":"controller/pod_reconciler.go:51","msg":"Pod being reconciled","controller":"pod","controllerGroup":"","controllerKind":"Pod","Pod":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-75dcm","namespace":"inf-ext-e2e"},"namespace":"inf-ext-e2e","name":"vllm-llama3-8b-instruct-77ff4f95f9-75dcm","reconcileID":"37d2f697-1372-47c6-9fa5-8859493d8803","name":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-75dcm","namespace":"inf-ext-e2e"}}
{"level":"Level(-4)","ts":"2025-06-11T14:15:17Z","caller":"controller/pod_reconciler.go:96","msg":"Pod removed or not added","controller":"pod","controllerGroup":"","controllerKind":"Pod","Pod":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-75dcm","namespace":"inf-ext-e2e"},"namespace":"inf-ext-e2e","name":"vllm-llama3-8b-instruct-77ff4f95f9-75dcm","reconcileID":"37d2f697-1372-47c6-9fa5-8859493d8803","name":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-75dcm","namespace":"inf-ext-e2e"}}
{"level":"Level(-3)","ts":"2025-06-11T14:15:17Z","caller":"controller/pod_reconciler.go:51","msg":"Pod being reconciled","controller":"pod","controllerGroup":"","controllerKind":"Pod","Pod":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-s6l92","namespace":"inf-ext-e2e"},"namespace":"inf-ext-e2e","name":"vllm-llama3-8b-instruct-77ff4f95f9-s6l92","reconcileID":"3e98bb76-5d67-4cc5-9d10-d3ff921b60b3","name":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-s6l92","namespace":"inf-ext-e2e"}}
{"level":"Level(-4)","ts":"2025-06-11T14:15:17Z","caller":"controller/pod_reconciler.go:96","msg":"Pod removed or not added","controller":"pod","controllerGroup":"","controllerKind":"Pod","Pod":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-s6l92","namespace":"inf-ext-e2e"},"namespace":"inf-ext-e2e","name":"vllm-llama3-8b-instruct-77ff4f95f9-s6l92","reconcileID":"3e98bb76-5d67-4cc5-9d10-d3ff921b60b3","name":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-s6l92","namespace":"inf-ext-e2e"}}
{"level":"Level(-3)","ts":"2025-06-11T14:15:17Z","caller":"controller/pod_reconciler.go:51","msg":"Pod being reconciled","controller":"pod","controllerGroup":"","controllerKind":"Pod","Pod":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-qx8st","namespace":"inf-ext-e2e"},"namespace":"inf-ext-e2e","name":"vllm-llama3-8b-instruct-77ff4f95f9-qx8st","reconcileID":"18e2fdfc-0139-4867-be80-179c83a8ae8f","name":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-qx8st","namespace":"inf-ext-e2e"}}
epp  | {"level":"Level(-4)","ts":"2025-06-11T14:15:17Z","caller":"controller/pod_reconciler.go:96","msg":"Pod removed or not added","controller":"pod","controllerGroup":"","controllerKind":"Pod","Pod":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-qx8st","namespace":"inf-ext-e2e"},"namespace":"inf-ext-e2e","name":"vllm-llama3-8b-instruct-77ff4f95f9-qx8st","reconcileID":"18e2fdfc-0139-4867-be80-179c83a8ae8f","name":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-qx8st","namespace":"inf-ext-e2e"}}
{"level":"Level(-3)","ts":"2025-06-11T14:15:20Z","caller":"controller/pod_reconciler.go:51","msg":"Pod being reconciled","controller":"pod","controllerGroup":"","controllerKind":"Pod","Pod":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-75dcm","namespace":"inf-ext-e2e"},"namespace":"inf-ext-e2e","name":"vllm-llama3-8b-instruct-77ff4f95f9-75dcm","reconcileID":"b7cf7a27-ad81-4805-bee8-404af8a0cd4c","name":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-75dcm","namespace":"inf-ext-e2e"}}
{"level":"Level(-2)","ts":"2025-06-11T14:15:20Z","caller":"controller/pod_reconciler.go:102","msg":"Pod already exists","controller":"pod","controllerGroup":"","controllerKind":"Pod","Pod":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-75dcm","namespace":"inf-ext-e2e"},"namespace":"inf-ext-e2e","name":"vllm-llama3-8b-instruct-77ff4f95f9-75dcm","reconcileID":"b7cf7a27-ad81-4805-bee8-404af8a0cd4c","name":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-75dcm","namespace":"inf-ext-e2e"}}
epp  | {"level":"Level(-2)","ts":"2025-06-11T14:15:20Z","caller":"metrics/pod_metrics.go:92","msg":"Starting refresher","pod":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-75dcm","namespace":"inf-ext-e2e"},"pod":"{NamespacedName:inf-ext-e2e/vllm-llama3-8b-instruct-77ff4f95f9-75dcm Address:10.244.0.14 Labels:map[app:vllm-llama3-8b-instruct pod-template-hash:77ff4f95f9]}"}
{"level":"Level(-3)","ts":"2025-06-11T14:15:21Z","caller":"controller/pod_reconciler.go:51","msg":"Pod being reconciled","controller":"pod","controllerGroup":"","controllerKind":"Pod","Pod":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-s6l92","namespace":"inf-ext-e2e"},"namespace":"inf-ext-e2e","name":"vllm-llama3-8b-instruct-77ff4f95f9-s6l92","reconcileID":"70038967-94c7-4a0c-8de7-e3d528e0d528","name":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-s6l92","namespace":"inf-ext-e2e"}}
{"level":"Level(-2)","ts":"2025-06-11T14:15:21Z","caller":"controller/pod_reconciler.go:102","msg":"Pod already exists","controller":"pod","controllerGroup":"","controllerKind":"Pod","Pod":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-s6l92","namespace":"inf-ext-e2e"},"namespace":"inf-ext-e2e","name":"vllm-llama3-8b-instruct-77ff4f95f9-s6l92","reconcileID":"70038967-94c7-4a0c-8de7-e3d528e0d528","name":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-s6l92","namespace":"inf-ext-e2e"}}
{"level":"Level(-2)","ts":"2025-06-11T14:15:21Z","caller":"metrics/pod_metrics.go:92","msg":"Starting refresher","pod":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-s6l92","namespace":"inf-ext-e2e"},"pod":"{NamespacedName:inf-ext-e2e/vllm-llama3-8b-instruct-77ff4f95f9-s6l92 Address:10.244.0.15 Labels:map[app:vllm-llama3-8b-instruct pod-template-hash:77ff4f95f9]}"}
epp  | {"level":"Level(-3)","ts":"2025-06-11T14:15:23Z","caller":"controller/pod_reconciler.go:51","msg":"Pod being reconciled","controller":"pod","controllerGroup":"","controllerKind":"Pod","Pod":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-qx8st","namespace":"inf-ext-e2e"},"namespace":"inf-ext-e2e","name":"vllm-llama3-8b-instruct-77ff4f95f9-qx8st","reconcileID":"45128d29-6674-48b4-963a-06b27de5d830","name":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-qx8st","namespace":"inf-ext-e2e"}}
epp  | {"level":"Level(-2)","ts":"2025-06-11T14:15:23Z","caller":"controller/pod_reconciler.go:102","msg":"Pod already exists","controller":"pod","controllerGroup":"","controllerKind":"Pod","Pod":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-qx8st","namespace":"inf-ext-e2e"},"namespace":"inf-ext-e2e","name":"vllm-llama3-8b-instruct-77ff4f95f9-qx8st","reconcileID":"45128d29-6674-48b4-963a-06b27de5d830","name":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-qx8st","namespace":"inf-ext-e2e"}}
epp  | {"level":"Level(-2)","ts":"2025-06-11T14:15:23Z","caller":"metrics/pod_metrics.go:92","msg":"Starting refresher","pod":{"name":"vllm-llama3-8b-instruct-77ff4f95f9-qx8st","namespace":"inf-ext-e2e"},"pod":"{NamespacedName:inf-ext-e2e/vllm-llama3-8b-instruct-77ff4f95f9-qx8st Address:10.244.0.16 Labels:map[app:vllm-llama3-8b-instruct pod-template-hash:77ff4f95f9]}"}
epp  | {"level":"Level(-2)","ts":"2025-06-11T14:15:23Z","caller":"controller/inferencemodel_reconciler.go:47","msg":"Reconciling InferenceModel","controller":"inferencemodel","controllerGroup":"inference.networking.x-k8s.io","controllerKind":"InferenceModel","InferenceModel":{"name":"inferencemodel-sample","namespace":"inf-ext-e2e"},"namespace":"inf-ext-e2e","name":"inferencemodel-sample","reconcileID":"f9eaaac4-0215-4328-baa9-5a95bbc67fcb","inferenceModel":{"name":"inferencemodel-sample","namespace":"inf-ext-e2e"}}
epp  | {"level":"Level(-2)","ts":"2025-06-11T14:15:23Z","caller":"controller/inferencemodel_reconciler.go:70","msg":"Added/Updated InferenceModel","controller":"inferencemodel","controllerGroup":"inference.networking.x-k8s.io","controllerKind":"InferenceModel","InferenceModel":{"name":"inferencemodel-sample","namespace":"inf-ext-e2e"},"namespace":"inf-ext-e2e","name":"inferencemodel-sample","reconcileID":"f9eaaac4-0215-4328-baa9-5a95bbc67fcb","inferenceModel":{"name":"inferencemodel-sample","namespace":"inf-ext-e2e"},"poolRef":{"group":"inference.networking.x-k8s.io","kind":"inferencepools","name":"vllm-llama3-8b-instruct"},"modelName":"food-review"}
epp  | {"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"requestcontrol/director.go:129","msg":"LLM request assembled","x-request-id":"e89f2637-a0ed-4bd6-823d-95738a7c1999","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical"}
epp  | {"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"requestcontrol/director.go:159","msg":"Critical request bypassing saturation check.","x-request-id":"e89f2637-a0ed-4bd6-823d-95738a7c1999","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical"}
epp  | {"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"scheduling/scheduler.go:109","msg":"Scheduling a request, Metrics: [{Pod:{NamespacedName:inf-ext-e2e/vllm-llama3-8b-instruct-77ff4f95f9-75dcm Address:10.244.0.14 Labels:map[app:vllm-llama3-8b-instruct pod-template-hash:77ff4f95f9]} MetricsState:{ActiveModels:map[] WaitingModels:map[] MaxActiveModels:0 RunningQueueSize:0 WaitingQueueSize:0 KVCacheUsagePercent:0 KvCacheMaxTokenCapacity:0 UpdateTime:2025-06-11 14:15:23.785517286 +0000 UTC m=+20.217038531}} {Pod:{NamespacedName:inf-ext-e2e/vllm-llama3-8b-instruct-77ff4f95f9-s6l92 Address:10.244.0.15 Labels:map[app:vllm-llama3-8b-instruct pod-template-hash:77ff4f95f9]} MetricsState:{ActiveModels:map[] WaitingModels:map[] MaxActiveModels:0 RunningQueueSize:0 WaitingQueueSize:0 KVCacheUsagePercent:0 KvCacheMaxTokenCapacity:0 UpdateTime:2025-06-11 14:15:23.760275321 +0000 UTC m=+20.191796691}} {Pod:{NamespacedName:inf-ext-e2e/vllm-llama3-8b-instruct-77ff4f95f9-qx8st Address:10.244.0.16 Labels:map[app:vllm-llama3-8b-instruct pod-template-hash:77ff4f95f9]} MetricsState:{ActiveModels:map[] WaitingModels:map[] MaxActiveModels:0 RunningQueueSize:0 WaitingQueueSize:0 KVCacheUsagePercent:0 KvCacheMaxTokenCapacity:0 UpdateTime:2025-06-11 14:15:23.770412741 +0000 UTC m=+20.201934069}}]","x-request-id":"e89f2637-a0ed-4bd6-823d-95738a7c1999","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical","request":"RequestID: e89f2637-a0ed-4bd6-823d-95738a7c1999, TargetModel: food-review-1, PromptLength: 44, Headers: map[:authority:envoy.inf-ext-e2e.svc:8081 :method:POST :path:/v1/completions :scheme:http accept:*/* content-length:119 content-type:application/json user-agent:curl/7.83.1-DEV x-envoy-external-address:10.244.0.12 x-forwarded-for:10.244.0.12 x-forwarded-proto:http x-request-id:e89f2637-a0ed-4bd6-823d-95738a7c1999]"}
{"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"framework/scheduler_profile.go:127","msg":"Before running filter plugins","x-request-id":"e89f2637-a0ed-4bd6-823d-95738a7c1999","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical","pods":[{"NamespacedName":{"Namespace":"inf-ext-e2e","Name":"vllm-llama3-8b-instruct-77ff4f95f9-75dcm"},"Address":"10.244.0.14","Labels":{"app":"vllm-llama3-8b-instruct","pod-template-hash":"77ff4f95f9"},"ActiveModels":{},"WaitingModels":{},"MaxActiveModels":0,"RunningQueueSize":0,"WaitingQueueSize":0,"KVCacheUsagePercent":0,"KvCacheMaxTokenCapacity":0,"UpdateTime":"2025-06-11T14:15:23.785517286Z"},{"NamespacedName":{"Namespace":"inf-ext-e2e","Name":"vllm-llama3-8b-instruct-77ff4f95f9-s6l92"},"Address":"10.244.0.15","Labels":{"app":"vllm-llama3-8b-instruct","pod-template-hash":"77ff4f95f9"},"ActiveModels":{},"WaitingModels":{},"MaxActiveModels":0,"RunningQueueSize":0,"WaitingQueueSize":0,"KVCacheUsagePercent":0,"KvCacheMaxTokenCapacity":0,"UpdateTime":"2025-06-11T14:15:23.760275321Z"},{"NamespacedName":{"Namespace":"inf-ext-e2e","Name":"vllm-llama3-8b-instruct-77ff4f95f9-qx8st"},"Address":"10.244.0.16","Labels":{"app":"vllm-llama3-8b-instruct","pod-template-hash":"77ff4f95f9"},"ActiveModels":{},"WaitingModels":{},"MaxActiveModels":0,"RunningQueueSize":0,"WaitingQueueSize":0,"KVCacheUsagePercent":0,"KvCacheMaxTokenCapacity":0,"UpdateTime":"2025-06-11T14:15:23.770412741Z"}]}
{"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"framework/scheduler_profile.go:130","msg":"Running filter plugin","x-request-id":"e89f2637-a0ed-4bd6-823d-95738a7c1999","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical","plugin":"low-queue"}
{"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"framework/scheduler_profile.go:134","msg":"Filter plugin result","x-request-id":"e89f2637-a0ed-4bd6-823d-95738a7c1999","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical","plugin":"low-queue","pods":[{"NamespacedName":{"Namespace":"inf-ext-e2e","Name":"vllm-llama3-8b-instruct-77ff4f95f9-75dcm"},"Addreepp  | ash":"77ff4f95f9"},"ActiveModels":{},"WaitingModels":{},"MaxActiveModels":0,"RunningQueueSize":0,"WaitingQueueSize":0,"KVCacheUsagePercent":0,"KvCacheMaxTokenCapacity":0,"UpdateTime":"2025-06-11T14:15:23.785517286Z"},{"NamespacedName":{"Namespace":"inf-ext-e2e","Name":"vllm-llama3-8b-instruct-77ff4f95f9-s6l92"},"Address":"10.244.0.15","Labels":{"app":"vllm-llama3-8b-instruct","pod-template-hash":"77ff4f95f9"},"ActiveModels":{},"WaitingModels":{},"MaxActiveModels":0,"RunningQueueSize":0,"WaitingQueueSize":0,"KVCacheUsagePercent":0,"KvCacheMaxTokenCapacity":0,"UpdateTime":"2025-06-11T14:15:23.760275321Z"},{"NamespacedName":{"Namespace":"inf-ext-e2e","Name":"vllm-llama3-8b-instruct-77ff4f95f9-qx8st"},"Address":"10.244.0.16","Labels":{"app":"vllm-llama3-8b-instruct","pod-template-hash":"77ff4f95f9"},"ActiveModels":{},"WaitingModels":{},"MaxActiveModels":0,"RunningQueueSize":0,"WaitingQueueSize":0,"KVCacheUsagePercent":0,"KvCacheMaxTokenCapacity":0,"UpdateTime":"2025-06-11T14:15:23.770412741Z"}]}
epp  | {"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"framework/scheduler_profile.go:139","msg":"After running filter plugins","x-request-id":"e89f2637-a0ed-4bd6-823d-95738a7c1999","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical"}
{"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"framework/scheduler_profile.go:146","msg":"Before running scorer plugins","x-request-id":"e89f2637-a0ed-4bd6-823d-95738a7c1999","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical","pods":[{"NamespacedName":{"Namespace":"inf-ext-e2e","Name":"vllm-llama3-8b-instruct-77ff4f95f9-75dcm"},"Address":"10.244.0.14","Labels":{"app":"vllm-llama3-8b-instruct","pod-template-hash":"77ff4f95f9"},"ActiveModels":{},"WaitingModels":{},"MaxActiveModels":0,"RunningQueueSize":0,"WaitingQueueSize":0,"KVCacheUsagePercent":0,"KvCacheMaxTokenCapacity":0,"UpdateTime":"2025-06-11T14:15:23.785517286Z"},{"NamespacedName":{"Namespace":"inf-ext-e2e","Name":"vllm-llama3-8b-instruct-77ff4f95f9-s6l92"},"Address":"10.244.0.15","Labels":{"app":"vllm-llama3-8b-instruct","pod-template-hash":"77ff4f95f9"},"ActiveModels":{},"WaitingModels":{},"MaxActiveModels":0,"RunningQueueSize":0,"WaitingQueueSize":0,"KVCacheUsagePercent":0,"KvCacheMaxTokenCapacity":0,"UpdateTime":"2025-06-11T14:15:23.760275321Z"},{"NamespacedName":{"Namespace":"inf-ext-e2e","Name":"vllm-llama3-8b-instruct-77ff4f95f9-qx8st"},"Address":"10.244.0.16","Labels":{"app":"vllm-llama3-8b-instruct","pod-template-hash":"77ff4f95f9"},"ActiveModels":{},"WaitingModels":{},"MaxActiveModels":0,"RunningQueueSize":0,"WaitingQueueSize":0,"KVCacheUsagePercent":0,"KvCacheMaxTokenCapacity":0,"UpdateTime":"2025-06-11T14:15:23.770412741Z"}]}
{"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"framework/scheduler_profile.go:163","msg":"After running scorer plugins","x-request-id":"e89f2637-a0ed-4bd6-823d-95738a7c1999","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical"}
{"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"framework/scheduler_profile.go:177","msg":"Before running picker plugin","x-request-id":"e89f2637-a0ed-4bd6-823d-95738a7c1999","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical","pods weighted score":"map[{Pod:{NamespacedName:inf-ext-e2e/vllm-llama3-8b-instruct-77ff4f95f9-75dcm Address:10.244.0.14 Labels:map[app:vllm-llama3-8b-instruct pod-template-hash:77ff4f95f9]} MetricsState:{ActiveModels:map[] WaitingModels:map[] MaxActiveModels:0 RunningQueueSize:0 WaitingQueueSize:0 KVCacheUsagePercent:0 KvCacheMaxTokenCapacity:0 UpdateTime:2025-06-11 14:15:23.785517286 +0000 UTC m=+20.217038531}}:0 {Pod:{NamespacedName:inf-ext-e2e/vllm-llama3-8b-instruct-77ff4f95f9-s6l92 Address:10.244.0.15 Labels:map[app:vllm-llama3-8b-instruct pod-template-hash:77ff4f95f9]} MetricsState:{ActiveModels:map[] WaitingModels:map[] MaxActiveModels:0 RunningQueueSize:0 WaitingQueueSize:0 KVCacheUsagePercent:0 KvCacheMaxTokenCapacity:0 UpdateTime:2025-06-11 14:15:23.760275321 +0000 UTC m=+20.191796691}}:0 {Pod:{NamespacedName:inf-ext-e2e/vllm-llama3-8b-instruct-77ff4f95f9-qx8st Address:10.244.0.16 Labels:map[app:vllm-llama3-8b-instruct pod-template-hash:77ff4f95f9]} MetricsState:{ActiveModels:map[] WaitingModels:map[] MaxActiveModels:0 RunningQueueSize:0 WaitingQueueSize:0 KVCacheUsagePercent:0 KvCacheMaxTokenCapacity:0 UpdateTime:2025-06-11 14:15:23.770412741 +0000 UTC m=+20.201934069}}:0]"}
{"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"picker/random_picker.go:48","msg":"Selecting a random pod from 3 candidates: [{Pod:{NamespacedName:inf-ext-e2e/vllm-llama3-8b-instruct-77ff4f95f9-75dcm Address:10.244.0.14 Labels:map[app:vllm-llama3-8b-instruct pod-template-hash:77ff4f95f9]} MetricsState:{ActiveModels:map[] WaitingModels:map[] MaxActiveModels:0 RunningQueueSize:0 WaitingQueueSize:0 KVCacheUsagePercent:0 KvCacheMaxTokenCapacity:0 UpdateTime:2025-06-11 14:15:23.785517286 +0000 UTC m=+20.217038531}} {Pod:{NamespacedName:inf-ext-e2e/vllm-llama3-8b-instruct-77ff4f9epp  | ess:10.244.0.15 Labels:map[app:vllm-llama3-8b-instruct pod-template-hash:77ff4f95f9]} MetricsState:{ActiveModels:map[] WaitingModels:map[] MaxActiveModels:0 RunningQueueSize:0 WaitingQueueSize:0 KVCacheUsagePercent:0 KvCacheMaxTokenCapacity:0 UpdateTime:2025-06-11 14:15:23.760275321 +0000 UTC m=+20.191796691}} {Pod:{NamespacedName:inf-ext-e2e/vllm-llama3-8b-instruct-77ff4f95f9-qx8st Address:10.244.0.16 Labels:map[app:vllm-llama3-8b-instruct pod-template-hash:77ff4f95f9]} MetricsState:{ActiveModels:map[] WaitingModels:map[] MaxActiveModels:0 RunningQueueSize:0 WaitingQueueSize:0 KVCacheUsagePercent:0 KvCacheMaxTokenCapacity:0 UpdateTime:2025-06-11 14:15:23.770412741 +0000 UTC m=+20.201934069}}]","x-request-id":"e89f2637-a0ed-4bd6-823d-95738a7c1999","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical"}
{"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"framework/scheduler_profile.go:181","msg":"After running picker plugin","x-request-id":"e89f2637-a0ed-4bd6-823d-95738a7c1999","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical","result":{"TargetPod":{"Pod":{"NamespacedName":{"Namespace":"inf-ext-e2e","Name":"vllm-llama3-8b-instruct-77ff4f95f9-75dcm"},"Address":"10.244.0.14","Labels":{"app":"vllm-llama3-8b-instruct","pod-template-hash":"77ff4f95f9"},"ActiveModels":{},"WaitingModels":{},"MaxActiveModels":0,"RunningQueueSize":0,"WaitingQueueSize":0,"KVCacheUsagePercent":0,"KvCacheMaxTokenCapacity":0,"UpdateTime":"2025-06-11T14:15:23.785517286Z"},"Score":0}}}
{"level":"Level(-2)","ts":"2025-06-11T14:15:23Z","caller":"requestcontrol/director.go:200","msg":"Request handled","x-request-id":"e89f2637-a0ed-4bd6-823d-95738a7c1999","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical","model":"food-review","targetModel":"food-review-1","endpoint":"{NamespacedName:inf-ext-e2e/vllm-llama3-8b-instruct-77ff4f95f9-75dcm Address:10.244.0.14 Labels:map[app:vllm-llama3-8b-instruct pod-template-hash:77ff4f95f9]}"}
{"level":"Level(-3)","ts":"2025-06-11T14:15:23Z","caller":"handlers/response.go:56","msg":"Response generated","x-request-id":"e89f2637-a0ed-4bd6-823d-95738a7c1999","usage":{"prompt_tokens":9,"completion_tokens":7,"total_tokens":16}}
{"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"requestcontrol/director.go:129","msg":"LLM request assembled","x-request-id":"f4e68fcf-c3b5-401f-89e3-24248e7f9ec4","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical"}
{"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"requestcontrol/director.go:159","msg":"Critical request bypassing saturation check.","x-request-id":"f4e68fcf-c3b5-401f-89e3-24248e7f9ec4","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical"}
{"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"scheduling/scheduler.go:109","msg":"Scheduling a request, Metrics: [{Pod:{NamespacedName:inf-ext-e2e/vllm-llama3-8b-instruct-77ff4f95f9-75dcm Address:10.244.0.14 Labels:map[app:vllm-llama3-8b-instruct pod-template-hash:77ff4f95f9]} MetricsState:{ActiveModels:map[food-review-1:0] WaitingModels:map[] MaxActiveModels:2 RunningQueueSize:0 WaitingQueueSize:0 KVCacheUsagePercent:0 KvCacheMaxTokenCapacity:0 UpdateTime:2025-06-11 14:15:23.837772856 +0000 UTC m=+20.269294059}} {Pod:{NamespacedName:inf-ext-e2e/vllm-llama3-8b-instruct-77ff4f95f9-s6l92 Address:10.244.0.15 Labels:map[app:vllm-llama3-8b-instruct pod-template-hash:77ff4f95f9]} MetricsState:{ActiveModels:map[] WaitingModels:map[] MaxActiveModels:0 RunningQueueSize:0 WaitingQueueSize:0 KVCacheUsagePercent:0 KvCacheMaxTokenCapacity:0 UpdateTime:2025-06-11 14:15:23.810581916 +0000 UTC m=+20.242103286}} {Pod:{NamespacedName:inf-ext-e2e/vllm-llama3-8b-instruct-77ff4f95f9-qx8st Address:10.244.0.16 Labels:map[app:vllm-llama3-8b-instruct pod-template-hash:77ff4f95f9]} MetricsState:{ActiveModels:map[] WaitingModels:map[] MaxActiveModels:0 RunningQueueSize:0 WaitingQueueSize:0 KVCacheUsagePercent:0 KvCacheMaxTokenCapacity:0 UpdateTime:2025-06-11 14:15:23.819322574 +0000 UTC m=+20.250843777}}]","x-request-id":"f4e68fcf-c3b5-401f-89e3-24248e7f9ec4","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical","request":"RequestID: f4e68fcf-c3b5-401f-89e3-24248e7f9ec4, TargetModel: food-review-1, PromptLength: 72, Headers: map[:authority:envoy.inf-ext-e2e.svc:8081 :method:POST :path:/v1/chat/completions :scheme:http accept:*/* content-length:152 content-type:application/json user-agent:curl/7.83.1-DEV x-envoy-external-address:10.244.0.12 x-forwarded-for:10.244.0.12 x-forwarded-proto:http x-request-id:f4e68fcf-c3b5-401f-89e3-24248e7f9ec4]"}
{"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"framework/scheduler_profile.go:127","msg":"Before running filter plugins","x-request-id":"f4e68fcf-c3b5-401f-89e3-24248e7f9ec4","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical","pods":[{"NamespacedName":{"Namespace":"inf-ext-e2e","Name":"vllm-llama3-8b-instruct-77ff4f95f9-75dcm"},"Address":"10.244.0.14","Labels":{"app":"vllm-llama3-8b-instruct","pod-template-hash":"77ff4f95f9"},"ActiveModels":{"food-review-1":0},"WaitingModels":{},"MaxActiveModels":2,"RunningQueueSize":0,"WaitingQueueSize":0,"KVCacheUsagePercent":0,"KvCacheMaxTokenCapacity":0,"UpdateTime":"2025-06-11T14:15:23.837772856Z"},{"NamespacedName":{"Namespace":"inf-ext-e2e","Name":"vllm-llama3-8b-instruct-77ff4f95f9-s6l92"},"Address":"10.244.0.15","Labels":{"app":"vllm-llama3-8b-instruct","pod-template-hash":"77ff4f95f9"},"ActiveModels":{},"WaitingModels":{},"MaxActiveModels":0,"RunningQueueSize":0,"WaitingQueueSize":0,"KVCacheUsagePercent":0,"KvCacheMaxTokenCapacity":0,"UpdateTime":"2025-06-11T14:15:23.810581916Z"},{"NamespacedName":{"Namespace":"inf-ext-e2e","Name":"vllm-llama3-8b-instruct-77ff4f95f9-qx8st"},"Address":"10.244.0.16","Labels":{"app":"vllm-llama3-8b-instruct","pod-template-hash":"77ff4f95f9"},"ActiveModels":{},"WaitingModels":{},"MaxActiveModels":0,"RunningQueueSize":0,"WaitingQueueSize":0,"KVCacheUsagePercent":0,"KvCacheMaxTokenCapacity":0,"UpdateTime":"2025-06-11T14:15:23.819322574Z"}]}
{"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"framework/scheduler_profile.go:130","msg":"Running filter plugin","x-request-id":"f4e68fcf-c3b5-401f-89e3-24248e7f9ec4","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical","plugin":"low-queue"}
epp  | {"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"framework/scheduler_profile.go:134","msg":"Filter plugin result","x-request-id":"f4e68fcf-c3b5-401f-89e3-24248e7f9ec4","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical","plugin":"low-queue","pods":[{"NamespacedName":{"Namespace":"inf-ext-e2e","Name":"vllm-llama3-8b-instruct-77ff4f95f9-75dcm"},"Address":"10.244.0.14","Labels":{"app":"vllm-llama3-8b-instruct","pod-template-hash":"77ff4f95f9"},"ActiveModels":{"food-review-1":0},"WaitingModels":{},"MaxActiveModels":2,"RunningQueueSize":0,"WaitingQueueSize":0,"KVCacheUsagePercent":0,"KvCacheMaxTokenCapacity":0,"UpdateTime":"2025-06-11T14:15:23.837772856Z"}]}
{"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"framework/scheduler_profile.go:139","msg":"After running filter plugins","x-request-id":"f4e68fcf-c3b5-401f-89e3-24248e7f9ec4","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical"}
{"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"framework/scheduler_profile.go:146","msg":"Before running scorer plugins","x-request-id":"f4e68fcf-c3b5-401f-89e3-24248e7f9ec4","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical","pods":[{"NamespacedName":{"Namespace":"inf-ext-e2e","Name":"vllm-llama3-8b-instruct-77ff4f95f9-75dcm"},"Address":"10.244.0.14","Labels":{"app":"vllm-llama3-8b-instruct","pod-template-hash":"77ff4f95f9"},"ActiveModels":{"food-review-1":0},"WaitingModels":{},"MaxActiveModels":2,"RunningQueueSize":0,"WaitingQueueSize":0,"KVCacheUsagePercent":0,"KvCacheMaxTokenCapacity":0,"UpdateTime":"2025-06-11T14:15:23.837772856Z"}]}
{"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"framework/scheduler_profile.go:163","msg":"After running scorer plugins","x-request-id":"f4e68fcf-c3b5-401f-89e3-24248e7f9ec4","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical"}
{"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"framework/scheduler_profile.go:177","msg":"Before running picker plugin","x-request-id":"f4e68fcf-c3b5-401f-89e3-24248e7f9ec4","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical","pods weighted score":"map[{Pod:{NamespacedName:inf-ext-e2e/vllm-llama3-8b-instruct-77ff4f95f9-75dcm Address:10.244.0.14 Labels:map[app:vllm-llama3-8b-instruct pod-template-hash:77ff4f95f9]} MetricsState:{ActiveModels:map[food-review-1:0] WaitingModels:map[] MaxActiveModels:2 RunningQueueSize:0 WaitingQueueSize:0 KVCacheUsagePercent:0 KvCacheMaxTokenCapacity:0 UpdateTime:2025-06-11 14:15:23.837772856 +0000 UTC m=+20.269294059}}:0]"}
{"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"picker/random_picker.go:48","msg":"Selecting a random pod from 1 candidates: [{Pod:{NamespacedName:inf-ext-e2e/vllm-llama3-8b-instruct-77ff4f95f9-75dcm Address:10.244.0.14 Labels:map[app:vllm-llama3-8b-instruct pod-template-hash:77ff4f95f9]} MetricsState:{ActiveModels:map[food-review-1:0] WaitingModels:map[] MaxActiveModels:2 RunningQueueSize:0 WaitingQueueSize:0 KVCacheUsagePercent:0 KvCacheMaxTokenCapacity:0 UpdateTime:2025-06-11 14:15:23.837772856 +0000 UTC m=+20.269294059}}]","x-request-id":"f4e68fcf-c3b5-401f-89e3-24248e7f9ec4","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical"}
{"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"framework/scheduler_profile.go:181","msg":"After running picker plugin","x-request-id":"f4e68fcf-c3b5-401f-89e3-24248e7f9ec4","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical","result":{"TargetPod":{"Pod":{"NamespacedName":{"Namespace":"inf-ext-e2e","Name":"vllm-llama3-8b-instruct-77ff4f95f9-75dcm"},"Address":"10.244.0.14","Labels":{"app":"vllm-llama3-8b-instruct","pod-template-hash":"77ff4f95f9"},"ActiveModels":{"food-review-1":0},"WaitingModels":{},"MaxActiveModels":2,"RunningQueueSize":0,"WaitingQueueSize":0,"KVCacheUsagePercent":0,"KvCacheMaxTokenCapacity":0,"UpdateTime":"2025-06-11T14:15:23.837772856Z"},"Score":0}}}
epp  | 6-11T14:15:23Z","caller":"requestcontrol/director.go:200","msg":"Request handled","x-request-id":"f4e68fcf-c3b5-401f-89e3-24248e7f9ec4","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical","model":"food-review","targetModel":"food-review-1","endpoint":"{NamespacedName:inf-ext-e2e/vllm-llama3-8b-instruct-77ff4f95f9-75dcm Address:10.244.0.14 Labels:map[app:vllm-llama3-8b-instruct pod-template-hash:77ff4f95f9]}"}
{"level":"Level(-3)","ts":"2025-06-11T14:15:23Z","caller":"handlers/response.go:56","msg":"Response generated","x-request-id":"f4e68fcf-c3b5-401f-89e3-24248e7f9ec4","usage":{"prompt_tokens":9,"completion_tokens":4,"total_tokens":13}}
{"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"requestcontrol/director.go:129","msg":"LLM request assembled","x-request-id":"0dd1c34d-d498-4a83-ad45-e8eff4a5e4da","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical"}
{"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"requestcontrol/director.go:159","msg":"Critical request bypassing saturation check.","x-request-id":"0dd1c34d-d498-4a83-ad45-e8eff4a5e4da","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical"}
{"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"scheduling/scheduler.go:109","msg":"Scheduling a request, Metrics: [{Pod:{NamespacedName:inf-ext-e2e/vllm-llama3-8b-instruct-77ff4f95f9-75dcm Address:10.244.0.14 Labels:map[app:vllm-llama3-8b-instruct pod-template-hash:77ff4f95f9]} MetricsState:{ActiveModels:map[food-review-1:0] WaitingModels:map[] MaxActiveModels:2 RunningQueueSize:0 WaitingQueueSize:0 KVCacheUsagePercent:0 KvCacheMaxTokenCapacity:0 UpdateTime:2025-06-11 14:15:23.885673764 +0000 UTC m=+20.317195009}} {Pod:{NamespacedName:inf-ext-e2e/vllm-llama3-8b-instruct-77ff4f95f9-s6l92 Address:10.244.0.15 Labels:map[app:vllm-llama3-8b-instruct pod-template-hash:77ff4f95f9]} MetricsState:{ActiveModels:map[] WaitingModels:map[] MaxActiveModels:0 RunningQueueSize:0 WaitingQueueSize:0 KVCacheUsagePercent:0 KvCacheMaxTokenCapacity:0 UpdateTime:2025-06-11 14:15:23.859904545 +0000 UTC m=+20.291425789}} {Pod:{NamespacedName:inf-ext-e2e/vllm-llama3-8b-instruct-77ff4f95f9-qx8st Address:10.244.0.16 Labels:map[app:vllm-llama3-8b-instruct pod-template-hash:77ff4f95f9]} MetricsState:{ActiveModels:map[] WaitingModels:map[] MaxActiveModels:0 RunningQueueSize:0 WaitingQueueSize:0 KVCacheUsagePercent:0 KvCacheMaxTokenCapacity:0 UpdateTime:2025-06-11 14:15:23.869753878 +0000 UTC m=+20.301275123}}]","x-request-id":"0dd1c34d-d498-4a83-ad45-e8eff4a5e4da","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical","request":"RequestID: 0dd1c34d-d498-4a83-ad45-e8eff4a5e4da, TargetModel: food-review-1, PromptLength: 179, Headers: map[:authority:envoy.inf-ext-e2e.svc:8081 :method:POST :path:/v1/chat/completions :scheme:http accept:*/* content-length:267 content-type:application/json user-agent:curl/7.83.1-DEV x-envoy-external-address:10.244.0.12 x-forwarded-for:10.244.0.12 x-forwarded-proto:http x-request-id:0dd1c34d-d498-4a83-ad45-e8eff4a5e4da]"}
{"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"framework/scheduler_profile.go:127","msg":"Before running filter plugins","x-request-id":"0dd1c34d-d498-4a83-ad45-e8eff4a5e4da","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical","pods":[{"NamespacedName":{"Namespace":"inf-ext-e2e","Name":"vllm-llama3-8b-instruct-77ff4f95f9-75dcm"},"Address":"10.244.0.14","Labels":{"app":"vllm-llama3-8b-instruct","pod-template-hash":"77ff4f95f9"},"ActiveModels":{"food-review-1":0},"WaitingModels":{},"MaxActiveModels":2,"RunningQueueSize":0,"WaitingQueueSize":0,"KVCacheUsagePercent":0,"KvCacheMaxTokenCapacity":0,"UpdateTime":"2025-06-11T14:15:23.885673764Z"},{"NamespacedName":{"Namespace":"inf-ext-e2e","Name":"vllm-llama3-8b-instruct-77ff4f95f9-s6l92"},"Address":"10.244.0.15","Labels":{"app":"vllm-llama3-8b-instruct","pod-template-hash":"77ff4f95f9"},"ActiveModels":{},"WaitingModels":{},"MaxActiveModels":0,"RunningQueueSize":0,"WaitingQueueSize":0,"KVCacheUsagePercent":0,"KvCacheMaxTokenCapacity":0,"UpdateTime":"2025-06-11T14:15:23.859904545Z"},{"NamespacedName":{"Namespace":"inf-ext-e2e","Name":"vllm-llama3-8b-instruct-77ff4f95f9-qx8st"},"Address":"10.244.0.16","Labels":{"app":"vllm-llama3-8b-instruct","pod-template-hash":"77ff4f95f9"},"ActiveModels":{},"WaitingModels":{},"MaxActiveModels":0,"RunningQueueSize":0,"WaitingQueueSize":0,"KVCacheUsagePercent":0,"KvCacheMaxTokenCapacity":0,"UpdateTime":"2025-06-11T14:15:23.869753878Z"}]}
{"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"framework/scheduler_profile.go:130","msg":"Running filter plugin","x-request-id":"0dd1c34d-d498-4a83-ad45-e8eff4a5e4da","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical","plugin":"low-queue"}
{"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"framework/scheduler_profile.go:134","msg":"Filter plugin result","x-request-id":"0dd1c34d-d498-4a83-ad45-e8eff4a5e4da","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical","plugin":"low-queue","pods":[{"NamespacedName":{"Namespace":"inf-ext-e2e","Name":"vllm-llama3-8b-instruct-77ff4f95f9-75dcm"},"Address":"10.244.0.14","Labels":{"app":"vllm-llama3-8b-instruct","pod-template-hash":"77ff4f95f9"},"ActiveModels":{"food-review-1":0},"WaitingModels":{},"MaxActiveModels":2,"RunningQueueSize":0,"WaitingQueueSize":0,"KVCacheUsagePercent":0,"KvCacheMaxTokenCapacity":0,"UpdateTime":"2025-06-11T14:15:23.885673764Z"}]}
{"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"framework/scheduler_profile.go:139","msg":"After running filter plugins","x-request-id":"0dd1c34d-d498-4a83-ad45-e8eff4a5e4da","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical"}
{"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"framework/scheduler_profile.go:146","msg":"Before running scorer plugins","x-request-id":"0dd1c34d-d498-4a83-ad45-e8eff4a5e4da","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical","pods":[{"NamespacedName":{"Namespace":"inf-ext-e2e","Name":"vllm-llama3-8b-instruct-77ff4f95f9-75dcm"},"Address":"10.244.0.14","Labels":{"app":"vllm-llama3-8b-instruct","pod-template-hash":"77ff4f95f9"},"ActiveModels":{"food-review-1":0},"WaitingModels":{},"MaxActiveModels":2,"RunningQueueSize":0,"WaitingQueueSize":0,"KVCacheUsagePercent":0,"KvCacheMaxTokenCapacity":0,"UpdateTime":"2025-06-11T14:15:23.885673764Z"}]}
{"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"framework/scheduler_profile.go:163","msg":"After running scorer plugins","x-request-id":"0dd1c34d-d498-4a83-ad45-e8eff4a5e4da","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical"}
{"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"framework/scheduler_profile.go:177","msg":"Before running picker plugin","x-request-id":"0dd1c34d-d498-4a83-ad45-e8eff4a5e4da","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical","pods weighted score":"map[{Pod:{NamespacedName:inf-ext-e2e/vllm-llama3-8b-instruct-77ff4f95f9-75dcm Address:10.244.0.14 Labels:map[app:vllm-llama3-8b-instruct pod-template-hash:77ff4f95f9]} MetricsState:{ActiveModels:map[food-review-1:0] WaitingModels:map[] MaxActiveModels:2 RunningQueueSize:0 WaitingQueueSize:0 KVCacheUsagePercent:0 KvCacheMaxTokenCapacity:0 UpdateTime:2025-06-11 14:15:23.885673764 +0000 UTC m=+20.317195009}}:0]"}
{"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"picker/random_picker.go:48","msg":"Selecting a random pod from 1 candidates: [{Pod:{NamespacedName:inf-ext-e2e/vllm-llama3-8b-instruct-77ff4f95f9-75dcm Address:10.244.0.14 Labels:map[app:vllm-llama3-8b-instruct pod-template-hash:77ff4f95f9]} MetricsState:{ActiveModels:map[food-review-1:0] WaitingModels:map[] MaxActiveModels:2 RunningQueueSize:0 WaitingQueueSize:0 KVCacheUsagePercent:0 KvCacheMaxTokenCapacity:0 UpdateTime:2025-06-11 14:15:23.885673764 +0000 UTC m=+20.317195009}}]","x-request-id":"0dd1c34d-d498-4a83-ad45-e8eff4a5e4da","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical"}
{"level":"Level(-4)","ts":"2025-06-11T14:15:23Z","caller":"framework/scheduler_profile.go:181","msg":"After running picker plugin","x-request-id":"0dd1c34d-d498-4a83-ad45-e8eff4a5e4da","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical","result":{"TargetPod":{"Pod":{"NamespacedName":{"Namespace":"inf-ext-e2e","Name":"vllm-llama3-8b-instruct-77ff4f95f9-75dcm"},"Address":"10.244.0.14","Labels":{"app":"vllm-llama3-8b-instruct","pod-template-hash":"77ff4f95f9"},"ActiveModels":{"food-review-1":0},"WaitingModels":{},"MaxActiveModels":2,"RunningQueueSize":0,"WaitingQueueSize":0,"KVCacheUsagePercent":0,"KvCacheMaxTokenCapacity":0,"UpdateTime":"2025-06-11T14:15:23.885673764Z"},"Score":0}}}
{"level":"Level(-2)","ts":"2025-06-11T14:15:23Z","caller":"requestcontrol/director.go:200","msg":"Request handled","x-request-id":"0dd1c34d-d498-4a83-ad45-e8eff4a5e4da","model":"food-review","resolvedTargetModel":"food-review-1","criticality":"Critical","model":"food-review","targetModel":"food-review-1","endpoint":"{NamespacedName:inf-ext-e2e/vllm-llama3-8b-instruct-77ff4f95f9-75dcm Address:10.244.0.14 Labels:map[app:vllm-llama3-8b-instruct pod-template-hash:77ff4f95f9]}"}
{"level":"Level(-3)","ts":"2025-06-11T14:15:23Z","caller":"handlers/response.go:56","msg":"Response generated","x-request-id":"0dd1c34d-d498-4a83-ad45-e8eff4a5e4da","usage":{"prompt_tokens":16,"completion_tokens":7,"total_tokens":23}}

envoy logs:

[2025-06-11 14:15:23.887][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:966] Sending a body chunk of 267 bytes, end_stream false
[2025-06-11 14:15:23.887][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:23] Start external processing call
[2025-06-11 14:15:23.887][18][trace][router] [source/common/router/upstream_codec_filter.cc:99] [Tags: "ConnectionId":"0","StreamId":"6508579852161680385"] proxying 280 bytes
[2025-06-11 14:15:23.887][18][trace][connection] [source/common/network/connection_impl.cc:529] [Tags: "ConnectionId":"7"] writing 289 bytes, end_stream false
[2025-06-11 14:15:23.887][18][trace][http2] [source/common/http/http2/codec_impl.cc:1198] [Tags: "ConnectionId":"7"] sent frame type=0, stream_id=3, length=280
[2025-06-11 14:15:23.887][18][trace][http] [source/common/http/filter_manager.cc:719] [Tags: "ConnectionId":"0","StreamId":"6508579852161680385"] decode data called: filter=envoy.filters.http.upstream_codec status=0
[2025-06-11 14:15:23.887][18][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:821] decodeData returning 3
[2025-06-11 14:15:23.887][18][trace][http] [source/common/http/filter_manager.cc:719] [Tags: "ConnectionId":"9","StreamId":"13551906667112814535"] decode data called: filter=envoy.filters.http.ext_proc status=3
[2025-06-11 14:15:23.887][18][debug][http] [source/common/http/conn_manager_impl.cc:1179] [Tags: "ConnectionId":"9","StreamId":"13551906667112814535"] request end stream timestamp recorded
[2025-06-11 14:15:23.887][18][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff765e00 for 86400000ms, min is 86400000ms
[2025-06-11 14:15:23.887][18][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:819] decodeData(0): end_stream = true
[2025-06-11 14:15:23.887][18][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:695] Sending body data even though header processing is still in progress as body mode is FULL_DUPLEX_STREAMED or STREAMED and send_body_without_waiting_for_header_response is enabled
[2025-06-11 14:15:23.887][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:966] Sending a body chunk of 0 bytes, end_stream true
[2025-06-11 14:15:23.887][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:23] Start external processing call
[2025-06-11 14:15:23.887][18][trace][router] [source/common/router/upstream_codec_filter.cc:99] [Tags: "ConnectionId":"0","StreamId":"6508579852161680385"] proxying 11 bytes
[2025-06-11 14:15:23.887][18][trace][connection] [source/common/network/connection_impl.cc:529] [Tags: "ConnectionId":"7"] writing 20 bytes, end_stream false
[2025-06-11 14:15:23.887][18][trace][http2] [source/common/http/http2/codec_impl.cc:1198] [Tags: "ConnectionId":"7"] sent frame type=0, stream_id=3, length=11
envoy  | [2025-06-11 14:15:23.887][18][trace][http] [source/common/http/filter_manager.cc:719] [Tags: "ConnectionId":"0","StreamId":"6508579852161680385"] decode data called: filter=envoy.filters.http.upstream_codec status=0
[2025-06-11 14:15:23.887][18][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:821] decodeData returning 3
[2025-06-11 14:15:23.887][18][trace][http] [source/common/http/filter_manager.cc:719] [Tags: "ConnectionId":"9","StreamId":"13551906667112814535"] decode data called: filter=envoy.filters.http.ext_proc status=3
[2025-06-11 14:15:23.887][18][trace][http] [source/common/http/http1/codec_impl.cc:695] [Tags: "ConnectionId":"9"] parsed 434 bytes
[2025-06-11 14:15:23.887][18][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"7"] socket event: 2
[2025-06-11 14:15:23.887][18][trace][connection] [source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"7"] write ready
[2025-06-11 14:15:23.887][18][trace][connection] [source/common/tls/ssl_socket.cc:284] [Tags: "ConnectionId":"7"] ssl write returns: 750
[2025-06-11 14:15:23.888][18][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"7"] socket event: 3
[2025-06-11 14:15:23.888][18][trace][connection] [source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"7"] write ready
[2025-06-11 14:15:23.888][18][trace][connection] [source/common/network/connection_impl.cc:654] [Tags: "ConnectionId":"7"] read ready. dispatch_buffered_data=0
[2025-06-11 14:15:23.888][18][trace][connection] [source/common/tls/ssl_socket.cc:94] [Tags: "ConnectionId":"7"] ssl read returns: 30
[2025-06-11 14:15:23.888][18][trace][connection] [source/common/tls/ssl_socket.cc:94] [Tags: "ConnectionId":"7"] ssl read returns: -1
[2025-06-11 14:15:23.888][18][trace][connection] [source/common/tls/ssl_socket.cc:134] [Tags: "ConnectionId":"7"] ssl error occurred while read: WANT_READ
[2025-06-11 14:15:23.888][18][trace][connection] [source/common/tls/ssl_socket.cc:170] [Tags: "ConnectionId":"7"] ssl read 30 bytes
[2025-06-11 14:15:23.888][18][trace][http2] [source/common/http/http2/codec_impl.cc:940] [Tags: "ConnectionId":"7"] dispatching 30 bytes
[2025-06-11 14:15:23.888][18][trace][http2] [source/common/http/http2/codec_impl.cc:1742] [Tags: "ConnectionId":"7"] Http2Visitor::OnFrameHeader(0, 4, 8, 0)
[2025-06-11 14:15:23.888][18][trace][http2] [source/common/http/http2/codec_impl.cc:1050] [Tags: "ConnectionId":"7"] about to recv frame type=8, flags=0, stream_id=0
[2025-06-11 14:15:23.888][18][trace][http2] [source/common/http/http2/codec_impl.cc:1339] [Tags: "ConnectionId":"7"] track inbound frame type=8 flags=0 length=4 padding_length=0
[2025-06-11 14:15:23.888][18][trace][http2] [source/common/http/http2/codec_impl.cc:1742] [Tags: "ConnectionId":"7"] Http2Visitor::OnFrameHeader(0, 8, 6, 0)
[2025-06-11 14:15:23.888][18][trace][http2] [source/common/http/http2/codec_impl.cc:1050] [Tags: "ConnectionId":"7"] about to recv frame type=6, flags=0, stream_id=0
[2025-06-11 14:15:23.888][18][trace][http2] [source/common/http/http2/codec_impl.cc:1339] [Tags: "ConnectionId":"7"] track inbound frame type=6 flags=0 length=8 padding_length=0
[2025-06-11 14:15:23.888][18][trace][http2] [source/common/http/http2/codec_impl.cc:1089] [Tags: "ConnectionId":"7"] recv frame type=PING
[2025-06-11 14:15:23.888][18][trace][http2] [source/common/http/http2/codec_impl.cc:978] [Tags: "ConnectionId":"7"] dispatched 30 bytes
[2025-06-11 14:15:23.888][18][trace][http2] [source/common/http/http2/codec_impl.cc:1312] [Tags: "ConnectionId":"7"] about to send frame type=6, flags=1
[2025-06-11 14:15:23.888][18][trace][http2] [source/common/http/http2/codec_impl.cc:1361] [Tags: "ConnectionId":"7"] send data: bytes=17
[2025-06-11 14:15:23.888][18][trace][connection] [source/common/network/connection_impl.cc:529] [Tags: "ConnectionId":"7"] writing 17 bytes, end_stream false
envoy  | _id=0, length=8][18][trace][http2] [source/common/http/http2/codec_impl.cc:1198] [Tags: "ConnectionId":"7"] sent frame type=6, stream
[2025-06-11 14:15:23.888][18][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"7"] socket event: 2
[2025-06-11 14:15:23.888][18][trace][connection] [source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"7"] write ready
[2025-06-11 14:15:23.888][18][trace][connection] [source/common/tls/ssl_socket.cc:284] [Tags: "ConnectionId":"7"] ssl write returns: 17
[2025-06-11 14:15:23.889][18][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"7"] socket event: 3
[2025-06-11 14:15:23.889][18][trace][connection] [source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"7"] write ready
[2025-06-11 14:15:23.889][18][trace][connection] [source/common/network/connection_impl.cc:654] [Tags: "ConnectionId":"7"] read ready. dispatch_buffered_data=0
[2025-06-11 14:15:23.889][18][trace][connection] [source/common/tls/ssl_socket.cc:94] [Tags: "ConnectionId":"7"] ssl read returns: 859
[2025-06-11 14:15:23.889][18][trace][connection] [source/common/tls/ssl_socket.cc:94] [Tags: "ConnectionId":"7"] ssl read returns: -1
[2025-06-11 14:15:23.889][18][trace][connection] [source/common/tls/ssl_socket.cc:134] [Tags: "ConnectionId":"7"] ssl error occurred while read: WANT_READ
[2025-06-11 14:15:23.889][18][trace][connection] [source/common/tls/ssl_socket.cc:170] [Tags: "ConnectionId":"7"] ssl read 859 bytes
[2025-06-11 14:15:23.889][18][trace][http2] [source/common/http/http2/codec_impl.cc:940] [Tags: "ConnectionId":"7"] dispatching 859 bytes
[2025-06-11 14:15:23.889][18][trace][http2] [source/common/http/http2/codec_impl.cc:1742] [Tags: "ConnectionId":"7"] Http2Visitor::OnFrameHeader(3, 2, 1, 4)
[2025-06-11 14:15:23.889][18][trace][http2] [source/common/http/http2/codec_impl.cc:1050] [Tags: "ConnectionId":"7"] about to recv frame type=1, flags=4, stream_id=3
[2025-06-11 14:15:23.889][18][trace][http2] [source/common/http/http2/codec_impl.cc:1339] [Tags: "ConnectionId":"7"] track inbound frame type=1 flags=4 length=2 padding_length=0
[2025-06-11 14:15:23.889][18][trace][http2] [source/common/http/http2/codec_impl.cc:1785] [Tags: "ConnectionId":"7"] Http2Visitor::OnEndHeadersForStream(3)
[2025-06-11 14:15:23.889][18][trace][http] [source/common/http/filter_manager.cc:906] [Tags: "ConnectionId":"0","StreamId":"6508579852161680385"] commonEncodePrefix end_stream: false, isHalfCloseEnabled: false
[2025-06-11 14:15:23.889][18][trace][router] [source/common/router/upstream_request.cc:267] [Tags: "ConnectionId":"0","StreamId":"6508579852161680385"] end_stream: false, upstream response headers:
':status', '200'
'content-type', 'application/grpc'

[2025-06-11 14:15:23.889][18][debug][router] [source/common/router/router.cc:1571] [Tags: "ConnectionId":"0","StreamId":"6508579852161680385"] upstream headers complete: end_stream=false
[2025-06-11 14:15:23.889][18][debug][http] [source/common/http/async_client_impl.cc:189] async http request response headers (end_stream=false):
':status', '200'
'content-type', 'application/grpc'

[2025-06-11 14:15:23.889][18][trace][http2] [source/common/http/http2/codec_impl.cc:1742] [Tags: "ConnectionId":"7"] Http2Visitor::OnFrameHeader(3, 555, 0, 0)
[2025-06-11 14:15:23.889][18][trace][http2] [source/common/http/http2/codec_impl.cc:1050] [Tags: "ConnectionId":"7"] about to recv frame type=0, flags=0, stream_id=3
[2025-06-11 14:15:23.889][18][trace][http2] [source/common/http/http2/codec_impl.cc:1793] [Tags: "ConnectionId":"7"] Http2Visitor::OnBeginDataForStream(3, 555)
[2025-06-11 14:15:23.889][18][debug][http2] [source/common/http/http2/codec_impl.cc:1805] [Tags: "ConnectionId":"7"] Http2Visitor: remaining data payload: 555, stream_id: 3, end_stream: false
[2025-06-11 14:15:23.889][18][trace][http2] [source/common/http/http2/codec_impl.cc:1834] [Tags: "ConnectionId":"7"] Http2Visitor dispatching DATA for stream 3
[2025-06-11 14:15:23.889][18][trace][http2] [source/common/http/http2/codec_impl.cc:1102] [Tags: "ConnectionId":"7"] recv frame type=DATA stream_id=3
[2025-06-11 14:15:23.889][18][trace][http2] [source/common/http/http2/codec_impl.cc:1339] [Tags: "ConnectionId":"7"] track inbound frame type=0 flags=0 length=555 padding_length=0
[2025-06-11 14:15:23.889][18][trace][http] [source/common/http/filter_manager.cc:906] [Tags: "ConnectionId":"0","StreamId":"6508579852161680385"] commonEncodePrefix end_stream: false, isHalfCloseEnabled: false
[2025-06-11 14:15:23.889][18][trace][http] [source/common/http/async_client_impl.cc:207] async http request response data (length=555 end_stream=false)
[2025-06-11 14:15:23.889][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1234] Received request headers response
[2025-06-11 14:15:23.889][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1148] processing response included dynamic metadata, but no receiving namespaces are configured.
[2025-06-11 14:15:23.889][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:146] applying headers response. body mode = FULL_DUPLEX_STREAMED
[2025-06-11 14:15:23.889][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:109] Applying header mutations
[2025-06-11 14:15:23.889][18][trace][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:176] Setting header x-gateway-destination-endpoint append = false
[2025-06-11 14:15:23.889][18][trace][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:176] Setting header content-type append = false
[2025-06-11 14:15:23.889][18][trace][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:176] Setting header x-forwarded-for append = false
[2025-06-11 14:15:23.889][18][trace][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:176] Setting header x-forwarded-proto append = false
[2025-06-11 14:15:23.889][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:184] Header x-envoy-external-address may not be modified per rules
[2025-06-11 14:15:23.889][18][trace][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:176] Setting header x-request-id append = false
[2025-06-11 14:15:23.889][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:184] Header :authority may not be modified per rules
[2025-06-11 14:15:23.889][18][trace][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:176] Setting header :path append = false
[2025-06-11 14:15:23.889][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:184] Header :method may not be modified per rules
[2025-06-11 14:15:23.889][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:184] Header :scheme may not be modified per rules
[2025-06-11 14:15:23.889][18][trace][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:176] Setting header user-agent append = false
[2025-06-11 14:15:23.889][18][trace][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:176] Setting header accept append = false
[2025-06-11 14:15:23.889][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:609] Clearing route cache due to the filter RouterCacheAction is configured with DEFAULT and response has clear_route_cache set.
[2025-06-11 14:15:23.889][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:42] Finish external processing call
[2025-06-11 14:15:23.889][18][trace][http2] [source/common/http/http2/codec_impl.cc:1742] [Tags: "ConnectionId":"7"] Http2Visitor::OnFrameHeader(3, 275, 0, 0)
[2025-06-11 14:15:23.889][18][trace][http2] [source/common/http/http2/codec_impl.cc:1050] [Tags: "ConnectionId":"7"] about to recv frame type=0, flags=0, stream_id=3
[2025-06-11 14:15:23.889][18][trace][http2] [source/common/http/http2/codec_impl.cc:1793] [Tags: "ConnectionId":"7"] Http2Visitor::OnBeginDataForStream(3, 275)
[2025-06-11 14:15:23.889][18][debug][http2] [source/common/http/http2/codec_impl.cc:1805] [Tags: "ConnectionId":"7"] Http2Visitor: remaining data payload: 275, stream_id: 3, end_stream: false
[2025-06-11 14:15:23.889][18][trace][http2] [source/common/http/http2/codec_impl.cc:1834] [Tags: "ConnectionId":"7"] Http2Visitor dispatching DATA for stream 3
[2025-06-11 14:15:23.889][18][trace][http2] [source/common/http/http2/codec_impl.cc:1102] [Tags: "ConnectionId":"7"] recv frame type=DATA stream_id=3
[2025-06-11 14:15:23.889][18][trace][http2] [source/common/http/http2/codec_impl.cc:1339] [Tags: "ConnectionId":"7"] track inbound frame type=0 flags=0 length=275 padding_length=0
[2025-06-11 14:15:23.889][18][trace][http] [source/common/http/filter_manager.cc:906] [Tags: "ConnectionId":"0","StreamId":"6508579852161680385"] commonEncodePrefix end_stream: false, isHalfCloseEnabled: false
[2025-06-11 14:15:23.889][18][trace][http] [source/common/http/async_client_impl.cc:207] async http request response data (length=275 end_stream=false)
[2025-06-11 14:15:23.889][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1234] Received request body response
[2025-06-11 14:15:23.889][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:280] Processing body response
[2025-06-11 14:15:23.889][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:347] FULL_DUPLEX_STREAMED body response is received and body_mode_: FULL_DUPLEX_STREAMED 
[2025-06-11 14:15:23.889][18][trace][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:545] Injecting 253 bytes of data to filter stream in FULL_DUPLEX_STREAMED mode. end_of_stream is true
[2025-06-11 14:15:23.889][18][debug][router] [source/common/router/router.cc:539] [Tags: "ConnectionId":"9","StreamId":"13551906667112814535"] cluster 'original_destination_cluster' match for URL '/v1/chat/completions'
[2025-06-11 14:15:23.889][18][debug][upstream] [source/extensions/clusters/original_dst/original_dst_cluster.cc:147] Using request override host 10.244.0.14:8000.
[2025-06-11 14:15:23.889][18][trace][upstream] [source/extensions/clusters/original_dst/original_dst_cluster.cc:65] Using existing host original_destination_cluster10.244.0.14:8000 10.244.0.14:8000.
[2025-06-11 14:15:23.889][18][debug][router] [source/common/router/router.cc:768] [Tags: "ConnectionId":"9","StreamId":"13551906667112814535"] router decoding headers:
':authority', 'envoy.inf-ext-e2e.svc:8081'
':method', 'POST'
':scheme', 'http'
':path', '/v1/chat/completions'
'x-envoy-external-address', '10.244.0.12'
'x-gateway-destination-endpoint', '10.244.0.14:8000'
'content-type', 'application/json'
'x-forwarded-for', '10.244.0.12'
'x-forwarded-proto', 'http'
'x-request-id', '0dd1c34d-d498-4a83-ad45-e8eff4a5e4da'
'user-agent', 'curl/7.83.1-DEV'
'accept', '*/*'

[2025-06-11 14:15:23.889][18][debug][pool] [source/common/conn_pool/conn_pool_base.cc:302] [Tags: "ConnectionId":"8"] using existing fully connected connection
[2025-06-11 14:15:23.889][18][debug][pool] [source/common/conn_pool/conn_pool_base.cc:219] [Tags: "ConnectionId":"8"] creating stream
[2025-06-11 14:15:23.889][18][debug][router] [source/common/router/upstream_request.cc:588] [Tags: "ConnectionId":"9","StreamId":"13551906667112814535"] pool ready
[2025-06-11 14:15:23.889][18][trace][pool] [source/common/conn_pool/conn_pool_base.cc:136] per-upstream shouldCreateNewConnection returns false for pending 0 active 1 connecting_and_connected_capacity 0 connecting_capacity 0 ratio 1
[2025-06-11 14:15:23.889][18][trace][router] [source/common/router/upstream_codec_filter.cc:61] [Tags: "ConnectionId":"9","StreamId":"13551906667112814535"] proxying headers
[2025-06-11 14:15:23.889][18][trace][connection] [source/common/network/connection_impl.cc:529] [Tags: "ConnectionId":"8"] writing 370 bytes, end_stream false
[2025-06-11 14:15:23.889][18][trace][http] [source/common/http/filter_manager.cc:573] [Tags: "ConnectionId":"9","StreamId":"13551906667112814535"] decode headers called: filter=envoy.filters.http.upstream_codec status=0
[2025-06-11 14:15:23.889][18][trace][http] [source/common/http/filter_manager.cc:573] [Tags: "ConnectionId":"9","StreamId":"13551906667112814535"] decode headers called: filter=envoy.filters.http.router status=1
[2025-06-11 14:15:23.889][18][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff765e00 for 86400000ms, min is 86400000ms
[2025-06-11 14:15:23.889][18][trace][router] [source/common/router/upstream_codec_filter.cc:99] [Tags: "ConnectionId":"9","StreamId":"13551906667112814535"] proxying 253 bytes
[2025-06-11 14:15:23.889][18][trace][connection] [source/common/network/connection_impl.cc:529] [Tags: "ConnectionId":"8"] writing 264 bytes, end_stream false
[2025-06-11 14:15:23.889][18][debug][client] [source/common/http/codec_client.cc:142] [Tags: "ConnectionId":"8"] encode complete
[2025-06-11 14:15:23.889][18][trace][http] [source/common/http/filter_manager.cc:719] [Tags: "ConnectionId":"9","StreamId":"13551906667112814535"] decode data called: filter=envoy.filters.http.upstream_codec status=0
[2025-06-11 14:15:23.889][18][trace][http] [source/common/http/filter_manager.cc:719] [Tags: "ConnectionId":"9","StreamId":"13551906667112814535"] decode data called: filter=envoy.filters.http.router status=3
[2025-06-11 14:15:23.889][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:42] Finish external processing call
[2025-06-11 14:15:23.889][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:501] Continuing processing
[2025-06-11 14:15:23.889][18][trace][http] [source/common/http/filter_manager.cc:66] [Tags: "ConnectionId":"9","StreamId":"13551906667112814535"] continuing filter chain: filter=0x636ff427d50
[2025-06-11 14:15:23.889][18][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff765e00 for 86400000ms, min is 86400000ms
[2025-06-11 14:15:23.889][18][trace][http2] [source/common/http/http2/codec_impl.cc:978] [Tags: "ConnectionId":"7"] dispatched 859 bytes
[2025-06-11 14:15:23.889][18][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"8"] socket event: 2
[2025-06-11 14:15:23.889][18][trace][connection] [source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"8"] write ready
[2025-06-11 14:15:23.889][18][trace][connection] [source/common/network/raw_buffer_socket.cc:70] [Tags: "ConnectionId":"8"] write returns: 634
[2025-06-11 14:15:23.890][18][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"8"] socket event: 3
[2025-06-11 14:15:23.890][18][trace][connection] [source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"8"] write ready
[2025-06-11 14:15:23.890][18][trace][connection] [source/common/network/connection_impl.cc:654] [Tags: "ConnectionId":"8"] read ready. dispatch_buffered_data=0
[2025-06-11 14:15:23.890][18][trace][connection] [source/common/network/raw_buffer_socket.cc:25] [Tags: "ConnectionId":"8"] read returns: 415
[2025-06-11 14:15:23.890][18][trace][connection] [source/common/network/raw_buffer_socket.cc:39] [Tags: "ConnectionId":"8"] read error: Resource temporarily unavailable, code: 0
[2025-06-11 14:15:23.890][18][trace][http] [source/common/http/http1/codec_impl.cc:645] [Tags: "ConnectionId":"8"] parsing 415 bytes
[2025-06-11 14:15:23.890][18][trace][http] [source/common/http/http1/codec_impl.cc:587] [Tags: "ConnectionId":"8"] message begin
[2025-06-11 14:15:23.890][18][trace][http] [source/common/http/http1/codec_impl.cc:544] [Tags: "ConnectionId":"8"] completed header: key=Server value=fasthttp
[2025-06-11 14:15:23.890][18][trace][http] [source/common/http/http1/codec_impl.cc:544] [Tags: "ConnectionId":"8"] completed header: key=Date value=Wed, 11 Jun 2025 14:15:23 GMT
[2025-06-11 14:15:23.890][18][trace][http] [source/common/http/http1/codec_impl.cc:544] [Tags: "ConnectionId":"8"] completed header: key=Content-Type value=application/json
[2025-06-11 14:15:23.890][18][trace][http] [source/common/http/http1/codec_impl.cc:838] [Tags: "ConnectionId":"8"] onHeadersCompleteImpl
envoy  | nt-Length value=288][trace][http] [source/common/http/http1/codec_impl.cc:544] [Tags: "ConnectionId":"8"] completed header: key=Conte
[2025-06-11 14:15:23.890][18][trace][http] [source/common/http/http1/codec_impl.cc:1490] [Tags: "ConnectionId":"8"] status_code 200
[2025-06-11 14:15:23.890][18][trace][http] [source/common/http/http1/codec_impl.cc:1500] [Tags: "ConnectionId":"8"] Client: onHeadersComplete size=4
[2025-06-11 14:15:23.890][18][trace][http] [source/common/http/filter_manager.cc:906] [Tags: "ConnectionId":"9","StreamId":"13551906667112814535"] commonEncodePrefix end_stream: false, isHalfCloseEnabled: false
[2025-06-11 14:15:23.890][18][trace][router] [source/common/router/upstream_request.cc:267] [Tags: "ConnectionId":"9","StreamId":"13551906667112814535"] end_stream: false, upstream response headers:
':status', '200'
'server', 'fasthttp'
'date', 'Wed, 11 Jun 2025 14:15:23 GMT'
'content-type', 'application/json'
'content-length', '288'

[2025-06-11 14:15:23.890][18][debug][router] [source/common/router/router.cc:1571] [Tags: "ConnectionId":"9","StreamId":"13551906667112814535"] upstream headers complete: end_stream=false
[2025-06-11 14:15:23.890][18][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff765e00 for 86400000ms, min is 86400000ms
[2025-06-11 14:15:23.890][18][trace][http] [source/common/http/filter_manager.cc:906] [Tags: "ConnectionId":"9","StreamId":"13551906667112814535"] commonEncodePrefix end_stream: false, isHalfCloseEnabled: false
[2025-06-11 14:15:23.890][18][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:918] encodeHeaders end_stream = false
[2025-06-11 14:15:23.890][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:23] Start external processing call
[2025-06-11 14:15:23.890][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:496] Sending headers message
[2025-06-11 14:15:23.890][18][trace][router] [source/common/router/upstream_codec_filter.cc:99] [Tags: "ConnectionId":"0","StreamId":"6508579852161680385"] proxying 145 bytes
[2025-06-11 14:15:23.890][18][trace][connection] [source/common/network/connection_impl.cc:529] [Tags: "ConnectionId":"7"] writing 154 bytes, end_stream false
[2025-06-11 14:15:23.890][18][trace][http2] [source/common/http/http2/codec_impl.cc:1198] [Tags: "ConnectionId":"7"] sent frame type=0, stream_id=3, length=145
[2025-06-11 14:15:23.890][18][trace][http] [source/common/http/filter_manager.cc:719] [Tags: "ConnectionId":"0","StreamId":"6508579852161680385"] decode data called: filter=envoy.filters.http.upstream_codec status=0
[2025-06-11 14:15:23.890][18][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:934] onHeaders returns 1
[2025-06-11 14:15:23.890][18][trace][http] [source/common/http/filter_manager.cc:1263] [Tags: "ConnectionId":"9","StreamId":"13551906667112814535"] encode headers called: filter=envoy.filters.http.ext_proc status=1
[2025-06-11 14:15:23.890][18][trace][http] [source/common/http/http1/codec_impl.cc:942] [Tags: "ConnectionId":"8"] message complete
[2025-06-11 14:15:23.890][18][trace][http] [source/common/http/filter_manager.cc:906] [Tags: "ConnectionId":"9","StreamId":"13551906667112814535"] commonEncodePrefix end_stream: false, isHalfCloseEnabled: false
[2025-06-11 14:15:23.890][18][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff765e00 for 86400000ms, min is 86400000ms
[2025-06-11 14:15:23.890][18][trace][http] [source/common/http/filter_manager.cc:906] [Tags: "ConnectionId":"9","StreamId":"13551906667112814535"] commonEncodePrefix end_stream: false, isHalfCloseEnabled: false
[2025-06-11 14:15:23.890][18][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:951] encodeData(288): end_stream = false
[2025-06-11 14:15:23.890][18][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:695] Sending body data even though header processing is still in progress as body mode is FULL_DUPLEX_STREAMED or STREAMED and send_body_without_waiting_for_header_response is enabled
[2025-06-11 14:15:23.890][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:966] Sending a body chunk of 288 bytes, end_stream false
[2025-06-11 14:15:23.890][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:23] Start external processing call
[2025-06-11 14:15:23.890][18][trace][router] [source/common/router/upstream_codec_filter.cc:99] [Tags: "ConnectionId":"0","StreamId":"6508579852161680385"] proxying 301 bytes
[2025-06-11 14:15:23.890][18][trace][connection] [source/common/network/connection_impl.cc:529] [Tags: "ConnectionId":"7"] writing 310 bytes, end_stream false
[2025-06-11 14:15:23.890][18][trace][http2] [source/common/http/http2/codec_impl.cc:1198] [Tags: "ConnectionId":"7"] sent frame type=0, stream_id=3, length=301
[2025-06-11 14:15:23.890][18][trace][http] [source/common/http/filter_manager.cc:719] [Tags: "ConnectionId":"0","StreamId":"6508579852161680385"] decode data called: filter=envoy.filters.http.upstream_codec status=0
[2025-06-11 14:15:23.890][18][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:953] encodeData returning 3
[2025-06-11 14:15:23.890][18][trace][http] [source/common/http/filter_manager.cc:1450] [Tags: "ConnectionId":"9","StreamId":"13551906667112814535"] encode data called: filter=envoy.filters.http.ext_proc status=3
[2025-06-11 14:15:23.890][18][trace][http] [source/common/http/http1/codec_impl.cc:1572] [Tags: "ConnectionId":"8"] message complete
[2025-06-11 14:15:23.890][18][debug][client] [source/common/http/codec_client.cc:129] [Tags: "ConnectionId":"8"] response complete
[2025-06-11 14:15:23.890][18][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=1)
[2025-06-11 14:15:23.890][18][trace][http] [source/common/http/filter_manager.cc:906] [Tags: "ConnectionId":"9","StreamId":"13551906667112814535"] commonEncodePrefix end_stream: true, isHalfCloseEnabled: false
[2025-06-11 14:15:23.890][18][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=2)
[2025-06-11 14:15:23.890][18][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=3)
[2025-06-11 14:15:23.890][18][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff765e00 for 86400000ms, min is 86400000ms
[2025-06-11 14:15:23.890][18][trace][http] [source/common/http/filter_manager.cc:906] [Tags: "ConnectionId":"9","StreamId":"13551906667112814535"] commonEncodePrefix end_stream: true, isHalfCloseEnabled: false
[2025-06-11 14:15:23.890][18][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:951] encodeData(0): end_stream = true
[2025-06-11 14:15:23.890][18][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:695] Sending body data even though header processing is still in progress as body mode is FULL_DUPLEX_STREAMED or STREAMED and send_body_without_waiting_for_header_response is enabled
[2025-06-11 14:15:23.890][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:966] Sending a body chunk of 0 bytes, end_stream true
[2025-06-11 14:15:23.890][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:23] Start external processing call
[2025-06-11 14:15:23.890][18][trace][router] [source/common/router/upstream_codec_filter.cc:99] [Tags: "ConnectionId":"0","StreamId":"6508579852161680385"] proxying 11 bytes
[2025-06-11 14:15:23.890][18][trace][connection] [source/common/network/connection_impl.cc:529] [Tags: "ConnectionId":"7"] writing 20 bytes, end_stream false
[2025-06-11 14:15:23.890][18][trace][http2] [source/common/http/http2/codec_impl.cc:1198] [Tags: "ConnectionId":"7"] sent frame type=0, stream_id=3, length=11
[2025-06-11 14:15:23.890][18][trace][http] [source/common/http/filter_manager.cc:719] [Tags: "ConnectionId":"0","StreamId":"6508579852161680385"] decode data called: filter=envoy.filters.http.upstream_codec status=0
[2025-06-11 14:15:23.890][18][trace][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:953] encodeData returning 3
[2025-06-11 14:15:23.890][18][trace][http] [source/common/http/filter_manager.cc:1450] [Tags: "ConnectionId":"9","StreamId":"13551906667112814535"] encode data called: filter=envoy.filters.http.ext_proc status=3
[2025-06-11 14:15:23.890][18][debug][pool] [source/common/http/http1/conn_pool.cc:53] [Tags: "ConnectionId":"8"] response complete
[2025-06-11 14:15:23.890][18][debug][pool] [source/common/conn_pool/conn_pool_base.cc:254] [Tags: "ConnectionId":"8"] destroying stream: 0 active remaining, readyForStream false, currentUnusedCapacity 1
[2025-06-11 14:15:23.890][18][trace][http] [source/common/http/http1/codec_impl.cc:695] [Tags: "ConnectionId":"8"] parsed 415 bytes
[2025-06-11 14:15:23.890][18][trace][main] [source/common/event/dispatcher_impl.cc:127] clearing deferred deletion list (size=3)
[2025-06-11 14:15:23.890][18][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"7"] socket event: 2
[2025-06-11 14:15:23.890][18][trace][connection] [source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"7"] write ready
[2025-06-11 14:15:23.890][18][trace][connection] [source/common/tls/ssl_socket.cc:284] [Tags: "ConnectionId":"7"] ssl write returns: 484
[2025-06-11 14:15:23.890][18][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"7"] socket event: 3
[2025-06-11 14:15:23.890][18][trace][connection] [source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"7"] write ready
[2025-06-11 14:15:23.890][18][trace][connection] [source/common/network/connection_impl.cc:654] [Tags: "ConnectionId":"7"] read ready. dispatch_buffered_data=0
[2025-06-11 14:15:23.890][18][trace][connection] [source/common/tls/ssl_socket.cc:94] [Tags: "ConnectionId":"7"] ssl read returns: 30
[2025-06-11 14:15:23.890][18][trace][connection] [source/common/tls/ssl_socket.cc:94] [Tags: "ConnectionId":"7"] ssl read returns: -1
[2025-06-11 14:15:23.890][18][trace][connection] [source/common/tls/ssl_socket.cc:134] [Tags: "ConnectionId":"7"] ssl error occurred while read: WANT_READ
[2025-06-11 14:15:23.890][18][trace][connection] [source/common/tls/ssl_socket.cc:170] [Tags: "ConnectionId":"7"] ssl read 30 bytes
[2025-06-11 14:15:23.890][18][trace][http2] [source/common/http/http2/codec_impl.cc:940] [Tags: "ConnectionId":"7"] dispatching 30 bytes
[2025-06-11 14:15:23.890][18][trace][http2] [source/common/http/http2/codec_impl.cc:1742] [Tags: "ConnectionId":"7"] Http2Visitor::OnFrameHeader(0, 4, 8, 0)
[2025-06-11 14:15:23.890][18][trace][http2] [source/common/http/http2/codec_impl.cc:1050] [Tags: "ConnectionId":"7"] about to recv frame type=8, flags=0, stream_id=0
[2025-06-11 14:15:23.891][18][trace][http2] [source/common/http/http2/codec_impl.cc:1339] [Tags: "ConnectionId":"7"] track inbound frame type=8 flags=0 length=4 padding_length=0
[2025-06-11 14:15:23.891][18][trace][http2] [source/common/http/http2/codec_impl.cc:1742] [Tags: "ConnectionId":"7"] Http2Visitor::OnFrameHeader(0, 8, 6, 0)
[2025-06-11 14:15:23.891][18][trace][http2] [source/common/http/http2/codec_impl.cc:1050] [Tags: "ConnectionId":"7"] about to recv frame type=6, flags=0, stream_id=0
[2025-06-11 14:15:23.891][18][trace][http2] [source/common/http/http2/codec_impl.cc:1339] [Tags: "ConnectionId":"7"] track inbound frame type=6 flags=0 length=8 padding_length=0
[2025-06-11 14:15:23.891][18][trace][http2] [source/common/http/http2/codec_impl.cc:1089] [Tags: "ConnectionId":"7"] recv frame type=PING
[2025-06-11 14:15:23.891][18][trace][http2] [source/common/http/http2/codec_impl.cc:978] [Tags: "ConnectionId":"7"] dispatched 30 bytes
[2025-06-11 14:15:23.891][18][trace][http2] [source/common/http/http2/codec_impl.cc:1312] [Tags: "ConnectionId":"7"] about to send frame type=6, flags=1
[2025-06-11 14:15:23.891][18][trace][http2] [source/common/http/http2/codec_impl.cc:1361] [Tags: "ConnectionId":"7"] send data: bytes=17
[2025-06-11 14:15:23.891][18][trace][connection] [source/common/network/connection_impl.cc:529] [Tags: "ConnectionId":"7"] writing 17 bytes, end_stream false
envoy  | ce][http2] [source/common/http/http2/codec_impl.cc:1198] [Tags: "ConnectionId":"7"] sent frame type=6, stream_id=0, length=8
[2025-06-11 14:15:23.891][18][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"7"] socket event: 2
[2025-06-11 14:15:23.891][18][trace][connection] [source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"7"] write ready
[2025-06-11 14:15:23.891][18][trace][connection] [source/common/tls/ssl_socket.cc:284] [Tags: "ConnectionId":"7"] ssl write returns: 17
[2025-06-11 14:15:23.891][18][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"7"] socket event: 3
[2025-06-11 14:15:23.891][18][trace][connection] [source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"7"] write ready
[2025-06-11 14:15:23.891][18][trace][connection] [source/common/network/connection_impl.cc:654] [Tags: "ConnectionId":"7"] read ready. dispatch_buffered_data=0
[2025-06-11 14:15:23.891][18][trace][connection] [source/common/tls/ssl_socket.cc:94] [Tags: "ConnectionId":"7"] ssl read returns: 201
[2025-06-11 14:15:23.891][18][trace][connection] [source/common/tls/ssl_socket.cc:94] [Tags: "ConnectionId":"7"] ssl read returns: -1
[2025-06-11 14:15:23.891][18][trace][connection] [source/common/tls/ssl_socket.cc:134] [Tags: "ConnectionId":"7"] ssl error occurred while read: WANT_READ
[2025-06-11 14:15:23.891][18][trace][connection] [source/common/tls/ssl_socket.cc:170] [Tags: "ConnectionId":"7"] ssl read 201 bytes
[2025-06-11 14:15:23.891][18][trace][http2] [source/common/http/http2/codec_impl.cc:940] [Tags: "ConnectionId":"7"] dispatching 201 bytes
[2025-06-11 14:15:23.891][18][trace][http2] [source/common/http/http2/codec_impl.cc:1742] [Tags: "ConnectionId":"7"] Http2Visitor::OnFrameHeader(3, 192, 0, 0)
[2025-06-11 14:15:23.891][18][trace][http2] [source/common/http/http2/codec_impl.cc:1050] [Tags: "ConnectionId":"7"] about to recv frame type=0, flags=0, stream_id=3
[2025-06-11 14:15:23.891][18][trace][http2] [source/common/http/http2/codec_impl.cc:1793] [Tags: "ConnectionId":"7"] Http2Visitor::OnBeginDataForStream(3, 192)
[2025-06-11 14:15:23.891][18][debug][http2] [source/common/http/http2/codec_impl.cc:1805] [Tags: "ConnectionId":"7"] Http2Visitor: remaining data payload: 192, stream_id: 3, end_stream: false
[2025-06-11 14:15:23.891][18][trace][http2] [source/common/http/http2/codec_impl.cc:1834] [Tags: "ConnectionId":"7"] Http2Visitor dispatching DATA for stream 3
[2025-06-11 14:15:23.891][18][trace][http2] [source/common/http/http2/codec_impl.cc:1102] [Tags: "ConnectionId":"7"] recv frame type=DATA stream_id=3
[2025-06-11 14:15:23.891][18][trace][http2] [source/common/http/http2/codec_impl.cc:1339] [Tags: "ConnectionId":"7"] track inbound frame type=0 flags=0 length=192 padding_length=0
[2025-06-11 14:15:23.891][18][trace][http] [source/common/http/filter_manager.cc:906] [Tags: "ConnectionId":"0","StreamId":"6508579852161680385"] commonEncodePrefix end_stream: false, isHalfCloseEnabled: false
[2025-06-11 14:15:23.891][18][trace][http] [source/common/http/async_client_impl.cc:207] async http request response data (length=192 end_stream=false)
[2025-06-11 14:15:23.891][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1234] Received response headers response
[2025-06-11 14:15:23.891][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:146] applying headers response. body mode = FULL_DUPLEX_STREAMED
[2025-06-11 14:15:23.891][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:109] Applying header mutations
[2025-06-11 14:15:23.891][18][trace][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:176] Setting header x-went-into-resp-headers append = false
[2025-06-11 14:15:23.891][18][trace][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:176] Setting header :status append = false
envoy  | r append = false[18][trace][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:176] Setting header serve
[2025-06-11 14:15:23.891][18][trace][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:176] Setting header date append = false
[2025-06-11 14:15:23.891][18][trace][ext_proc] [source/extensions/filters/http/ext_proc/mutation_utils.cc:176] Setting header content-type append = false
[2025-06-11 14:15:23.891][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:42] Finish external processing call
[2025-06-11 14:15:23.891][18][trace][http2] [source/common/http/http2/codec_impl.cc:978] [Tags: "ConnectionId":"7"] dispatched 201 bytes
[2025-06-11 14:15:23.891][18][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"7"] socket event: 3
[2025-06-11 14:15:23.891][18][trace][connection] [source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"7"] write ready
[2025-06-11 14:15:23.891][18][trace][connection] [source/common/network/connection_impl.cc:654] [Tags: "ConnectionId":"7"] read ready. dispatch_buffered_data=0
[2025-06-11 14:15:23.891][18][trace][connection] [source/common/tls/ssl_socket.cc:94] [Tags: "ConnectionId":"7"] ssl read returns: 319
[2025-06-11 14:15:23.891][18][trace][connection] [source/common/tls/ssl_socket.cc:94] [Tags: "ConnectionId":"7"] ssl read returns: -1
[2025-06-11 14:15:23.891][18][trace][connection] [source/common/tls/ssl_socket.cc:134] [Tags: "ConnectionId":"7"] ssl error occurred while read: WANT_READ
[2025-06-11 14:15:23.891][18][trace][connection] [source/common/tls/ssl_socket.cc:170] [Tags: "ConnectionId":"7"] ssl read 319 bytes
[2025-06-11 14:15:23.891][18][trace][http2] [source/common/http/http2/codec_impl.cc:940] [Tags: "ConnectionId":"7"] dispatching 319 bytes
[2025-06-11 14:15:23.891][18][trace][http2] [source/common/http/http2/codec_impl.cc:1742] [Tags: "ConnectionId":"7"] Http2Visitor::OnFrameHeader(3, 310, 0, 0)
[2025-06-11 14:15:23.891][18][trace][http2] [source/common/http/http2/codec_impl.cc:1050] [Tags: "ConnectionId":"7"] about to recv frame type=0, flags=0, stream_id=3
[2025-06-11 14:15:23.891][18][trace][http2] [source/common/http/http2/codec_impl.cc:1793] [Tags: "ConnectionId":"7"] Http2Visitor::OnBeginDataForStream(3, 310)
[2025-06-11 14:15:23.891][18][debug][http2] [source/common/http/http2/codec_impl.cc:1805] [Tags: "ConnectionId":"7"] Http2Visitor: remaining data payload: 310, stream_id: 3, end_stream: false
[2025-06-11 14:15:23.891][18][trace][http2] [source/common/http/http2/codec_impl.cc:1834] [Tags: "ConnectionId":"7"] Http2Visitor dispatching DATA for stream 3
[2025-06-11 14:15:23.891][18][trace][http2] [source/common/http/http2/codec_impl.cc:1102] [Tags: "ConnectionId":"7"] recv frame type=DATA stream_id=3
[2025-06-11 14:15:23.891][18][trace][http2] [source/common/http/http2/codec_impl.cc:1339] [Tags: "ConnectionId":"7"] track inbound frame type=0 flags=0 length=310 padding_length=0
[2025-06-11 14:15:23.891][18][trace][http] [source/common/http/filter_manager.cc:906] [Tags: "ConnectionId":"0","StreamId":"6508579852161680385"] commonEncodePrefix end_stream: false, isHalfCloseEnabled: false
[2025-06-11 14:15:23.891][18][trace][http] [source/common/http/async_client_impl.cc:207] async http request response data (length=310 end_stream=false)
[2025-06-11 14:15:23.891][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:1234] Received response body response
[2025-06-11 14:15:23.891][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:280] Processing body response
[2025-06-11 14:15:23.891][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:347] FULL_DUPLEX_STREAMED body response is received and body_mode_: FULL_DUPLEX_STREAMED 
[2025-06-11 14:15:23.891][18][trace][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:545] Injecting 288 bytes of data to filter stream in FULL_DUPLEX_STREAMED mode. end_of_stream is true
[2025-06-11 14:15:23.891][18][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff765e00 for 86400000ms, min is 86400000ms
[2025-06-11 14:15:23.891][18][trace][http] [source/common/http/filter_manager.cc:906] [Tags: "ConnectionId":"9","StreamId":"13551906667112814535"] commonEncodePrefix end_stream: false, isHalfCloseEnabled: false
[2025-06-11 14:15:23.891][18][debug][http] [source/common/http/conn_manager_impl.cc:1896] [Tags: "ConnectionId":"9","StreamId":"13551906667112814535"] encoding headers via codec (end_stream=false):
':status', '200'
'x-went-into-resp-headers', 'true'
'server', 'fasthttp'
'date', 'Wed, 11 Jun 2025 14:15:23 GMT'
'content-type', 'application/json'

[2025-06-11 14:15:23.891][18][trace][connection] [source/common/network/connection_impl.cc:529] [Tags: "ConnectionId":"9"] writing 166 bytes, end_stream false
[2025-06-11 14:15:23.891][18][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff765e00 for 86400000ms, min is 86400000ms
[2025-06-11 14:15:23.891][18][trace][http] [source/common/http/filter_manager.cc:906] [Tags: "ConnectionId":"9","StreamId":"13551906667112814535"] commonEncodePrefix end_stream: true, isHalfCloseEnabled: false
[2025-06-11 14:15:23.891][18][trace][http] [source/common/http/conn_manager_impl.cc:1920] [Tags: "ConnectionId":"9","StreamId":"13551906667112814535"] encoding data via codec (size=288 end_stream=true)
[2025-06-11 14:15:23.891][18][trace][connection] [source/common/network/connection_impl.cc:529] [Tags: "ConnectionId":"9"] writing 300 bytes, end_stream false
[2025-06-11 14:15:23.891][18][debug][http] [source/common/http/conn_manager_impl.cc:2011] [Tags: "ConnectionId":"9","StreamId":"13551906667112814535"] Codec completed encoding stream.
[2025-06-11 14:15:23.891][18][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=1)
[2025-06-11 14:15:23.892][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:447] onDestroy
[2025-06-11 14:15:23.892][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/ext_proc.cc:430] Calling close on stream
[2025-06-11 14:15:23.892][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/client_impl.cc:70] Closing gRPC stream
[2025-06-11 14:15:23.892][18][trace][router] [source/common/router/upstream_codec_filter.cc:99] [Tags: "ConnectionId":"0","StreamId":"6508579852161680385"] proxying 0 bytes
[2025-06-11 14:15:23.892][18][debug][client] [source/common/http/codec_client.cc:142] [Tags: "ConnectionId":"7"] encode complete
[2025-06-11 14:15:23.892][18][trace][http] [source/common/http/filter_manager.cc:719] [Tags: "ConnectionId":"0","StreamId":"6508579852161680385"] decode data called: filter=envoy.filters.http.upstream_codec status=0
[2025-06-11 14:15:23.892][18][debug][router] [source/common/router/upstream_request.cc:486] [Tags: "ConnectionId":"0","StreamId":"6508579852161680385"] resetting pool request
[2025-06-11 14:15:23.892][18][debug][client] [source/common/http/codec_client.cc:159] [Tags: "ConnectionId":"7"] request reset
[2025-06-11 14:15:23.892][18][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=2)
[2025-06-11 14:15:23.892][18][debug][pool] [source/common/conn_pool/conn_pool_base.cc:254] [Tags: "ConnectionId":"7"] destroying stream: 0 active remaining, readyForStream true, currentUnusedCapacity 536870910
[2025-06-11 14:15:23.892][18][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=3)
[2025-06-11 14:15:23.892][18][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=4)
[2025-06-11 14:15:23.892][18][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=5)
[2025-06-11 14:15:23.892][18][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=6)
[2025-06-11 14:15:23.892][18][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=7)
[2025-06-11 14:15:23.892][18][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff456f00 for 3600000ms, min is 3600000ms
[2025-06-11 14:15:23.892][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:42] Finish external processing call
[2025-06-11 14:15:23.892][18][debug][ext_proc] [source/extensions/filters/http/ext_proc/processor_state.cc:501] Continuing processing
[2025-06-11 14:15:23.892][18][trace][http] [source/common/http/filter_manager.cc:53] [Tags: "ConnectionId":"9","StreamId":"13551906667112814535"] cannot continue filter chain: filter=0x636ff427ab0
[2025-06-11 14:15:23.892][18][trace][http2] [source/common/http/http2/codec_impl.cc:978] [Tags: "ConnectionId":"7"] dispatched 319 bytes
[2025-06-11 14:15:23.892][18][trace][http2] [source/common/http/http2/codec_impl.cc:1312] [Tags: "ConnectionId":"7"] about to send frame type=3, flags=0
[2025-06-11 14:15:23.892][18][trace][http2] [source/common/http/http2/codec_impl.cc:1361] [Tags: "ConnectionId":"7"] send data: bytes=13
[2025-06-11 14:15:23.892][18][trace][connection] [source/common/network/connection_impl.cc:529] [Tags: "ConnectionId":"7"] writing 13 bytes, end_stream false
[2025-06-11 14:15:23.892][18][trace][http2] [source/common/http/http2/codec_impl.cc:1198] [Tags: "ConnectionId":"7"] sent frame type=3, stream_id=3, length=4
[2025-06-11 14:15:23.892][18][debug][http2] [source/common/http/http2/codec_impl.cc:1227] [Tags: "ConnectionId":"7"] sent reset code=0
[2025-06-11 14:15:23.892][18][debug][http2] [source/common/http/http2/codec_impl.cc:1386] [Tags: "ConnectionId":"7"] stream 3 closed: 0
[2025-06-11 14:15:23.892][18][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=8)
[2025-06-11 14:15:23.892][18][debug][http2] [source/common/http/http2/codec_impl.cc:1449] [Tags: "ConnectionId":"7"] Recouping 0 bytes of flow control window for stream 3.
[2025-06-11 14:15:23.892][18][trace][http2] [source/common/http/http2/codec_impl.cc:1868] [Tags: "ConnectionId":"7"] Http2Visitor invoking stream close listener for stream 3
[2025-06-11 14:15:23.892][18][trace][main] [source/common/event/dispatcher_impl.cc:127] clearing deferred deletion list (size=8)
[2025-06-11 14:15:23.892][18][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"9"] socket event: 2
[2025-06-11 14:15:23.892][18][trace][connection] [source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"9"] write ready
[2025-06-11 14:15:23.892][18][trace][connection] [source/common/network/raw_buffer_socket.cc:70] [Tags: "ConnectionId":"9"] write returns: 466
[2025-06-11 14:15:23.892][18][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"7"] socket event: 2
[2025-06-11 14:15:23.892][18][trace][connection] [source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"7"] write ready
[2025-06-11 14:15:23.892][18][trace][connection] [source/common/tls/ssl_socket.cc:284] [Tags: "ConnectionId":"7"] ssl write returns: 13
[2025-06-11 14:15:23.892][18][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"9"] socket event: 3
[2025-06-11 14:15:23.892][18][trace][connection] [source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"9"] write ready
[2025-06-11 14:15:23.892][18][trace][connection] [source/common/network/connection_impl.cc:654] [Tags: "ConnectionId":"9"] read ready. dispatch_buffered_data=0
[2025-06-11 14:15:23.892][18][trace][connection] [source/common/network/raw_buffer_socket.cc:25] [Tags: "ConnectionId":"9"] read returns: 0
[2025-06-11 14:15:23.892][18][debug][connection] [source/common/network/connection_impl.cc:714] [Tags: "ConnectionId":"9"] remote close
[2025-06-11 14:15:23.892][18][debug][connection] [source/common/network/connection_impl.cc:276] [Tags: "ConnectionId":"9"] closing socket: 0
[2025-06-11 14:15:23.892][18][trace][connection] [source/common/network/connection_impl.cc:469] [Tags: "ConnectionId":"9"] raising connection event 0
[2025-06-11 14:15:23.892][18][trace][conn_handler] [source/common/listener_manager/active_stream_listener_base.cc:126] [Tags: "ConnectionId":"9"] tcp connection on event 0
[2025-06-11 14:15:23.892][18][debug][conn_handler] [source/common/listener_manager/active_stream_listener_base.cc:136] [Tags: "ConnectionId":"9"] adding to cleanup list
[2025-06-11 14:15:23.892][18][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=1)
[2025-06-11 14:15:23.892][18][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=2)
[2025-06-11 14:15:23.892][18][trace][main] [source/common/event/dispatcher_impl.cc:127] clearing deferred deletion list (size=2)
[2025-06-11 14:15:27.265][1][trace][upstream] [source/extensions/clusters/original_dst/original_dst_cluster.cc:254] Cleaning up stale original dst hosts.
[2025-06-11 14:15:27.265][1][trace][upstream] [source/extensions/clusters/original_dst/original_dst_cluster.cc:293] Keeping active address 10.244.0.14:8000.
{"start_time":"2025-06-11T14:15:23.841Z","method":"POST",...}
{"start_time":"2025-06-11T14:15:23.886Z","method":"POST",...}
[2025-06-11 14:15:27.273][1][debug][main] [source/server/server.cc:239] flushing stats
[2025-06-11 14:15:27.291][1][trace][upstream] [source/extensions/clusters/strict_dns/strict_dns_cluster.cc:128] starting async DNS resolution for vllm-llama3-8b-instruct-epp.inf-ext-e2e
[2025-06-11 14:15:27.291][1][debug][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:410] dns resolution for vllm-llama3-8b-instruct-epp.inf-ext-e2e started
[2025-06-11 14:15:27.291][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:27.291][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:27.291][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:27.291][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:27.294][1][debug][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:192] dns resolution without records for vllm-llama3-8b-instruct-epp.inf-ext-e2e
[2025-06-11 14:15:27.294][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:27.294][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:27.294][1][debug][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:327] dns resolution for vllm-llama3-8b-instruct-epp.inf-ext-e2e completed with status 0
[2025-06-11 14:15:27.294][1][trace][upstream] [source/extensions/clusters/strict_dns/strict_dns_cluster.cc:136] async DNS resolution complete for vllm-llama3-8b-instruct-epp.inf-ext-e2e details cares_success:Successful completion
[2025-06-11 14:15:27.294][1][debug][upstream] [source/common/upstream/upstream_impl.cc:485] transport socket match, socket default selected for host with address 10.96.209.200:9002
[2025-06-11 14:15:27.294][1][debug][upstream] [source/extensions/clusters/strict_dns/strict_dns_cluster.cc:218] DNS refresh rate reset for vllm-llama3-8b-instruct-epp.inf-ext-e2e, refresh rate 5000 ms
[2025-06-11 14:15:27.414][20][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff457800 for 3600000ms, min is 3600000ms
[2025-06-11 14:15:27.414][20][trace][connection] [source/common/network/connection_impl.cc:469] [Tags: "ConnectionId":"10"] raising connection event 2
[2025-06-11 14:15:27.414][20][debug][conn_handler] [source/common/listener_manager/active_tcp_listener.cc:160] [Tags: "ConnectionId":"10"] new connection from 10.244.0.1:56994
[2025-06-11 14:15:27.414][20][trace][misc] [source/common/network/tcp_listener_impl.cc:123] TcpListener accepted 1 new connections.
envoy  | nection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"10"] socket event: 3
[2025-06-11 14:15:27.414][20][trace][connection] [source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"10"] write ready
[2025-06-11 14:15:27.414][20][trace][connection] [source/common/network/connection_impl.cc:654] [Tags: "ConnectionId":"10"] read ready. dispatch_buffered_data=0
[2025-06-11 14:15:27.414][20][trace][connection] [source/common/network/raw_buffer_socket.cc:25] [Tags: "ConnectionId":"10"] read returns: 109
[2025-06-11 14:15:27.414][20][trace][connection] [source/common/network/raw_buffer_socket.cc:39] [Tags: "ConnectionId":"10"] read error: Resource temporarily unavailable, code: 0
[2025-06-11 14:15:27.414][20][trace][http] [source/common/http/http1/codec_impl.cc:645] [Tags: "ConnectionId":"10"] parsing 109 bytes
[2025-06-11 14:15:27.414][20][trace][http] [source/common/http/http1/codec_impl.cc:587] [Tags: "ConnectionId":"10"] message begin
[2025-06-11 14:15:27.414][20][debug][http] [source/common/http/conn_manager_impl.cc:394] [Tags: "ConnectionId":"10"] new stream
[2025-06-11 14:15:27.414][20][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff456480 for 300000ms, min is 300000ms
[2025-06-11 14:15:27.414][20][trace][http] [source/common/http/http1/codec_impl.cc:544] [Tags: "ConnectionId":"10"] completed header: key=Host value=10.244.0.13:19001
[2025-06-11 14:15:27.414][20][trace][http] [source/common/http/http1/codec_impl.cc:544] [Tags: "ConnectionId":"10"] completed header: key=User-Agent value=kube-probe/1.33
[2025-06-11 14:15:27.414][20][trace][http] [source/common/http/http1/codec_impl.cc:544] [Tags: "ConnectionId":"10"] completed header: key=Accept value=*/*
[2025-06-11 14:15:27.414][20][trace][http] [source/common/http/http1/codec_impl.cc:838] [Tags: "ConnectionId":"10"] onHeadersCompleteImpl
[2025-06-11 14:15:27.414][20][trace][http] [source/common/http/http1/codec_impl.cc:544] [Tags: "ConnectionId":"10"] completed header: key=Connection value=close
[2025-06-11 14:15:27.414][20][trace][http] [source/common/http/http1/codec_impl.cc:1191] [Tags: "ConnectionId":"10"] Server: onHeadersComplete size=4
[2025-06-11 14:15:27.414][20][trace][http] [source/common/http/http1/codec_impl.cc:942] [Tags: "ConnectionId":"10"] message complete
[2025-06-11 14:15:27.414][20][debug][http] [source/common/http/conn_manager_impl.cc:1196] [Tags: "ConnectionId":"10","StreamId":"15493613003968368065"] request headers complete (end_stream=true):
':authority', '10.244.0.13:19001'
':path', '/ready'
':method', 'GET'
'user-agent', 'kube-probe/1.33'
'accept', '*/*'
'connection', 'close'

[2025-06-11 14:15:27.414][20][debug][http] [source/common/http/conn_manager_impl.cc:1179] [Tags: "ConnectionId":"10","StreamId":"15493613003968368065"] request end stream timestamp recorded
[2025-06-11 14:15:27.414][20][debug][connection] [./source/common/network/connection_impl.h:98] [Tags: "ConnectionId":"10"] current connecting state: false
[2025-06-11 14:15:27.414][20][debug][router] [source/common/router/config_impl.cc:2071] route was resolved but final route list did not match incoming request
[2025-06-11 14:15:27.414][20][debug][http] [source/common/http/filter_manager.cc:1040] [Tags: "ConnectionId":"10","StreamId":"15493613003968368065"] Preparing local reply with details health_check_ok
[2025-06-11 14:15:27.414][20][debug][http] [source/common/http/filter_manager.cc:1082] [Tags: "ConnectionId":"10","StreamId":"15493613003968368065"] Executing sending local reply.
[2025-06-11 14:15:27.414][20][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff456480 for 300000ms, min is 300000ms
[2025-06-11 14:15:27.415][20][trace][http] [source/common/http/filter_manager.cc:906] [Tags: "ConnectionId":"10","StreamId":"15493613003968368065"] commonEncodePrefix end_stream: true, isHalfCloseEnabled: false
[2025-06-11 14:15:27.415][20][trace][http] [source/common/http/filter_manager.cc:1263] [Tags: "ConnectionId":"10","StreamId":"15493613003968368065"] encode headers called: filter=envoy.filters.http.health_check status=0
[2025-06-11 14:15:27.415][20][debug][http] [source/common/http/conn_manager_impl.cc:1830] [Tags: "ConnectionId":"10","StreamId":"15493613003968368065"] closing connection due to connection close header
[2025-06-11 14:15:27.415][20][debug][http] [source/common/http/conn_manager_impl.cc:1896] [Tags: "ConnectionId":"10","StreamId":"15493613003968368065"] encoding headers via codec (end_stream=true):
':status', '200'
'x-envoy-upstream-healthchecked-cluster', 'inf-ext-e2e/inference-gateway'
'date', 'Wed, 11 Jun 2025 14:15:27 GMT'
'server', 'envoy'
'connection', 'close'

[2025-06-11 14:15:27.415][20][trace][connection] [source/common/network/connection_impl.cc:529] [Tags: "ConnectionId":"10"] writing 180 bytes, end_stream false
[2025-06-11 14:15:27.415][20][debug][http] [source/common/http/conn_manager_impl.cc:2011] [Tags: "ConnectionId":"10","StreamId":"15493613003968368065"] Codec completed encoding stream.
[2025-06-11 14:15:27.415][20][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=1)
[2025-06-11 14:15:27.415][20][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=2)
[2025-06-11 14:15:27.415][20][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff457800 for 3600000ms, min is 3600000ms
[2025-06-11 14:15:27.415][20][debug][connection] [source/common/network/connection_impl.cc:150] [Tags: "ConnectionId":"10"] closing data_to_write=180 type=0
[2025-06-11 14:15:27.415][20][debug][connection] [source/common/network/connection_impl_base.cc:51] [Tags: "ConnectionId":"10"] setting delayed close timer with timeout 1000 ms
[2025-06-11 14:15:27.415][20][trace][http] [source/common/http/filter_manager.cc:564] [Tags: "ConnectionId":"10","StreamId":"15493613003968368065"] decodeHeaders filter iteration aborted due to local reply: filter=envoy.filters.http.health_check
[2025-06-11 14:15:27.415][20][trace][http] [source/common/http/filter_manager.cc:573] [Tags: "ConnectionId":"10","StreamId":"15493613003968368065"] decode headers called: filter=envoy.filters.http.health_check status=1
[2025-06-11 14:15:27.415][20][trace][http] [source/common/http/http1/codec_impl.cc:695] [Tags: "ConnectionId":"10"] parsed 109 bytes
[2025-06-11 14:15:27.415][20][debug][connection] [source/common/network/connection_impl.cc:150] [Tags: "ConnectionId":"10"] closing data_to_write=180 type=2
[2025-06-11 14:15:27.415][20][trace][main] [source/common/event/dispatcher_impl.cc:127] clearing deferred deletion list (size=2)
[2025-06-11 14:15:27.415][20][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"10"] socket event: 2
[2025-06-11 14:15:27.415][20][trace][connection] [source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"10"] write ready
[2025-06-11 14:15:27.415][20][trace][connection] [source/common/network/raw_buffer_socket.cc:70] [Tags: "ConnectionId":"10"] write returns: 180
[2025-06-11 14:15:27.415][20][debug][connection] [source/common/network/connection_impl.cc:788] [Tags: "ConnectionId":"10"] write flush complete
[2025-06-11 14:15:27.415][20][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"10"] socket event: 6
[2025-06-11 14:15:27.415][20][debug][connection] [source/common/network/connection_impl.cc:636] [Tags: "ConnectionId":"10"] remote early close
[2025-06-11 14:15:27.415][20][debug][connection] [source/common/network/connection_impl.cc:276] [Tags: "ConnectionId":"10"] closing socket: 0
[2025-06-11 14:15:27.415][20][trace][connection] [source/common/network/connection_impl.cc:469] [Tags: "ConnectionId":"10"] raising connection event 0
[2025-06-11 14:15:27.415][20][trace][conn_handler] [source/common/listener_manager/active_stream_listener_base.cc:126] [Tags: "ConnectionId":"10"] tcp connection on event 0
[2025-06-11 14:15:27.415][20][debug][conn_handler] [source/common/listener_manager/active_stream_listener_base.cc:136] [Tags: "ConnectionId":"10"] adding to cleanup list
[2025-06-11 14:15:27.415][20][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=1)
[2025-06-11 14:15:27.415][20][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=2)
[2025-06-11 14:15:27.415][20][trace][main] [source/common/event/dispatcher_impl.cc:127] clearing deferred deletion list (size=2)
[2025-06-11 14:15:32.267][1][trace][upstream] [source/extensions/clusters/original_dst/original_dst_cluster.cc:254] Cleaning up stale original dst hosts.
[2025-06-11 14:15:32.267][1][trace][upstream] [source/extensions/clusters/original_dst/original_dst_cluster.cc:293] Keeping active address 10.244.0.14:8000.
[2025-06-11 14:15:32.275][1][debug][main] [source/server/server.cc:239] flushing stats
[2025-06-11 14:15:32.296][1][trace][upstream] [source/extensions/clusters/strict_dns/strict_dns_cluster.cc:128] starting async DNS resolution for vllm-llama3-8b-instruct-epp.inf-ext-e2e
[2025-06-11 14:15:32.296][1][debug][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:410] dns resolution for vllm-llama3-8b-instruct-epp.inf-ext-e2e started
[2025-06-11 14:15:32.296][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:32.297][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:32.297][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:32.297][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:32.301][1][debug][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:192] dns resolution without records for vllm-llama3-8b-instruct-epp.inf-ext-e2e
[2025-06-11 14:15:32.301][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:32.301][1][debug][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:327] dns resolution for vllm-llama3-8b-instruct-epp.inf-ext-e2e completed with status 0
[2025-06-11 14:15:32.301][1][trace][upstream] [source/extensions/clusters/strict_dns/strict_dns_cluster.cc:136] async DNS resolution complete for vllm-llama3-8b-instruct-epp.inf-ext-e2e details cares_success:Successful completion
[2025-06-11 14:15:32.301][1][debug][upstream] [source/common/upstream/upstream_impl.cc:485] transport socket match, socket default selected for host with address 10.96.209.200:9002
[2025-06-11 14:15:32.301][1][debug][upstream] [source/extensions/clusters/strict_dns/strict_dns_cluster.cc:218] DNS refresh rate reset for vllm-llama3-8b-instruct-epp.inf-ext-e2e, refresh rate 5000 ms
[2025-06-11 14:15:32.414][27][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff456400 for 3600000ms, min is 3600000ms
[2025-06-11 14:15:32.414][27][trace][connection] [source/common/network/connection_impl.cc:469] [Tags: "ConnectionId":"11"] raising connection event 2
[2025-06-11 14:15:32.414][27][debug][conn_handler] [source/common/listener_manager/active_tcp_listener.cc:160] [Tags: "ConnectionId":"11"] new connection from 10.244.0.1:56996
[2025-06-11 14:15:32.414][27][trace][misc] [source/common/network/tcp_listener_impl.cc:123] TcpListener accepted 1 new connections.
[2025-06-11 14:15:32.414][27][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"11"] socket event: 2
[2025-06-11 14:15:32.414][27][trace][connection] [source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"11"] write ready
[2025-06-11 14:15:32.415][27][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"11"] socket event: 3
envoy  | ctionId":"11"] write ready][connection] [source/common/network/connection_impl.cc:737] [Tags: "Conne
[2025-06-11 14:15:32.415][27][trace][connection] [source/common/network/connection_impl.cc:654] [Tags: "ConnectionId":"11"] read ready. dispatch_buffered_data=0
[2025-06-11 14:15:32.415][27][trace][connection] [source/common/network/raw_buffer_socket.cc:25] [Tags: "ConnectionId":"11"] read returns: 109
[2025-06-11 14:15:32.415][27][trace][connection] [source/common/network/raw_buffer_socket.cc:39] [Tags: "ConnectionId":"11"] read error: Resource temporarily unavailable, code: 0
[2025-06-11 14:15:32.415][27][trace][http] [source/common/http/http1/codec_impl.cc:645] [Tags: "ConnectionId":"11"] parsing 109 bytes
[2025-06-11 14:15:32.415][27][trace][http] [source/common/http/http1/codec_impl.cc:587] [Tags: "ConnectionId":"11"] message begin
[2025-06-11 14:15:32.415][27][debug][http] [source/common/http/conn_manager_impl.cc:394] [Tags: "ConnectionId":"11"] new stream
[2025-06-11 14:15:32.415][27][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff456380 for 300000ms, min is 300000ms
[2025-06-11 14:15:32.415][27][trace][http] [source/common/http/http1/codec_impl.cc:544] [Tags: "ConnectionId":"11"] completed header: key=Host value=10.244.0.13:19001
[2025-06-11 14:15:32.415][27][trace][http] [source/common/http/http1/codec_impl.cc:544] [Tags: "ConnectionId":"11"] completed header: key=User-Agent value=kube-probe/1.33
[2025-06-11 14:15:32.415][27][trace][http] [source/common/http/http1/codec_impl.cc:544] [Tags: "ConnectionId":"11"] completed header: key=Accept value=*/*
[2025-06-11 14:15:32.415][27][trace][http] [source/common/http/http1/codec_impl.cc:838] [Tags: "ConnectionId":"11"] onHeadersCompleteImpl
[2025-06-11 14:15:32.415][27][trace][http] [source/common/http/http1/codec_impl.cc:544] [Tags: "ConnectionId":"11"] completed header: key=Connection value=close
[2025-06-11 14:15:32.416][27][trace][http] [source/common/http/http1/codec_impl.cc:1191] [Tags: "ConnectionId":"11"] Server: onHeadersComplete size=4
[2025-06-11 14:15:32.416][27][trace][http] [source/common/http/http1/codec_impl.cc:942] [Tags: "ConnectionId":"11"] message complete
[2025-06-11 14:15:32.416][27][debug][http] [source/common/http/conn_manager_impl.cc:1196] [Tags: "ConnectionId":"11","StreamId":"10849347830340189279"] request headers complete (end_stream=true):
':authority', '10.244.0.13:19001'
':path', '/ready'
':method', 'GET'
'user-agent', 'kube-probe/1.33'
'accept', '*/*'
'connection', 'close'

[2025-06-11 14:15:32.416][27][debug][http] [source/common/http/conn_manager_impl.cc:1179] [Tags: "ConnectionId":"11","StreamId":"10849347830340189279"] request end stream timestamp recorded
[2025-06-11 14:15:32.416][27][debug][connection] [./source/common/network/connection_impl.h:98] [Tags: "ConnectionId":"11"] current connecting state: false
[2025-06-11 14:15:32.416][27][debug][router] [source/common/router/config_impl.cc:2071] route was resolved but final route list did not match incoming request
[2025-06-11 14:15:32.416][27][debug][http] [source/common/http/filter_manager.cc:1040] [Tags: "ConnectionId":"11","StreamId":"10849347830340189279"] Preparing local reply with details health_check_ok
[2025-06-11 14:15:32.416][27][debug][http] [source/common/http/filter_manager.cc:1082] [Tags: "ConnectionId":"11","StreamId":"10849347830340189279"] Executing sending local reply.
[2025-06-11 14:15:32.416][27][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff456380 for 300000ms, min is 300000ms
[2025-06-11 14:15:32.416][27][trace][http] [source/common/http/filter_manager.cc:906] [Tags: "ConnectionId":"11","StreamId":"10849347830340189279"] commonEncodePrefix end_stream: true, isHalfCloseEnabled: false
[2025-06-11 14:15:32.416][27][trace][http] [source/common/http/filter_manager.cc:1263] [Tags: "ConnectionId":"11","StreamId":"10849347830340189279"] encode headers called: filter=envoy.filters.http.health_check status=0
envoy  | mId":"10849347830340189279"] closing connection due to connection close header0] [Tags: "ConnectionId":"11","Strea
[2025-06-11 14:15:32.416][27][debug][http] [source/common/http/conn_manager_impl.cc:1896] [Tags: "ConnectionId":"11","StreamId":"10849347830340189279"] encoding headers via codec (end_stream=true):
':status', '200'
'x-envoy-upstream-healthchecked-cluster', 'inf-ext-e2e/inference-gateway'
'date', 'Wed, 11 Jun 2025 14:15:32 GMT'
'server', 'envoy'
'connection', 'close'

[2025-06-11 14:15:32.416][27][trace][connection] [source/common/network/connection_impl.cc:529] [Tags: "ConnectionId":"11"] writing 180 bytes, end_stream false
[2025-06-11 14:15:32.416][27][debug][http] [source/common/http/conn_manager_impl.cc:2011] [Tags: "ConnectionId":"11","StreamId":"10849347830340189279"] Codec completed encoding stream.
[2025-06-11 14:15:32.416][27][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=1)
[2025-06-11 14:15:32.416][27][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=2)
[2025-06-11 14:15:32.416][27][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff456400 for 3600000ms, min is 3600000ms
[2025-06-11 14:15:32.416][27][debug][connection] [source/common/network/connection_impl.cc:150] [Tags: "ConnectionId":"11"] closing data_to_write=180 type=0
[2025-06-11 14:15:32.416][27][debug][connection] [source/common/network/connection_impl_base.cc:51] [Tags: "ConnectionId":"11"] setting delayed close timer with timeout 1000 ms
[2025-06-11 14:15:32.416][27][trace][http] [source/common/http/filter_manager.cc:564] [Tags: "ConnectionId":"11","StreamId":"10849347830340189279"] decodeHeaders filter iteration aborted due to local reply: filter=envoy.filters.http.health_check
[2025-06-11 14:15:32.416][27][trace][http] [source/common/http/filter_manager.cc:573] [Tags: "ConnectionId":"11","StreamId":"10849347830340189279"] decode headers called: filter=envoy.filters.http.health_check status=1
[2025-06-11 14:15:32.416][27][trace][http] [source/common/http/http1/codec_impl.cc:695] [Tags: "ConnectionId":"11"] parsed 109 bytes
[2025-06-11 14:15:32.416][27][debug][connection] [source/common/network/connection_impl.cc:150] [Tags: "ConnectionId":"11"] closing data_to_write=180 type=2
[2025-06-11 14:15:32.416][27][trace][main] [source/common/event/dispatcher_impl.cc:127] clearing deferred deletion list (size=2)
[2025-06-11 14:15:32.416][27][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"11"] socket event: 2
[2025-06-11 14:15:32.416][27][trace][connection] [source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"11"] write ready
[2025-06-11 14:15:32.416][27][trace][connection] [source/common/network/raw_buffer_socket.cc:70] [Tags: "ConnectionId":"11"] write returns: 180
[2025-06-11 14:15:32.416][27][debug][connection] [source/common/network/connection_impl.cc:788] [Tags: "ConnectionId":"11"] write flush complete
[2025-06-11 14:15:32.417][27][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"11"] socket event: 6
[2025-06-11 14:15:32.417][27][debug][connection] [source/common/network/connection_impl.cc:636] [Tags: "ConnectionId":"11"] remote early close
[2025-06-11 14:15:32.417][27][debug][connection] [source/common/network/connection_impl.cc:276] [Tags: "ConnectionId":"11"] closing socket: 0
[2025-06-11 14:15:32.417][27][trace][connection] [source/common/network/connection_impl.cc:469] [Tags: "ConnectionId":"11"] raising connection event 0
[2025-06-11 14:15:32.417][27][trace][conn_handler] [source/common/listener_manager/active_stream_listener_base.cc:126] [Tags: "ConnectionId":"11"] tcp connection on event 0
[2025-06-11 14:15:32.417][27][debug][conn_handler] [source/common/listener_manager/active_stream_listener_base.cc:136] [Tags: "ConnectionId":"11"] adding to cleanup list
[2025-06-11 14:15:32.417][27][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=1)
[2025-06-11 14:15:32.417][27][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=2)
[2025-06-11 14:15:32.417][27][trace][main] [source/common/event/dispatcher_impl.cc:127] clearing deferred deletion list (size=2)
[2025-06-11 14:15:37.267][1][trace][upstream] [source/extensions/clusters/original_dst/original_dst_cluster.cc:254] Cleaning up stale original dst hosts.
[2025-06-11 14:15:37.267][1][trace][upstream] [source/extensions/clusters/original_dst/original_dst_cluster.cc:293] Keeping active address 10.244.0.14:8000.
[2025-06-11 14:15:37.275][1][debug][main] [source/server/server.cc:239] flushing stats
[2025-06-11 14:15:37.301][1][trace][upstream] [source/extensions/clusters/strict_dns/strict_dns_cluster.cc:128] starting async DNS resolution for vllm-llama3-8b-instruct-epp.inf-ext-e2e
[2025-06-11 14:15:37.301][1][debug][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:410] dns resolution for vllm-llama3-8b-instruct-epp.inf-ext-e2e started
[2025-06-11 14:15:37.301][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:37.302][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:37.302][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:37.302][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:37.304][1][debug][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:192] dns resolution without records for vllm-llama3-8b-instruct-epp.inf-ext-e2e
[2025-06-11 14:15:37.304][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:37.304][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:37.305][1][debug][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:327] dns resolution for vllm-llama3-8b-instruct-epp.inf-ext-e2e completed with status 0
[2025-06-11 14:15:37.305][1][trace][upstream] [source/extensions/clusters/strict_dns/strict_dns_cluster.cc:136] async DNS resolution complete for vllm-llama3-8b-instruct-epp.inf-ext-e2e details cares_success:Successful completion
[2025-06-11 14:15:37.305][1][debug][upstream] [source/common/upstream/upstream_impl.cc:485] transport socket match, socket default selected for host with address 10.96.209.200:9002
[2025-06-11 14:15:37.305][1][debug][upstream] [source/extensions/clusters/strict_dns/strict_dns_cluster.cc:218] DNS refresh rate reset for vllm-llama3-8b-instruct-epp.inf-ext-e2e, refresh rate 5000 ms
[2025-06-11 14:15:37.414][23][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff456400 for 3600000ms, min is 3600000ms
[2025-06-11 14:15:37.415][23][trace][connection] [source/common/network/connection_impl.cc:469] [Tags: "ConnectionId":"12"] raising connection event 2
[2025-06-11 14:15:37.415][23][debug][conn_handler] [source/common/listener_manager/active_tcp_listener.cc:160] [Tags: "ConnectionId":"12"] new connection from 10.244.0.1:49202
[2025-06-11 14:15:37.415][23][trace][misc] [source/common/network/tcp_listener_impl.cc:123] TcpListener accepted 1 new connections.
[2025-06-11 14:15:37.415][23][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"12"] socket event: 2
[2025-06-11 14:15:37.415][23][trace][connection] [source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"12"] write ready
[2025-06-11 14:15:37.415][23][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"12"] socket event: 3
[2025-06-11 14:15:37.415][23][trace][connection] [source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"12"] write ready
[2025-06-11 14:15:37.415][23][trace][connection] [source/common/network/connection_impl.cc:654] [Tags: "ConnectionId":"12"] read ready. dispatch_buffered_data=0
[2025-06-11 14:15:37.415][23][trace][connection] [source/common/network/raw_buffer_socket.cc:25] [Tags: "ConnectionId":"12"] read returns: 109
[2025-06-11 14:15:37.415][23][trace][connection] [source/common/network/raw_buffer_socket.cc:39] [Tags: "ConnectionId":"12"] read error: Resource temporarily unavailable, code: 0
[2025-06-11 14:15:37.415][23][trace][http] [source/common/http/http1/codec_impl.cc:645] [Tags: "ConnectionId":"12"] parsing 109 bytes
[2025-06-11 14:15:37.416][23][trace][http] [source/common/http/http1/codec_impl.cc:587] [Tags: "ConnectionId":"12"] message begin
[2025-06-11 14:15:37.416][23][debug][http] [source/common/http/conn_manager_impl.cc:394] [Tags: "ConnectionId":"12"] new stream
[2025-06-11 14:15:37.416][23][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff456380 for 300000ms, min is 300000ms
[2025-06-11 14:15:37.416][23][trace][http] [source/common/http/http1/codec_impl.cc:544] [Tags: "ConnectionId":"12"] completed header: key=Host value=10.244.0.13:19001
[2025-06-11 14:15:37.416][23][trace][http] [source/common/http/http1/codec_impl.cc:544] [Tags: "ConnectionId":"12"] completed header: key=User-Agent value=kube-probe/1.33
[2025-06-11 14:15:37.416][23][trace][http] [source/common/http/http1/codec_impl.cc:544] [Tags: "ConnectionId":"12"] completed header: key=Accept value=*/*
[2025-06-11 14:15:37.416][23][trace][http] [source/common/http/http1/codec_impl.cc:838] [Tags: "ConnectionId":"12"] onHeadersCompleteImpl
[2025-06-11 14:15:37.416][23][trace][http] [source/common/http/http1/codec_impl.cc:544] [Tags: "ConnectionId":"12"] completed header: key=Connection value=close
[2025-06-11 14:15:37.416][23][trace][http] [source/common/http/http1/codec_impl.cc:1191] [Tags: "ConnectionId":"12"] Server: onHeadersComplete size=4
[2025-06-11 14:15:37.416][23][trace][http] [source/common/http/http1/codec_impl.cc:942] [Tags: "ConnectionId":"12"] message complete
[2025-06-11 14:15:37.416][23][debug][http] [source/common/http/conn_manager_impl.cc:1196] [Tags: "ConnectionId":"12","StreamId":"7699195888193226753"] request headers complete (end_stream=true):
':authority', '10.244.0.13:19001'
':path', '/ready'
':method', 'GET'
'user-agent', 'kube-probe/1.33'
'accept', '*/*'
'connection', 'close'

[2025-06-11 14:15:37.416][23][debug][http] [source/common/http/conn_manager_impl.cc:1179] [Tags: "ConnectionId":"12","StreamId":"7699195888193226753"] request end stream timestamp recorded
[2025-06-11 14:15:37.416][23][debug][connection] [./source/common/network/connection_impl.h:98] [Tags: "ConnectionId":"12"] current connecting state: false
[2025-06-11 14:15:37.416][23][debug][router] [source/common/router/config_impl.cc:2071] route was resolved but final route list did not match incoming request
[2025-06-11 14:15:37.416][23][debug][http] [source/common/http/filter_manager.cc:1040] [Tags: "ConnectionId":"12","StreamId":"7699195888193226753"] Preparing local reply with details health_check_ok
[2025-06-11 14:15:37.416][23][debug][http] [source/common/http/filter_manager.cc:1082] [Tags: "ConnectionId":"12","StreamId":"7699195888193226753"] Executing sending local reply.
[2025-06-11 14:15:37.416][23][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff456380 for 300000ms, min is 300000ms
[2025-06-11 14:15:37.416][23][trace][http] [source/common/http/filter_manager.cc:906] [Tags: "ConnectionId":"12","StreamId":"7699195888193226753"] commonEncodePrefix end_stream: true, isHalfCloseEnabled: false
[2025-06-11 14:15:37.416][23][trace][http] [source/common/http/filter_manager.cc:1263] [Tags: "ConnectionId":"12","StreamId":"7699195888193226753"] encode headers called: filter=envoy.filters.http.health_check status=0
[2025-06-11 14:15:37.416][23][debug][http] [source/common/http/conn_manager_impl.cc:1830] [Tags: "ConnectionId":"12","StreamId":"7699195888193226753"] closing connection due to connection close header
[2025-06-11 14:15:37.416][23][debug][http] [source/common/http/conn_manager_impl.cc:1896] [Tags: "ConnectionId":"12","StreamId":"7699195888193226753"] encoding headers via codec (end_stream=true):
':status', '200'
'x-envoy-upstream-healthchecked-cluster', 'inf-ext-e2e/inference-gateway'
'date', 'Wed, 11 Jun 2025 14:15:37 GMT'
'server', 'envoy'
'connection', 'close'

[2025-06-11 14:15:37.416][23][trace][connection] [source/common/network/connection_impl.cc:529] [Tags: "ConnectionId":"12"] writing 180 bytes, end_stream false
[2025-06-11 14:15:37.416][23][debug][http] [source/common/http/conn_manager_impl.cc:2011] [Tags: "ConnectionId":"12","StreamId":"7699195888193226753"] Codec completed encoding stream.
[2025-06-11 14:15:37.417][23][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=1)
[2025-06-11 14:15:37.417][23][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=2)
[2025-06-11 14:15:37.417][23][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff456400 for 3600000ms, min is 3600000ms
[2025-06-11 14:15:37.417][23][debug][connection] [source/common/network/connection_impl.cc:150] [Tags: "ConnectionId":"12"] closing data_to_write=180 type=0
[2025-06-11 14:15:37.417][23][debug][connection] [source/common/network/connection_impl_base.cc:51] [Tags: "ConnectionId":"12"] setting delayed close timer with timeout 1000 ms
[2025-06-11 14:15:37.417][23][trace][http] [source/common/http/filter_manager.cc:564] [Tags: "ConnectionId":"12","StreamId":"7699195888193226753"] decodeHeaders filter iteration aborted due to local reply: filter=envoy.filters.http.health_check
[2025-06-11 14:15:37.417][23][trace][http] [source/common/http/filter_manager.cc:573] [Tags: "ConnectionId":"12","StreamId":"7699195888193226753"] decode headers called: filter=envoy.filters.http.health_check status=1
[2025-06-11 14:15:37.417][23][trace][http] [source/common/http/http1/codec_impl.cc:695] [Tags: "ConnectionId":"12"] parsed 109 bytes
[2025-06-11 14:15:37.417][23][debug][connection] [source/common/network/connection_impl.cc:150] [Tags: "ConnectionId":"12"] closing data_to_write=180 type=2
[2025-06-11 14:15:37.417][23][trace][main] [source/common/event/dispatcher_impl.cc:127] clearing deferred deletion list (size=2)
[2025-06-11 14:15:37.417][23][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"12"] socket event: 2
[2025-06-11 14:15:37.417][23][trace][connection] [source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"12"] write ready
[2025-06-11 14:15:37.417][23][trace][connection] [source/common/network/raw_buffer_socket.cc:70] [Tags: "ConnectionId":"12"] write returns: 180
[2025-06-11 14:15:37.417][23][debug][connection] [source/common/network/connection_impl.cc:788] [Tags: "ConnectionId":"12"] write flush complete
[2025-06-11 14:15:37.417][23][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"12"] socket event: 6
[2025-06-11 14:15:37.417][23][debug][connection] [source/common/network/connection_impl.cc:636] [Tags: "ConnectionId":"12"] remote early close
[2025-06-11 14:15:37.417][23][debug][connection] [source/common/network/connection_impl.cc:276] [Tags: "ConnectionId":"12"] closing socket: 0
[2025-06-11 14:15:37.417][23][trace][connection] [source/common/network/connection_impl.cc:469] [Tags: "ConnectionId":"12"] raising connection event 0
[2025-06-11 14:15:37.417][23][trace][conn_handler] [source/common/listener_manager/active_stream_listener_base.cc:126] [Tags: "ConnectionId":"12"] tcp connection on event 0
[2025-06-11 14:15:37.417][23][debug][conn_handler] [source/common/listener_manager/active_stream_listener_base.cc:136] [Tags: "ConnectionId":"12"] adding to cleanup list
[2025-06-11 14:15:37.417][23][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=1)
envoy  | ] item added to deferred deletion list (size=2)n/event/dispatcher_impl.cc:233
[2025-06-11 14:15:37.417][23][trace][main] [source/common/event/dispatcher_impl.cc:127] clearing deferred deletion list (size=2)
[2025-06-11 14:15:42.267][1][trace][upstream] [source/extensions/clusters/original_dst/original_dst_cluster.cc:254] Cleaning up stale original dst hosts.
[2025-06-11 14:15:42.267][1][trace][upstream] [source/extensions/clusters/original_dst/original_dst_cluster.cc:293] Keeping active address 10.244.0.14:8000.
[2025-06-11 14:15:42.278][1][debug][main] [source/server/server.cc:239] flushing stats
[2025-06-11 14:15:42.305][1][trace][upstream] [source/extensions/clusters/strict_dns/strict_dns_cluster.cc:128] starting async DNS resolution for vllm-llama3-8b-instruct-epp.inf-ext-e2e
[2025-06-11 14:15:42.305][1][debug][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:410] dns resolution for vllm-llama3-8b-instruct-epp.inf-ext-e2e started
[2025-06-11 14:15:42.306][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:42.307][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:42.307][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:42.307][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:42.311][1][debug][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:192] dns resolution without records for vllm-llama3-8b-instruct-epp.inf-ext-e2e
[2025-06-11 14:15:42.311][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:42.312][1][debug][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:327] dns resolution for vllm-llama3-8b-instruct-epp.inf-ext-e2e completed with status 0
[2025-06-11 14:15:42.312][1][trace][upstream] [source/extensions/clusters/strict_dns/strict_dns_cluster.cc:136] async DNS resolution complete for vllm-llama3-8b-instruct-epp.inf-ext-e2e details cares_success:Successful completion
[2025-06-11 14:15:42.312][1][debug][upstream] [source/common/upstream/upstream_impl.cc:485] transport socket match, socket default selected for host with address 10.96.209.200:9002
[2025-06-11 14:15:42.312][1][debug][upstream] [source/extensions/clusters/strict_dns/strict_dns_cluster.cc:218] DNS refresh rate reset for vllm-llama3-8b-instruct-epp.inf-ext-e2e, refresh rate 5000 ms
[2025-06-11 14:15:42.415][18][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff456f00 for 3600000ms, min is 3600000ms
[2025-06-11 14:15:42.415][18][trace][connection] [source/common/network/connection_impl.cc:469] [Tags: "ConnectionId":"13"] raising connection event 2
[2025-06-11 14:15:42.415][18][debug][conn_handler] [source/common/listener_manager/active_tcp_listener.cc:160] [Tags: "ConnectionId":"13"] new connection from 10.244.0.1:49212
[2025-06-11 14:15:42.415][18][trace][misc] [source/common/network/tcp_listener_impl.cc:123] TcpListener accepted 1 new connections.
[2025-06-11 14:15:42.415][18][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"13"] socket event: 3
[2025-06-11 14:15:42.415][18][trace][connection] [source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"13"] write ready
[2025-06-11 14:15:42.415][18][trace][connection] [source/common/network/connection_impl.cc:654] [Tags: "ConnectionId":"13"] read ready. dispatch_buffered_data=0
[2025-06-11 14:15:42.415][18][trace][connection] [source/common/network/raw_buffer_socket.cc:25] [Tags: "ConnectionId":"13"] read returns: 109
[2025-06-11 14:15:42.415][18][trace][connection] [source/common/network/raw_buffer_socket.cc:39] [Tags: "ConnectionId":"13"] read error: Resource temporarily unavailable, code: 0
[2025-06-11 14:15:42.415][18][trace][http] [source/common/http/http1/codec_impl.cc:645] [Tags: "ConnectionId":"13"] parsing 109 bytes
[2025-06-11 14:15:42.415][18][trace][http] [source/common/http/http1/codec_impl.cc:587] [Tags: "ConnectionId":"13"] message begin
[2025-06-11 14:15:42.415][18][debug][http] [source/common/http/conn_manager_impl.cc:394] [Tags: "ConnectionId":"13"] new stream
[2025-06-11 14:15:42.416][18][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff456f80 for 300000ms, min is 300000ms
[2025-06-11 14:15:42.416][18][trace][http] [source/common/http/http1/codec_impl.cc:544] [Tags: "ConnectionId":"13"] completed header: key=Host value=10.244.0.13:19001
[2025-06-11 14:15:42.416][18][trace][http] [source/common/http/http1/codec_impl.cc:544] [Tags: "ConnectionId":"13"] completed header: key=User-Agent value=kube-probe/1.33
[2025-06-11 14:15:42.416][18][trace][http] [source/common/http/http1/codec_impl.cc:544] [Tags: "ConnectionId":"13"] completed header: key=Accept value=*/*
[2025-06-11 14:15:42.416][18][trace][http] [source/common/http/http1/codec_impl.cc:838] [Tags: "ConnectionId":"13"] onHeadersCompleteImpl
[2025-06-11 14:15:42.416][18][trace][http] [source/common/http/http1/codec_impl.cc:544] [Tags: "ConnectionId":"13"] completed header: key=Connection value=close
[2025-06-11 14:15:42.416][18][trace][http] [source/common/http/http1/codec_impl.cc:1191] [Tags: "ConnectionId":"13"] Server: onHeadersComplete size=4
[2025-06-11 14:15:42.416][18][trace][http] [source/common/http/http1/codec_impl.cc:942] [Tags: "ConnectionId":"13"] message complete
[2025-06-11 14:15:42.416][18][debug][http] [source/common/http/conn_manager_impl.cc:1196] [Tags: "ConnectionId":"13","StreamId":"13791320532856108179"] request headers complete (end_stream=true):
':authority', '10.244.0.13:19001'
':path', '/ready'
':method', 'GET'
'user-agent', 'kube-probe/1.33'
'accept', '*/*'
'connection', 'close'

[2025-06-11 14:15:42.416][18][debug][http] [source/common/http/conn_manager_impl.cc:1179] [Tags: "ConnectionId":"13","StreamId":"13791320532856108179"] request end stream timestamp recorded
[2025-06-11 14:15:42.416][18][debug][connection] [./source/common/network/connection_impl.h:98] [Tags: "ConnectionId":"13"] current connecting state: false
[2025-06-11 14:15:42.416][18][debug][router] [source/common/router/config_impl.cc:2071] route was resolved but final route list did not match incoming request
[2025-06-11 14:15:42.416][18][debug][http] [source/common/http/filter_manager.cc:1040] [Tags: "ConnectionId":"13","StreamId":"13791320532856108179"] Preparing local reply with details health_check_ok
[2025-06-11 14:15:42.416][18][debug][http] [source/common/http/filter_manager.cc:1082] [Tags: "ConnectionId":"13","StreamId":"13791320532856108179"] Executing sending local reply.
[2025-06-11 14:15:42.416][18][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff456f80 for 300000ms, min is 300000ms
[2025-06-11 14:15:42.416][18][trace][http] [source/common/http/filter_manager.cc:906] [Tags: "ConnectionId":"13","StreamId":"13791320532856108179"] commonEncodePrefix end_stream: true, isHalfCloseEnabled: false
[2025-06-11 14:15:42.416][18][trace][http] [source/common/http/filter_manager.cc:1263] [Tags: "ConnectionId":"13","StreamId":"13791320532856108179"] encode headers called: filter=envoy.filters.http.health_check status=0
[2025-06-11 14:15:42.416][18][debug][http] [source/common/http/conn_manager_impl.cc:1830] [Tags: "ConnectionId":"13","StreamId":"13791320532856108179"] closing connection due to connection close header
[2025-06-11 14:15:42.416][18][debug][http] [source/common/http/conn_manager_impl.cc:1896] [Tags: "ConnectionId":"13","StreamId":"13791320532856108179"] encoding headers via codec (end_stream=true):
':status', '200'
'x-envoy-upstream-healthchecked-cluster', 'inf-ext-e2e/inference-gateway'
'date', 'Wed, 11 Jun 2025 14:15:42 GMT'
'server', 'envoy'
'connection', 'close'

[2025-06-11 14:15:42.417][18][trace][connection] [source/common/network/connection_impl.cc:529] [Tags: "ConnectionId":"13"] writing 180 bytes, end_stream false
[2025-06-11 14:15:42.417][18][debug][http] [source/common/http/conn_manager_impl.cc:2011] [Tags: "ConnectionId":"13","StreamId":"13791320532856108179"] Codec completed encoding stream.
[2025-06-11 14:15:42.417][18][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=1)
[2025-06-11 14:15:42.417][18][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=2)
[2025-06-11 14:15:42.417][18][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff456f00 for 3600000ms, min is 3600000ms
[2025-06-11 14:15:42.417][18][debug][connection] [source/common/network/connection_impl.cc:150] [Tags: "ConnectionId":"13"] closing data_to_write=180 type=0
[2025-06-11 14:15:42.417][18][debug][connection] [source/common/network/connection_impl_base.cc:51] [Tags: "ConnectionId":"13"] setting delayed close timer with timeout 1000 ms
[2025-06-11 14:15:42.417][18][trace][http] [source/common/http/filter_manager.cc:564] [Tags: "ConnectionId":"13","StreamId":"13791320532856108179"] decodeHeaders filter iteration aborted due to local reply: filter=envoy.filters.http.health_check
[2025-06-11 14:15:42.417][18][trace][http] [source/common/http/filter_manager.cc:573] [Tags: "ConnectionId":"13","StreamId":"13791320532856108179"] decode headers called: filter=envoy.filters.http.health_check status=1
[2025-06-11 14:15:42.417][18][trace][http] [source/common/http/http1/codec_impl.cc:695] [Tags: "ConnectionId":"13"] parsed 109 bytes
[2025-06-11 14:15:42.417][18][debug][connection] [source/common/network/connection_impl.cc:150] [Tags: "ConnectionId":"13"] closing data_to_write=180 type=2
[2025-06-11 14:15:42.417][18][trace][main] [source/common/event/dispatcher_impl.cc:127] clearing deferred deletion list (size=2)
[2025-06-11 14:15:42.417][18][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"13"] socket event: 2
[2025-06-11 14:15:42.417][18][trace][connection] [source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"13"] write ready
[2025-06-11 14:15:42.418][18][trace][connection] [source/common/network/raw_buffer_socket.cc:70] [Tags: "ConnectionId":"13"] write returns: 180
[2025-06-11 14:15:42.418][18][debug][connection] [source/common/network/connection_impl.cc:788] [Tags: "ConnectionId":"13"] write flush complete
[2025-06-11 14:15:42.418][18][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"13"] socket event: 6
[2025-06-11 14:15:42.418][18][debug][connection] [source/common/network/connection_impl.cc:636] [Tags: "ConnectionId":"13"] remote early close
[2025-06-11 14:15:42.418][18][debug][connection] [source/common/network/connection_impl.cc:276] [Tags: "ConnectionId":"13"] closing socket: 0
[2025-06-11 14:15:42.418][18][trace][connection] [source/common/network/connection_impl.cc:469] [Tags: "ConnectionId":"13"] raising connection event 0
[2025-06-11 14:15:42.418][18][trace][conn_handler] [source/common/listener_manager/active_stream_listener_base.cc:126] [Tags: "ConnectionId":"13"] tcp connection on event 0
[2025-06-11 14:15:42.418][18][debug][conn_handler] [source/common/listener_manager/active_stream_listener_base.cc:136] [Tags: "ConnectionId":"13"] adding to cleanup list
[2025-06-11 14:15:42.418][18][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=1)
[2025-06-11 14:15:42.418][18][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=2)
[2025-06-11 14:15:42.418][18][trace][main] [source/common/event/dispatcher_impl.cc:127] clearing deferred deletion list (size=2)
[2025-06-11 14:15:47.268][1][trace][upstream] [source/extensions/clusters/original_dst/original_dst_cluster.cc:254] Cleaning up stale original dst hosts.
envoy  | 0. 14:15:47.269][1][trace][upstream] [source/extensions/clusters/original_dst/original_dst_cluster.cc:293] Keeping active address 10.244.0.14:800
[2025-06-11 14:15:47.277][1][debug][main] [source/server/server.cc:239] flushing stats
[2025-06-11 14:15:47.312][1][trace][upstream] [source/extensions/clusters/strict_dns/strict_dns_cluster.cc:128] starting async DNS resolution for vllm-llama3-8b-instruct-epp.inf-ext-e2e
[2025-06-11 14:15:47.312][1][debug][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:410] dns resolution for vllm-llama3-8b-instruct-epp.inf-ext-e2e started
[2025-06-11 14:15:47.312][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:47.313][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:47.314][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:47.314][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:47.317][1][debug][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:192] dns resolution without records for vllm-llama3-8b-instruct-epp.inf-ext-e2e
[2025-06-11 14:15:47.317][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:47.318][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:47.318][1][debug][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:327] dns resolution for vllm-llama3-8b-instruct-epp.inf-ext-e2e completed with status 0
[2025-06-11 14:15:47.318][1][trace][upstream] [source/extensions/clusters/strict_dns/strict_dns_cluster.cc:136] async DNS resolution complete for vllm-llama3-8b-instruct-epp.inf-ext-e2e details cares_success:Successful completion
[2025-06-11 14:15:47.318][1][debug][upstream] [source/common/upstream/upstream_impl.cc:485] transport socket match, socket default selected for host with address 10.96.209.200:9002
[2025-06-11 14:15:47.318][1][debug][upstream] [source/extensions/clusters/strict_dns/strict_dns_cluster.cc:218] DNS refresh rate reset for vllm-llama3-8b-instruct-epp.inf-ext-e2e, refresh rate 5000 ms
[2025-06-11 14:15:47.414][23][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff457800 for 3600000ms, min is 3600000ms
[2025-06-11 14:15:47.415][23][trace][connection] [source/common/network/connection_impl.cc:469] [Tags: "ConnectionId":"14"] raising connection event 2
[2025-06-11 14:15:47.415][23][debug][conn_handler] [source/common/listener_manager/active_tcp_listener.cc:160] [Tags: "ConnectionId":"14"] new connection from 10.244.0.1:48856
[2025-06-11 14:15:47.415][23][trace][misc] [source/common/network/tcp_listener_impl.cc:123] TcpListener accepted 1 new connections.
[2025-06-11 14:15:47.415][23][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"14"] socket event: 3
[2025-06-11 14:15:47.415][23][trace][connection] [source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"14"] write ready
[2025-06-11 14:15:47.415][23][trace][connection] [source/common/network/connection_impl.cc:654] [Tags: "ConnectionId":"14"] read ready. dispatch_buffered_data=0
[2025-06-11 14:15:47.415][23][trace][connection] [source/common/network/raw_buffer_socket.cc:25] [Tags: "ConnectionId":"14"] read returns: 109
[2025-06-11 14:15:47.415][23][trace][connection] [source/common/network/raw_buffer_socket.cc:39] [Tags: "ConnectionId":"14"] read error: Resource temporarily unavailable, code: 0
[2025-06-11 14:15:47.415][23][trace][http] [source/common/http/http1/codec_impl.cc:645] [Tags: "ConnectionId":"14"] parsing 109 bytes
[2025-06-11 14:15:47.415][23][trace][http] [source/common/http/http1/codec_impl.cc:587] [Tags: "ConnectionId":"14"] message begin
envoy  | c:394] [Tags: "ConnectionId":"14"] new streammon/http/conn_manager_impl.c
[2025-06-11 14:15:47.415][23][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff456480 for 300000ms, min is 300000ms
[2025-06-11 14:15:47.415][23][trace][http] [source/common/http/http1/codec_impl.cc:544] [Tags: "ConnectionId":"14"] completed header: key=Host value=10.244.0.13:19001
[2025-06-11 14:15:47.415][23][trace][http] [source/common/http/http1/codec_impl.cc:544] [Tags: "ConnectionId":"14"] completed header: key=User-Agent value=kube-probe/1.33
[2025-06-11 14:15:47.415][23][trace][http] [source/common/http/http1/codec_impl.cc:544] [Tags: "ConnectionId":"14"] completed header: key=Accept value=*/*
[2025-06-11 14:15:47.415][23][trace][http] [source/common/http/http1/codec_impl.cc:838] [Tags: "ConnectionId":"14"] onHeadersCompleteImpl
[2025-06-11 14:15:47.415][23][trace][http] [source/common/http/http1/codec_impl.cc:544] [Tags: "ConnectionId":"14"] completed header: key=Connection value=close
[2025-06-11 14:15:47.415][23][trace][http] [source/common/http/http1/codec_impl.cc:1191] [Tags: "ConnectionId":"14"] Server: onHeadersComplete size=4
[2025-06-11 14:15:47.415][23][trace][http] [source/common/http/http1/codec_impl.cc:942] [Tags: "ConnectionId":"14"] message complete
[2025-06-11 14:15:47.415][23][debug][http] [source/common/http/conn_manager_impl.cc:1196] [Tags: "ConnectionId":"14","StreamId":"4824806956959647069"] request headers complete (end_stream=true):
':authority', '10.244.0.13:19001'
':path', '/ready'
':method', 'GET'
'user-agent', 'kube-probe/1.33'
'accept', '*/*'
'connection', 'close'

[2025-06-11 14:15:47.415][23][debug][http] [source/common/http/conn_manager_impl.cc:1179] [Tags: "ConnectionId":"14","StreamId":"4824806956959647069"] request end stream timestamp recorded
[2025-06-11 14:15:47.415][23][debug][connection] [./source/common/network/connection_impl.h:98] [Tags: "ConnectionId":"14"] current connecting state: false
[2025-06-11 14:15:47.415][23][debug][router] [source/common/router/config_impl.cc:2071] route was resolved but final route list did not match incoming request
[2025-06-11 14:15:47.415][23][debug][http] [source/common/http/filter_manager.cc:1040] [Tags: "ConnectionId":"14","StreamId":"4824806956959647069"] Preparing local reply with details health_check_ok
[2025-06-11 14:15:47.415][23][debug][http] [source/common/http/filter_manager.cc:1082] [Tags: "ConnectionId":"14","StreamId":"4824806956959647069"] Executing sending local reply.
[2025-06-11 14:15:47.415][23][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff456480 for 300000ms, min is 300000ms
[2025-06-11 14:15:47.415][23][trace][http] [source/common/http/filter_manager.cc:906] [Tags: "ConnectionId":"14","StreamId":"4824806956959647069"] commonEncodePrefix end_stream: true, isHalfCloseEnabled: false
[2025-06-11 14:15:47.415][23][trace][http] [source/common/http/filter_manager.cc:1263] [Tags: "ConnectionId":"14","StreamId":"4824806956959647069"] encode headers called: filter=envoy.filters.http.health_check status=0
[2025-06-11 14:15:47.415][23][debug][http] [source/common/http/conn_manager_impl.cc:1830] [Tags: "ConnectionId":"14","StreamId":"4824806956959647069"] closing connection due to connection close header
[2025-06-11 14:15:47.415][23][debug][http] [source/common/http/conn_manager_impl.cc:1896] [Tags: "ConnectionId":"14","StreamId":"4824806956959647069"] encoding headers via codec (end_stream=true):
':status', '200'
'x-envoy-upstream-healthchecked-cluster', 'inf-ext-e2e/inference-gateway'
'date', 'Wed, 11 Jun 2025 14:15:47 GMT'
'server', 'envoy'
'connection', 'close'

[2025-06-11 14:15:47.416][23][trace][connection] [source/common/network/connection_impl.cc:529] [Tags: "ConnectionId":"14"] writing 180 bytes, end_stream false
[2025-06-11 14:15:47.416][23][debug][http] [source/common/http/conn_manager_impl.cc:2011] [Tags: "ConnectionId":"14","StreamId":"4824806956959647069"] Codec completed encoding stream.
[2025-06-11 14:15:47.416][23][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=1)
[2025-06-11 14:15:47.416][23][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=2)
[2025-06-11 14:15:47.416][23][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff457800 for 3600000ms, min is 3600000ms
[2025-06-11 14:15:47.416][23][debug][connection] [source/common/network/connection_impl.cc:150] [Tags: "ConnectionId":"14"] closing data_to_write=180 type=0
[2025-06-11 14:15:47.416][23][debug][connection] [source/common/network/connection_impl_base.cc:51] [Tags: "ConnectionId":"14"] setting delayed close timer with timeout 1000 ms
[2025-06-11 14:15:47.416][23][trace][http] [source/common/http/filter_manager.cc:564] [Tags: "ConnectionId":"14","StreamId":"4824806956959647069"] decodeHeaders filter iteration aborted due to local reply: filter=envoy.filters.http.health_check
[2025-06-11 14:15:47.416][23][trace][http] [source/common/http/filter_manager.cc:573] [Tags: "ConnectionId":"14","StreamId":"4824806956959647069"] decode headers called: filter=envoy.filters.http.health_check status=1
[2025-06-11 14:15:47.416][23][trace][http] [source/common/http/http1/codec_impl.cc:695] [Tags: "ConnectionId":"14"] parsed 109 bytes
[2025-06-11 14:15:47.416][23][debug][connection] [source/common/network/connection_impl.cc:150] [Tags: "ConnectionId":"14"] closing data_to_write=180 type=2
[2025-06-11 14:15:47.416][23][trace][main] [source/common/event/dispatcher_impl.cc:127] clearing deferred deletion list (size=2)
[2025-06-11 14:15:47.416][23][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"14"] socket event: 2
[2025-06-11 14:15:47.416][23][trace][connection] [source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"14"] write ready
[2025-06-11 14:15:47.416][23][trace][connection] [source/common/network/raw_buffer_socket.cc:70] [Tags: "ConnectionId":"14"] write returns: 180
[2025-06-11 14:15:47.416][23][debug][connection] [source/common/network/connection_impl.cc:788] [Tags: "ConnectionId":"14"] write flush complete
[2025-06-11 14:15:47.416][23][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"14"] socket event: 6
[2025-06-11 14:15:47.416][23][debug][connection] [source/common/network/connection_impl.cc:636] [Tags: "ConnectionId":"14"] remote early close
[2025-06-11 14:15:47.416][23][debug][connection] [source/common/network/connection_impl.cc:276] [Tags: "ConnectionId":"14"] closing socket: 0
[2025-06-11 14:15:47.416][23][trace][connection] [source/common/network/connection_impl.cc:469] [Tags: "ConnectionId":"14"] raising connection event 0
[2025-06-11 14:15:47.416][23][trace][conn_handler] [source/common/listener_manager/active_stream_listener_base.cc:126] [Tags: "ConnectionId":"14"] tcp connection on event 0
[2025-06-11 14:15:47.416][23][debug][conn_handler] [source/common/listener_manager/active_stream_listener_base.cc:136] [Tags: "ConnectionId":"14"] adding to cleanup list
[2025-06-11 14:15:47.416][23][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=1)
[2025-06-11 14:15:47.416][23][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=2)
[2025-06-11 14:15:47.416][23][trace][main] [source/common/event/dispatcher_impl.cc:127] clearing deferred deletion list (size=2)
[2025-06-11 14:15:52.269][1][trace][upstream] [source/extensions/clusters/original_dst/original_dst_cluster.cc:254] Cleaning up stale original dst hosts.
[2025-06-11 14:15:52.269][1][trace][upstream] [source/extensions/clusters/original_dst/original_dst_cluster.cc:293] Keeping active address 10.244.0.14:8000.
[2025-06-11 14:15:52.278][1][debug][main] [source/server/server.cc:239] flushing stats
[2025-06-11 14:15:52.319][1][trace][upstream] [source/extensions/clusters/strict_dns/strict_dns_cluster.cc:128] starting async DNS resolution for vllm-llama3-8b-instruct-epp.inf-ext-e2e
[2025-06-11 14:15:52.319][1][debug][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:410] dns resolution for vllm-llama3-8b-instruct-epp.inf-ext-e2e started
[2025-06-11 14:15:52.319][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:52.320][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:52.320][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:52.320][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:52.322][1][debug][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:192] dns resolution without records for vllm-llama3-8b-instruct-epp.inf-ext-e2e
[2025-06-11 14:15:52.323][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:52.323][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:52.323][1][debug][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:327] dns resolution for vllm-llama3-8b-instruct-epp.inf-ext-e2e completed with status 0
[2025-06-11 14:15:52.323][1][trace][upstream] [source/extensions/clusters/strict_dns/strict_dns_cluster.cc:136] async DNS resolution complete for vllm-llama3-8b-instruct-epp.inf-ext-e2e details cares_success:Successful completion
[2025-06-11 14:15:52.323][1][debug][upstream] [source/common/upstream/upstream_impl.cc:485] transport socket match, socket default selected for host with address 10.96.209.200:9002
[2025-06-11 14:15:52.323][1][debug][upstream] [source/extensions/clusters/strict_dns/strict_dns_cluster.cc:218] DNS refresh rate reset for vllm-llama3-8b-instruct-epp.inf-ext-e2e, refresh rate 5000 ms
[2025-06-11 14:15:52.414][26][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff456700 for 3600000ms, min is 3600000ms
[2025-06-11 14:15:52.415][26][trace][connection] [source/common/network/connection_impl.cc:469] [Tags: "ConnectionId":"15"] raising connection event 2
[2025-06-11 14:15:52.415][26][debug][conn_handler] [source/common/listener_manager/active_tcp_listener.cc:160] [Tags: "ConnectionId":"15"] new connection from 10.244.0.1:48860
[2025-06-11 14:15:52.415][26][trace][misc] [source/common/network/tcp_listener_impl.cc:123] TcpListener accepted 1 new connections.
[2025-06-11 14:15:52.415][26][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"15"] socket event: 2
[2025-06-11 14:15:52.415][26][trace][connection] [source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"15"] write ready
[2025-06-11 14:15:52.415][26][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"15"] socket event: 3
[2025-06-11 14:15:52.415][26][trace][connection] [source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"15"] write ready
[2025-06-11 14:15:52.415][26][trace][connection] [source/common/network/connection_impl.cc:654] [Tags: "ConnectionId":"15"] read ready. dispatch_buffered_data=0
[2025-06-11 14:15:52.415][26][trace][connection] [source/common/network/raw_buffer_socket.cc:25] [Tags: "ConnectionId":"15"] read returns: 109
[2025-06-11 14:15:52.415][26][trace][connection] [source/common/network/raw_buffer_socket.cc:39] [Tags: "ConnectionId":"15"] read error: Resource temporarily unavailable, code: 0
[2025-06-11 14:15:52.415][26][trace][http] [source/common/http/http1/codec_impl.cc:645] [Tags: "ConnectionId":"15"] parsing 109 bytes
[2025-06-11 14:15:52.416][26][trace][http] [source/common/http/http1/codec_impl.cc:587] [Tags: "ConnectionId":"15"] message begin
[2025-06-11 14:15:52.416][26][debug][http] [source/common/http/conn_manager_impl.cc:394] [Tags: "ConnectionId":"15"] new stream
[2025-06-11 14:15:52.416][26][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff456800 for 300000ms, min is 300000ms
[2025-06-11 14:15:52.416][26][trace][http] [source/common/http/http1/codec_impl.cc:544] [Tags: "ConnectionId":"15"] completed header: key=Host value=10.244.0.13:19001
[2025-06-11 14:15:52.416][26][trace][http] [source/common/http/http1/codec_impl.cc:544] [Tags: "ConnectionId":"15"] completed header: key=User-Agent value=kube-probe/1.33
[2025-06-11 14:15:52.416][26][trace][http] [source/common/http/http1/codec_impl.cc:544] [Tags: "ConnectionId":"15"] completed header: key=Accept value=*/*
[2025-06-11 14:15:52.416][26][trace][http] [source/common/http/http1/codec_impl.cc:838] [Tags: "ConnectionId":"15"] onHeadersCompleteImpl
[2025-06-11 14:15:52.416][26][trace][http] [source/common/http/http1/codec_impl.cc:544] [Tags: "ConnectionId":"15"] completed header: key=Connection value=close
[2025-06-11 14:15:52.416][26][trace][http] [source/common/http/http1/codec_impl.cc:1191] [Tags: "ConnectionId":"15"] Server: onHeadersComplete size=4
[2025-06-11 14:15:52.416][26][trace][http] [source/common/http/http1/codec_impl.cc:942] [Tags: "ConnectionId":"15"] message complete
[2025-06-11 14:15:52.416][26][debug][http] [source/common/http/conn_manager_impl.cc:1196] [Tags: "ConnectionId":"15","StreamId":"207920590749629080"] request headers complete (end_stream=true):
':authority', '10.244.0.13:19001'
':path', '/ready'
':method', 'GET'
'user-agent', 'kube-probe/1.33'
'accept', '*/*'
'connection', 'close'

[2025-06-11 14:15:52.416][26][debug][http] [source/common/http/conn_manager_impl.cc:1179] [Tags: "ConnectionId":"15","StreamId":"207920590749629080"] request end stream timestamp recorded
[2025-06-11 14:15:52.416][26][debug][connection] [./source/common/network/connection_impl.h:98] [Tags: "ConnectionId":"15"] current connecting state: false
[2025-06-11 14:15:52.416][26][debug][router] [source/common/router/config_impl.cc:2071] route was resolved but final route list did not match incoming request
[2025-06-11 14:15:52.417][26][debug][http] [source/common/http/filter_manager.cc:1040] [Tags: "ConnectionId":"15","StreamId":"207920590749629080"] Preparing local reply with details health_check_ok
[2025-06-11 14:15:52.417][26][debug][http] [source/common/http/filter_manager.cc:1082] [Tags: "ConnectionId":"15","StreamId":"207920590749629080"] Executing sending local reply.
[2025-06-11 14:15:52.417][26][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff456800 for 300000ms, min is 300000ms
[2025-06-11 14:15:52.417][26][trace][http] [source/common/http/filter_manager.cc:906] [Tags: "ConnectionId":"15","StreamId":"207920590749629080"] commonEncodePrefix end_stream: true, isHalfCloseEnabled: false
[2025-06-11 14:15:52.417][26][trace][http] [source/common/http/filter_manager.cc:1263] [Tags: "ConnectionId":"15","StreamId":"207920590749629080"] encode headers called: filter=envoy.filters.http.health_check status=0
[2025-06-11 14:15:52.417][26][debug][http] [source/common/http/conn_manager_impl.cc:1830] [Tags: "ConnectionId":"15","StreamId":"207920590749629080"] closing connection due to connection close header
[2025-06-11 14:15:52.417][26][debug][http] [source/common/http/conn_manager_impl.cc:1896] [Tags: "ConnectionId":"15","StreamId":"207920590749629080"] encoding headers via codec (end_stream=true):
':status', '200'
'x-envoy-upstream-healthchecked-cluster', 'inf-ext-e2e/inference-gateway'
'date', 'Wed, 11 Jun 2025 14:15:52 GMT'
'server', 'envoy'
'connection', 'close'

[2025-06-11 14:15:52.417][26][trace][connection] [source/common/network/connection_impl.cc:529] [Tags: "ConnectionId":"15"] writing 180 bytes, end_stream false
[2025-06-11 14:15:52.417][26][debug][http] [source/common/http/conn_manager_impl.cc:2011] [Tags: "ConnectionId":"15","StreamId":"207920590749629080"] Codec completed encoding stream.
[2025-06-11 14:15:52.417][26][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=1)
envoy  |  14:15:52.417][26][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=2)
[2025-06-11 14:15:52.417][26][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff456700 for 3600000ms, min is 3600000ms
[2025-06-11 14:15:52.417][26][debug][connection] [source/common/network/connection_impl.cc:150] [Tags: "ConnectionId":"15"] closing data_to_write=180 type=0
[2025-06-11 14:15:52.417][26][debug][connection] [source/common/network/connection_impl_base.cc:51] [Tags: "ConnectionId":"15"] setting delayed close timer with timeout 1000 ms
[2025-06-11 14:15:52.417][26][trace][http] [source/common/http/filter_manager.cc:564] [Tags: "ConnectionId":"15","StreamId":"207920590749629080"] decodeHeaders filter iteration aborted due to local reply: filter=envoy.filters.http.health_check
[2025-06-11 14:15:52.417][26][trace][http] [source/common/http/filter_manager.cc:573] [Tags: "ConnectionId":"15","StreamId":"207920590749629080"] decode headers called: filter=envoy.filters.http.health_check status=1
[2025-06-11 14:15:52.417][26][trace][http] [source/common/http/http1/codec_impl.cc:695] [Tags: "ConnectionId":"15"] parsed 109 bytes
[2025-06-11 14:15:52.417][26][debug][connection] [source/common/network/connection_impl.cc:150] [Tags: "ConnectionId":"15"] closing data_to_write=180 type=2
[2025-06-11 14:15:52.417][26][trace][main] [source/common/event/dispatcher_impl.cc:127] clearing deferred deletion list (size=2)
[2025-06-11 14:15:52.417][26][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"15"] socket event: 2
[2025-06-11 14:15:52.417][26][trace][connection] [source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"15"] write ready
[2025-06-11 14:15:52.417][26][trace][connection] [source/common/network/raw_buffer_socket.cc:70] [Tags: "ConnectionId":"15"] write returns: 180
[2025-06-11 14:15:52.417][26][debug][connection] [source/common/network/connection_impl.cc:788] [Tags: "ConnectionId":"15"] write flush complete
[2025-06-11 14:15:52.417][26][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"15"] socket event: 6
[2025-06-11 14:15:52.417][26][debug][connection] [source/common/network/connection_impl.cc:636] [Tags: "ConnectionId":"15"] remote early close
[2025-06-11 14:15:52.417][26][debug][connection] [source/common/network/connection_impl.cc:276] [Tags: "ConnectionId":"15"] closing socket: 0
[2025-06-11 14:15:52.418][26][trace][connection] [source/common/network/connection_impl.cc:469] [Tags: "ConnectionId":"15"] raising connection event 0
[2025-06-11 14:15:52.418][26][trace][conn_handler] [source/common/listener_manager/active_stream_listener_base.cc:126] [Tags: "ConnectionId":"15"] tcp connection on event 0
[2025-06-11 14:15:52.418][26][debug][conn_handler] [source/common/listener_manager/active_stream_listener_base.cc:136] [Tags: "ConnectionId":"15"] adding to cleanup list
[2025-06-11 14:15:52.418][26][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=1)
[2025-06-11 14:15:52.418][26][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=2)
[2025-06-11 14:15:52.418][26][trace][main] [source/common/event/dispatcher_impl.cc:127] clearing deferred deletion list (size=2)
[2025-06-11 14:15:57.271][1][trace][upstream] [source/extensions/clusters/original_dst/original_dst_cluster.cc:254] Cleaning up stale original dst hosts.
[2025-06-11 14:15:57.271][1][trace][upstream] [source/extensions/clusters/original_dst/original_dst_cluster.cc:293] Keeping active address 10.244.0.14:8000.
[2025-06-11 14:15:57.278][1][debug][main] [source/server/server.cc:239] flushing stats
[2025-06-11 14:15:57.323][1][trace][upstream] [source/extensions/clusters/strict_dns/strict_dns_cluster.cc:128] starting async DNS resolution for vllm-llama3-8b-instruct-epp.inf-ext-e2e
[2025-06-11 14:15:57.324][1][debug][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:410] dns resolution for vllm-llama3-8b-instruct-epp.inf-ext-e2e started
[2025-06-11 14:15:57.324][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:57.325][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:57.325][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:57.325][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:57.330][1][debug][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:192] dns resolution without records for vllm-llama3-8b-instruct-epp.inf-ext-e2e
[2025-06-11 14:15:57.331][1][trace][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:369] Setting DNS resolution timer for 5000 milliseconds
[2025-06-11 14:15:57.331][1][debug][dns] [source/extensions/network/dns_resolver/cares/dns_impl.cc:327] dns resolution for vllm-llama3-8b-instruct-epp.inf-ext-e2e completed with status 0
[2025-06-11 14:15:57.331][1][trace][upstream] [source/extensions/clusters/strict_dns/strict_dns_cluster.cc:136] async DNS resolution complete for vllm-llama3-8b-instruct-epp.inf-ext-e2e details cares_success:Successful completion
[2025-06-11 14:15:57.331][1][debug][upstream] [source/common/upstream/upstream_impl.cc:485] transport socket match, socket default selected for host with address 10.96.209.200:9002
[2025-06-11 14:15:57.331][1][debug][upstream] [source/extensions/clusters/strict_dns/strict_dns_cluster.cc:218] DNS refresh rate reset for vllm-llama3-8b-instruct-epp.inf-ext-e2e, refresh rate 5000 ms
[2025-06-11 14:15:57.414][25][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff457880 for 3600000ms, min is 3600000ms
[2025-06-11 14:15:57.414][25][trace][connection] [source/common/network/connection_impl.cc:469] [Tags: "ConnectionId":"16"] raising connection event 2
[2025-06-11 14:15:57.414][25][debug][conn_handler] [source/common/listener_manager/active_tcp_listener.cc:160] [Tags: "ConnectionId":"16"] new connection from 10.244.0.1:49794
[2025-06-11 14:15:57.414][25][trace][misc] [source/common/network/tcp_listener_impl.cc:123] TcpListener accepted 1 new connections.
[2025-06-11 14:15:57.414][25][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"16"] socket event: 3
[2025-06-11 14:15:57.414][25][trace][connection] [source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"16"] write ready
[2025-06-11 14:15:57.414][25][trace][connection] [source/common/network/connection_impl.cc:654] [Tags: "ConnectionId":"16"] read ready. dispatch_buffered_data=0
[2025-06-11 14:15:57.414][25][trace][connection] [source/common/network/raw_buffer_socket.cc:25] [Tags: "ConnectionId":"16"] read returns: 109
[2025-06-11 14:15:57.414][25][trace][connection] [source/common/network/raw_buffer_socket.cc:39] [Tags: "ConnectionId":"16"] read error: Resource temporarily unavailable, code: 0
[2025-06-11 14:15:57.414][25][trace][http] [source/common/http/http1/codec_impl.cc:645] [Tags: "ConnectionId":"16"] parsing 109 bytes
[2025-06-11 14:15:57.414][25][trace][http] [source/common/http/http1/codec_impl.cc:587] [Tags: "ConnectionId":"16"] message begin
[2025-06-11 14:15:57.414][25][debug][http] [source/common/http/conn_manager_impl.cc:394] [Tags: "ConnectionId":"16"] new stream
[2025-06-11 14:15:57.414][25][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff456680 for 300000ms, min is 300000ms
[2025-06-11 14:15:57.414][25][trace][http] [source/common/http/http1/codec_impl.cc:544] [Tags: "ConnectionId":"16"] completed header: key=Host value=10.244.0.13:19001
[2025-06-11 14:15:57.414][25][trace][http] [source/common/http/http1/codec_impl.cc:544] [Tags: "ConnectionId":"16"] completed header: key=User-Agent value=kube-probe/1.33
[2025-06-11 14:15:57.414][25][trace][http] [source/common/http/http1/codec_impl.cc:544] [Tags: "ConnectionId":"16"] completed header: key=Accept value=*/*
[2025-06-11 14:15:57.414][25][trace][http] [source/common/http/http1/codec_impl.cc:838] [Tags: "ConnectionId":"16"] onHeadersCompleteImpl
[2025-06-11 14:15:57.414][25][trace][http] [source/common/http/http1/codec_impl.cc:544] [Tags: "ConnectionId":"16"] completed header: key=Connection value=close
[2025-06-11 14:15:57.414][25][trace][http] [source/common/http/http1/codec_impl.cc:1191] [Tags: "ConnectionId":"16"] Server: onHeadersComplete size=4
[2025-06-11 14:15:57.414][25][trace][http] [source/common/http/http1/codec_impl.cc:942] [Tags: "ConnectionId":"16"] message complete
[2025-06-11 14:15:57.414][25][debug][http] [source/common/http/conn_manager_impl.cc:1196] [Tags: "ConnectionId":"16","StreamId":"10595792538043134761"] request headers complete (end_stream=true):
':authority', '10.244.0.13:19001'
':path', '/ready'
':method', 'GET'
'user-agent', 'kube-probe/1.33'
'accept', '*/*'
'connection', 'close'

[2025-06-11 14:15:57.414][25][debug][http] [source/common/http/conn_manager_impl.cc:1179] [Tags: "ConnectionId":"16","StreamId":"10595792538043134761"] request end stream timestamp recorded
[2025-06-11 14:15:57.414][25][debug][connection] [./source/common/network/connection_impl.h:98] [Tags: "ConnectionId":"16"] current connecting state: false
envoy  | [2025-06-11 14:15:57.414][25][debug][router] [source/common/router/config_impl.cc:2071] route was resolved but final route list did not match incoming request
[2025-06-11 14:15:57.414][25][debug][http] [source/common/http/filter_manager.cc:1040] [Tags: "ConnectionId":"16","StreamId":"10595792538043134761"] Preparing local reply with details health_check_ok
[2025-06-11 14:15:57.414][25][debug][http] [source/common/http/filter_manager.cc:1082] [Tags: "ConnectionId":"16","StreamId":"10595792538043134761"] Executing sending local reply.
envoy  | [2025-06-11 14:15:57.414][25][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff456680 for 300000ms, min is 300000ms
[2025-06-11 14:15:57.414][25][trace][http] [source/common/http/filter_manager.cc:906] [Tags: "ConnectionId":"16","StreamId":"10595792538043134761"] commonEncodePrefix end_stream: true, isHalfCloseEnabled: false
[2025-06-11 14:15:57.414][25][trace][http] [source/common/http/filter_manager.cc:1263] [Tags: "ConnectionId":"16","StreamId":"10595792538043134761"] encode headers called: filter=envoy.filters.http.health_check status=0
[2025-06-11 14:15:57.414][25][debug][http] [source/common/http/conn_manager_impl.cc:1830] [Tags: "ConnectionId":"16","StreamId":"10595792538043134761"] closing connection due to connection close header
[2025-06-11 14:15:57.414][25][debug][http] [source/common/http/conn_manager_impl.cc:1896] [Tags: "ConnectionId":"16","StreamId":"10595792538043134761"] encoding headers via codec (end_stream=true):
':status', '200'
'x-envoy-upstream-healthchecked-cluster', 'inf-ext-e2e/inference-gateway'
'date', 'Wed, 11 Jun 2025 14:15:57 GMT'
'server', 'envoy'
'connection', 'close'

[2025-06-11 14:15:57.414][25][trace][connection] [source/common/network/connection_impl.cc:529] [Tags: "ConnectionId":"16"] writing 180 bytes, end_stream false
[2025-06-11 14:15:57.415][25][debug][http] [source/common/http/conn_manager_impl.cc:2011] [Tags: "ConnectionId":"16","StreamId":"10595792538043134761"] Codec completed encoding stream.
[2025-06-11 14:15:57.415][25][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=1)
envoy  | [2025-06-11 14:15:57.415][25][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=2)
[2025-06-11 14:15:57.415][25][trace][misc] [source/common/event/scaled_range_timer_manager_impl.cc:60] enableTimer called on 0x636ff457880 for 3600000ms, min is 3600000ms
envoy  | [2025-06-11 14:15:57.415][25][debug][connection] [source/common/network/connection_impl.cc:150] [Tags: "ConnectionId":"16"] closing data_to_write=180 type=0
[2025-06-11 14:15:57.415][25][debug][connection] [source/common/network/connection_impl_base.cc:51] [Tags: "ConnectionId":"16"] setting delayed close timer with timeout 1000 ms
[2025-06-11 14:15:57.415][25][trace][http] [source/common/http/filter_manager.cc:564] [Tags: "ConnectionId":"16","StreamId":"10595792538043134761"] decodeHeaders filter iteration aborted due to local reply: filter=envoy.filters.http.health_check
[2025-06-11 14:15:57.415][25][trace][http] [source/common/http/filter_manager.cc:573] [Tags: "ConnectionId":"16","StreamId":"10595792538043134761"] decode headers called: filter=envoy.filters.http.health_check status=1
[2025-06-11 14:15:57.415][25][trace][http] [source/common/http/http1/codec_impl.cc:695] [Tags: "ConnectionId":"16"] parsed 109 bytes
envoy  | [2025-06-11 14:15:57.415][25][debug][connection] [source/common/network/connection_impl.cc:150] [Tags: "ConnectionId":"16"] closing data_to_write=180 type=2
envoy  | [2025-06-11 14:15:57.415][25][trace][main] [source/common/event/dispatcher_impl.cc:127] clearing deferred deletion list (size=2)
envoy  | [2025-06-11 14:15:57.415][25][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"16"] socket event: 2
[2025-06-11 14:15:57.415][25][trace][connection] [source/common/network/connection_impl.cc:737] [Tags: "ConnectionId":"16"] write ready
envoy  | [2025-06-11 14:15:57.415][25][trace][connection] [source/common/network/raw_buffer_socket.cc:70] [Tags: "ConnectionId":"16"] write returns: 180
envoy  | [2025-06-11 14:15:57.415][25][debug][connection] [source/common/network/connection_impl.cc:788] [Tags: "ConnectionId":"16"] write flush complete
envoy  | [2025-06-11 14:15:57.415][25][trace][connection] [source/common/network/connection_impl.cc:614] [Tags: "ConnectionId":"16"] socket event: 6
[2025-06-11 14:15:57.415][25][debug][connection] [source/common/network/connection_impl.cc:636] [Tags: "ConnectionId":"16"] remote early close
[2025-06-11 14:15:57.415][25][debug][connection] [source/common/network/connection_impl.cc:276] [Tags: "ConnectionId":"16"] closing socket: 0
envoy  | [2025-06-11 14:15:57.415][25][trace][connection] [source/common/network/connection_impl.cc:469] [Tags: "ConnectionId":"16"] raising connection event 0
[2025-06-11 14:15:57.415][25][trace][conn_handler] [source/common/listener_manager/active_stream_listener_base.cc:126] [Tags: "ConnectionId":"16"] tcp connection on event 0
envoy  | [2025-06-11 14:15:57.415][25][debug][conn_handler] [source/common/listener_manager/active_stream_listener_base.cc:136] [Tags: "ConnectionId":"16"] adding to cleanup list
[2025-06-11 14:15:57.415][25][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=1)
envoy  | [2025-06-11 14:15:57.415][25][trace][main] [source/common/event/dispatcher_impl.cc:233] item added to deferred deletion list (size=2)
[2025-06-11 14:15:57.415][25][trace][main] [source/common/event/dispatcher_impl.cc:127] clearing deferred deletion list (size=2)

@danehans
Copy link
Contributor

Can you remove the TLS transport socket and retest?

@zhengkezhou1
Copy link
Contributor Author

Yes its works

[2025-06-13 16:56:17.874][1][debug][hc] [source/extensions/health_checkers/grpc/health_checker_impl.cc:390] [Tags: "ConnectionId":"0"] hc grpc_status=0 service_status=serving health_flags=healthy

But there is also a new issue: SecureServing can't be set to false by passing args, which will cause the test to fail.

epp  | {"level":"info","ts":"2025-06-13T16:53:36Z","logger":"setup","caller":"runner/runner.go:161","msg":"Flags processed","flags":{"DestinationEndpointHintMetadataNamespace":"envoy.lb","certPath":"","destinationEndpointHintKey":"x-gateway-destination-endpoint","grpcHealthPort":9003,"grpcPort":9002,"kubeconfig":"","kvCacheUsagePercentageMetric":"vllm:gpu_cache_usage_perc","loraInfoMetric":"vllm:lora_requests_info","metricsPort":9090,"poolName":"vllm-llama3-8b-instruct","poolNamespace":"inf-ext-e2e","refreshMetricsInterval":50000000,"refreshPrometheusMetricsInterval":5000000000,"secureServing":true,"totalQueuedRequestsMetric":"vllm:num_requests_waiting","v":4,"zap-devel":true,"zap-encoder":{},"zap-log-level":{},"zap-stacktrace-level":{},"zap-time-encoding":{}}}

To avoid this, should we change the default value of secureServing to false?

Signed-off-by: zhengkezhou1 <madzhou1@gmail.com>
Signed-off-by: zhengkezhou1 <madzhou1@gmail.com>
@kfswain
Copy link
Collaborator

kfswain commented Jun 13, 2025

/ok-to-test

@k8s-ci-robot k8s-ci-robot added ok-to-test Indicates a non-member PR verified by an org member that is safe to test. and removed needs-ok-to-test Indicates a PR that requires an org member to verify it is safe to test. labels Jun 13, 2025
@danehans
Copy link
Contributor

The current grpc health server (port 9003) is used for kubelet liveness/readiness probes. Since kubectl does not support TLS-based gRPC probes (xref), the current health server must remain as-is.

You will need to update the extproc endpoint (9002) to use grpc health checking. Here is a skeleton of what the implementation would look like:

// pkg/epp/server/runserver.go

import (
    healthpb "google.golang.org/grpc/health/grpc_health_v1"
    "google.golang.org/grpc/health"
)

func (r *ExtProcServerRunner) AsRunnable(logger logr.Logger) manager.Runnable {
...

		extProcPb.RegisterExternalProcessorServer(
			srv,
			extProcServer,
		)

                // Register the gRPC health server with the existing extproc server
                healthServer := health.NewServer()
                healthpb.RegisterHealthServer(svr, healthServer)

                // Mark the extproc service as SERVING
                svcName := extProcPb.ExternalProcessor_ServiceDesc.ServiceName
                healthServer.SetServingStatus(svcName, healthpb.HealthCheckResponse_SERVING)

		// Forward to the gRPC runnable.
		return runnable.GRPCServer("ext-proc", srv, r.GrpcPort).Start(ctx)
}

With the above changes, a health endpoint is added to the EPP ext-proc server (TCP 9002). Next, update the Envoy e2e test configmap with the health_checks:

static_resources:
  clusters:
    - name: ext_proc
      type: STRICT_DNS
      connect_timeout: 1s
      lb_policy: LEAST_REQUEST

      # Enable active health checking
      health_checks:
        - timeout:             2s        # wait this long for a reply
          interval:            10s       # probe every 10s
          unhealthy_threshold: 3         # 3 consecutive failures → unhealthy
          healthy_threshold:   2         # 2 successes → healthy again
          reuse_connection:    true      # keep HTTP2 conn open
          grpc_health_check:            # invoke gRPC Health/Check
            service_name: "envoy.service.ext_proc.v3.ExternalProcessor" # Must match the service name registered by EPP

Since this is considered a breaking change, the new code should be gated by a CLI flag with it disabled by default.

Signed-off-by: zhengkezhou1 <madzhou1@gmail.com>
@k8s-ci-robot k8s-ci-robot added size/M Denotes a PR that changes 30-99 lines, ignoring generated files. and removed size/S Denotes a PR that changes 10-29 lines, ignoring generated files. labels Jun 14, 2025
Signed-off-by: zhengkezhou1 <madzhou1@gmail.com>
Signed-off-by: zhengkezhou1 <madzhou1@gmail.com>
Signed-off-by: zhengkezhou1 <madzhou1@gmail.com>
Comment on lines +181 to +182
tls_options:
alpn_protocols: ["h2"]
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

After adding the TLS options, it works now. 😅

[2025-06-15 11:08:22.735][1][debug][hc] [source/extensions/health_checkers/grpc/health_checker_impl.cc:390] [Tags: "ConnectionId":"0"] hc grpc_status=0 service_status=serving health_flags=healthy

@danehans
Copy link
Contributor

/approve

@k8s-ci-robot
Copy link
Contributor

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: danehans, zhengkezhou1

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

@k8s-ci-robot k8s-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Jun 16, 2025
@danehans
Copy link
Contributor

PTAL @ahg-g since you commented on the related issue.

@danehans
Copy link
Contributor

To avoid this, should we change the default value of secureServing to false?

We need to keep this setting as-is.

@ahg-g
Copy link
Contributor

ahg-g commented Jun 17, 2025

/hold cancel
/lgtm

@k8s-ci-robot k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Jun 17, 2025
@k8s-ci-robot k8s-ci-robot merged commit 7ca36bf into kubernetes-sigs:main Jun 17, 2025
9 checks passed
shmuelk pushed a commit to shmuelk/gateway-api-inference-extension that referenced this pull request Jun 17, 2025
* feat: add health check for epp cluster

Signed-off-by: zhengkezhou1 <madzhou1@gmail.com>

* remove tls

Signed-off-by: zhengkezhou1 <madzhou1@gmail.com>

* don't use tls

Signed-off-by: zhengkezhou1 <madzhou1@gmail.com>

* health checking flag

Signed-off-by: zhengkezhou1 <madzhou1@gmail.com>

* fix import

Signed-off-by: zhengkezhou1 <madzhou1@gmail.com>

* add tls options

Signed-off-by: zhengkezhou1 <madzhou1@gmail.com>

---------

Signed-off-by: zhengkezhou1 <madzhou1@gmail.com>
k8s-ci-robot pushed a commit that referenced this pull request Jun 18, 2025
…e it easier to add plugins (#881)

* configuration implementation (after rebase...)

Signed-off-by: Shmuel Kallner <kallner@il.ibm.com>

* Moved plugin registry back to pkg/epp/plugins

Signed-off-by: Shmuel Kallner <kallner@il.ibm.com>

* Removed unneeded 'forced imports' of scorers

Signed-off-by: Shmuel Kallner <kallner@il.ibm.com>

* Changed 'profilepicker' to 'profilehandler' in new and old code

Signed-off-by: Shmuel Kallner <kallner@il.ibm.com>

* Pass the configured SchedulingProfiles to LoadSchedulerConfig

Signed-off-by: Shmuel Kallner <kallner@il.ibm.com>

* Ensure that both the configText and configFile flags are not specified

Signed-off-by: Shmuel Kallner <kallner@il.ibm.com>

* Load RequestControl plugins from the configuration

Signed-off-by: Shmuel Kallner <kallner@il.ibm.com>

* Register all plugin factories

Signed-off-by: Shmuel Kallner <kallner@il.ibm.com>

* Review fixes

Signed-off-by: Shmuel Kallner <kallner@il.ibm.com>

* Reverted unneeded change

Signed-off-by: Shmuel Kallner <kallner@il.ibm.com>

* Updates from review comments

Signed-off-by: Shmuel Kallner <kallner@il.ibm.com>

* Added a stub interface for plugins to get data from the EPP

Signed-off-by: Shmuel Kallner <kallner@il.ibm.com>

* Added a temporary implementation of plugins.Handle

Signed-off-by: Shmuel Kallner <kallner@il.ibm.com>

* Added pluginName and plugins.Handle to plugin factory interface

Signed-off-by: Shmuel Kallner <kallner@il.ibm.com>

* Updated plugin factory signatures to reflect new API

Signed-off-by: Shmuel Kallner <kallner@il.ibm.com>

* Updated plugin instantiation to reflect new API

Signed-off-by: Shmuel Kallner <kallner@il.ibm.com>

* Updated plugin instantiation to reflect new API

Signed-off-by: Shmuel Kallner <kallner@il.ibm.com>

* Updated tests to reflect new API

Signed-off-by: Shmuel Kallner <kallner@il.ibm.com>

* Do not rename the imported package

Signed-off-by: Shmuel Kallner <kallner@il.ibm.com>

* Only upper layer of code should log errors

Signed-off-by: Shmuel Kallner <kallner@il.ibm.com>

* Only pass what is needed to instantiate the plugins

Signed-off-by: Shmuel Kallner <kallner@il.ibm.com>

* Review updates

Signed-off-by: Shmuel Kallner <kallner@il.ibm.com>

* Review update

Signed-off-by: Shmuel Kallner <kallner@il.ibm.com>

* Review update. Make more clear that the code only checks for already defined names

Signed-off-by: Shmuel Kallner <kallner@il.ibm.com>

* fixed e2e doc in makefile (does not require GPUs) (#976)

Signed-off-by: Nir Rozenbaum <nirro@il.ibm.com>

* API: Adds 5xx Status Code for Invalid ExtRef (#991)

Signed-off-by: Daneyon Hansen <daneyon.hansen@solo.io>

* feat(conformance): Add test for invalid EPP service reference (#959)

* fix boilerplate header

* add tests for InferencePoolInvalidEPPService

* change to expect error on httproute refcond

* moved the creation of the context to main.go. (#995)

this is useful when writing a different main like llm-d, allowing to propogate the same context to the whole system.

Signed-off-by: Nir Rozenbaum <nirro@il.ibm.com>

* fix dead links (#989)

* feat: add health check for epp cluster (#966)

* feat: add health check for epp cluster

Signed-off-by: zhengkezhou1 <madzhou1@gmail.com>

* remove tls

Signed-off-by: zhengkezhou1 <madzhou1@gmail.com>

* don't use tls

Signed-off-by: zhengkezhou1 <madzhou1@gmail.com>

* health checking flag

Signed-off-by: zhengkezhou1 <madzhou1@gmail.com>

* fix import

Signed-off-by: zhengkezhou1 <madzhou1@gmail.com>

* add tls options

Signed-off-by: zhengkezhou1 <madzhou1@gmail.com>

---------

Signed-off-by: zhengkezhou1 <madzhou1@gmail.com>

* Server unit test and utility to help with such tests (#820)

Signed-off-by: Ira <IRAR@il.ibm.com>

* Update dynamic-lora-sidecar to expose metrics to track loaded adapters (#980)

* Add a metrics to track loaded adapters

* Update the sample manifests

* Add explanation of metrics from dyanmic LoRA adapter sidecar

* Add explanation of metrics from dyanmic LoRA adapter sidecar (take 2)

* Update metrics.md based on feedback

* refactor: Replace prefix cache structure with golang-lru (#928)

* refactor: Replace prefix cache structure with golang-lru

Signed-off-by: Kfir Toledo <kfir.toledo@ibm.com>
Co-authored-by: Maroon Ayoub <maroon.ayoub@ibm.com>

* fix: rename prefix scorer parameters and convert test to benchmark test

Signed-off-by: Kfir Toledo <kfir.toledo@ibm.com>

* feat: Add per server LRU capacity

Signed-off-by: Kfir Toledo <kfir.toledo@ibm.com>

* fix: Fix typos and error handle

Signed-off-by: Kfir Toledo <kfir.toledo@ibm.com>

* fix: add safety check for LRUCapacityPerServer

Signed-off-by: Kfir Toledo <kfir.toledo@ibm.com>

---------

Signed-off-by: Kfir Toledo <kfir.toledo@ibm.com>
Co-authored-by: Maroon Ayoub <maroon.ayoub@ibm.com>

* feat(conformance): Add HTTPRouteMultipleRulesDifferentPools test (#834)

* copy of accepted inference pool test to start from.

* add yaml file for the test

* update time out

* update the yaml file to add port 9002

* read timeout config from local repo

* remove excess comments

* correct spelling for scenarios

* check route condition on RouteConditionResolvedRefs

* remove empty lines in yaml

* set optional/defaulted fields as unspecified

* fix timeout

* fix boilerplate header

* change varialbe names to use primary secondary consistently.

* remove extra comments

* factor out common code

* Add actual http traffic validation using echo-basic

* remove extra comments from manifest

* remove modifiedTimeoutConfig.HTTPRouteMustHaveCondition per review comment.

* intermediate update

* fix the test run

* factor out common code

* move epp def to shared manifest

* remove extra comments

* revert back to two epps

* add to do for epp image

* switch to GeneralMustHaveConditionTimeout

* undo gateway version changes

* remove unused HTTPRouteMustHaveConditions

* update doc string for GetPod

* update docstring

* Remove resource type from names in manifests.

* remove type from name

* remove health check

* add todo for combining getpod methods

* configuration implementation (after rebase...)

Signed-off-by: Shmuel Kallner <kallner@il.ibm.com>

* After review, made code more obvious

Signed-off-by: Shmuel Kallner <kallner@il.ibm.com>

* Fixed merge issues

Signed-off-by: Shmuel Kallner <kallner@il.ibm.com>

---------

Signed-off-by: Shmuel Kallner <kallner@il.ibm.com>
Signed-off-by: Nir Rozenbaum <nirro@il.ibm.com>
Signed-off-by: Daneyon Hansen <daneyon.hansen@solo.io>
Signed-off-by: zhengkezhou1 <madzhou1@gmail.com>
Signed-off-by: Ira <IRAR@il.ibm.com>
Signed-off-by: Kfir Toledo <kfir.toledo@ibm.com>
Co-authored-by: Nir Rozenbaum <nirro@il.ibm.com>
Co-authored-by: Daneyon Hansen <daneyon.hansen@solo.io>
Co-authored-by: sina chavoshi <chavoshi@google.com>
Co-authored-by: Xudong Wang <68834160+caozhuozi@users.noreply.github.com>
Co-authored-by: Zhengke Zhou <madzhou1@gmail.com>
Co-authored-by: Ira Rosen <irar@il.ibm.com>
Co-authored-by: Shotaro Kohama <khmshtr28@gmail.com>
Co-authored-by: Kfir Toledo <kfir.toledo@gmail.com>
Co-authored-by: Maroon Ayoub <maroon.ayoub@ibm.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
approved Indicates a PR has been approved by an approver from all required OWNERS files. cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. lgtm "Looks good to me", indicates that a PR is ready to be merged. ok-to-test Indicates a non-member PR verified by an org member that is safe to test. size/M Denotes a PR that changes 30-99 lines, ignoring generated files.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Ext-Proc Cluster Health Checking
5 participants