istio: Sporadic 503 errors

Describe the bug I have a web application in a Pod running with an Istio sidecar and I get random 503 errors from the sidecar itself (Envoy) not even reaching the web application. This is happening with a very low demand. In the logs below you will see a request to an endpoint named /logout which is throwing the 503 error and not reaching the web application whatsoever.

Expected behavior Everything is forwarded to the web application.

Steps to reproduce the bug Simple test invoking several endpoints in the web application, with a very small load.

Version Istio --> 1.0.1 Kubernetes --> 1.11.3

Installation istio.yaml - use this generated file for installation without authentication enabled

Environment Bare metal servers, on premise, OL7.5, Linux 4.17.5-1.el7.elrepo.x86_64 #1 SMP Sun Jul 8 10:40:01 EDT 2018 x86_64 x86_64 x86_64 GNU/Linux

Logs

preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.958][95][debug][http] external/envoy/source/common/http/conn_manager_impl.cc:190] [C32] new stream
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.958][95][trace][http] external/envoy/source/common/http/http1/codec_impl.cc:309] [C32] completed header: key=host value=pp-helpers.test.oami.eu
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.958][95][trace][http] external/envoy/source/common/http/http1/codec_impl.cc:309] [C32] completed header: key=cookie value=CLASSIFSESSIONID=MjM2N2MyOWUtODFhOS00ZGVjLTkwNjktOTQ5NzhlZTc2ZDk1
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.958][95][trace][http] external/envoy/source/common/http/http1/codec_impl.cc:309] [C32] completed header: key=content-type value=application/x-www-form-urlencoded
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.958][95][trace][http] external/envoy/source/common/http/http1/codec_impl.cc:309] [C32] completed header: key=content-length value=0
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.958][95][trace][http] external/envoy/source/common/http/http1/codec_impl.cc:309] [C32] completed header: key=user-agent value=Apache-HttpClient/4.5.5 (Java/1.8.0_151)
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.958][95][trace][http] external/envoy/source/common/http/http1/codec_impl.cc:309] [C32] completed header: key=x-forwarded-for value=10.133.0.44, 174.16.212.0
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.958][95][trace][http] external/envoy/source/common/http/http1/codec_impl.cc:309] [C32] completed header: key=x-forwarded-proto value=http
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.958][95][trace][http] external/envoy/source/common/http/http1/codec_impl.cc:309] [C32] completed header: key=x-envoy-external-address value=174.16.212.0
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.958][95][trace][http] external/envoy/source/common/http/http1/codec_impl.cc:309] [C32] completed header: key=x-request-id value=82aeb468-9f91-9b30-9482-2aa3591e1979
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.958][95][trace][http] external/envoy/source/common/http/http1/codec_impl.cc:309] [C32] completed header: key=x-envoy-decorator-operation value=classification-helper-ui.preprod-cb.svc.cluster.local:8080/api/classification*
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.958][95][trace][http] external/envoy/source/common/http/http1/codec_impl.cc:309] [C32] completed header: key=x-b3-traceid value=e4ece8f07a5a7481
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.958][95][trace][http] external/envoy/source/common/http/http1/codec_impl.cc:309] [C32] completed header: key=x-b3-spanid value=e4ece8f07a5a7481
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.958][95][trace][http] external/envoy/source/common/http/http1/codec_impl.cc:309] [C32] completed header: key=x-b3-sampled value=1
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.958][95][trace][http] external/envoy/source/common/http/http1/codec_impl.cc:309] [C32] completed header: key=x-istio-attributes value=Ck8KCnNvdXJjZS51aWQSQRI/a3ViZXJuZXRlczovL2lzdGlvLWluZ3Jlc3NnYXRld2F5LTVkOTk5Yzg3NTctZHY5cnMuaXN0aW8tc3lzdGVtCk4KE2Rlc3RpbmF0aW9uLnNlcnZpY2USNxI1Y2xhc3NpZmljYXRpb24taGVscGVyLXVpLnByZXByb2QtY2Iuc3ZjLmNsdXN0ZXIubG9jYWwKUwoYZGVzdGluYXRpb24uc2VydmljZS5ob3N0EjcSNWNsYXNzaWZpY2F0aW9uLWhlbHBlci11aS5wcmVwcm9kLWNiLnN2Yy5jbHVzdGVyLmxvY2FsClEKF2Rlc3RpbmF0aW9uLnNlcnZpY2UudWlkEjYSNGlzdGlvOi8vcHJlcHJvZC1jYi9zZXJ2aWNlcy9jbGFzc2lmaWNhdGlvbi1oZWxwZXItdWkKLQodZGVzdGluYXRpb24uc2VydmljZS5uYW1lc3BhY2USDBIKcHJlcHJvZC1jYgo2ChhkZXN0aW5hdGlvbi5zZXJ2aWNlLm5hbWUSGhIYY2xhc3NpZmljYXRpb24taGVscGVyLXVp
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.958][95][trace][http] external/envoy/source/common/http/http1/codec_impl.cc:405] [C32] headers complete
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.958][95][trace][http] external/envoy/source/common/http/http1/codec_impl.cc:309] [C32] completed header: key=x-envoy-original-path value=/api/classification/logout
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.958][95][trace][http] external/envoy/source/common/http/http1/codec_impl.cc:426] [C32] message complete
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.958][95][debug][filter] src/envoy/http/mixer/filter.cc:60] Called Mixer::Filter : Filter
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.958][95][debug][filter] src/envoy/http/mixer/filter.cc:204] Called Mixer::Filter : setDecoderFilterCallbacks
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.958][95][debug][http] external/envoy/source/common/http/conn_manager_impl.cc:889] [C32][S16141632285256672176] request end stream
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.958][95][debug][http] external/envoy/source/common/http/conn_manager_impl.cc:490] [C32][S16141632285256672176] request headers complete (end_stream=true):
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: ':authority', 'pp-helpers.test.oami.eu'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: ':path', '//logout'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: ':method', 'POST'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'cookie', 'CLASSIFSESSIONID=MjM2N2MyOWUtODFhOS00ZGVjLTkwNjktOTQ5NzhlZTc2ZDk1'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'content-type', 'application/x-www-form-urlencoded'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'content-length', '0'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'user-agent', 'Apache-HttpClient/4.5.5 (Java/1.8.0_151)'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'x-forwarded-for', '10.133.0.44, 174.16.212.0'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'x-forwarded-proto', 'http'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'x-envoy-external-address', '174.16.212.0'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'x-request-id', '82aeb468-9f91-9b30-9482-2aa3591e1979'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'x-envoy-decorator-operation', 'classification-helper-ui.preprod-cb.svc.cluster.local:8080/api/classification*'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'x-b3-traceid', 'e4ece8f07a5a7481'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'x-b3-spanid', 'e4ece8f07a5a7481'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'x-b3-sampled', '1'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'x-istio-attributes', 'Ck8KCnNvdXJjZS51aWQSQRI/a3ViZXJuZXRlczovL2lzdGlvLWluZ3Jlc3NnYXRld2F5LTVkOTk5Yzg3NTctZHY5cnMuaXN0aW8tc3lzdGVtCk4KE2Rlc3RpbmF0aW9uLnNlcnZpY2USNxI1Y2xhc3NpZmljYXRpb24taGVscGVyLXVpLnByZXByb2QtY2Iuc3ZjLmNsdXN0ZXIubG9jYWwKUwoYZGVzdGluYXRpb24uc2VydmljZS5ob3N0EjcSNWNsYXNzaWZpY2F0aW9uLWhlbHBlci11aS5wcmVwcm9kLWNiLnN2Yy5jbHVzdGVyLmxvY2FsClEKF2Rlc3RpbmF0aW9uLnNlcnZpY2UudWlkEjYSNGlzdGlvOi8vcHJlcHJvZC1jYi9zZXJ2aWNlcy9jbGFzc2lmaWNhdGlvbi1oZWxwZXItdWkKLQodZGVzdGluYXRpb24uc2VydmljZS5uYW1lc3BhY2USDBIKcHJlcHJvZC1jYgo2ChhkZXN0aW5hdGlvbi5zZXJ2aWNlLm5hbWUSGhIYY2xhc3NpZmljYXRpb24taGVscGVyLXVp'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'x-envoy-original-path', '/api/classification/logout'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.958][95][debug][filter] src/envoy/http/mixer/filter.cc:122] Called Mixer::Filter : decodeHeaders
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.958][95][debug][filter] ./src/envoy/utils/header_update.h:46] Mixer forward attributes set: ClEKCnNvdXJjZS51aWQSQxJBa3ViZXJuZXRlczovL2NsYXNzaWZpY2F0aW9uLWhlbHBlci11aS03NmY5Y2RjZDRkLXJ6Nm45LnByZXByb2QtY2I=
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.958][95][debug][router] external/envoy/source/common/router/router.cc:252] [C0][S14382728320977988265] cluster 'outbound|9091||istio-policy.istio-system.svc.cluster.local' match for URL '/istio.mixer.v1.Mixer/Check'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.958][95][debug][router] external/envoy/source/common/router/router.cc:303] [C0][S14382728320977988265] router decoding headers:
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: ':method', 'POST'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: ':path', '/istio.mixer.v1.Mixer/Check'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: ':authority', 'mixer'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: ':scheme', 'http'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'te', 'trailers'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'grpc-timeout', '5000m'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'content-type', 'application/grpc'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'x-b3-traceid', 'e4ece8f07a5a7481'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'x-b3-spanid', 'df547f7d4992bf4e'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'x-b3-parentspanid', 'e4ece8f07a5a7481'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'x-b3-sampled', '1'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'x-istio-attributes', 'ClEKCnNvdXJjZS51aWQSQxJBa3ViZXJuZXRlczovL2NsYXNzaWZpY2F0aW9uLWhlbHBlci11aS03NmY5Y2RjZDRkLXJ6Nm45LnByZXByb2QtY2I='
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'x-envoy-internal', 'true'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'x-forwarded-for', '174.16.213.27'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'x-envoy-expected-rq-timeout-ms', '5000'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.958][95][debug][pool] external/envoy/source/common/http/http2/conn_pool.cc:97] [C236] creating stream
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.958][95][debug][router] external/envoy/source/common/router/router.cc:971] [C0][S14382728320977988265] pool ready
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.958][95][trace][http2] external/envoy/source/common/http/http2/codec_impl.cc:492] [C236] send data: bytes=85
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.958][95][trace][connection] external/envoy/source/common/network/connection_impl.cc:326] [C236] writing 85 bytes, end_stream false
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.958][95][trace][http2] external/envoy/source/common/http/http2/codec_impl.cc:446] [C236] sent frame type=1
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.958][95][trace][router] external/envoy/source/common/router/router.cc:871] [C0][S14382728320977988265] proxying 985 bytes
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.958][95][trace][connection] external/envoy/source/common/network/connection_impl.cc:326] [C236] writing 994 bytes, end_stream false
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.958][95][trace][http2] external/envoy/source/common/http/http2/codec_impl.cc:446] [C236] sent frame type=0
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.959][95][debug][grpc] src/envoy/utils/grpc_transport.cc:46] Sending Check request: attributes {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   words: "inbound"
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   words: "x-envoy-original-path"
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   words: "/api/classification/logout"
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   words: "Apache-HttpClient/4.5.5 (Java/1.8.0_151)"
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   words: "e4ece8f07a5a7481"
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   words: "//logout"
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   words: "x-envoy-external-address"
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   words: "174.16.212.0"
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   words: "application/x-www-form-urlencoded"
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   words: "CLASSIFSESSIONID=MjM2N2MyOWUtODFhOS00ZGVjLTkwNjktOTQ5NzhlZTc2ZDk1"
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   words: "pp-helpers.test.oami.eu"
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   words: "82aeb468-9f91-9b30-9482-2aa3591e1979"
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   words: "10.133.0.44, 174.16.212.0"
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   words: "classification-helper-ui.preprod-cb.svc.cluster.local"
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   words: "preprod-cb"
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   words: "classification-helper-ui"
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   words: "kubernetes://classification-helper-ui-76f9cdcd4d-rz6n9.preprod-cb"
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   words: "origin.ip"
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   words: "kubernetes://istio-ingressgateway-5d999c8757-dv9rs.istio-system"
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   words: "istio://preprod-cb/services/classification-helper-ui"
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   strings {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     key: 3
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     value: -19
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   strings {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     key: 17
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     value: -6
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   strings {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     key: 18
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     value: -11
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   strings {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     key: 19
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     value: 91
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   strings {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     key: 22
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     value: 92
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   strings {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     key: 25
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     value: -4
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   strings {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     key: 131
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     value: 92
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   strings {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     key: 152
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     value: -14
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   strings {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     key: 154
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     value: -17
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   strings {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     key: 155
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     value: -15
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   strings {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     key: 190
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     value: -20
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   strings {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     key: 191
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     value: -16
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   strings {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     key: 192
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     value: -15
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   strings {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     key: 193
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     value: -14
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   strings {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     key: 197
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     value: -17
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   strings {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     key: 201
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     value: -1
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   int64s {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     key: 151
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     value: 8080
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   bools {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     key: 177
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     value: false
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   timestamps {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     key: 24
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     value {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       seconds: 1538556462
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       nanos: 958551761
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   bytes {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     key: -18
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     value: "\256\020=8"
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   bytes {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     key: 150
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     value: "\000\000\000\000\000\000\000\000\000\000\377\377\256\020\325\033"
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   string_maps {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     key: 15
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     value {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       entries {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:         key: -7
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:         value: -8
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       entries {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:         key: -2
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:         value: -3
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       entries {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:         key: 31
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:         value: -11
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       entries {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:         key: 32
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:         value: 91
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       entries {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:         key: 33
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:         value: -6
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       entries {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:         key: 55
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:         value: 134
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       entries {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:         key: 58
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:         value: -9
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       entries {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:         key: 59
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:         value: -10
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       entries {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:         key: 86
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:         value: -4
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       entries {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:         key: 98
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:         value: -13
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       entries {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:         key: 100
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:         value: 92
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       entries {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:         key: 102
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:         value: -12
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       entries {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:         key: 121
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:         value: -5
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       entries {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:         key: 122
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:         value: 135
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       entries {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:         key: 123
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:         value: -5
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: global_word_count: 203
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: deduplication_id: "231e89c0-6dcb-4ada-a813-375cedb8a64427"
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.959][95][debug][filter] src/envoy/http/mixer/filter.cc:146] Called Mixer::Filter : decodeHeaders Stop
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.959][95][trace][http] external/envoy/source/common/http/conn_manager_impl.cc:719] [C32][S16141632285256672176] decode headers called: filter=0x115c9040 status=1
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.959][95][trace][http] external/envoy/source/common/http/http1/codec_impl.cc:362] [C32] parsed 1253 bytes
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.959][95][trace][connection] external/envoy/source/common/network/connection_impl.cc:232] [C32] readDisable: enabled=true disable=true
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.959][95][trace][connection] external/envoy/source/common/network/connection_impl.cc:389] [C236] socket event: 2
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.959][95][trace][connection] external/envoy/source/common/network/connection_impl.cc:457] [C236] write ready
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.959][95][trace][connection] external/envoy/source/common/network/raw_buffer_socket.cc:62] [C236] write returns: 1079
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.959][95][trace][connection] external/envoy/source/common/network/connection_impl.cc:389] [C32] socket event: 2
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.959][95][trace][connection] external/envoy/source/common/network/connection_impl.cc:457] [C32] write ready
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.960][95][trace][connection] external/envoy/source/common/network/connection_impl.cc:389] [C236] socket event: 3
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.960][95][trace][connection] external/envoy/source/common/network/connection_impl.cc:457] [C236] write ready
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.960][95][trace][connection] external/envoy/source/common/network/connection_impl.cc:427] [C236] read ready
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.960][95][trace][connection] external/envoy/source/common/network/raw_buffer_socket.cc:21] [C236] read returns: 103
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.960][95][trace][connection] external/envoy/source/common/network/raw_buffer_socket.cc:21] [C236] read returns: -1
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.960][95][trace][connection] external/envoy/source/common/network/raw_buffer_socket.cc:29] [C236] read error: 11
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.960][95][trace][http2] external/envoy/source/common/http/http2/codec_impl.cc:277] [C236] dispatching 103 bytes
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.960][95][trace][http2] external/envoy/source/common/http/http2/codec_impl.cc:335] [C236] recv frame type=1
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.960][95][debug][router] external/envoy/source/common/router/router.cc:583] [C0][S14382728320977988265] upstream headers complete: end_stream=false
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.960][95][debug][http] external/envoy/source/common/http/async_client_impl.cc:93] async http request response headers (end_stream=false):
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: ':status', '200'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'content-type', 'application/grpc'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'x-envoy-upstream-service-time', '1'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'date', 'Wed, 03 Oct 2018 08:47:42 GMT'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'server', 'envoy'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'x-envoy-decorator-operation', 'Check'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.960][95][trace][http2] external/envoy/source/common/http/http2/codec_impl.cc:335] [C236] recv frame type=0
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.960][95][trace][http] external/envoy/source/common/http/async_client_impl.cc:101] async http request response data (length=45 end_stream=false)
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.960][95][trace][http2] external/envoy/source/common/http/http2/codec_impl.cc:335] [C236] recv frame type=1
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.960][95][debug][client] external/envoy/source/common/http/codec_client.cc:94] [C236] response complete
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.960][95][trace][main] external/envoy/source/common/event/dispatcher_impl.cc:126] item added to deferred deletion list (size=1)
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.960][95][debug][pool] external/envoy/source/common/http/http2/conn_pool.cc:189] [C236] destroying stream: 0 remaining
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.960][95][debug][http] external/envoy/source/common/http/async_client_impl.cc:108] async http request response trailers:
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'grpc-status', '0'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'grpc-message', ''
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.960][95][debug][grpc] src/envoy/utils/grpc_transport.cc:67] Check response: precondition {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   status {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   valid_duration {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     seconds: 46
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     nanos: 386564935
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   valid_use_count: 10000
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   referenced_attributes {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     attribute_matches {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       name: 155
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       condition: EXACT
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     attribute_matches {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       name: 201
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       condition: EXACT
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     attribute_matches {
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       name: 152
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:       condition: EXACT
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:     }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:   }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: }
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.960][95][debug][filter] src/envoy/http/mixer/filter.cc:211] Called Mixer::Filter : check complete OK
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.960][95][trace][http] external/envoy/source/common/http/conn_manager_impl.cc:1296] [C32][S16141632285256672176] continuing filter chain: filter=0x115c9040
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.960][95][trace][http] external/envoy/source/common/http/conn_manager_impl.cc:719] [C32][S16141632285256672176] decode headers called: filter=0x12d6f310 status=0
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.960][95][trace][http] external/envoy/source/common/http/conn_manager_impl.cc:719] [C32][S16141632285256672176] decode headers called: filter=0x12d6fcc0 status=0
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.960][95][debug][router] external/envoy/source/common/router/router.cc:252] [C32][S16141632285256672176] cluster 'inbound|8080||classification-helper-ui.preprod-cb.svc.cluster.local' match for URL '//logout'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.960][95][debug][router] external/envoy/source/common/router/router.cc:303] [C32][S16141632285256672176] router decoding headers:
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: ':authority', 'pp-helpers.test.oami.eu'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: ':path', '//logout'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: ':method', 'POST'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: ':scheme', 'http'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'cookie', 'CLASSIFSESSIONID=MjM2N2MyOWUtODFhOS00ZGVjLTkwNjktOTQ5NzhlZTc2ZDk1'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'content-type', 'application/x-www-form-urlencoded'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'content-length', '0'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'user-agent', 'Apache-HttpClient/4.5.5 (Java/1.8.0_151)'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'x-forwarded-for', '10.133.0.44, 174.16.212.0'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'x-forwarded-proto', 'http'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'x-envoy-external-address', '174.16.212.0'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'x-request-id', '82aeb468-9f91-9b30-9482-2aa3591e1979'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'x-b3-traceid', 'e4ece8f07a5a7481'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'x-b3-spanid', 'e4ece8f07a5a7481'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'x-b3-sampled', '1'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'x-envoy-original-path', '/api/classification/logout'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.960][95][debug][pool] external/envoy/source/common/http/http1/conn_pool.cc:89] [C502] using existing connection
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.960][95][trace][connection] external/envoy/source/common/network/connection_impl.cc:232] [C502] readDisable: enabled=false disable=false
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.960][95][debug][router] external/envoy/source/common/router/router.cc:971] [C32][S16141632285256672176] pool ready
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][trace][connection] external/envoy/source/common/network/connection_impl.cc:326] [C502] writing 546 bytes, end_stream false
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][trace][http] external/envoy/source/common/http/conn_manager_impl.cc:719] [C32][S16141632285256672176] decode headers called: filter=0x111d3c20 status=1
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][trace][main] external/envoy/source/common/event/dispatcher_impl.cc:126] item added to deferred deletion list (size=2)
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][trace][main] external/envoy/source/common/event/dispatcher_impl.cc:126] item added to deferred deletion list (size=3)
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][debug][http2] external/envoy/source/common/http/http2/codec_impl.cc:501] [C236] stream closed: 0
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][trace][main] external/envoy/source/common/event/dispatcher_impl.cc:126] item added to deferred deletion list (size=4)
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][trace][http2] external/envoy/source/common/http/http2/codec_impl.cc:292] [C236] dispatched 103 bytes
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][trace][main] external/envoy/source/common/event/dispatcher_impl.cc:52] clearing deferred deletion list (size=4)
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][trace][connection] external/envoy/source/common/network/connection_impl.cc:389] [C502] socket event: 2
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][trace][connection] external/envoy/source/common/network/connection_impl.cc:457] [C502] write ready
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][trace][connection] external/envoy/source/common/network/raw_buffer_socket.cc:62] [C502] write returns: 546
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][trace][connection] external/envoy/source/common/network/connection_impl.cc:389] [C502] socket event: 3
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][trace][connection] external/envoy/source/common/network/connection_impl.cc:457] [C502] write ready
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][trace][connection] external/envoy/source/common/network/connection_impl.cc:427] [C502] read ready
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][trace][connection] external/envoy/source/common/network/raw_buffer_socket.cc:21] [C502] read returns: 0
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][debug][connection] external/envoy/source/common/network/connection_impl.cc:451] [C502] remote close
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][debug][connection] external/envoy/source/common/network/connection_impl.cc:133] [C502] closing socket: 0
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][trace][http] external/envoy/source/common/http/http1/codec_impl.cc:341] [C502] parsing 0 bytes
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][trace][http] external/envoy/source/common/http/http1/codec_impl.cc:362] [C502] parsed 0 bytes
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][debug][client] external/envoy/source/common/http/codec_client.cc:81] [C502] disconnect. resetting 1 pending requests
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][debug][client] external/envoy/source/common/http/codec_client.cc:104] [C502] request reset
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][trace][main] external/envoy/source/common/event/dispatcher_impl.cc:126] item added to deferred deletion list (size=1)
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][debug][router] external/envoy/source/common/router/router.cc:457] [C32][S16141632285256672176] upstream reset
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][debug][filter] src/envoy/http/mixer/filter.cc:191] Called Mixer::Filter : encodeHeaders 2
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][trace][http] external/envoy/source/common/http/conn_manager_impl.cc:997] [C32][S16141632285256672176] encode headers called: filter=0x11d85140 status=0
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][trace][http] external/envoy/source/common/http/conn_manager_impl.cc:997] [C32][S16141632285256672176] encode headers called: filter=0x11305dc0 status=0
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][debug][http] external/envoy/source/common/http/conn_manager_impl.cc:1083] [C32][S16141632285256672176] encoding headers via codec (end_stream=false):
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: ':status', '503'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'content-length', '57'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'content-type', 'text/plain'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'date', 'Wed, 03 Oct 2018 08:47:42 GMT'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: 'server', 'envoy'
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]:
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][trace][connection] external/envoy/source/common/network/connection_impl.cc:326] [C32] writing 134 bytes, end_stream false
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][trace][http] external/envoy/source/common/http/conn_manager_impl.cc:1157] [C32][S16141632285256672176] encode data called: filter=0x11d85140 status=0
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][trace][http] external/envoy/source/common/http/conn_manager_impl.cc:1157] [C32][S16141632285256672176] encode data called: filter=0x11305dc0 status=0
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][trace][http] external/envoy/source/common/http/conn_manager_impl.cc:1170] [C32][S16141632285256672176] encoding data via codec (size=57 end_stream=true)
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][trace][connection] external/envoy/source/common/network/connection_impl.cc:326] [C32] writing 57 bytes, end_stream false
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][debug][filter] src/envoy/http/mixer/filter.cc:257] Called Mixer::Filter : onDestroy state: 2
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][trace][main] external/envoy/source/common/event/dispatcher_impl.cc:126] item added to deferred deletion list (size=2)
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][trace][connection] external/envoy/source/common/network/connection_impl.cc:232] [C32] readDisable: enabled=false disable=false
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][debug][pool] external/envoy/source/common/http/http1/conn_pool.cc:122] [C502] client disconnected
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][trace][main] external/envoy/source/common/event/dispatcher_impl.cc:126] item added to deferred deletion list (size=3)
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][trace][main] external/envoy/source/common/event/dispatcher_impl.cc:52] clearing deferred deletion list (size=3)

About this issue

  • Original URL
  • State: closed
  • Created 6 years ago
  • Reactions: 10
  • Comments: 130 (70 by maintainers)

Most upvoted comments

FYI. There is a chance some of these 503s might be related to this bug where Envoy doesn’t acknowledge a FIN packet immediately after getting a response from upstream and returns the connection to the connection pool instead, which will trigger a 503 on the next write to the stream: https://github.com/envoyproxy/envoy/issues/6190.

We run Envoy in a cluster that currently gets on average about 1k requests/minute and used to see 503s left and right across different services after about 15min or so of a fresh deployment. We swept them under the rug by doing retries, but as others mentioned, this can’t be a long term solution due to its potential side effects on non-idempotent requests. We recently started playing around with idle upstream timeout values as introduced by https://github.com/envoyproxy/envoy/pull/2714 and haven’t had any 503s within the past week (with the same amount of traffic). Would be interesting to see if envoyproxy/envoy/issues/6190 would fix any/most of these mysterious connection resets but I think it’d make sense for Istio to at the very least support this idle timeout option for upstream connections (option 4).

+6
arianmotamedi on Apr 2, 2019

I think this is ‘fixed’ for 1.1, but we didn’t have consensus so I’ll try to capture the objections and alternatives for the record…

The problem: envoy as a client borrows a connection from a connection pool that has already been closed by the peer. Since this is a routine occurrence we don’t want to lose the request and return a 503 to the downstream client.

Approach 1: Envoy should notice the reset/close when sending the request to the upstream and automatically borrow a new connection from the pool or initiate a new connection. AFAIK Envoy does not support this today so we can’t get this into Istio 1.1. @PiotrSikora @htuch @jplevyak @alyssawilk

Approach 2: @knrc’s https://github.com/istio/istio/pull/12188 which was built upon work done by @nmittler: Configure Envoy to retry these requests. This covers the connection pool race condition, but is imperfect because it may retry additional cases we don’t want to retry. This is the current solution going into 1.1.

Approach 3: @rshriram abandoned https://github.com/istio/istio/pull/12227 to set max requests per connection to 1. This certainly avoids the race condition, but also completely disables connection pooling. Several of us (@costinm @knrc @mandarjog @duderino) were not comfortable doing this without substantial performance testing and doing that would delay 1.1 too much.

Approach 4: We could instead set the an idle timeout for connections using the mechanism introduced in https://github.com/envoyproxy/envoy/pull/2714. The idea is that we can close idle connections and remove them from the connection pool before the peer is likely to close them. The peer can still close them for other reasons (e.g., overload) but in theory this would reduce the number of 503s without potentially retrying requests we don’t want retried. The concern I have with this one is that it’s not clear to me that the idle timeout only applies to sockets with no active requests on them. If there were active requests with infrequent activity (e.g,. long polls) we might lose those too.

So Approach 2 IMHO is the least risky option for 1.1, but it’s arguable.

+3
duderino on Mar 4, 2019

I see the same issue, with Istio service mesh sidecars, Istio IngressGateway, and Ambassador API Gateway. I believe the root cause is a race condition between the TCP keepalive setting and the stream idle timeout. Istio does connection pooling of HTTP connections under the covers. If a connection is idle for 5 minutes, the TCP keepalive should fire to keep the conneciton alive. But, the stream idle timeout is also 5 minutes, so a race condition exists.

I’ve commented more about it here: https://github.com/istio/istio/issues/9906

We were able to correct the issue by setting the spec->http->retries->attempts field on the VirtualService manifest. In Istio v1.1, they’ve introduced the retryOn configuration setting to Envoy, so you can retry on only 5xx errors. They’ve also introduced the ability to set the steam idle timeout. I haven’t tested this hypothesis against the snapshot builds of 1.1–we’ll resume testing of this when 1.1 goes GA.

+3
dankirkpatrick on Feb 20, 2019

Update for today’s call

I have traces from both ingressgateway and httpbin sides, the error is happening when the sidecar returns RST/ACK in response to the request (GET in this case) but without trying to talk with the application. The response from ingressgateway to the caller is then a 503.

I’m still investigating the reason behind the RST/ACK from the sidecar.

+2
knrc on Mar 6, 2019

Now a valid workaround is to use the retry mechanism configurable through HTTPRetry in the VirtualService, and when 1.1 is finally released, the retryOn with 5xx.

Testing this out with 1.1.0-rc.0 and just a single attempts: 1 results in no 503 whatsoever:

#  kubectl exec -ti fortio-deploy-5588f84b45-5xx5v -- fortio load -qps 10 -t 1800s -c 10 -httpbufferkb 8569 -H "Host: httpbin.org" http://10.138.132.8:32500/json

Code 200 : 18000 (100.0 %)

# kubectl exec -ti fortio-deploy-5588f84b45-5xx5v -- fortio load -qps 10 -t 1800s -c 10 -httpbufferkb 8569 -H "Host: httpbin.org" http://10.138.132.8:32500/html

Code 200 : 18000 (100.0 %)
+2
emedina on Feb 24, 2019

More feedback…

Tried 1.1.0-rc.0 in a clean LAB environment running v1.13.2 and it’s still throwing sporadic 503 with a simple load test using fortio and two endpoints of httpbin:

kubectl exec -ti fortio-deploy-5588f84b45-5xx5v -- fortio load -qps 10 -t 600s -c 10 -httpbufferkb 8569 -H "Host: httpbin.org" http://10.138.132.8:32500/json

kubectl exec -ti fortio-deploy-5588f84b45-5xx5v -- fortio load -qps 10 -t 600s -c 10 -httpbufferkb 8569 -H "Host: httpbin.org" http://10.138.132.8:32500/html

As you can see, I’m using the NodePort to call the Ingress Gateway, so no external impact by HAProxy (just in case). Additionally, this is definitively a very low demanding load test running for 10m. However, there are several 503 errors:

From the endpoint /html:

08:58:38 W http_client.go:679> Parsed non ok code 503 (HTTP/1.1 503)
08:58:42 W http_client.go:679> Parsed non ok code 503 (HTTP/1.1 503)
08:58:45 W http_client.go:679> Parsed non ok code 503 (HTTP/1.1 503)
09:06:01 W http_client.go:679> Parsed non ok code 503 (HTTP/1.1 503)

From the endpoint /json:

09:05:47 W http_client.go:679> Parsed non ok code 503 (HTTP/1.1 503)
09:05:56 W http_client.go:679> Parsed non ok code 503 (HTTP/1.1 503)
09:06:00 W http_client.go:679> Parsed non ok code 503 (HTTP/1.1 503)

The logs from the Ingress Gateway are:

# kail -l app=istio-ingressgateway --since 10m | grep ' 503 '
istio-system/istio-ingressgateway-5979b99885-rxd66[istio-proxy]: [2019-02-24T08:58:38.611Z] "GET /html HTTP/1.1" 503 UC "-" 0 57 2 - "174.16.249.64" "fortio.org/fortio-1.3.1" "ad930b2f-b08c-99bf-93b3-e93d4d3aa475" "httpbin.org" "174.16.249.69:80" outbound|8000||httpbin.default.svc.cluster.local - 174.16.71.101:80 174.16.249.64:33416 -
istio-system/istio-ingressgateway-5979b99885-rxd66[istio-proxy]: [2019-02-24T08:58:42.641Z] "GET /html HTTP/1.1" 503 UC "-" 0 57 19 - "174.16.249.64" "fortio.org/fortio-1.3.1" "447f4df1-99fe-9efa-9302-f2084120baaa" "httpbin.org" "174.16.249.69:80" outbound|8000||httpbin.default.svc.cluster.local - 174.16.71.101:80 174.16.249.64:33421 -
istio-system/istio-ingressgateway-5979b99885-rxd66[istio-proxy]: [2019-02-24T08:58:45.874Z] "GET /html HTTP/1.1" 503 UC "-" 0 57 6 - "174.16.249.64" "fortio.org/fortio-1.3.1" "13c3e002-6f69-9575-a642-3e130cc1aeea" "httpbin.org" "174.16.249.69:80" outbound|8000||httpbin.default.svc.cluster.local - 174.16.71.101:80 174.16.249.64:33415 -
istio-system/istio-ingressgateway-5979b99885-rxd66[istio-proxy]: [2019-02-24T09:05:47.855Z] "GET /json HTTP/1.1" 503 UC "-" 0 57 15 - "174.16.249.64" "fortio.org/fortio-1.3.1" "96cb8b74-7a29-9829-8bde-30d58b70d353" "httpbin.org" "174.16.249.69:80" outbound|8000||httpbin.default.svc.cluster.local - 174.16.71.101:80 174.16.249.64:33554 -
istio-system/istio-ingressgateway-5979b99885-rxd66[istio-proxy]: [2019-02-24T09:05:55.955Z] "GET /json HTTP/1.1" 503 UC "-" 0 57 26 - "174.16.249.64" "fortio.org/fortio-1.3.1" "dce86649-0f9e-946f-b15a-4e48300f45b8" "httpbin.org" "174.16.249.69:80" outbound|8000||httpbin.default.svc.cluster.local - 174.16.71.101:80 174.16.249.64:33561 -
istio-system/istio-ingressgateway-5979b99885-rxd66[istio-proxy]: [2019-02-24T09:05:59.924Z] "GET /json HTTP/1.1" 503 UC "-" 0 57 146 - "174.16.249.64" "fortio.org/fortio-1.3.1" "fb921a6f-2f04-993b-9e45-25349c3962f1" "httpbin.org" "174.16.249.69:80" outbound|8000||httpbin.default.svc.cluster.local - 174.16.71.101:80 174.16.249.64:33550 -
istio-system/istio-ingressgateway-5979b99885-rxd66[istio-proxy]: [2019-02-24T09:06:01.426Z] "GET /html HTTP/1.1" 503 UC "-" 0 57 0 - "174.16.249.64" "fortio.org/fortio-1.3.1" "e821b8b9-4273-9814-bb3a-e13d6749a35d" "httpbin.org" "174.16.249.69:80" outbound|8000||httpbin.default.svc.cluster.local - 174.16.71.101:80 174.16.249.64:33419 -

No apparent issues in httpbin itself;

# kubectl logs -f httpbin-54f5bb4957-sgt4v
[2019-02-20 16:32:08 +0000] [1] [INFO] Starting gunicorn 19.9.0
[2019-02-20 16:32:08 +0000] [1] [INFO] Listening at: http://0.0.0.0:80 (1)
[2019-02-20 16:32:08 +0000] [1] [INFO] Using worker: gevent
[2019-02-20 16:32:08 +0000] [10] [INFO] Booting worker with pid: 10

And eventually the fortio load test concludes reporting the issues:

For the endpoint `/json`:

Code 200 : 5997 (100.0 %)
Code 503 : 3 (0.1 %)

For the endpoint `/html`:

Code 200 : 5996 (99.9 %)
Code 503 : 4 (0.1 %)

This scenario can be reproduced consistently and always throws 503 errors.

+2
emedina on Feb 24, 2019

Also did some basic testing using Google Cloud with httpbin and fortio running a minimal load test (10 qps using 10 threads during 10m) against /html and /json endpoints, and I get 503 errors:

Code 200 : 5998 (100.0 %)
Code 503 : 2 (0.0 %)

I know that Google Cloud may not be using the latest Istio, but I’m wondering how Google can provide this functionality when a basic test fails so easily.

And I presume this issue is still there… because I keep getting it even with latest 1.1-rc.

+2
emedina on Feb 23, 2019

Still facing sporadic 503s, but maybe related to the HPA autoscaling the Control Plane and impacting applications. Does this make sense?

+2
emedina on Nov 21, 2018

1.1.8 contains important upgrades for people who are experiencing this issue. Because it’s believed to be triggered at Envoy side: https://github.com/envoyproxy/envoy/pull/6578

After upgrading to 1.1.8, I’ve not seen 503s so far.

+1
iandyh on Jun 10, 2019

The log from @emedina shows

  • the 503 connection C502 reuses upstream connection
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.960][95][debug][pool] external/envoy/source/common/http/http1/conn_pool.cc:89] [C502] using existing connection
  • The upstream connection is writable
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][trace][connection] external/envoy/source/common/network/connection_impl.cc:326] [C502] writing 546 bytes, end_stream false
  • The upstream connection is somehow not readable
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][trace][connection] external/envoy/source/common/network/connection_impl.cc:389] [C502] socket event: 3
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][trace][connection] external/envoy/source/common/network/connection_impl.cc:457] [C502] write ready
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][trace][connection] external/envoy/source/common/network/connection_impl.cc:427] [C502] read ready
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][trace][connection] external/envoy/source/common/network/raw_buffer_socket.cc:21] [C502] read returns: 0
  • envoy will return 503 to downstream
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][debug][connection] external/envoy/source/common/network/connection_impl.cc:451] [C502] remote close
preprod-cb/classification-helper-ui-76f9cdcd4d-rz6n9[istio-proxy]: [2018-10-03 08:47:42.961][95][debug][connection] external/envoy/source/common/network/connection_impl.cc:133] [C502] closing socket: 0
+1
lambdai on May 14, 2019

I did, thanks! Setting it to 3s (nodejs server is 5s) eliminated 100% of my errors during runtime. I did continue to get some 503s but was able to correlate them with deployments. The Istio default retry should catch those but I tracked that problem down to an Envoy issue: https://github.com/envoyproxy/envoy/issues/6726

+1
jaygorrell on Apr 30, 2019

@arianmotamedi So we actually need to combine them 😃

I will try to provide feedback ASAP on 1.1.3 then.

+1
emedina on Apr 16, 2019

@TonyJDavies I recommend you to check out this too https://github.com/istio/istio/issues/12183#issuecomment-477044517 – how many services do you have? If it is lots of sidecar, implementing the sidecar config would be recommended as it has proved to be helpful for @Stono

+1
linsun on Apr 5, 2019

@GregHanson could you look into adding this as a configuration for our users? This is a very recent feature from envoy, not sure if Istio proxy has that fix yet.

@TonyJDavies I would definitely recommend disable mixer or disable mixer check in your env. Even if you are not using mixer policy, the proxy still asks mixer to see if a call is allowed thus can introduce additional 503s for you.

If you don’t need mixer policy checks, then disable it. If you rely on that functionality you could try enabling the experimental mixer retries which were introduced with 1.1.0. Instructions for enabling it can be found here: https://github.com/istio/istio/issues/9992#issuecomment-466229569

+1
duderino on Apr 4, 2019

@GregHanson could you look into adding this as a configuration for our users? This is a very recent feature from envoy, not sure if Istio proxy has that fix yet.

@TonyJDavies I would definitely recommend disable mixer or disable mixer check in your env. Even if you are not using mixer policy, the proxy still asks mixer to see if a call is allowed thus can introduce additional 503s for you.

+1
linsun on Apr 4, 2019

@arianmotamedi Would you mind sharing some configuration snippets about how you have set up the idle upstream timeouts in your Istio installation?

Thanks!

+1
emedina on Apr 3, 2019

@TonyJDavies re the log spam: https://github.com/istio/istio/issues/12642

+1
Stono on Mar 29, 2019

Upgrading to Istio 1.1.0 has given us a more resilient installation, in that the 503 responses are being handled such that they are less disruptive to our applications.

Istio 1.1.0 Kubernetes : 1.13.4_1515

However, we are nevertheless seeing a continuous stream of 503 responses across all of our pods, making them all apparently unhealthy.

It would be highly preferable to see these eliminated so that we can see a correct health status for our pods.

I’m also intrigued to see that we have many thousands of messages from the istio-proxy as shown below. If there is anything further I can try/provide to help track down this issue I can do so.

[2019-03-29 09:26:31.637][18][warning][misc] [external/envoy/source/common/protobuf/utility.cc:129] Using deprecated option 'envoy.api.v2.route.Route.per_filter_config'. This configuration will be removed from Envoy soon. Please see https://github.com/envoyproxy/envoy/blob/master/DEPRECATED.md for details.
[2019-03-29 09:26:31.637][18][warning][misc] [external/envoy/source/common/protobuf/utility.cc:129] Using deprecated option 'envoy.api.v2.route.Route.per_filter_config'. This configuration will be removed from Envoy soon. Please see https://github.com/envoyproxy/envoy/blob/master/DEPRECATED.md for details.
[2019-03-29 09:26:31.637][18][warning][misc] [external/envoy/source/common/protobuf/utility.cc:129] Using deprecated option 'envoy.api.v2.route.Route.per_filter_config'. This configuration will be removed from Envoy soon. Please see https://github.com/envoyproxy/envoy/blob/master/DEPRECATED.md for details.
+1
TonyJDavies on Mar 29, 2019

Also having sporadic 503 errors. In my case it’s coming from a simple health check. The 503 does not come from the application. It comes from the istio-proxy. Found this when my pods were failing health checks, yet the application logs were 100% devoid of 503s. The istio-proxy logs showed about 2.9% of responses were 503 UC, the rest are 200.

All 503 responses had the UC flag.

From the envoy docs:

UC: Upstream connection termination in addition to 503 response code.

Running Istio 1.0.6 GKE 1.10.x

PS – This is the only deployment that is throwing 503s like this. However… I may have a malformed ip address in a ServiceEntry.

The malformed IP address happens to be the FQDN of a service that’s on the same cluster but outside the mesh. The service does exist. The FQDN is correct. Resolution is set to DNS. Not sure why this is trying to get read as an IP Address…

Logs 

[2019-03-07 20:10:30.719][17][warning][config] bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_mux_subscription_lib/common/config/grpc_mux_subscription_impl.h:70] gRPC config for type.googleapis.com/envoy.api.v2.ClusterLoadAssignment rejected: malformed IP address: api-pricing.pricing.svc.cluster.local. Consider setting resolver_name or setting cluster type to 'STRICT_DNS' or 'LOGICAL_DNS'
...
This line shows up in the logs 2,141 times
+1
mehemken on Mar 7, 2019
Read more comments on GitHub
← istio: specify value for "spec.subjects.properties.version" doesn't work as expected in ServiceRoleBinding
istio: SSL Error Between Sidecar Service and Kafka →