Istio envoy 504 网关在出站连接 15 秒后超时

Question

背景：

\n\n

我使用的是istio 1.2.5

\n\n

我已经使用 istio 文档中的 helm 默认配置文件部署了 istio，将跟踪、kiali 和 logLevel 启用为“调试”。

\n\n

我的 pod 和 istio 系统命名空间中的服务如下所示：

\n\n

(\xe2\x8e\x88 |cluster-dev:default)\xe2\x9e\x9c  istio-1.2.5 git:(master) \xe2\x9c\x97 k pods -n istio-system\nNAME                                      READY     STATUS    RESTARTS   AGE\ngrafana-97fb6966d-cv5fq                   1/1       Running   0          1d\nistio-citadel-76f9586b8b-4bbcx            1/1       Running   0          1d\nistio-galley-78f65c8469-v5cmn             1/1       Running   0          1d\nistio-ingressgateway-5d5487c666-jjhb7     1/1       Running   0          1d\nistio-pilot-65cb5648bf-4nfl7              2/2       Running   0          1d\nistio-policy-8596cc6554-7sgzt             2/2       Running   0          1d\nistio-sidecar-injector-76f487845d-ktf6p   1/1       Running   0          1d\nistio-telemetry-5c6b6d59f6-lppqt          2/2       Running   0          1d\nistio-tracing-595796cf54-zsnvj            1/1       Running   0          1d\nkiali-55fcfc86cc-p2jrk                    1/1       Running   0          1d\nprometheus-5679cb4dcd-h7qsj               1/1       Running   0          1d\n\n(\xe2\x8e\x88 |cluster-dev:default)\xe2\x9e\x9c  istio-1.2.5 git:(master) \xe2\x9c\x97 k svc  -n istio-system\nNAME                     TYPE           CLUSTER-IP       EXTERNAL-IP        PORT(S)                                                                                                                                      AGE\ngrafana                  ClusterIP      172.20.116.246   <none>             3000/TCP                                                                                                                                     1d\nistio-citadel            ClusterIP      172.20.177.97    <none>             8060/TCP,15014/TCP                                                                                                                           1d\nistio-galley             ClusterIP      172.20.162.16    <none>             443/TCP,15014/TCP,9901/TCP                                                                                                                   1d\nistio-ingressgateway     LoadBalancer   172.20.199.160   xxxxxxxxxxxxx...   15020:31334/TCP,80:31380/TCP,443:31390/TCP,31400:31400/TCP,15029:30200/TCP,15030:32111/TCP,15031:32286/TCP,15032:32720/TCP,15443:30857/TCP   1d\nistio-pilot              ClusterIP      172.20.137.21    <none>             15010/TCP,15011/TCP,8080/TCP,15014/TCP                                                                                                       1d\nistio-policy             ClusterIP      172.20.188.114   <none>             9091/TCP,15004/TCP,15014/TCP                                                                                                                 1d\nistio-sidecar-injector   ClusterIP      172.20.47.238    <none>             443/TCP                                                                                                                                      1d\nistio-telemetry          ClusterIP      172.20.77.52     <none>             9091/TCP,15004/TCP,15014/TCP,42422/TCP                                                                                                       1d\njaeger-agent             ClusterIP      None             <none>             5775/UDP,6831/UDP,6832/UDP                                                                                                                   1d\njaeger-collector         ClusterIP      172.20.225.255   <none>             14267/TCP,14268/TCP                                                                                                                          1d\njaeger-query             ClusterIP      172.20.181.245   <none>             16686/TCP                                                                                                                                    1d\nkiali                    ClusterIP      172.20.72.227    <none>             20001/TCP                                                                                                                                    1d\nprometheus               ClusterIP      172.20.25.75     <none>             9090/TCP                                                                                                                                     1d\ntracing                  ClusterIP      172.20.211.135   <none>             80/TCP                                                                                                                                       1d\nzipkin                   ClusterIP      172.20.204.123   <none>             9411/TCP                                                                                                                                     1d\n

\n\n

我没有使用任何出口网关，并且我的 outboundTrafficPolicy 模式为 ALLOW_ANY。所以，我假设我不需要任何服务条目。

\n\n

我使用 nginx 入口控制器作为集群的入口点，但尚未启动 istio 入口网关。

\n\n

问题：

\n\n

我的集群中有一个微服务，它通过 HTTP POST 查询访问/到达外部 URL（从集群到旧系统）。该系统通常会在 25 秒内响应我的微服务，并且自身具有 0f 30 秒的硬超时。

\n\n

当我不使用 istio sidecar 时，我的微服务响应正常。但是在使用 sidecar 部署 istio 后，每次 15 秒后我都会收到 504 网关。

\n\n

微服务和istio-proxy的日志：

\n\n

没有 istio 的微服务日志（日志中搜索响应花费了 21.957 秒）

\n\n

2019-09-06 19:42:20.113  INFO [xx-xx-adapter,9b32565791541300,9b32565791541300,false] 1 --- [or-http-epoll-4] c.s.t.s.impl.common.PrepareRequest       : Start Preparing search request\n2019-09-06 19:42:20.117  INFO [xx-xx-adapter,9b32565791541300,9b32565791541300,false] 1 --- [or-http-epoll-4] c.s.t.s.impl.common.PrepareRequest       : Done Preparing search request\n2019-09-06 19:42:42.162  INFO [xx-xx-adapter,9b32565791541300,9b32565791541300,false] 1 --- [or-http-epoll-8] c.s.t.service.impl.TVSearchServiceImpl   : xxxx search response took 21.957 Seconds\n2019-09-06 19:42:42.292  INFO [xx-xx-adapter,9b32565791541300,9b32565791541300,false] 1 --- [or-http-epoll-8] c.s.t.service.impl.common.Transformer    : Doing transformation of supplier response into our response\n2019-09-06 19:42:42.296  INFO [xx-xx-adapter,9b32565791541300,9b32565791541300,false] 1 --- [or-http-epoll-8] c.s.t.service.impl.common.Transformer    : Transformer: Parsing completed in 3 mSeconds\n

\n\n

使用 istio 进行微服务日志（日志中响应时间为 15.009 秒）

\n\n

2019-09-06 19:40:00.048  INFO [xxx-xx-adapter,32c55821a507d6f3,32c55821a507d6f3,false] 1 --- [or-http-epoll-3] c.s.t.s.impl.common.PrepareRequest       : Start Preparing search request\n2019-09-06 19:40:00.048  INFO [xxx-xx-adapter,32c55821a507d6f3,32c55821a507d6f3,false] 1 --- [or-http-epoll-3] c.s.t.s.impl.common.PrepareRequest       : Done Preparing search request\n\n2019-09-06 19:40:15.058  INFO [xx-xx-adapter,32c55821a507d6f3,32c55821a507d6f3,false] 1 --- [or-http-epoll-7] c.s.t.service.impl.xxxx   : xxx Search Request {"rqst":{"Request":{"__type":"xx","CheckIn":"/Date(1569628800000+0000)/","CheckOut":"/Date(1569801600000+0000)/","DetailLevel":9,"ExcludeHotelDetails":false,"GeoLocationInfo":{"Latitude":25.204849,"Longitude":55.270782},"Nights":0,"RadiusInMeters":25000,"Rooms":[{"AdultsCount":2,"KidsAges":[2]}],"DesiredResultCurrency":"EUR","Residency":"GB","TimeoutSeconds":25,"ClientIP":"127.0.0.1"},"RequestType":1,"TypeOfService":2,"Credentials":{"UserName":"xxxx","Password":"xx"}}}\n2019-09-06 19:40:15.058 ERROR [xx-xx-adapter,32c55821a507d6f3,32c55821a507d6f3,false] 1 --- [or-http-epoll-7] c.s.t.service.impl.xxxx   : xxx Search request failed 504 GATEWAY_TIMEOUT\n\n2019-09-06 19:40:15.058  INFO [xxx-xx-adapter,32c55821a507d6f3,32c55821a507d6f3,false] 1 --- [or-http-epoll-7] c.s.t.service.impl.xxxx   : xx search response took 15.009 Seconds\n\n2019-09-06 19:40:15.059 ERROR [xxx-xx-adapter,32c55821a507d6f3,32c55821a507d6f3,false] 1 --- [or-http-epoll-7] a.w.r.e.AbstractErrorWebExceptionHandler : [79d38e2f] 500 Server Error for HTTP POST "/search/geo-location"\n\njava.lang.RuntimeException: Error occurred, We did not receive proper search response from xx please check internal logs for more info\n\n<Java Stack trace >\n\n2019-09-06 19:40:15.061 ERROR [xxx-xx-adapter,32c55821a507d6f3,32c55821a507d6f3,false] 1 --- [or-http-epoll-7] c.s.t.service.impl.xxxx   : xxx search response upstream request timeout\n2019-09-06 19:41:16.081  INFO [xxx-xx--adapter,,,] 1 --- [      Thread-22] o.s.s.concurrent.ThreadPoolTaskExecutor  : Shutting down ExecutorService \'executor\'\n

\n\n

Envoy sidecar 代理日志被屏蔽

\n\n

[2019-09-06T20:32:15.418Z] "POST /xxxxxx/xxxxx.svc/xx/ServiceRequest HTTP/1.1" 504 UT "-" "-" 517 24 14997 - "-" "ReactorNetty/0.8.10.RELEASE" "c273fac1-8xxa-xxxx-xxxx-xxxxxx" "testdomain.testurl.com" "40.67.217.71:80" PassthroughCluster - 1.7.17.71:80 1.20.21.25:42386 -\n\n[2019-09-06 20:39:01.719][34][debug][router] [external/envoy/source/common/router/router.cc:332] [C57][S17104382791712695742] cluster \'PassthroughCluster\' match for URL \'/xxxxx/xxxx.svc/json/ServiceRequest\'\n\n\n[2019-09-06 20:39:01.719][34][debug][router] [external/envoy/source/common/router/router.cc:332] [C57][S17104382791712695742] cluster \'PassthroughCluster\' match for URL \'/xxxxx/xxxx.svc/json/ServiceRequest\'\n[2019-09-06 20:39:01.719][34][debug][upstream] [external/envoy/source/common/upstream/original_dst_cluster.cc:87] Created host 40.67.217.71:80.\n[2019-09-06 20:39:01.719][34][debug][router] [external/envoy/source/common/router/router.cc:393] [C57][S17104382791712695742] router decoding headers:\n\':authority\', \'x.x.com\'\n\':path\', \'/xxxxx/xxxxx.svc/json/ServiceRequest\'\n\':method\', \'POST\'\n\':scheme\', \'http\'\n\'user-agent\', \'ReactorNetty/0.8.10.RELEASE\'\n\'accept\', \'application/json\'\n\'accept-encoding\', \'gzip, deflate\'\n\'x-newrelic-transaction\', \'PxRSBVVQXAdVUgNTUgcPUQUBFB8EBw8RVU4aB1wLB1YHAA8DAAQFWlNXB0NKQV5XCVVQAQcGFTs=\'\n\'x-newrelic-id\', \'VgUDWFVaARADUFNWAgQHV1A=\'\n\'content-type\', \'application/json;charset=UTF-8\'\n\'content-length\', \'517\'\n\'x-forwarded-proto\', \'http\'\n\'x-request-id\', \'750f4fdb-83f9-409c-9ecf-e0a1fdacbb65\'\n\'x-istio-attributes\', \'CloKCnNvdXJjZS51aWQSTBJKa3ViZXJuZXRlczovL2hvdGVscy10di1hZGFwdGVyLXNlcnZpY2UtZGVwbG95bWVudC03ZjQ0ZDljNjVjLWhweHo3LmRlZmF1bHQ=\'\n\'x-envoy-expected-rq-timeout-ms\', \'15000\'\n\'x-b3-traceid\', \'971ac547c63fa66e\'\n\'x-b3-spanid\', \'58c12e7da54ae50f\'\n\'x-b3-parentspanid\', \'dc7bda5b98d522bf\'\n\'x-b3-sampled\', \'0\'\n\n[2019-09-06 20:39:01.719][34][debug][pool] [external/envoy/source/common/http/http1/conn_pool.cc:88] creating a new connection\n[2019-09-06 20:39:01.719][34][debug][client] [external/envoy/source/common/http/codec_client.cc:26] [C278] connecting\n[2019-09-06 20:39:01.719][35][debug][upstream] [external/envoy/source/common/upstream/cluster_manager_impl.cc:973] membership update for TLS cluster PassthroughCluster added 1 removed 0\n[2019-09-06 20:39:01.719][28][debug][upstream] [external/envoy/source/common/upstream/cluster_manager_impl.cc:973] membership update for TLS cluster PassthroughCluster added 1 removed 0\n[2019-09-06 20:39:01.719][34][debug][connection] [external/envoy/source/common/network/connection_impl.cc:704] [C278] connecting to 40.67.217.71:80\n[2019-09-06 20:39:01.720][35][debug][upstream] [external/envoy/source/common/upstream/original_dst_cluster.cc:41] Adding host 40.67.217.71:80.\n[2019-09-06 20:39:01.720][28][debug][upstream] [external/envoy/source/common/upstream/original_dst_cluster.cc:41] Adding host 40.67.217.71:80.\n[2019-09-06 20:39:01.720][34][debug][connection] [external/envoy/source/common/network/connection_impl.cc:713] [C278] connection in progress\n[2019-09-06 20:39:01.720][34][debug][pool] [external/envoy/source/common/http/conn_pool_base.cc:20] queueing request due to no available connections\n[2019-09-06 20:39:01.720][34][debug][filter] [src/envoy/http/mixer/filter.cc:102] Called Mixer::Filter : decodeData (517, false)\n[2019-09-06 20:39:01.720][34][debug][http] [external/envoy/source/common/http/conn_manager_impl.cc:1079] [C57][S17104382791712695742] request end stream\n[2019-09-06 20:39:01.720][34][debug][filter] [src/envoy/http/mixer/filter.cc:102] Called Mixer::Filter : decodeData (0, true)\n[2019-09-06 20:39:01.720][34][debug][upstream] [external/envoy/source/common/upstream/cluster_manager_impl.cc:973] membership update for TLS cluster PassthroughCluster added 1 removed 0\n[2019-09-06 20:39:01.748][34][debug][connection] [external/envoy/source/common/network/connection_impl.cc:552] [C278] connected\n[2019-09-06 20:39:01.748][34][debug][client] [external/envoy/source/common/http/codec_client.cc:64] [C278] connected\n[2019-09-06 20:39:01.748][34][debug][pool] [external/envoy/source/common/http/http1/conn_pool.cc:245] [C278] attaching to next request\n[2019-09-06 20:39:01.748][34][debug][router] [external/envoy/source/common/router/router.cc:1210] [C57][S17104382791712695742] pool ready\n[2019-09-06 20:39:02.431][35][debug][filter] [external/envoy/source/extensions/filters/listener/original_dst/original_dst.cc:18] original_dst: New connection accepted\n[2019-09-06 20:39:02.431][35][debug][filter] [external/envoy/source/extensions/filters/listener/tls_inspector/tls_inspector.cc:72] tls inspector: new connection accepted\n[2019-09-06 20:39:02.431][35][debug][filter] [src/envoy/tcp/mixer/filter.cc:30] Called tcp filter: Filter\n[2019-09-06 20:39:02.431][35][debug][filter] [src/envoy/tcp/mixer/filter.cc:40] Called tcp filter: initializeReadFilterCallbacks\n[2019-09-06 20:39:02.431][35][debug][filter] [external/envoy/source/common/tcp_proxy/tcp_proxy.cc:200] [C279] new tcp proxy session\n[2019-09-06 20:39:02.431][35][debug][filter] [src/envoy/tcp/mixer/filter.cc:135] [C279] Called tcp filter onNewConnection: remote 1.210.4.2:39482, local 1.10.1.5:80\n[2019-09-06 20:39:02.431][35][debug][filter] [external/envoy/source/common/tcp_proxy/tcp_proxy.cc:343] [C279] Creating connection to cluster inbound|80|xx-xx-adapter-service|xx-xx-adapter-service.default.svc.cluster.local\n[2019-09-06 20:39:02.431][35][debug][pool] [external/envoy/source/common/tcp/conn_pool.cc:80] creating a new connection\n[2019-09-06 20:39:02.431][35][debug][pool] [external/envoy/source/common/tcp/conn_pool.cc:372] [C280] connecting\n[2019-09-06 20:39:02.431][35][debug][connection] [external/envoy/source/common/network/connection_impl.cc:704] [C280] connecting to 127.0.0.1:80\n[2019-09-06 20:39:02.431][35][debug][connection] [external/envoy/source/common/network/connection_impl.cc:713] [C280] connection in progress\n[2019-09-06 20:39:02.431][35][debug][pool] [external/envoy/source/common/tcp/conn_pool.cc:106] queueing request due to no available connections\n[2019-09-06 20:39:02.431][35][debug][main] [external/envoy/source/server/connection_handler_impl.cc:257] [C279] new connection\n[2019-09-06 20:39:02.431][35][debug][connection] [external/envoy/source/common/network/connection_impl.cc:552] [C280] connected\n[2019-09-06 20:39:02.431][35][debug][pool] [external/envoy/source/common/tcp/conn_pool.cc:293] [C280] assigning connection\n[2019-09-06 20:39:02.431][35][debug][filter] [external/envoy/source/common/tcp_proxy/tcp_proxy.cc:542] TCP:onUpstreamEvent(), requestedServerName:\n[2019-09-06 20:39:02.431][35][debug][filter] [src/envoy/tcp/mixer/filter.cc:143] Called tcp filter completeCheck: OK\n[2019-09-06 20:39:02.432][35][debug][filter] [src/istio/control/client_context_base.cc:140] Report attributes: attributes {\n  key: "connection.event"\n  value {\n    string_value: "open"\n  }\n}\nattributes {\n  key: "connection.id"\n  value {\n    string_value: "82e869af-aec6-406a-8a52-4168a19eb1f0-279"\n\n[2019-09-06 20:39:02.432][35][debug][filter] [src/envoy/tcp/mixer/filter.cc:102] [C279] Called tcp filter onRead bytes: 130\n[2019-09-06 20:39:02.435][35][debug][filter] [src/envoy/tcp/mixer/filter.cc:125] [C279] Called tcp filter onWrite bytes: 147\n[2019-09-06 20:39:02.435][35][debug][filter] [src/envoy/tcp/mixer/filter.cc:102] [C279] Called tcp filter onRead bytes: 0\n[2019-09-06 20:39:02.436][35][debug][filter] [src/envoy/tcp/mixer/filter.cc:125] [C279] Called tcp filter onWrite bytes: 0\n[2019-09-06 20:39:02.436][35][debug][connection] [external/envoy/source/common/network/connection_impl.cc:520] [C280] remote close\n[2019-09-06 20:39:02.436][35][debug][connection] [external/envoy/source/common/network/connection_impl.cc:190] [C280] closing socket: 0\n[2019-09-06 20:39:02.436][35][debug][pool] [external/envoy/source/common/tcp/conn_pool.cc:121] [C280] client disconnected\n[2019-09-06 20:39:02.436][35][debug][connection] [external/envoy/source/common/network/connection_impl.cc:101] [C279] closing data_to_write=0 type=0\n[2019-09-06 20:39:02.436][35][debug][connection] [external/envoy/source/common/network/connection_impl.cc:190] [C279] closing socket: 1\n[2019-09-06 20:39:02.436][35][debug][filter] [src/envoy/tcp/mixer/filter.cc:174] [C279] Called tcp filter onEvent: 1 upstream 127.0.0.1:80\n[2019-09-06 20:39:02.436][35][debug][filter] [src/istio/control/client_context_base.cc:140] Report attributes: attributes {\n  key: "connection.duration"\n  value {\n    duration_value {\n      nanos: 4358000\n    }\n  }\n}\nattributes {\n  key: "connection.event"\n  value {\n    string_value: "close"\n  }\n}\nat\n[2019-09-06 20:39:02.436][35][debug][main] [external/envoy/source/server/connection_handler_impl.cc:68] [C279] adding to cleanup list\n[2019-09-06 20:39:02.436][35][debug][pool] [external/envoy/source/common/tcp/conn_pool.cc:246] [C280] connection destroyed\n

\n\n

我尝试在我的 MS 上创建一个虚拟服务，超时时间为 30 秒，但没有成功。

\n\n

我不确定我错过了什么。需要帮忙。

\n\n

症结： \n互联网（或来自 pod 控制台）--> 微服务 --> 微服务在代码中内部调用第三部分遗留 URL，每次都会在 15 秒内超时。

\n\n

编辑和添加更多详细信息：

\n\n

为了增加延迟，我curl http://slowwly.robertomurray.co.uk/delay/17000/url/http://www.google.com从任何具有 istio-proxy sidecar 的微服务 pod 中尝试了“”（17000 = 17 秒），并且总是在 15 秒时超时。\n我不知道在哪里更改这个 15 秒特使设置。

\n

Answer 1

经过大量的尝试和尝试，我们成功了。

参考： https: //github.com/istio/istio/issues/16915#issuecomment-529210672

因此，对于任何出站流量，无论您是否有出口网关，默认超时都是 15 秒。因此，如果你想增加它，你需要有一个 ServiceEntry 和一个定义超时的 VirtualService。

服务入口

apiVersion: networking.istio.io/v1alpha3
kind: ServiceEntry
metadata:
  name: external-se-test
spec:
  hosts:
  - slowwly.robertomurray.co.uk
  location: MESH_EXTERNAL
  ports:
  - number: 80
    name: example-http
    protocol: HTTP
  resolution: DNS

虚拟服务

apiVersion: networking.istio.io/v1alpha3
kind: VirtualService
metadata:
  name: slow-ext
spec:
  hosts:
    - slowwly.robertomurray.co.uk
  http:
  - timeout: 30s
    route:
      - destination:
          host: slowwly.robertomurray.co.uk
        weight: 100